Horizon does not recover after redis going away for a short time

[graemlourens]

Horizon Version: v3.4.2
Laravel Version: v6.0.3
PHP Version: 7.2.23
Redis Driver & Version: phpredis 5.1.1

Description:

If the used redis instance for horizon is not available even for a short period of time, it seems that horizon can not recover. Even if redis is back and available again, errors like
"ERROR: Redis server redis:6379 went away {"exception":"[object] (RedisException(code: 0): Redis server redis:6379 went away at"
will occur every second (this is our current sleep interval)

Steps To Reproduce:

• Have horizon & redis running normally. Then do anything so that horizon can not access redis anymore (for example if running on docker, just stop the redis instance).
• Horizon will now be throwing exceptions as mentioned above (what is correct and understandable).
• start redis again / let horizon access redis again
• horizon will still be throwing exceptions even if redis is normally available again. No jobs will be processed.

Are we missing something obvious? This does not seem to be intended behaviour. We also started a ticket #708 which we later figured out was also due to network issues where redis was not available for a short time, but in that ticket we were experimenting with redis behind TLS & Auth.

We have now reproduced it locally without AUTH and no TLS. The behaviour is similar, but not sure if its exactly related.

[driesvints]

I currently don't have time to check in on this so appreciating anyone who can help out here.

[graemlourens]

We have spent quite a good amount of time today to experiment in what situations this happens, and found out an important detail: This ONLY happens with the phpredis driver. If you use predis driver, horizon has no issues with redis going away, and then coming back. It gracefully picks up where it left off.

We were digging deep down into the code, but can not explain why with the phpredis driver the connection can not be established anymore, even if redis is available again.
This is can be reproduced 100% of the times.

We are not using any persistent connections or anything of the sort.

Attached are both exception traces from predis and phpredis driver:

PREDIS

[2019-12-06 16:31:37] log-2019.12.ERROR: Error while reading line from the server. [tcp://redis:6379] {"exception":"[object] (Predis\\Connection\\ConnectionException(code: 0): Error while reading line from the server. [tcp://redis:6379] at /var/www/vendor/predis/predis/src/Connection/AbstractConnection.php:155)
[stacktrace]
#0 /var/www/vendor/predis/predis/src/Connection/StreamConnection.php(314): Predis\\Connection\\AbstractConnection->onConnectionError('Error while rea...')
#1 /var/www/vendor/predis/predis/src/Connection/AbstractConnection.php(120): Predis\\Connection\\StreamConnection->read()
#2 /var/www/vendor/predis/predis/src/Connection/AbstractConnection.php(112): Predis\\Connection\\AbstractConnection->readResponse(Object(Predis\\Command\\ListLength))
#3 /var/www/vendor/predis/predis/src/Client.php(331): Predis\\Connection\\AbstractConnection->executeCommand(Object(Predis\\Command\\ListLength))
#4 /var/www/vendor/predis/predis/src/Client.php(314): Predis\\Client->executeCommand(Object(Predis\\Command\\ListLength))
#5 /var/www/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php(111): Predis\\Client->__call('llen', Array)
#6 /var/www/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php(211): Illuminate\\Redis\\Connections\\Connection->command('llen', Array)
#7 /var/www/vendor/laravel/horizon/src/RedisHorizonCommandQueue.php(51): Illuminate\\Redis\\Connections\\Connection->__call('llen', Array)
#8 /var/www/vendor/laravel/horizon/src/MasterSupervisor.php(263): Laravel\\Horizon\\RedisHorizonCommandQueue->pending('master:b1860d8f...')
#9 /var/www/vendor/laravel/horizon/src/MasterSupervisor.php(240): Laravel\\Horizon\\MasterSupervisor->processPendingCommands()
#10 /var/www/vendor/laravel/horizon/src/MasterSupervisor.php(213): Laravel\\Horizon\\MasterSupervisor->loop()
#11 /var/www/vendor/laravel/horizon/src/Console/HorizonCommand.php(63): Laravel\\Horizon\\MasterSupervisor->monitor()
#12 [internal function]: Laravel\\Horizon\\Console\\HorizonCommand->handle(Object(Laravel\\Horizon\\Repositories\\RedisMasterSupervisorRepository))
#13 /var/www/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(32): call_user_func_array(Array, Array)
#14 /var/www/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(90): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#15 /var/www/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(34): Illuminate\\Container\\BoundMethod::callBoundMethod(Object(App\\Extensions\\Illuminate\\Foundation\\Application), Array, Object(Closure))
#16 /var/www/vendor/laravel/framework/src/Illuminate/Container/Container.php(591): Illuminate\\Container\\BoundMethod::call(Object(App\\Extensions\\Illuminate\\Foundation\\Application), Array, Array, NULL)
#17 /var/www/vendor/laravel/framework/src/Illuminate/Console/Command.php(192): Illuminate\\Container\\Container->call(Array)
#18 /var/www/vendor/symfony/console/Command/Command.php(255): Illuminate\\Console\\Command->execute(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#19 /var/www/vendor/laravel/framework/src/Illuminate/Console/Command.php(179): Symfony\\Component\\Console\\Command\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#20 /var/www/vendor/symfony/console/Application.php(915): Illuminate\\Console\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#21 /var/www/vendor/symfony/console/Application.php(272): Symfony\\Component\\Console\\Application->doRunCommand(Object(Laravel\\Horizon\\Console\\HorizonCommand), Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#22 /var/www/vendor/symfony/console/Application.php(148): Symfony\\Component\\Console\\Application->doRun(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#23 /var/www/vendor/laravel/framework/src/Illuminate/Console/Application.php(90): Symfony\\Component\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#24 /var/www/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(131): Illuminate\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#25 /var/www/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#26 {main}
"} 

PHPREDIS

[2019-12-06 16:29:41] log-2019.12.ERROR: Redis server redis:6379 went away {"exception":"[object] (RedisException(code: 0): Redis server redis:6379 went away at /var/www/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php:111)
[stacktrace]
#0 /var/www/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php(111): Redis->lLen('commands:master...')
#1 /var/www/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php(211): Illuminate\\Redis\\Connections\\Connection->command('llen', Array)
#2 /var/www/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php(451): Illuminate\\Redis\\Connections\\Connection->__call('llen', Array)
#3 /var/www/vendor/laravel/horizon/src/RedisHorizonCommandQueue.php(51): Illuminate\\Redis\\Connections\\PhpRedisConnection->__call('llen', Array)
#4 /var/www/vendor/laravel/horizon/src/MasterSupervisor.php(263): Laravel\\Horizon\\RedisHorizonCommandQueue->pending('master:b1860d8f...')
#5 /var/www/vendor/laravel/horizon/src/MasterSupervisor.php(240): Laravel\\Horizon\\MasterSupervisor->processPendingCommands()
#6 /var/www/vendor/laravel/horizon/src/MasterSupervisor.php(213): Laravel\\Horizon\\MasterSupervisor->loop()
#7 /var/www/vendor/laravel/horizon/src/Console/HorizonCommand.php(63): Laravel\\Horizon\\MasterSupervisor->monitor()
#8 [internal function]: Laravel\\Horizon\\Console\\HorizonCommand->handle(Object(Laravel\\Horizon\\Repositories\\RedisMasterSupervisorRepository))
#9 /var/www/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(32): call_user_func_array(Array, Array)
#10 /var/www/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(90): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#11 /var/www/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(34): Illuminate\\Container\\BoundMethod::callBoundMethod(Object(App\\Extensions\\Illuminate\\Foundation\\Application), Array, Object(Closure))
#12 /var/www/vendor/laravel/framework/src/Illuminate/Container/Container.php(591): Illuminate\\Container\\BoundMethod::call(Object(App\\Extensions\\Illuminate\\Foundation\\Application), Array, Array, NULL)
#13 /var/www/vendor/laravel/framework/src/Illuminate/Console/Command.php(192): Illuminate\\Container\\Container->call(Array)
#14 /var/www/vendor/symfony/console/Command/Command.php(255): Illuminate\\Console\\Command->execute(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#15 /var/www/vendor/laravel/framework/src/Illuminate/Console/Command.php(179): Symfony\\Component\\Console\\Command\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#16 /var/www/vendor/symfony/console/Application.php(915): Illuminate\\Console\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#17 /var/www/vendor/symfony/console/Application.php(272): Symfony\\Component\\Console\\Application->doRunCommand(Object(Laravel\\Horizon\\Console\\HorizonCommand), Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#18 /var/www/vendor/symfony/console/Application.php(148): Symfony\\Component\\Console\\Application->doRun(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#19 /var/www/vendor/laravel/framework/src/Illuminate/Console/Application.php(90): Symfony\\Component\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#20 /var/www/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(131): Illuminate\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#21 /var/www/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#22 {main}

[mfn]

Question out of the blue: can the phpredis driver even do this on its own?

[taylorotwell]

Possible solution I've worked up here: laravel/framework#30778

[graemlourens]

Thank you @taylorotwell, i just checked out the change manually applied to the horizon & laravel-version we're running (stated in the ticket) and this does indeed solve the problem!

Horizon now gracefully recovers if redis is gone for short, or long period of time.

I highly suspect that this also solves my issue #708 just that there we are behind tls & auth, i suspect the reason is the same, just the error message was very misleading. We will be able to confirm when we've upgraded to the eventual new release of laravel (where this fix will be included) and rollout to our k8-setup.

Not sure if these kind of tickets get closed before a release is created or only after? feel free to close if 'before'.

[driesvints]

Closing since the PR was merged. Will be in next Tuesday's release.