Page MenuHomePhabricator

phabricator daemon fails when updating repository (possibly due to attempting to email a user without access)
Closed, ResolvedPublic

Description

Phabricator daemons will crash and restart continuously when attempting to update a repository. This seems to be caused by attempting to email a user who cannot view the repository.

[2015-08-04 11:14:59] EXCEPTION: (PhutilProxyException) Error while executing Task ID 494684. {>} (Exception) No such repository 'RS'. at [<phabricator>/src/applications/diffusion/request/DiffusionRequest.php:159]
arcanist(head=master, ref.master=0d6f3328a08f), phabricator(head=master, ref.master=ec7a0837d56d), phutil(head=master, ref.master=aa6cd8f7e5e5)
  #0 <#2> DiffusionRequest::newFromCallsign(string, PhabricatorUser) called at [<phabricator>/src/applications/diffusion/request/DiffusionRequest.php:86]
  #1 <#2> DiffusionRequest::newFromDictionary(array) called at [<phabricator>/src/applications/diffusion/conduit/DiffusionQueryConduitAPIMethod.php:105]
  #2 <#2> DiffusionQueryConduitAPIMethod::execute(ConduitAPIRequest) called at [<phabricator>/src/applications/conduit/method/ConduitAPIMethod.php:90]
  #3 <#2> ConduitAPIMethod::executeMethod(ConduitAPIRequest) called at [<phabricator>/src/applications/conduit/call/ConduitCall.php:135]
  #4 <#2> ConduitCall::executeMethod() called at [<phabricator>/src/applications/conduit/call/ConduitCall.php:85]
  #5 <#2> ConduitCall::execute() called at [<phabricator>/src/applications/repository/customfield/PhabricatorCommitTagsField.php:34]
  #6 <#2> PhabricatorCommitTagsField::updateTransactionMailBody(PhabricatorMetaMTAMailBody, PhabricatorAuditEditor, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:2631]
  #7 <#2> PhabricatorApplicationTransactionEditor::addCustomFieldsToMailBody(PhabricatorMetaMTAMailBody, PhabricatorRepositoryCommit, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:2561]
  #8 <#2> PhabricatorApplicationTransactionEditor::buildMailBody(PhabricatorRepositoryCommit, array) called at [<phabricator>/src/applications/audit/editor/PhabricatorAuditEditor.php:646]
  #9 <#2> PhabricatorAuditEditor::buildMailBody(PhabricatorRepositoryCommit, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:2326]
  #10 <#2> PhabricatorApplicationTransactionEditor::buildMailForTarget(PhabricatorRepositoryCommit, array, PhabricatorMailTarget) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:2285]
  #11 <#2> PhabricatorApplicationTransactionEditor::buildMail(PhabricatorRepositoryCommit, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:1046]
  #12 <#2> PhabricatorApplicationTransactionEditor::publishTransactions(PhabricatorRepositoryCommit, array) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:21]
  #13 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:91]
  #14 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:162]
  #15 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
  #16 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:183]
  #17 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:125]

This succeeds when running a manual update from the command line:

sse-review:phabricator osystem$ ./bin/repository update --trace RS
>>> [2] <connect> phabricator_repository
<<< [2] <connect> 910 us
>>> [3] <query> SELECT `r`.* FROM `repository` r  WHERE (r.callsign IN ('RS'))   ORDER BY `r`.`id` DESC 
<<< [3] <query> 296 us
>>> [4] <lock> ph:phabric-6rILUDHKjHKu:repository.update:58
>>> [5] <connect> phabricator_repository
<<< [5] <connect> 277 us
>>> [6] <query> SET wait_timeout = 2147483
<<< [6] <query> 97 us
>>> [7] <query> SELECT GET_LOCK('ph:phabric-6rILUDHKjHKu:repository.update:58', 0)
<<< [7] <query> 139 us
>>> [8] <connect> phabricator_repository
<<< [8] <connect> 323 us
>>> [9] <query> INSERT INTO `repository_statusmessage`
          (repositoryID, statusType, statusCode, parameters, epoch)
          VALUES (58, 'init', 'working', '{\"message\":\"Updating the working copy for repository \'RS\'.\"}', 1438712450)
          ON DUPLICATE KEY UPDATE
            statusCode = VALUES(statusCode),
            parameters = VALUES(parameters),
            epoch = VALUES(epoch)
<<< [9] <query> 441 us
>>> [10] <exec> $ git remote show -n origin
<<< [10] <exec> 7,962 us
>>> [11] <exec> $ git rev-parse --show-toplevel
<<< [11] <exec> 7,213 us
>>> [12] <exec> $ git fetch origin '+refs/heads/*:refs/heads/*' --prune
<<< [12] <exec> 617,750 us
>>> [13] <query> INSERT INTO `repository_statusmessage`
          (repositoryID, statusType, statusCode, parameters, epoch)
          VALUES (58, 'init', 'okay', '{\"message\":null}', 1438712451)
          ON DUPLICATE KEY UPDATE
            statusCode = VALUES(statusCode),
            parameters = VALUES(parameters),
            epoch = VALUES(epoch)
<<< [13] <query> 641 us
>>> [14] <query> DELETE FROM `repository_statusmessage` WHERE repositoryID = 58 AND statusType = 'needs-update'
<<< [14] <query> 185 us
>>> [15] <exec> $ git remote show -n origin
<<< [15] <exec> 7,544 us
>>> [16] <exec> $ git for-each-ref --sort='-creatordate' --format='%(objectname)%01%(objecttype)%01%(refname)%01%(*objectname)%01%(*objecttype)%01%(subject)%01%(creator)' 'refs/heads/'
<<< [16] <exec> 8,782 us
>>> [17] <query> SELECT * FROM `repository_commit` WHERE repositoryID = 58 AND commitIdentifier IN ('95f27500067b39ac6247be38793a19f0b0993dd2', '95f27500067b39ac6247be38793a19f0b0993dd2', '4681ff12712cd1ed7623b9137c2f9d2e56165ae2') 
<<< [17] <query> 452 us
>>> [18] <exec> $ git for-each-ref --sort='-creatordate' --format='%(objectname)%01%(objecttype)%01%(refname)%01%(*objectname)%01%(*objecttype)%01%(subject)%01%(creator)' 'refs/heads/'
<<< [18] <exec> 9,999 us
>>> [19] <exec> $ git for-each-ref --sort='-creatordate' --format='%(objectname)%01%(objecttype)%01%(refname)%01%(*objectname)%01%(*objecttype)%01%(subject)%01%(creator)' 'refs/tags/'
<<< [19] <exec> 7,679 us
>>> [20] <query> SELECT * FROM `repository_refcursor` r WHERE (repositoryPHID IN ('PHID-REPO-ixt73b7kl3p2hu53dbyz')) ORDER BY `id` DESC 
<<< [20] <query> 437 us
>>> [21] <query> SELECT `r`.* FROM `repository` r  WHERE (r.phid IN ('PHID-REPO-ixt73b7kl3p2hu53dbyz', 'PHID-REPO-ixt73b7kl3p2hu53dbyz', 'PHID-REPO-ixt73b7kl3p2hu53dbyz'))   ORDER BY `r`.`id` DESC 
<<< [21] <query> 330 us
>>> [22] <exec> $ git for-each-ref --sort='-creatordate' --format='%(objectname)%01%(objecttype)%01%(refname)%01%(*objectname)%01%(*objecttype)%01%(subject)%01%(creator)' 'refs/heads/'
>>> [23] <exec> $ git for-each-ref --sort='-creatordate' --format='%(objectname)%01%(objecttype)%01%(refname)%01%(*objectname)%01%(*objecttype)%01%(subject)%01%(creator)' 'refs/tags/'
<<< [23] <exec> 7,172 us
<<< [22] <exec> 8,524 us
>>> [24] <exec> $ git cat-file --batch-check
<<< [24] <exec> 8,728 us
>>> [25] <query> SELECT * FROM `repository_mirror` WHERE (repositoryPHID IN ('PHID-REPO-ixt73b7kl3p2hu53dbyz')) ORDER BY `id` DESC 
<<< [25] <query> 381 us
>>> [26] <query> INSERT INTO `repository_statusmessage`
          (repositoryID, statusType, statusCode, parameters, epoch)
          VALUES (58, 'fetch', 'okay', '[]', 1438712451)
          ON DUPLICATE KEY UPDATE
            statusCode = VALUES(statusCode),
            parameters = VALUES(parameters),
            epoch = VALUES(epoch)
<<< [26] <query> 473 us
>>> [27] <query> SELECT RELEASE_LOCK('ph:phabric-6rILUDHKjHKu:repository.update:58')
<<< [27] <query> 168 us
<<< [4] <lock> 705,339 us
Updated repository rRS.

Event Timeline

jcarrillo7 raised the priority of this task from to Needs Triage.
jcarrillo7 updated the task description. (Show Details)
jcarrillo7 added projects: Daemons, Differential.
jcarrillo7 added a subscriber: jcarrillo7.

@epriestley I believe this is happening because I have the repo in a space, but it also has a project set on it. I noticed that if you are in the space you can see the repo even if you are not in the project? I believe the person it is trying to email is not in the project but is in the space. Is this intentional? Are people supposed to be able to see the repo if they are not in the project but in the space?

Phabricators access control setup is a bit complicated..

Are people supposed to be able to see the repo if they are not in the project but in the space?

Yes. Adding projects never affect access control.

Are people supposed to be able to see the repo if they are not in the project but in the space?

Yes. Adding projects never affect access control.

Interesting. What is the actual purpose of projects then? Just organizational? I guess my confusion came from the fact that they are used everywhere in access control.

Anyways, removing the projects (but not the spaces) from the repo's caused a lot of the issues to go away, though some repo's are still failing in the daemons with the same error. Not sure why anymore. Maybe commits from users that don't exist in phabricator ? (ex employees).

@epriestley Did a little more digging in phabricator and it seems to be trying to email an employee who has a herald rule that emails him on any commit anywhere (he doesn't have access to all repositories though).

This also seems to have been trying to email a disabled user (who was never enabled) for some reason unknown to me.

On a side note, does anyone know of a way to clear (PhabricatorApplicationTransactionPublishWorker) tasks from the daemon queue? These will fail forever on my system since this user does not have access. Multiple have already failed over 6000 times to send the email.

epriestley claimed this task.

Oh, I didn't look at the stack trace carefully when dealing with T9458. I think the fix for that (D14142) almost certainly resolved this, too.

This also seems to have been trying to email a disabled user (who was never enabled) for some reason unknown to me.

We build email first, then decide which recipients are actually eligible to receive it later. For disabled users, we'll build the mail, then decline to deliver it at the last second.

The main reason we do this is to make delivery debuggable: doing this means that the mail shows up in bin/mail list-outbound, etc., and users can figure out why mail they expected to receive was not delivered. If we dropped this mail without a trace it would be impossible to guide users who report "Phabricator didn't send mail" to this root cause conclusively. Since we generate the mail, then mark it as "we didn't send this mail, because the recipient was disabled when we went to deliver it", I can walk users through a sequence of commands which produce this information.

On a side note, does anyone know of a way to clear (PhabricatorApplicationTransactionPublishWorker) tasks from the daemon queue?

phabricator/ $ ./bin/worker cancel --id ...