Herald rule not adding auditors to commits following upgrade

Hi

I recently upgraded our phabricator installation to:

  • phabricator: cc11dff7d317b5a1e82e24ab571fef9abb633a49 (Thu, Jan 30) (branched from ccf28a81121ea21d72b342cfb8ab2eee4e56bf86 on origin)
  • arcanist: 729100955129851a52588cdfd9b425197cf05815 (Thu, Jan 30) (branched from 21a1828ea06cf031e93082db8664d73efc88290a on origin)
  • phutil: 034cf7cc39940b935e83923dbb1bacbcfe645a85 (Thu, Jan 30) (branched from cc2a3dbf590389400da55563cb6993f321ec6d73 on origin)

We have herald rules to add auditors when commits are added to certain repositories. Following the upgrade, these aren’t working.

In herald, if I use the test console against one of the new commits, the rules match, so I think the rules are still OK. However, if I look in the transcript, there is nothing there for the new commits, so it seems that Herald isn’t triggering at all?

I’m not sure if it’s related but I tried to check the daemons and noticed the following error when running /var/phabricator/phabricator/bin/phd log

    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000] [2020-02-03 12:25:55] EXCEPTION: (PhutilProxyException) Error while executing Task ID 1331842. {>} (Exception) You must use withSourcePHIDs() to query edges. at [<phabricator>/src/infrastructure/edges/query/PhabricatorEdgeQuery.php:162]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000] arcanist(head=stable, ref.master=3b6b523c2b23, ref.stable=729100955129), phabricator(head=stable, ref.master=e2868a0da24c, ref.stable=cc11dff7d317), phutil(head=stable, ref.master=ef580c9ccc21, ref.stable=034cf7cc3994)
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #0 <#2> PhabricatorEdgeQuery::execute() called at [<phabricator>/src/applications/project/query/PhabricatorProjectQuery.php:316]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #1 <#2> PhabricatorProjectQuery::willFilterPage(array) called at [<phabricator>/src/infrastructure/query/policy/PhabricatorPolicyAwareQuery.php:262]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #2 <#2> PhabricatorPolicyAwareQuery::execute() called at [<phabricator>/src/applications/metamta/query/PhabricatorMetaMTAMemberQuery.php:76]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #3 <#2> PhabricatorMetaMTAMemberQuery::execute() called at [<phabricator>/src/applications/metamta/replyhandler/PhabricatorMailReplyHandler.php:300]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #4 <#2> PhabricatorMailReplyHandler::expandRecipientPHIDs(array, array) called at [<phabricator>/src/applications/metamta/replyhandler/PhabricatorMailReplyHandler.php:207]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #5 <#2> PhabricatorMailReplyHandler::getMailTargets(array, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:3068]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #6 <#2> PhabricatorApplicationTransactionEditor::buildMailWithRecipients(ManiphestTask, array, array, array, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:3052]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #7 <#2> PhabricatorApplicationTransactionEditor::buildMail(ManiphestTask, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:1494]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #8 <#2> PhabricatorApplicationTransactionEditor::publishTransactions(ManiphestTask, array) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:21]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #9 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:124]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #10 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:158]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #11 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #12 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:219]
    Daemon 702941 STDE [Mon, 03 Feb 2020 12:25:55 +0000]   #13 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:131]
    Daemon 702941 FAIL [Mon, 03 Feb 2020 12:25:55 +0000] Process exited with error 255.
    Daemon 702941 WAIT [Mon, 03 Feb 2020 12:25:55 +0000] Waiting 5 second(s) to restart process.

Any ideas on what the problem might be, or what else I could check?

Thanks in advance
Will

Thanks, this is a bug in Phabricator. It should be fixed by https://secure.phabricator.com/D20962, which will be available in master and stable in a few minutes.

1 Like

(This is also probably a bug, but I have no idea how to reproduce it, and it isn’t obvious from looking at the code. It doesn’t look related to the audit issue, although it might stop some mail from being generated/delivered.)

Hi

Great - I’ve pulled the latest stable and it’s working again. :smile:
Thanks for the quick fix!

Anything I can do to get more info on the other potential issue?

Thanks
Will

As a starting point, you can likely reproduce it locally with:

phabricator/ $ ./bin/worker execute --id 1331842

If that does reproduce the issue and you run that command with --trace, the output might be useful, but probably not.

You can probably get more details about the task by visiting /daemon/task/1331842/ in the web UI.

It looks like the task is trying to figure out who the members of a project are so it can generate mail about something. When it goes to load the members, it hits a condition where it tries to load members of an empty list. (The error itself is worded/detected misleadingly – in this case, it is really “trying to query edges with an empty sourcePHID list”).

This should be impossible. willFilterPage() is only called with a nonempty list of objects, and it should be impossible to reach the edge query without at least the initial PHIDs.

My best guess is that your project table is in some nonstandard state, but I’m not even sure what state that could be.

If I had a local reproduction case, I’d proceed by adding debugging code to PhabricatorProjectQuery->willFilterPage() since I have no guesses about how or why the list is becoming empty.

Thanks for the hints.

The trace gives the following:

root@phabricator:/var/phabricator/phabricator# ./bin/worker execute --id 1331842 --trace
>>> [2] (+0) <connect> phabricator_worker
<<< [2] (+5) <connect> 5,432 us
>>> [3] (+5) <query> SELECT * FROM `worker_activetask` WHERE (id in (1331842)) ORDER BY id DESC
<<< [3] (+6) <query> 422 us
>>> [4] (+7) <query> SELECT * FROM `worker_archivetask` WHERE (id in (1331842)) ORDER BY id DESC
<<< [4] (+7) <query> 440 us
>>> [5] (+8) <connect> phabricator_worker
<<< [5] (+9) <connect> 729 us
>>> [6] (+11) <query> UPDATE `phabricator_worker`.`worker_activetask` SET `failureTime` = '1580742286', `taskClass` = 'PhabricatorApplicationTransactionPublishWorker', `leaseOwner` = NULL, `leaseExpires` = '1580742293', `failureCount` = '53849', `dataID` = '1331841', `priority` = '1000', `objectPHID` = 'PHID-TASK-pj3sc4rdnfctju4enrda', `id` = '1331842', `dateCreated` = '1564589124', `dateModified` = '1580742293' WHERE `id` = '1331842'
<<< [6] (+21) <query> 10,116 us
>>> [7] (+22) <query> SELECT * FROM `phabricator_worker`.`worker_taskdata` WHERE id = 1331841
<<< [7] (+22) <query> 551 us
Executing task 1331842 (PhabricatorApplicationTransactionPublishWorker)...
>>> [8] (+58) <connect> phabricator_maniphest
<<< [8] (+59) <connect> 1,029 us
>>> [9] (+68) <query> SELECT `task`.* FROM `maniphest_task` task WHERE (task.phid in ('PHID-TASK-pj3sc4rdnfctju4enrda')) ORDER BY `task`.`id` DESC
<<< [9] (+69) <query> 1,397 us
>>> [10] (+106) <query> SELECT `x`.* FROM `maniphest_transaction` `x` WHERE (x.phid IN ('PHID-XACT-TASK-wmw53s7g6hg6xcg')) ORDER BY `x`.`id` DESC
<<< [10] (+106) <query> 614 us
>>> [11] (+116) <query> SELECT `task`.* FROM `maniphest_task` task WHERE (task.phid in ('PHID-TASK-pj3sc4rdnfctju4enrda')) ORDER BY `task`.`id` DESC
<<< [11] (+117) <query> 597 us
>>> [12] (+123) <connect> phabricator_user
<<< [12] (+124) <connect> 878 us
>>> [13] (+127) <query> SELECT `user`.* FROM `user` `user` WHERE (user.phid IN ('PHID-USER-cwr4xu2aexpiyb6jy3i4')) ORDER BY `user`.`id` DESC
<<< [13] (+130) <query> 2,967 us
>>> [14] (+131) <query> SELECT * FROM `phabricator_user`.`user_profile` WHERE userPHID IN ('PHID-USER-cwr4xu2aexpiyb6jy3i4')
<<< [14] (+131) <query> 349 us
>>> [15] (+134) <query> SELECT cacheKey, userPHID, cacheData, cacheType FROM `user_cache` WHERE cacheIndex IN ('y_FPXujT93U3') AND userPHID IN ('PHID-USER-cwr4xu2aexpiyb6jy3i4')
<<< [15] (+136) <query> 1,967 us
>>> [16] (+138) <query> SELECT `task`.* FROM `maniphest_task` task WHERE (task.phid in ('PHID-TASK-pj3sc4rdnfctju4enrda', 'PHID-TASK-xfdbc44ibazrfwafddza')) ORDER BY `task`.`id` DESC
<<< [16] (+139) <query> 1,088 us
>>> [17] (+144) <connect> phabricator_project
<<< [17] (+145) <connect> 1,058 us
>>> [18] (+148) <query> SELECT `project`.* FROM `project` `project` WHERE (project.phid IN ('PHID-PROJ-vp3fmhxg542j2vtmk4i6')) ORDER BY `project`.`name` ASC
<<< [18] (+150) <query> 1,405 us
>>> [19] (+150) <query> SELECT * FROM `phabricator_project`.`project` WHERE projectPath IN ('_6VH')
<<< [19] (+151) <query> 689 us
>>> [20] (+154) <query> UPDATE `phabricator_worker`.`worker_activetask` SET `failureTime` = '1580742293', `taskClass` = 'PhabricatorApplicationTransactionPublishWorker', `leaseOwner` = NULL, `leaseExpires` = '1580742593', `failureCount` = '53850', `dataID` = '1331841', `priority` = '1000', `objectPHID` = 'PHID-TASK-pj3sc4rdnfctju4enrda', `id` = '1331842', `dateCreated` = '1564589124', `dateModified` = '1580742293' WHERE `id` = '1331842'
<<< [20] (+193) <query> 38,987 us
[2020-02-03 15:04:53] EXCEPTION: (Exception) You must use withSourcePHIDs() to query edges. at [<phabricator>/src/infrastructure/edges/query/PhabricatorEdgeQuery.php:162]
arcanist(head=stable, ref.master=3b6b523c2b23, ref.stable=729100955129), phabricator(head=stable, ref.master=e2868a0da24c, ref.stable=46fcd135ae68), phutil(head=stable, ref.master=ef580c9ccc21, ref.stable=034cf7cc3994)
  #0 PhabricatorEdgeQuery::execute() called at [<phabricator>/src/applications/project/query/PhabricatorProjectQuery.php:316]
  #1 PhabricatorProjectQuery::willFilterPage(array) called at [<phabricator>/src/infrastructure/query/policy/PhabricatorPolicyAwareQuery.php:262]
  #2 PhabricatorPolicyAwareQuery::execute() called at [<phabricator>/src/applications/metamta/query/PhabricatorMetaMTAMemberQuery.php:76]
  #3 PhabricatorMetaMTAMemberQuery::execute() called at [<phabricator>/src/applications/metamta/replyhandler/PhabricatorMailReplyHandler.php:300]
  #4 PhabricatorMailReplyHandler::expandRecipientPHIDs(array, array) called at [<phabricator>/src/applications/metamta/replyhandler/PhabricatorMailReplyHandler.php:207]
  #5 PhabricatorMailReplyHandler::getMailTargets(array, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:3068]
  #6 PhabricatorApplicationTransactionEditor::buildMailWithRecipients(ManiphestTask, array, array, array, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:3052]
  #7 PhabricatorApplicationTransactionEditor::buildMail(ManiphestTask, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:1494]
  #8 PhabricatorApplicationTransactionEditor::publishTransactions(ManiphestTask, array) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:21]
  #9 PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:124]
  #10 PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:158]
  #11 PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/management/PhabricatorWorkerManagementExecuteWorkflow.php:93]
  #12 PhabricatorWorkerManagementExecuteWorkflow::execute(PhutilArgumentParser) called at [<phutil>/src/parser/argument/PhutilArgumentParser.php:457]
  #13 PhutilArgumentParser::parseWorkflowsFull(array) called at [<phutil>/src/parser/argument/PhutilArgumentParser.php:349]
  #14 PhutilArgumentParser::parseWorkflows(array) called at [<phabricator>/scripts/setup/manage_worker.php:21]

daemon/task/1331842/

Gives:

Object: {Super secret task}
Task Status: Queued
Task Class: PhabricatorApplicationTransactionPublishWorker
Lease Status: Leased
Lease Owner: …
Lease Expires: 1 m, 16 s
Duration: Not Completed
Failure Count: 53853
Maximum Retries: Retries Forever
Retries After: 1 m, 2 m, 3 m, 4 m, 5 m, 6 m, 7 m, 8 m, 9 m, 10 m, 11 m, …

Looking through the trace I can see it refers to a very old task, and it’s obvious it has failed quite a number of times. I tried searching the project (PHID-PROJ-vp3fmhxg542j2vtmk4i6) in conduit, and got the following:

error_code ERR-CONDUIT-CORE
error_info You must use withSourcePHIDs() to query edges.

It is being caused by the 3rd latest transaction, which in the UI looks like:

user removed a project: Restricted Project.

So there’s something strange going on.

Want me to look deeper? I’m guessing if I cancel the task the problem will go away…?

Thanks
Will

That might be enough to go on, let me see if I can figure things out from there.

You can bin/worker cancel --id <id> the task to get rid of it. Ideally, the “right” way to resolve this sort of issue is upgrade into a bugfix, then let the task complete. However, I’m not confident I’m actually going to be able to figure out what’s going on, so you might be waiting indefinitely if you take this path.

I’ll leave it in there for a while in case you need me to check something, it doesn’t seem to be causing any harm and it’s been there for a while by the look of it.
Thanks
Will

I was only able to reproduce this error by explicitly mangling the database with UPDATE statements, but may have fixed it.

See https://secure.phabricator.com/T13484 for some related discussion and https://secure.phabricator.com/D20963 for the patch.

This is available in master now; it will promote to stable on the normal release schedule (likely circa February 8th).