Trying to access array offset on value of type null

[dimzeta]

• Horizon Version: 5.4.0
• Laravel Version: 8.13.0
• PHP Version: 7.4.3
• Redis Driver & Version: phpredis 5.3.0
• Database Driver & Version: MySQL 8.0.22

Description:

Horizon is working nicely for few days, and next I woke up in the morning and see all my Jobs are failed. When I check the logs, I got these:

[2020-11-09 10:27:37] production.ERROR: Trying to access array offset on value of type null {"exception":"[object] (ErrorException(code: 0): Trying to access array offset on value of type null at /var/www/laravel-api/production/vendor/laravel/horizon/src/JobPayload.php:48)
[stacktrace]
#0 /var/www/laravel-api/production/vendor/laravel/horizon/src/JobPayload.php(48): Illuminate\\Foundation\\Bootstrap\\HandleExceptions->handleError()
#1 /var/www/laravel-api/production/vendor/laravel/horizon/src/Repositories/RedisJobRepository.php(428): Laravel\\Horizon\\JobPayload->id()
#2 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Support/helpers.php(263): Laravel\\Horizon\\Repositories\\RedisJobRepository->Laravel\\Horizon\\Repositories\\{closure}()
#3 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php(406): tap()
#4 /var/www/laravel-api/production/vendor/laravel/horizon/src/Repositories/RedisJobRepository.php(435): Illuminate\\Redis\\Connections\\PhpRedisConnection->pipeline()
#5 /var/www/laravel-api/production/vendor/laravel/horizon/src/Listeners/MarkJobsAsMigrated.php(36): Laravel\\Horizon\\Repositories\\RedisJobRepository->migrated()
#6 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(411): Laravel\\Horizon\\Listeners\\MarkJobsAsMigrated->handle()
#7 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(236): Illuminate\\Events\\Dispatcher->Illuminate\\Events\\{closure}()
#8 /var/www/laravel-api/production/vendor/laravel/horizon/src/RedisQueue.php(174): Illuminate\\Events\\Dispatcher->dispatch()
#9 /var/www/laravel-api/production/vendor/laravel/horizon/src/RedisQueue.php(128): Laravel\\Horizon\\RedisQueue->event()
#10 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Support/helpers.php(263): Laravel\\Horizon\\RedisQueue->Laravel\\Horizon\\{closure}()
#11 /var/www/laravel-api/production/vendor/laravel/horizon/src/RedisQueue.php(129): tap()
#12 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(211): Laravel\\Horizon\\RedisQueue->migrateExpiredJobs()
#13 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(187): Illuminate\\Queue\\RedisQueue->migrate()
#14 /var/www/laravel-api/production/vendor/laravel/horizon/src/RedisQueue.php(111): Illuminate\\Queue\\RedisQueue->pop()
#15 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(323): Laravel\\Horizon\\RedisQueue->pop()
#16 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(332): Illuminate\\Queue\\Worker->Illuminate\\Queue\\{closure}()
#17 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(145): Illuminate\\Queue\\Worker->getNextJob()
#18 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(116): Illuminate\\Queue\\Worker->daemon()
#19 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(100): Illuminate\\Queue\\Console\\WorkCommand->runWorker()
#20 /var/www/laravel-api/production/vendor/laravel/horizon/src/Console/WorkCommand.php(50): Illuminate\\Queue\\Console\\WorkCommand->handle()
#21 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Laravel\\Horizon\\Console\\WorkCommand->handle()
#22 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#23 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\\Container\\Util::unwrapIfClosure()
#24 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\\Container\\BoundMethod::callBoundMethod()
#25 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/Container.php(596): Illuminate\\Container\\BoundMethod::call()
#26 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Illuminate\\Container\\Container->call()
#27 /var/www/laravel-api/production/vendor/symfony/console/Command/Command.php(258): Illuminate\\Console\\Command->execute()
#28 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run()
#29 /var/www/laravel-api/production/vendor/symfony/console/Application.php(920): Illuminate\\Console\\Command->run()
#30 /var/www/laravel-api/production/vendor/symfony/console/Application.php(266): Symfony\\Component\\Console\\Application->doRunCommand()
#31 /var/www/laravel-api/production/vendor/symfony/console/Application.php(142): Symfony\\Component\\Console\\Application->doRun()
#32 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\\Component\\Console\\Application->run()
#33 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\\Console\\Application->run()
#34 /var/www/laravel-api/production/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle()
#35 {main}

[2020-11-09 10:27:38] production.ERROR: Undefined offset: 1 {"exception":"[object] (ErrorException(code: 0): Undefined offset: 1 at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php:250)
[stacktrace]
#0 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(250): Illuminate\\Foundation\\Bootstrap\\HandleExceptions->handleError()
#1 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(189): Illuminate\\Queue\\RedisQueue->retrieveNextJob()
#2 /var/www/laravel-api/production/vendor/laravel/horizon/src/RedisQueue.php(111): Illuminate\\Queue\\RedisQueue->pop()
#3 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(323): Laravel\\Horizon\\RedisQueue->pop()
#4 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(332): Illuminate\\Queue\\Worker->Illuminate\\Queue\\{closure}()
#5 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(145): Illuminate\\Queue\\Worker->getNextJob()
#6 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(116): Illuminate\\Queue\\Worker->daemon()
#7 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(100): Illuminate\\Queue\\Console\\WorkCommand->runWorker()
#8 /var/www/laravel-api/production/vendor/laravel/horizon/src/Console/WorkCommand.php(50): Illuminate\\Queue\\Console\\WorkCommand->handle()
#9 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Laravel\\Horizon\\Console\\WorkCommand->handle()
#10 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#11 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\\Container\\Util::unwrapIfClosure()
#12 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\\Container\\BoundMethod::callBoundMethod()
#13 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Container/Container.php(596): Illuminate\\Container\\BoundMethod::call()
#14 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Illuminate\\Container\\Container->call()
#15 /var/www/laravel-api/production/vendor/symfony/console/Command/Command.php(258): Illuminate\\Console\\Command->execute()
#16 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run()
#17 /var/www/laravel-api/production/vendor/symfony/console/Application.php(920): Illuminate\\Console\\Command->run()
#18 /var/www/laravel-api/production/vendor/symfony/console/Application.php(266): Symfony\\Component\\Console\\Application->doRunCommand()
#19 /var/www/laravel-api/production/vendor/symfony/console/Application.php(142): Symfony\\Component\\Console\\Application->doRun()
#20 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\\Component\\Console\\Application->run()
#21 /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\\Console\\Application->run()
#22 /var/www/laravel-api/production/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle()
#23 {main}
"} 

config/horizon.php:

<?php

use Illuminate\Support\Str;

return [
    'domain' => null,
    'path' => 'admin/horizon',
    'use' => 'default',
    'prefix' => env(
        'HORIZON_PREFIX',
        Str::slug(env('APP_NAME', 'laravel'), '_').'@'.env('APP_ENV').'_horizon:'
    ),
    'middleware' => ['web'],
    'waits' => [
        'redis:default' => 60,
    ],
    'trim' => [
        'recent' => 60,
        'pending' => 60,
        'completed' => 60,
        'recent_failed' => 10080,
        'failed' => 10080,
        'monitored' => 10080,
    ],
    'metrics' => [
        'trim_snapshots' => [
            'job' => 24,
            'queue' => 24,
        ],
    ],
    'fast_termination' => false,
    'memory_limit' => 64,
    'environments' => [
        'production' => [
            'supervisor-1' => [
                'connection' => 'redis',
                'queue' => ['default'],
                'balance' => 'simple',
                'processes' => 10,
                'tries' => 1,
                'timeout' => 600,
            ],
            'scrapper' => [
                'connection' => 'redis',
                'queue' => ['price'],
                'balance' => 'simple',
                'processes' => 1,
                'tries' => 1,
                'timeout' => 600,
            ],
            'scout' => [
                'connection' => 'redis',
                'queue' => ['scout'],
                'balance' => 'simple',
                'processes' => 1,
                'tries' => 3,
                'timeout' => 600,
            ],
        ],

        'development' => [
            'supervisor-1' => [
                'connection' => 'redis',
                'queue' => ['default'],
                'balance' => 'simple',
                'processes' => 2,
                'tries' => 1,
                'timeout' => 600,
            ],
            'scrapper' => [
                'connection' => 'redis',
                'queue' => ['price'],
                'balance' => 'simple',
                'processes' => 1,
                'tries' => 1,
                'timeout' => 600,
            ],
            'scout' => [
                'connection' => 'redis',
                'queue' => ['scout'],
                'balance' => 'simple',
                'processes' => 1,
                'tries' => 1,
                'timeout' => 600,
            ],
        ],

        'local' => [
            'supervisor-1' => [
                'connection' => 'redis',
                'queue' => ['default'],
                'balance' => 'simple',
                'processes' => 2,
                'tries' => 1,
            ],
            'scrapper' => [
                'connection' => 'redis',
                'queue' => ['price'],
                'balance' => 'simple',
                'processes' => 1,
                'tries' => 1,
            ],
            'scout' => [
                'connection' => 'redis',
                'queue' => ['scout'],
                'balance' => 'simple',
                'processes' => 1,
                'tries' => 3,
            ],
        ],
    ],
];

I had also this error on Laravel 7 / Horizon 4, so I upgrated to Laravel 8 / Horizon 5 with the hope that this error will disappear, in vain.

[paras-malhotra]

Looks like Laravel is unable to json decode the job on the queue. You may have perhaps used pushRaw and forgot to json encode the raw payload. A way to debug is to run this on the Redis CLI and check for any malformed/un-encoded jobs:

lrange prefixqueues:default 0 -1

Replace prefix above with your Redis connection prefix.

[driesvints]

Also please post your job that's causing this.

[driesvints]

Hey there,

Can you first please try one of the support channels below? If you can actually identify this as a bug, feel free to report back and I'll gladly help you out and re-open this issue.

• Laracasts Forums
• Laravel.io Forums
• StackOverflow
• Discord
• Larachat
• IRC

Thanks!

[dimzeta]

The issue appeared again today. Starting at 1am, I got these error messages:

[2020-11-13 01:00:12] production.ERROR: socket error on read socket {"exception":"[object] (RedisException(code: 0): socket error on read socket at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php:116)
[2020-11-13 01:00:12] production.ERROR: read error on connection to 127.0.0.1:6379 {"exception":"[object] (RedisException(code: 0): read error on connection to 127.0.0.1:6379 at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php:116)
[2020-11-13 01:00:12] production.ERROR: socket error on read socket {"exception":"[object] (RedisException(code: 0): socket error on read socket at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php:116)
[2020-11-13 01:00:12] production.ERROR: Connection closed {"exception":"[object] (RedisException(code: 0): Connection closed at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php:406)
[previous exception] [object] (RedisException(code: 0): read error on connection to 127.0.0.1:6379 at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php:406)
[2020-11-13 01:00:13] production.ERROR: SQLSTATE[HY000] [2002] Connection refused (SQL: select * from `users` where `id` = 286 and `users`.`deleted_at` is null limit 1) {"exception":"[object] (Illuminate\\Database\\QueryException(code: 2002): SQLSTATE[HY000] [2002] Connection refused (SQL: select * from `users` where `id` = 286 and `users`.`deleted_at` is null limit 1) at /var/www/laravel-api/production/vendor/laravel/framework/src/Illuminate/Database/Connection.php:671)
[2020-11-13 01:00:17] production.ERROR: Trying to access array offset on value of type null {"exception":"[object] (ErrorException(code: 0): Trying to access array offset on value of type null at /var/www/laravel-api/production/vendor/laravel/horizon/src/JobPayload.php:48)

I understand there is something closing or locking temporary my MySQL and Redis at this specific time, I'm investigating on that. but I need to restart supervisor every time to make Horizon work again even if MySQL and Redis restart/unlock by themself, otherwise I still have the last message (and got 1Go logs per day).

[aap-tim]

@dimitribocquet

If you end up finding a solution for this, I would love to hear about it. I am currently seeing the same issue with a production application of ours. @driesvints I noticed another closed issue that seems to be the same (#919). I've traced my error back to the id() method in

horizon/src/JobPayload.php

Line 48 in b3fba0d

return $this->decoded['id'];

as well.

Unfortunately I am currently still running Laravel 7 and Horizon 5.4.0 but I can upgrade shortly and provide any details needed to help troubleshoot this issue. I apologize in advance for bringing this straight here but I have not been able to locate any good information within any of the other support channels!

[dimzeta]

@aap-tim I have no idea how and when this bug appears. Sometimes it's at 1AM, sometimes at midnight, 0.30AM...
I only have few delayed jobs (sending daily emails, indexing searchable models...) and 1 scheduled job (triggered every 30 seconds). The scheduled job uses Redis as cache, but I don't think this is the guilty.

Then I thought it was my custom backup shell scripts, so I disabled all of them. But the bug is still there.

BTW I use Redis with password protected, I don't know if it's relevant to say.

For now, I hotfix that my restarting supervisor everyday around 1:05AM, to make sure this issue won't last to long. i'm still looking for resolve this issue definitely, because now I'm not really confident to use horizon/redis queue.

[aap-tim]

@dimitribocquet I'm wondering if you are by chance dispatching your scheduled job inside of the schedule->call() method?

Something Like this:

[dimzeta]

@aap-tim I always disptach my jobs with dispatch static method:

SendPasswordUpdatedEmail::dispatch($user);

[graemlourens]

I can confirm we also have this issue and it is happens nearly every time in our maintenance window where redis is rebootet.
We are running latest version of laravel and horizon.

Some of the workers get 'stuck' (while others gracefully recover) with exactly this error. Until now we didn't find the root issue but for us it seems like its about when network connections are shaky or redis disappears shortly. Will update if we find anything new.

[j3j5]

Just adding some info in case is useful to debug this issue. I can confirm the issue with Laravel 8.29.0 and Horizon 5.7.0. I'm using Redis 5.0.7 and PHP 7.4.15 with php-redis version 5.3.2.

Not sure if useful, but we're using phpredis driver, on a Redis server which is password protected and that hasn't been restarted on a long while.

I've recently set up Sentry and got 7.7K events for that error on the last 24h. The exception itself isn't really useful but it looks to me like the jobs are somehow corrupted and the $this->decoded variable on the JobPayload class does not contain an array. Not sure if there's some sort of corruption or horizon is trying to read jobs on redis from somewhere else than where it should be stored and hence the structure of the keys isn't the correct one or, and I think this is the most likely, something else is writing into the jobs namespace something that's not formatted as a job.

[graemlourens]

also an update from our side: We have switched from directly accessing redis to using a stunnel sidecar to offload ssl encryption. Since that change we have not encountered this issue since, so it is in my opinion pointing to some timing issue combined with shaky network. (@j3j5 are you behind ssl or not?)

But until we can reproduce this we're sadly tapping in the dark.

[j3j5]

I'm not connecting through SSL, two different servers on the same internal network (one for the worker, one for the redis queue). AFAICS our works are being processed properly so this is more an annoyance than an worrying issue (apart from the fact that I almost burnt the quota for Sentry on 1 day :P ).

I'm wondering whether it is related to this issue phpredis/phpredis#1713 , I'm going to try tweaking the timeout values and I'll report back. I've seen laravel uses 0.0 as default timeouts

[j3j5]

I'm happy to report that adding a timeout of 1.0 (I've added both keys, timeout and read_timeout on my connection array) has made this error disappear completely which means that, apparently on my case, it was related to timeouts.

The mystery remains as to why a timeout causes horizon to fall on an endless loop trying to access a wrongly decoded job, but so far this is good enough for me. I'll report back if I ever see it again.

I didn't try different values bigger than 0, I went to 1.0 as it was what the person on the phpredis issue I posted above used, but I may try testing with different values.

[graemlourens]

I can confirm that we also have a timeout of 1, and read_timeout of 5 seconds and currently we're not seeing that error, but sadly i can not say if it disappeared since we set those values or not. It remains a mystery. Too many variables! :)

Happy however it is working for you. Long live the queues (with short lived jobs)

[dimzeta]

@j3j5 So we can't have a Job taking more than 1 second? To me the purpose of dispatched Jobs is to handle long time tasks, that means we lost the interest of Jobs here.

[graemlourens]

@dimitribocquet no, those are redis connection settings. So the timeout for redis calls to connect & process, this has nothing to do with the actual job process time (which your maximum is dependent on other factors)

[dimzeta]

@graemlourens My bad, I was developing in config/horizon.php while I read this message 😅
Thank you for clarifying this point, I will try this and see if it works for me.

[dimzeta]

Looks like everything is working well, thank you @j3j5 and @graemlourens !

[vlauciani]

Hi
I've the same issue...

Where did you set timeout and read_timeout? In config/database.php under redis key?

Thank you

[dimzeta]

@vlauciani in config/database. Here is my default config:

    'redis' => [
        'client' => env('REDIS_CLIENT', 'phpredis'),

        'options' => [
            'cluster' => env('REDIS_CLUSTER', 'redis'),
            'prefix' => env('REDIS_PREFIX', Str::slug(env('APP_NAME', 'laravel'), '_').'_database_'),
            'password' => env('REDIS_PASSWORD', null),
        ],

        'default' => [
            'host' => env('REDIS_HOST', '127.0.0.1'),
            'password' => env('REDIS_PASSWORD', null),
            'port' => env('REDIS_PORT', 6379),
            'database' => env('REDIS_DB', 0),
            'persistent' => env('REDIS_PERSISTENT', false),
            'timeout' => env('REDIS_TIMEOUT', 1),
            'read_timeout' => env('REDIS_READ_TIMEOUT', 5),
        ],

        'cache' => [
            'host' => env('REDIS_HOST', '127.0.0.1'),
            'password' => env('REDIS_PASSWORD', null),
            'port' => env('REDIS_PORT', 6379),
            'database' => env('REDIS_CACHE_DB', 1),
        ],
],

[vlauciani]

Thank you!

[incoming-th]

Hi,

I know this is closed but I have opened a ticket that is redirecting me here.

I have the same issue and I have added the timeout and read_timeout but I continue to get this error message once in a while.

Supervisord are in a different datacenter than the REDIS server, that could explain the problem, but timeout seems to be still occurring.

Here is an extract of my database.php config:

`
'redis' => [

    'client' => env('REDIS_CLIENT', 'phpredis'),

    'options' => [
        'cluster' => env('REDIS_CLUSTER', 'redis'),
        'prefix' => env('REDIS_PREFIX', Str::slug(env('APP_NAME', 'laravel'), '_').'_database_'),
    ],

    'default' => [
        'url' => env('REDIS_URL'),
        'host' => env('REDIS_HOST', '127.0.0.1'),
        'password' => env('REDIS_PASSWORD', null),
        'port' => env('REDIS_PORT', '6379'),
        'database' => env('REDIS_DB', '0'),
        'timeout' => 60,
        'read_timeout' => 60,
    ],

    'cache' => [
        'url' => env('REDIS_URL'),
        'host' => env('REDIS_HOST', '127.0.0.1'),
        'password' => env('REDIS_PASSWORD', null),
        'port' => env('REDIS_PORT', '6379'),
        'database' => env('REDIS_CACHE_DB', '1'),
        'timeout' => 60,
        'read_timeout' => 60,
    ],

],

`

The only way I can make the issue disappear for a while after getting hundreds of error messages per hours is to log into the server where superversord is running and do php artisan:horizon terminate.

Maybe I am missing something so hopefully someone will guide me in the right direction.

Laravel ^8.0
Horizon 5.*
predis ^1.1

Thanks

[dimzeta]

@MickaelTH Change the values of timeout and read_timeout:

'timeout' => 1,
'read_timeout' => 5,

[incoming-th]

@dimitribocquet Thanks for your suggestion, but before I try it can you explain why my values are wrong first please? Thanks

[incoming-th]

Just an update, I have changed the value to 1 and 5 but I still get the message:

ERROR: Trying to access array offset on value of type null {"exception":"[object] (ErrorException(code: 0): Trying to access array offset on value of type null at /home/forge/xxxxx/releases/20210408173433/vendor/laravel/horizon/src/JobPayload.php:48)

Also could this be related to job dispatched in the shedule via $schedule->job()?

[dimzeta]

@dimitribocquet Thanks for your suggestion, but before I try it can you explain why my values are wrong first please? Thanks

We don't know why, but we know that having a too big timeout causes horizon to fall on an endless loop.

Just an update, I have changed the value to 1 and 5 but I still get the message:

ERROR: Trying to access array offset on value of type null {"exception":"[object] (ErrorException(code: 0): Trying to access array offset on value of type null at /home/forge/xxxxx/releases/20210408173433/vendor/laravel/horizon/src/JobPayload.php:48)

Also could this be related to job dispatched in the shedule via $schedule->job()?

I have scheduled jobs, async jobs and everything work fine to me (after I updated my timeout values.
Of course, don't forget to completely stop & restart your supervisor after (or any tool you use to run your horizon).

[incoming-th]

Tried a lot of different values, restarted supervisord of course but still getting

Trying to access array offset on value of type null {"exception":"[object] (ErrorException(code: 0): Trying to access array offset on value of type null at /home/forge/xxx/releases/20210415112038/vendor/laravel/horizon/src/JobPayload.php:48

The supervisord are in US and Redis in UK, no issue when using telnet to test. If anyone got another idea, that would be very helpful.

Also got this, can be a hint to someone:

[markvdputten]

We have experienced this issue before as well, but last night it went into new proportions making me want to search for a solution and I ended up here.

Last night the connection to multiple Redis clusters, hosted through RedisLabs was lost for a short period of time, triggering this error basically every minute until I noticed and was able to restart the Horizon daemon this morning.

We are starting investigations now, but at first sight this seems to occur for us if the daemon that is running Horizon is not able to make a connection to Redis for whatever reason and after that gets stuck into this.

We have timeout and read_timeout both set to 5 in our config.

[incoming-th]

@markvdputten I tried lot of combination from a US server to a UK redis server.

This is so far my config, give it a try, I get less errors messages in the logs (where it was up to 5000+ per hours!)

This is not a final solution, just a way to mitigate the issue.

[gbalduzzi]

After struggling with this issue for some months, I finally managed to resolve it from my logs.

The problem was caused by a queue without any jobs ever pushed on them.
Probably the 'queue' didn't exist at all in the redis database and the supervisors querying it caused the error while parsing the redis response.

I manually pushed a job on the queue and I don't get any error anymore.

(in case you are wondering why I had a queue that was never used, the issue was caused by a staging environment where some features that used the aforementioned queue were never used).

I'm using Redis 6.

I hope this info can help anyone to figure out the issue, I'm not familiar with the horizon codebase but I can try to navigate it and find a fix

[mira-thakkar]

@MickaelTH You got any proper solution or do you still have same error after this setup?
i have used the same configs suggested by you.

[incoming-th]

@mira-thakkar Using this config for 2.5 months now and I got the error message from 1 server 1 time only.

I still believe in my architecture that this is not an horizon related problem but a timeout between server in US and Redis in UK.

Every config/infrastructure is different so it is a matter of finding the correct value I guess.

[mira-thakkar]

Thanks @MickaelTH

[Lumrenion]

After struggling with this issue for some months, I finally managed to resolve it from my logs.

The problem was caused by a queue without any jobs ever pushed on them. Probably the 'queue' didn't exist at all in the redis database and the supervisors querying it caused the error while parsing the redis response.

I manually pushed a job on the queue and I don't get any error anymore.

(in case you are wondering why I had a queue that was never used, the issue was caused by a staging environment where some features that used the aforementioned queue were never used).

I'm using Redis 6.

I hope this info can help anyone to figure out the issue, I'm not familiar with the horizon codebase but I can try to navigate it and find a fix

This was basically my issue. But why were there no pushed jobs? Laravel uses LUA scripting with eval for pushing jobs and fails silently (!) when the command fails. Well, my server had LUA scripting disabled.

/** @var \Illuminate\Contracts\Redis\Factory $redis */
$redis = app(\Illuminate\Contracts\Redis\Factory::class);
$connection = $redis->connection();
$result = $connection->command('eval', ["return 1"]);
$error = $connection->client()->getLastError();

When it works, $result contains 1. When it fails, $error will contain the error message

"ERR unknown command EVAL, with args beginning with: return 1, 0, "

So all I had to do was to make eval availlable, but it was a long debugging session because the error was not logged by Laravel.