Queue worker daemon loses connection when unserializing model

[REBELinBLUE]

This only seems to happen when using MariaDB and the mysqlnd driver

When the queue worker is running in daemon mode and it takes a job from the queue which has a model passed into the constructor the following error occurs

[2015-10-14 21:03:42] local.ERROR: exception 'ErrorException' with message 'Error while sending STMT_PREPARE packet. PID=11613' in /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Connection.php:319
Stack trace:
#0 [internal function]: Illuminate\Foundation\Bootstrap\HandleExceptions->handleError(2, 'Error while sen...', '/var/www/test/v...', 319, Array)
#1 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Connection.php(319): PDO->prepare('select * from `...')
#2 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Connection.php(644): Illuminate\Database\Connection->Illuminate\Database\{closure}(Object(Illuminate\Database\MySqlConnection), 'select * from `...', Array)
#3 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Connection.php(611): Illuminate\Database\Connection->runQueryCallback('select * from `...', Array, Object(Closure))
#4 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Connection.php(324): Illuminate\Database\Connection->run('select * from `...', Array, Object(Closure))
#5 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(1406): Illuminate\Database\Connection->select('select * from `...', Array, true)
#6 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(1383): Illuminate\Database\Query\Builder->runSelect()
#7 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php(409): Illuminate\Database\Query\Builder->get(Array)
#8 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php(168): Illuminate\Database\Eloquent\Builder->getModels(Array)
#9 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php(140): Illuminate\Database\Eloquent\Builder->get(Array)
#10 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php(87): Illuminate\Database\Eloquent\Builder->first(Array)
#11 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php(119): Illuminate\Database\Eloquent\Builder->find(25, Array)
#12 [internal function]: Illuminate\Database\Eloquent\Builder->findOrFail(25)
#13 /var/www/test/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Model.php(3459): call_user_func_array(Array, Array)
#14 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/SerializesModels.php(65): Illuminate\Database\Eloquent\Model->__call('findOrFail', Array)
#15 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/SerializesModels.php(65): App\Post->findOrFail(25)
#16 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/SerializesModels.php(40): App\Jobs\QueuePost->getRestoredPropertyValue(Object(Illuminate\Contracts\Database\ModelIdentifier))
#17 [internal function]: App\Jobs\QueuePost->__wakeup()
#18 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(38): unserialize('O:18:"App\\Jobs\\...')
#19 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(129): Illuminate\Queue\CallQueuedHandler->call(Object(Illuminate\Queue\Jobs\BeanstalkdJob), Array)
#20 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Jobs/BeanstalkdJob.php(53): Illuminate\Queue\Jobs\Job->resolveAndFire(Array)
#21 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(208): Illuminate\Queue\Jobs\BeanstalkdJob->fire()
#22 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(159): Illuminate\Queue\Worker->process('beanstalkd', Object(Illuminate\Queue\Jobs\BeanstalkdJob), '1', 0)
#23 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(111): Illuminate\Queue\Worker->pop(NULL, 'default', 0, '3', '1')
#24 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(87): Illuminate\Queue\Worker->runNextJobForDaemon(NULL, 'default', 0, '3', '1')
#25 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(103): Illuminate\Queue\Worker->daemon(NULL, 'default', 0, 128, '3', '1')
#26 /var/www/test/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(71): Illuminate\Queue\Console\WorkCommand->runWorker(NULL, 'default', 0, 128, true)
#27 [internal function]: Illuminate\Queue\Console\WorkCommand->fire()
#28 /var/www/test/vendor/laravel/framework/src/Illuminate/Container/Container.php(503): call_user_func_array(Array, Array)
#29 /var/www/test/vendor/laravel/framework/src/Illuminate/Console/Command.php(150): Illuminate\Container\Container->call(Array)
#30 /var/www/test/vendor/symfony/console/Command/Command.php(259): Illuminate\Console\Command->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#31 /var/www/test/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#32 /var/www/test/vendor/symfony/console/Application.php(878): Illuminate\Console\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#33 /var/www/test/vendor/symfony/console/Application.php(195): Symfony\Component\Console\Application->doRunCommand(Object(Illuminate\Queue\Console\WorkCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#34 /var/www/test/vendor/symfony/console/Application.php(126): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#35 /var/www/test/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(107): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#36 /var/www/test/artisan(36): Illuminate\Foundation\Console\Kernel->handle(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#37 {main}

As you can see, this is happening inside Laravel's automatic call to findOrFail when getting a job from the queue

Adding the following to the model seems to fix it

    public function findOrFail()
    {
        if (App::runningInConsole()) {
            DB::reconnect();
        }

        return parent::__call('findOrFail', func_get_args());
    }

but from what I can see, Laravel is supposed to try and reconnect automatically, and does appear to with the normal mysql server

You can see this in action by cloning this repo

https://github.com/REBELinBLUE/laravel-queue-test

running vagrant up && vagrant ssh (it uses laravel/homestead) then in the vm sudo /vagrant/provision/provision.sh to remove MySQL and install maria, run the migrations and start the queue worker etc

then start tailing the log tail -f /var/www/test/storage/logs/laravel.log

Leave it running for a while and visit http://192.168.10.200/ to add a Post model to the queue, you can see beanstalk console at http://192.168.10.200:81/

You will eventually see this error in the log. Obviously by default the DB has a wait_timeout of an hour and default interactive_timeout of several hours so you will want to edit /etc/mysql/my.cnf and set them quite low (I used 30 seconds in my testing). Restart mysql and queue listener service restart mysql and service restart supervisor.

Wait until the time limit and then visit the URL to add the queue to the job

Hope that explains it clear enough

[deefour]

I have a worker that does nothing but process a single, very heavy job that runs once every 24hours. I believe the default 8hr wait_timeout is my problem after my latest research. I'm seeing this issue on that worker, also using mariadb and mysqlnd. I don't think this is a Laravel issue though.

I plan to raise the wait_timeout. I will also be adding a manual reconnect to that job when it gets started.

[REBELinBLUE]

Problem is the error occurs before it gets to any application code so you don't get a chance to reconnect without overloading a framework method, which seems a bit wrong, especially since the method isn't even inside the Job but inside the Model

Maybe I'm being really stupid and missing something obvious

[REBELinBLUE]

@GrahamCampbell sorry, what am I misunderstanding then?

[GrahamCampbell]

We already will reconnect under the hood if the query fails.

[GrahamCampbell]

Oh, I see.

[GrahamCampbell]

Is Error while sending STMT_PREPARE packet. always the error when the connection has timed out?

[GrahamCampbell]

Let me know if #10609 fixes you problem. Please comment on the PR though rather than this issue since I don't read comments on closed issues.

[abhisheksrivastav]

Hi @GrahamCampbell can you please do this patch for 5.0 branch also as I am experiencing similar issue. I hope that could fix my problem.

Current details are --
mysql Ver 14.14 Distrib 5.7.13
"laravel/framework": "5.0.*"

It happens in case of longer running jobs a few times.

Thanks,