jackdpeterson
commented
8 years ago Open jackdpeterson opened 8 years ago
jackdpeterson
commented
8 years ago 
basz
commented
8 years ago Looking at the error a 'PDO::query(): Error reading result set's header' error occures, which this plugin doesn't handle.
Are you able to repeat this error? You could try to set this $dbh->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION) on the connection and tell me what exception exactly is thrown. (That setting will make PDO::query throw exceptions instead of returning FALSE on failures).
Additionally I believe you should FALSE as a result from the query at 'src/exampleDomainModel/Queue/Job/PersistentSearch/PollFeedProviders.php:34' and recover as required.
jackdpeterson
commented
8 years ago Interesting -- I think I may be able to remove some deprecated / incompatible code.
Here's what's broken/incompatible with the auto-reconnection magic (what I was using before integrating your module):
if (! $this->_em->getConnection()->ping()) { // ln 34
$this->_em->getConnection()->close();
$this->_em->getConnection()->connect();
}
In this case, I'm not using PDO directly, but rather the DBAL stuff seems to be calling to that.
jackdpeterson
commented
8 years ago I found one more that mimicks this -- this time, without any usage of ping() or other application-reconnection magic in place:
2016-03-16T20:30:53.010586+00:00 web.prod.example.com Zend\Log[18686]: pollFeedProvider Exception - An exception occurred while executing 'SELECT t0.id AS id_1, t0.keywords AS keywords_2, t0.filters AS filters_3, t0.isActive AS isActive_4, t0.currentJobId AS currentJobId_5, t0.createdAt AS createdAt_6, t0.updatedAt AS updatedAt_7, t0.user_id AS user_id_8 FROM PersistentSearch t0 WHERE t0.id = ?' with params [4]:#012#012SQLSTATE[HY000]: General error: 2006 MySQL server has gone away - #0 /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php(116): Doctrine\DBAL\Driver\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\DBAL\Driver\PDOException))#012#1 /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(836): Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Object(BsbDoctrineReconnect\DBAL\Driver\PDOMySql\Driver), Object(Doctrine\DBAL\Driver\PDOException), 'SELECT t0.id AS...', Array)#012#2 /var/www/builds/production-d-SFVPW1UHE/vendor/bushbaby/doctrine-reconnect/src/DBAL/Connection.php(48): Doctrine\DBAL\Connection->executeQuery('SELECT t0.id AS...', Array, Array)#012#3 /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/Persisters/Entity/BasicEntityPersister.php(712): BsbDoctrineReconnect\DBAL\Connection->executeQuery('SELECT t0.id AS...', Array, Array)#012#4 /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/Persisters/Entity/BasicEntityPersister.php(730): Doctrine\ORM\Persisters\Entity\BasicEntityPersister->load(Array, NULL)#012#5 /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/EntityManager.php(462): Doctrine\ORM\Persisters\Entity\BasicEntityPersister->loadById(Array)#012#6 /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/EntityRepository.php(154): Doctrine\ORM\EntityManager->find('exampleDomain...', Array, NULL, NULL)#012#7 /var/www/builds/production-d-SFVPW1UHE/module/exampleDomainModel/src/exampleDomainModel/Queue/Job/
2016-03-16T20:30:53.010808+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP Warning: Error while sending QUERY packet. PID=18686 in /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php on line 91
2016-03-16T20:30:53.010864+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP Stack trace:
2016-03-16T20:30:53.010922+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 1. {main}() /var/www/builds/production-d-SFVPW1UHE/public/index.php:0
2016-03-16T20:30:53.010987+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 2. Zend\Mvc\Application->run() /var/www/builds/production-d-SFVPW1UHE/public/index.php:61
2016-03-16T20:30:53.011033+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 3. Zend\EventManager\EventManager->triggerEventUntil() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-mvc/src/Application.php:340
2016-03-16T20:30:53.011072+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 4. Zend\EventManager\EventManager->triggerListeners() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:263
2016-03-16T20:30:53.011110+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 5. call_user_func:{/var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490}() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011156+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 6. Zend\Mvc\DispatchListener->onDispatch() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011194+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 7. Zend\Mvc\Controller\AbstractController->dispatch() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-mvc/src/DispatchListener.php:114
2016-03-16T20:30:53.011231+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 8. Zend\EventManager\EventManager->triggerEventUntil() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-mvc/src/Controller/AbstractController.php:118
2016-03-16T20:30:53.011266+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 9. Zend\EventManager\EventManager->triggerListeners() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:263
2016-03-16T20:30:53.011310+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 10. call_user_func:{/var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490}() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011348+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 11. Zend\Mvc\Controller\AbstractActionController->onDispatch() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011385+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 12. SlmQueueSqs\Controller\SqsWorkerController->processAction() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-mvc/src/Controller/AbstractActionController.php:82
2016-03-16T20:30:53.011428+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 13. SlmQueue\Worker\AbstractWorker->processQueue() /var/www/builds/production-d-SFVPW1UHE/vendor/slm/queue-sqs/src/SlmQueueSqs/Controller/SqsWorkerController.php:33
2016-03-16T20:30:53.011474+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 14. Zend\EventManager\EventManager->trigger() /var/www/builds/production-d-SFVPW1UHE/vendor/slm/queue/src/SlmQueue/Worker/AbstractWorker.php:46
2016-03-16T20:30:53.011511+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 15. Zend\EventManager\EventManager->triggerListeners() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:214
2016-03-16T20:30:53.011548+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 16. call_user_func:{/var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490}() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011583+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 17. SlmQueue\Strategy\ProcessQueueStrategy->onJobPop() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011627+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 18. Zend\EventManager\EventManager->trigger() /var/www/builds/production-d-SFVPW1UHE/vendor/slm/queue/src/SlmQueue/Strategy/ProcessQueueStrategy.php:55
2016-03-16T20:30:53.011664+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 19. Zend\EventManager\EventManager->triggerListeners() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:214
2016-03-16T20:30:53.011700+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 20. call_user_func:{/var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490}() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011735+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 21. SlmQueue\Strategy\ProcessQueueStrategy->onJobProcess() /var/www/builds/production-d-SFVPW1UHE/vendor/zendframework/zend-eventmanager/src/EventManager.php:490
2016-03-16T20:30:53.011779+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 22. SlmQueueSqs\Worker\SqsWorker->processJob() /var/www/builds/production-d-SFVPW1UHE/vendor/slm/queue/src/SlmQueue/Strategy/ProcessQueueStrategy.php:70
2016-03-16T20:30:53.011817+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 23. exampleDomainModel\Queue\Job\PersistentSearch\PollFeedProviders->execute() /var/www/builds/production-d-SFVPW1UHE/vendor/slm/queue-sqs/src/SlmQueueSqs/Worker/SqsWorker.php:31
2016-03-16T20:30:53.011859+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 24. Doctrine\ORM\EntityRepository->find() /var/www/builds/production-d-SFVPW1UHE/module/exampleDomainModel/src/exampleDomainModel/Queue/Job/PersistentSearch/PollFeedProviders.php:73
2016-03-16T20:30:53.011895+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 25. Doctrine\ORM\EntityManager->find() /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/EntityRepository.php:154
2016-03-16T20:30:53.011931+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 26. Doctrine\ORM\Persisters\Entity\BasicEntityPersister->loadById() /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/EntityManager.php:462
2016-03-16T20:30:53.011976+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 27. Doctrine\ORM\Persisters\Entity\BasicEntityPersister->load() /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/Persisters/Entity/BasicEntityPersister.php:730
2016-03-16T20:30:53.012020+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 28. BsbDoctrineReconnect\DBAL\Connection->executeQuery() /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/orm/lib/Doctrine/ORM/Persisters/Entity/BasicEntityPersister.php:712
2016-03-16T20:30:53.012057+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 29. Doctrine\DBAL\Connection->executeQuery() /var/www/builds/production-d-SFVPW1UHE/vendor/bushbaby/doctrine-reconnect/src/DBAL/Connection.php:48
2016-03-16T20:30:53.012093+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 30. Doctrine\DBAL\Driver\PDOStatement->execute() /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php:828
2016-03-16T20:30:53.012129+00:00 web.prod.example.com supervisord: com.example.api-production_01 PHP 31. PDOStatement->execute() /var/www/builds/production-d-SFVPW1UHE/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:91
2016-03-16T20:30:53.012165+00:00 web.prod.example.com supervisord: com.example.api-production_01
2016-03-16T20:30:53.012200+00:00 web.prod.example.com supervisord: com.example.api-production_01 ,--.!,
2016-03-16T20:30:53.012236+00:00 web.prod.example.com supervisord: com.example.api-production_01 __/ -*-
2016-03-16T20:30:53.012272+00:00 web.prod.example.com supervisord: com.example.api-production_01 ,d08b. '|`
2016-03-16T20:30:53.012307+00:00 web.prod.example.com supervisord: com.example.api-production_01 0088MM
2016-03-16T20:30:53.012343+00:00 web.prod.example.com supervisord: com.example.api-production_01 `9MMP'
2016-03-16T20:30:53.012387+00:00 web.prod.example.com supervisord: com.example.api-production_01
2016-03-16T20:30:53.012425+00:00 web.prod.example.com supervisord: com.example.api-production_01 DBAL EXCEPTION THROWN
2016-03-16T20:30:53.012461+00:00 web.prod.example.com supervisord: com.example.api-production_01 └ txn nesting level: 0
2016-03-16T20:30:53.012498+00:00 web.prod.example.com supervisord: com.example.api-production_01 └ error: An exception occurred while executing 'SELECT t0.id AS id_1, t0.keywords AS keywords_2, t0.filters AS filters_3, t0.isActive AS isActive_4, t0.currentJobId AS currentJobId_5, t0.createdAt AS createdAt_6, t0.updatedAt AS updatedAt_7, t0.user_id AS user_id_8 FROM PersistentSearch t0 WHERE t0.id = ?' with params [4]:
2016-03-16T20:30:53.012535+00:00 web.prod.example.com supervisord: com.example.api-production_01
2016-03-16T20:30:53.012571+00:00 web.prod.example.com supervisord: com.example.api-production_01 SQLSTATE[HY000]: General error: 2006 MySQL server has gone away
2016-03-16T20:30:53.012608+00:00 web.prod.example.com supervisord: com.example.api-production_01
2016-03-16T20:30:53.012643+00:00 web.prod.example.com supervisord: com.example.api-production_01 └ FAIL - could not be validated
Hello,
Just following up on this as I have another example here that may be useful / related.
I can reproduce this issue again and it's exhibiting the same symptoms -- throwing a mysql server has gone away exception; however, the part of code,
public function validateReconnectAttempt(DBALException $e, $attempt)
{
if (!$this->getTransactionNestingLevel()) {
return false;
}seems to be returning false since the TransactionNestingLevel is 0. Now, I'm not sure what the exact behavior is intended to be with this part; however, it appears that this would return false, which would immediately cause the reconnect flow to be aborted.
In the meantime, I've forked the repository and will be testing this out to see if this 'resolves the issue'. If so, perhaps we can work something out that's a bit more friendly to non-transactional queries that may fail.
jackdpeterson
commented
8 years ago Okay, after playing around quite a bit with this module ... I've found various issues -- only some of which are appropriately handled:
,--.!,
__/ -*-
,d08b. '|`
0088MM
`9MMP'
DBAL EXCEPTION THROWN
└ txn nesting level: 0
└ error: An exception occurred while executing 'SELECT t0.job_id AS job_id_1, t0.createdAt AS createdAt_2, t0.components AS components_3 FROM isst_job t0 WHERE t0.job_id = ?' with params ["14"]:
SQLSTATE[HY000]: General error: 2006 MySQL server has gone away
error conditions as described above.
PHP Warning: Error while sending QUERY packet. PID=18951 in /var/www/domains/com.example.api/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php on line 91Either way though, the module doesn't appear to safely restart the connection. Instead, the job fails and is eventually re-sent to another worker that doesn't have a dead connection.
basz
commented
8 years ago 2 - The other weird thing that then comes up is a PHP warning that I didn't see earlier:
http://stackoverflow.com/questions/30753674/error-while-sending-query-packet https://bugs.php.net/bug.php?id=50300
basz
commented
8 years ago hi, i've update master a bit. nothing in src actually changed. you should be ably to rebase without problems... By the way, you mentioned SlmQueueSQS. I've just released 0.6....
jackdpeterson
commented
8 years ago Cool, I'll check out the SlmQueue[SQS] updates.
What we decided to do in the meantime is adjust our wait_timeout to be longer than the maximum lifetime of our workers. Then every 30 minutes or so we exit the worker loop and then supervisor restarts a new worker in the background. I think for our purposes that may be enough to keep things running smoothly. But I'll poke around with this a bit more -- it was just weird that things wouldn't resume after a connection was closed (it seems almost like the query wasn't replaying or something like that).
basz
commented
8 years ago Well I seems to me you found an pretty big bug that essentially rendered the whole thing useless.
:)
I must admit I don't follow the complete implementation at the moment, but this is wrongish
If not is transaction then don't attempt to reconnect
I'll try to setup a test locally and test a bit...
You would not be any chance know how to actually test such behavior do you? How can we test a gone away server???
Op 28 jun. 2016 om 18:35 heeft Jack Peterson notifications@github.com het volgende geschreven:
Cool, I'll check out the SlmQueue[SQS] updates.
What we decided to do in the meantime is adjust our wait_timeout to be longer than the maximum lifetime of our workers. Then every 30 minutes or so we exit the worker loop and then supervisor restarts a new worker in the background. I think for our purposes that may be enough to keep things running smoothly. But I'll poke around with this a bit more -- it was just weird that things wouldn't resume after a connection was closed (it seems almost like the query wasn't replaying or something like that).
— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.
jackdpeterson
commented
8 years ago So how I ended up testing the issues at hand were to drop the wait_timeout directive in MySQL to something reasonably low (eg., 30 seconds, rather than say something incredibly long like 30 minutes -- as I currently have my API MySQL server configured) ... This then chokes out an idle connection after 30 seconds. You could make it much shorter just as well to speed things along.
Start a persist/flush operation ... sleep that sucker for say 35 seconds ... then attempt to modify an entity and do another persist / flush operation.
basz
commented
8 years ago This i did not know. I'll try that.
'kill -9 xxx', is what I use to test.
Have you seen the latest master?
I've added the fix we discussed (removed that !) and added a few delays of a sec (or I would get a path not found exception, bc the socket wasn't recreated yet)
That made sure my connection was correctly restarted...
Op 1 jul. 2016 om 19:05 heeft Jack Peterson notifications@github.com het volgende geschreven:
So how I ended up testing the issues at hand were to drop the wait_timeout directive in MySQL to something reasonably low (eg., 30 seconds, rather than say something incredibly long like 30 minutes -- as I currently have my API MySQL server configured) ... This then chokes out an idle connection after 30 seconds. You could make it much shorter just as well to speed things along.
Start a persist/flush operation ... sleep that sucker for say 35 seconds ... then attempt to modify an entity and do another persist / flush operation.
— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.