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.