Page MenuHomePhabricator

Editing Menu Items leads into daemon or transaction errors
Closed, ResolvedPublic

Description

Version Information

Running on Centos 7 machine with:

  • httpd-2.4.6-40.el7.centos.4.x86_64
  • php-pear-1.9.4-21.el7.noarch
  • php-devel-5.4.16-36.3.el7_2.x86_64
  • php-mbstring-5.4.16-36.3.el7_2.x86_64
  • php-common-5.4.16-36.3.el7_2.x86_64
  • php-pdo-5.4.16-36.3.el7_2.x86_64
  • php-5.4.16-36.3.el7_2.x86_64
  • php-process-5.4.16-36.3.el7_2.x86_64
  • php-ldap-5.4.16-36.3.el7_2.x86_64
  • php-cli-5.4.16-36.3.el7_2.x86_64
  • php-mysql-5.4.16-36.3.el7_2.x86_64
  • php-gd-5.4.16-36.3.el7_2.x86_64
  • php-xml-5.4.16-36.3.el7_2.x86_64
  • mariadb-5.5.50-1.el7_2.x86_64
  • mariadb-server-5.5.50-1.el7_2.x86_64
  • mariadb-libs-5.5.50-1.el7_2.x86_64

Situation

After updating I started customizing menu items. Then I noticed some performance issues and checked the deamons.
Phabricator now tells me that the daemons would not run. So I restarted them but the warning an performance issues still exists.

So I checked the daemons status page and found a lot of hanging transcations / tasks:

Error Details

Daemons status page:

Task Details:

Daemon log entries:

[02-Feb-2017 10:35:37 Europe/Berlin]   #0 PhutilBootloader::executeInclude called at [<phutil>/src/moduleutils/PhutilBootloader.php:226]
[02-Feb-2017 10:35:37 Europe/Berlin]   #1 PhutilBootloader::executeInclude(string) called at [<phutil>/src/moduleutils/PhutilBootloader.php:216]
[02-Feb-2017 10:35:37 Europe/Berlin]   #2 PhutilBootloader::loadLibrarySource(string, string) called at [<phutil>/src/symbols/PhutilSymbolLoader.php:381]
[02-Feb-2017 10:35:37 Europe/Berlin]   #3 PhutilSymbolLoader::loadSymbol(array) called at [<phutil>/src/symbols/PhutilSymbolLoader.php:256]
[02-Feb-2017 10:35:37 Europe/Berlin]   #4 PhutilSymbolLoader::selectAndLoadSymbols() called at [<phutil>/src/symbols/PhutilSymbolLoader.php:324]
[02-Feb-2017 10:35:37 Europe/Berlin]   #5 PhutilSymbolLoader::loadObjects() called at [<phutil>/src/symbols/PhutilClassMapQuery.php:239]
[02-Feb-2017 10:35:37 Europe/Berlin]   #6 PhutilClassMapQuery::loadMap() called at [<phutil>/src/symbols/PhutilClassMapQuery.php:179]
[02-Feb-2017 10:35:37 Europe/Berlin]   #7 PhutilClassMapQuery::execute() called at [<phabricator>/src/applications/search/menuitem/PhabricatorProfileMenuItem.php:76]
[02-Feb-2017 10:35:37 Europe/Berlin]   #8 PhabricatorProfileMenuItem::getAllMenuItems() called at [<phabricator>/src/applications/search/query/PhabricatorProfileMenuItemConfigurationQuery.php:87]
[02-Feb-2017 10:35:37 Europe/Berlin]   #9 PhabricatorProfileMenuItemConfigurationQuery::willFilterPage(array) called at [<phabricator>/src/infrastructure/query/policy/PhabricatorPolicyAwareQuery.php:247]
[02-Feb-2017 10:35:37 Europe/Berlin]   #10 PhabricatorPolicyAwareQuery::execute() called at [<phabricator>/src/applications/phid/type/PhabricatorPHIDType.php:91]
[02-Feb-2017 10:35:37 Europe/Berlin]   #11 PhabricatorPHIDType::loadObjects(PhabricatorObjectQuery, array) called at [<phabricator>/src/applications/phid/query/PhabricatorObjectQuery.php:153]
[02-Feb-2017 10:35:37 Europe/Berlin]   #12 PhabricatorObjectQuery::loadObjectsByPHID(array, array) called at [<phabricator>/src/applications/phid/query/PhabricatorObjectQuery.php:73]
[02-Feb-2017 10:35:37 Europe/Berlin]   #13 PhabricatorObjectQuery::loadPage() called at [<phabricator>/src/infrastructure/query/policy/PhabricatorPolicyAwareQuery.php:236]
[02-Feb-2017 10:35:37 Europe/Berlin]   #14 PhabricatorPolicyAwareQuery::execute() called at [<phabricator>/src/infrastructure/query/policy/PhabricatorPolicyAwareQuery.php:168]
[02-Feb-2017 10:35:37 Europe/Berlin]   #15 PhabricatorPolicyAwareQuery::executeOne() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:46]
[02-Feb-2017 10:35:37 Europe/Berlin]   #16 PhabricatorApplicationTransactionPublishWorker::loadObject() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:17]
[02-Feb-2017 10:35:37 Europe/Berlin]   #17 PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:123]
[02-Feb-2017 10:35:37 Europe/Berlin]   #18 PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:171]
[02-Feb-2017 10:35:37 Europe/Berlin]   #19 PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[02-Feb-2017 10:35:37 Europe/Berlin]   #20 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:181]
[02-Feb-2017 10:35:37 Europe/Berlin]   #21 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:131]
[02-Feb-2017 10:35:37 Europe/Berlin] PHP Fatal error:  Class 'PhutilConsole' not found in /opt/phabricator/src/applications/home/menuitem/PhabricatorHomeProfileMenuItem.php on line 68

Apache error log:

[Thu Feb 02 08:01:13.900578 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465] [2017-02-02 08:01:13] ERROR 2048: Declaration of PhabricatorHomeProfileMenuItem::newPageContent() should be compatible with PhabricatorProfileMenuItem::newPageContent(PhabricatorProfileMenuItemConfiguration $config) at [/opt/phabricator/src/applications/home/menuitem/PhabricatorHomeProfileMenuItem.php:4]
[Thu Feb 02 08:01:13.901125 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465] arcanist(head=master, ref.master=ade25facfdf2), phabricator(head=master, ref.master=7e3adb1257af), phutil(head=master, ref.master=9d85dfab0f53)
[Thu Feb 02 08:01:13.901140 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #0 include_once(string) called at [<phutil>/src/moduleutils/PhutilBootloader.php:226]
[Thu Feb 02 08:01:13.901144 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #1 PhutilBootloader::executeInclude(string) called at [<phutil>/src/moduleutils/PhutilBootloader.php:216]
[Thu Feb 02 08:01:13.901147 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #2 PhutilBootloader::loadLibrarySource(string, string) called at [<phutil>/src/symbols/PhutilSymbolLoader.php:381]
[Thu Feb 02 08:01:13.901151 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #3 PhutilSymbolLoader::loadSymbol(array) called at [<phutil>/src/symbols/PhutilSymbolLoader.php:256]
[Thu Feb 02 08:01:13.901154 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #4 PhutilSymbolLoader::selectAndLoadSymbols() called at [<phutil>/src/__phutil_library_init__.php:22]
[Thu Feb 02 08:01:13.901158 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #5 __phutil_autoload(string)
[Thu Feb 02 08:01:13.901173 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #6 spl_autoload_call(string) called at [<phabricator>/src/applications/home/engine/PhabricatorHomeProfileMenuEngine.php:29]
[Thu Feb 02 08:01:13.901178 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #7 PhabricatorHomeProfileMenuEngine::getBuiltinProfileItems(PhabricatorHomeApplication) called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:500]
[Thu Feb 02 08:01:13.901181 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #8 PhabricatorProfileMenuEngine::loadBuiltinProfileItems(string) called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:403]
[Thu Feb 02 08:01:13.901185 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #9 PhabricatorProfileMenuEngine::loadItems(string) called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:393]
[Thu Feb 02 08:01:13.901188 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #10 PhabricatorProfileMenuEngine::getItems() called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:155]
[Thu Feb 02 08:01:13.901192 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #11 PhabricatorProfileMenuEngine::buildResponse() called at [<phabricator>/src/applications/home/controller/PhabricatorHomeMenuItemController.php:39]
[Thu Feb 02 08:01:13.901195 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #12 PhabricatorHomeMenuItemController::handleRequest(AphrontRequest) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:269]
[Thu Feb 02 08:01:13.901199 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #13 AphrontApplicationConfiguration::processRequest(AphrontRequest, PhutilDeferredLog, AphrontPHPHTTPSink, MultimeterControl) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:181]
[Thu Feb 02 08:01:13.901202 2017] [:error] [pid 4182] [client XX.YYY.ZZ.WW:63465]   #14 AphrontApplicationConfiguration::runHTTPRequest(AphrontPHPHTTPSink) called at [<phabricator>/webroot/index.php:17]
[Thu Feb 02 08:04:21.072976 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156] [2017-02-02 08:04:21] ERROR 2048: Declaration of PhabricatorHomeProfileMenuItem::newPageContent() should be compatible with PhabricatorProfileMenuItem::newPageContent(PhabricatorProfileMenuItemConfiguration $config) at [/opt/phabricator/src/applications/home/menuitem/PhabricatorHomeProfileMenuItem.php:68]
[Thu Feb 02 08:04:21.073561 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156] arcanist(head=master, ref.master=ade25facfdf2), phabricator(head=master, ref.master=7e3adb1257af), phutil(head=master, ref.master=9d85dfab0f53)
[Thu Feb 02 08:04:21.073575 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #0 PhutilBootloader::executeInclude called at [<phutil>/src/moduleutils/PhutilBootloader.php:226]
[Thu Feb 02 08:04:21.073579 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #1 PhutilBootloader::executeInclude(string) called at [<phutil>/src/moduleutils/PhutilBootloader.php:216]
[Thu Feb 02 08:04:21.073582 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #2 PhutilBootloader::loadLibrarySource(string, string) called at [<phutil>/src/symbols/PhutilSymbolLoader.php:381]
[Thu Feb 02 08:04:21.073585 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #3 PhutilSymbolLoader::loadSymbol(array) called at [<phutil>/src/symbols/PhutilSymbolLoader.php:256]
[Thu Feb 02 08:04:21.073588 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #4 PhutilSymbolLoader::selectAndLoadSymbols() called at [<phutil>/src/symbols/PhutilSymbolLoader.php:324]
[Thu Feb 02 08:04:21.073591 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #5 PhutilSymbolLoader::loadObjects() called at [<phutil>/src/symbols/PhutilClassMapQuery.php:239]
[Thu Feb 02 08:04:21.073595 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #6 PhutilClassMapQuery::loadMap() called at [<phutil>/src/symbols/PhutilClassMapQuery.php:179]
[Thu Feb 02 08:04:21.073620 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #7 PhutilClassMapQuery::execute() called at [<phabricator>/src/applications/search/menuitem/PhabricatorProfileMenuItem.php:76]
[Thu Feb 02 08:04:21.073624 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #8 PhabricatorProfileMenuItem::getAllMenuItems() called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:505]
[Thu Feb 02 08:04:21.073627 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #9 PhabricatorProfileMenuEngine::loadBuiltinProfileItems(string) called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:403]
[Thu Feb 02 08:04:21.073630 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #10 PhabricatorProfileMenuEngine::loadItems(string) called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:393]
[Thu Feb 02 08:04:21.073634 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #11 PhabricatorProfileMenuEngine::getItems() called at [<phabricator>/src/applications/search/engine/PhabricatorProfileMenuEngine.php:343]
[Thu Feb 02 08:04:21.073637 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #12 PhabricatorProfileMenuEngine::buildNavigation() called at [<phabricator>/src/applications/favorites/engineextension/PhabricatorFavoritesMainMenuBarExtension.php:56]
[Thu Feb 02 08:04:21.073640 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #13 PhabricatorFavoritesMainMenuBarExtension::newDropdown(PhabricatorUser) called at [<phabricator>/src/applications/favorites/engineextension/PhabricatorFavoritesMainMenuBarExtension.php:21]
[Thu Feb 02 08:04:21.073643 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #14 PhabricatorFavoritesMainMenuBarExtension::buildMainMenus() called at [<phabricator>/src/view/page/menu/PhabricatorMainMenuView.php:107]
[Thu Feb 02 08:04:21.073647 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #15 PhabricatorMainMenuView::render() called at [<phabricator>/src/view/page/PhabricatorStandardPageView.php:381]
[Thu Feb 02 08:04:21.073650 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #16 PhabricatorStandardPageView::willRenderPage() called at [<phabricator>/src/view/page/AphrontPageView.php:46]
[Thu Feb 02 08:04:21.073653 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #17 AphrontPageView::render() called at [<phabricator>/src/view/page/PhabricatorStandardPageView.php:884]
[Thu Feb 02 08:04:21.073656 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #18 PhabricatorStandardPageView::produceAphrontResponse() called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:649]
[Thu Feb 02 08:04:21.073659 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #19 AphrontApplicationConfiguration::produceResponse(AphrontRequest, PhabricatorStandardPageView) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:278]
[Thu Feb 02 08:04:21.073662 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #20 AphrontApplicationConfiguration::processRequest(AphrontRequest, PhutilDeferredLog, AphrontPHPHTTPSink, MultimeterControl) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:181]
[Thu Feb 02 08:04:21.073666 2017] [:error] [pid 4548] [client WW.XXX.YY.ZZ:65156]   #21 AphrontApplicationConfiguration::runHTTPRequest(AphrontPHPHTTPSink) called at [<phabricator>/webroot/index.php:17

Reproduction steps

  • Create a new menu item like this:
    • Edit Menu -Global Menu Items -Add new Menu Item (Application) -Select any, with or without name
  • The item wille be created
  • Now you get an tailing task and the corresponding error in the phd log.

Questions

  • Is there a way to clean the task queue or to find the source?
    • deleted them with <phabricator_roo>/bin/worker cancel --class PhabricatorApplicationTransactionPublishWorker
  • Could I set cluster.read-onlyuntil there is a fix?
    • stopped the phd daemons and set cluster to read only.

Event Timeline

OCram created this task.Feb 2 2017, 9:37 AM
OCram updated the task description. (Show Details)
OCram updated the task description. (Show Details)Feb 2 2017, 10:03 AM
OCram updated the task description. (Show Details)Feb 2 2017, 10:14 AM
OCram updated the task description. (Show Details)Feb 2 2017, 1:32 PM

@epriestley: Was deleting the active task the right way or did I broke my database or relations?

In 99% of cases, the right thing to do when you see an error in the daemon logs is:

  • report the issue to us;
  • wait for us to fix it;
  • upgrade Phabricator to pick up the fix;
  • after the upgrade, the task will complete normally.

When you cancel tasks, you permanently prevent the work they would have done from occurring. In this case, whatever tasks you cancelled will never send email, update search indexes, etc. This is probably not a major issue, but using bin/worker cancel can permanently prevent tasks from completing and should be a measure of last resort.

Repeated daemon errors in the logs are not concerning. Repeated restarts of daemons when the queue only has failing tasks are also not concerning. These are normal behaviors of the queue and things work that way to make sure that things self-heal after you upgrade with the fix.

I don't know what you mean when you say this: "Phabricator now tells me that the daemons would not run". As far as I know, we do not have any error message like that.

I am skeptical that these tasks are the root cause of whatever performance problems you observed, although it's hard to be sure since I'm not sure what you observed. The screenshot of the daemon page looks normal, and shows that the daemons have only spent about 6 seconds processing tasks in the last 15 minutes. This doesn't include time spent attempting tasks and failing, but the screenshot shows all four daemons in a "waiting" backoff state. Again, this is normal, and the expected failure mode of the daemon queue when a task can't be completed.

OCram added a comment.Feb 2 2017, 2:33 PM

First of all: thank you again for the quick response and great work!

Well I never notices so many queued and leased tasks. I created about 20 menu items and it seemed like they all produced a task. These tasks never completed successful and it seems like they were restarted endlessly.

Finally, caused by the system load I got an configuration warning that says, the daemons would not run. That's what I tried to explain ^^