Page MenuHomePhabricator

Builds can get stuck into a "restarting" status if the worker fails due to lock timeout
Closed, InvalidPublic

Description

So I actually managed to catch this issue and grab the detail from the log:

Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000] [2014-09-04 21:31:30] EXCEPTION: (PhutilProxyException) Error while executing task ID 239944 from queue. {>} (AphrontDeadlockQueryException) #1205: Lock wait timeout exceeded; try restarting transaction at [<phutil>/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnectionBase.php:290]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #0 AphrontMySQLDatabaseConnectionBase::throwQueryCodeException(integer, string) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnectionBase.php:275]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #1 AphrontMySQLDatabaseConnectionBase::throwQueryException(mysqli) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnectionBase.php:181]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #2 AphrontMySQLDatabaseConnectionBase::executeRawQuery(string) called at [<phutil>/src/xsprintf/queryfx.php:6]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #3 queryfx(AphrontMySQLiDatabaseConnection, string, string, string, string, string)
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #4 call_user_func_array(string, array) called at [<phutil>/src/xsprintf/queryfx.php:16]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #5 queryfx_all(AphrontMySQLiDatabaseConnection, string, string, string, string, string)
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #6 call_user_func_array(string, array) called at [<phutil>/src/aphront/storage/connection/AphrontDatabaseConnection.php:20]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #7 AphrontDatabaseConnection::queryData(string, string, string, string, string)
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #8 call_user_func_array(array, array) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:496]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #9 LiskDAO::loadRawDataWhere(string, string, string)
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #10 call_user_func_array(array, array) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:460]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #11 LiskDAO::loadOneWhere(string, string, string) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:517]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #12 LiskDAO::reload() called at [<phabricator>/src/applications/drydock/blueprint/DrydockBlueprintImplementation.php:304]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #13 DrydockBlueprintImplementation::releaseLease(DrydockResource, DrydockLease) called at [<phabricator>/src/applications/harbormaster/storage/build/HarbormasterBuildArtifact.php:142]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #14 HarbormasterBuildArtifact::releaseDrydockLease() called at [<phabricator>/src/applications/harbormaster/storage/build/HarbormasterBuildArtifact.php:131]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #15 HarbormasterBuildArtifact::release() called at [<phabricator>/src/applications/harbormaster/engine/HarbormasterBuildEngine.php:462]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #16 HarbormasterBuildEngine::releaseAllArtifacts(HarbormasterBuild) called at [<phabricator>/src/applications/harbormaster/engine/HarbormasterBuildEngine.php:128]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #17 HarbormasterBuildEngine::restartBuild(HarbormasterBuild) called at [<phabricator>/src/applications/harbormaster/engine/HarbormasterBuildEngine.php:103]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #18 HarbormasterBuildEngine::updateBuild(HarbormasterBuild) called at [<phabricator>/src/applications/harbormaster/engine/HarbormasterBuildEngine.php:60]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #19 HarbormasterBuildEngine::continueBuild() called at [<phabricator>/src/applications/harbormaster/worker/HarbormasterBuildWorker.php:25]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #20 HarbormasterBuildWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:87]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #21 PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:124]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #22 PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:19]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #23 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:91]
Daemon 3157 STDE [Thu, 04 Sep 2014 21:31:30 +1000]   #24 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:111]
Daemon 3157 FAIL [Thu, 04 Sep 2014 21:31:30 +1000] (255) Process exited with error 255.

There was another failure in the log right before that, and I'm guessing it's related:

Daemon 3189 STDO [Thu, 04 Sep 2014 21:31:09 +1000] Fatal error: Uncaught exception 'Exception' with message 'Process exited with an open transaction! The transaction will be implicitly rolled back. Calls to openTransaction() must always be paired with a call to saveTransaction() or killTransaction().' in /srv/phabricator/libphutil/src/aphront/storage/connection/AphrontDatabaseTransactionState.php:69
Daemon 3189 STDO [Thu, 04 Sep 2014 21:31:09 +1000] Stack trace:
Daemon 3189 STDO [Thu, 04 Sep 2014 21:31:09 +1000] #0 [internal function]: AphrontDatabaseTransactionState->__destruct()
Daemon 3189 STDO [Thu, 04 Sep 2014 21:31:09 +1000] #1 {main}
Daemon 3189 STDO [Thu, 04 Sep 2014 21:31:09 +1000]   thrown in /srv/phabricator/libphutil/src/aphront/storage/connection/AphrontDatabaseTransactionState.php on line 69
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000] [2014-09-04 21:31:09] EXCEPTION: (PhutilProxyException) Error while executing task ID 239947 from queue. {>} (AphrontDeadlockQueryException) #1205: Lock wait timeout exceeded; try restarting transaction at [<phutil>/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnectionBase.php:290]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #0 AphrontMySQLDatabaseConnectionBase::throwQueryCodeException(integer, string) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnectionBase.php:275]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #1 AphrontMySQLDatabaseConnectionBase::throwQueryException(mysqli) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnectionBase.php:181]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #2 AphrontMySQLDatabaseConnectionBase::executeRawQuery(string) called at [<phutil>/src/xsprintf/queryfx.php:6]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #3 queryfx(AphrontMySQLiDatabaseConnection, string, string, array, string, string)
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #4 call_user_func_array(string, array) called at [<phutil>/src/xsprintf/queryfx.php:16]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #5 queryfx_all(AphrontMySQLiDatabaseConnection, string, string, array, string, string)
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #6 call_user_func_array(string, array) called at [<phutil>/src/aphront/storage/connection/AphrontDatabaseConnection.php:20]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #7 AphrontDatabaseConnection::queryData(string, string, array, string, string)
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #8 call_user_func_array(array, array) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:496]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #9 LiskDAO::loadRawDataWhere(string, array, string)
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #10 call_user_func_array(array, array) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:439]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #11 LiskDAO::loadAllWhere(string, array, string) called at [<phabricator>/src/applications/drydock/blueprint/DrydockBlueprintImplementation.php:150]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #12 DrydockBlueprintImplementation::allocateLease(DrydockResource, DrydockLease) called at [<phabricator>/src/applications/drydock/worker/DrydockAllocatorWorker.php:110]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #13 DrydockAllocatorWorker::allocateLease(DrydockLease) called at [<phabricator>/src/applications/drydock/worker/DrydockAllocatorWorker.php:41]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #14 DrydockAllocatorWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:87]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #15 PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:124]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #16 PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:19]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #17 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:91]
Daemon 3189 STDE [Thu, 04 Sep 2014 21:31:09 +1000]   #18 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:111]
Daemon 3189 FAIL [Thu, 04 Sep 2014 21:31:09 +1000] (255) Process exited with error 255.

Event Timeline

hach-que raised the priority of this task from to Needs Triage.
hach-que updated the task description. (Show Details)
hach-que added subscribers: hach-que, epriestley.
epriestley claimed this task.

This report doesn't contain enough information to reproduce the issue.