Page MenuHomePhabricator

PhabricatorTaskmasterDaemon fatals in PublishWorker
Closed, ResolvedPublic

Description

Issue: daemon.log is filled with stack traces from PhabricatorTaskmasterDaemon
VCS: SVN (Partial import), externally hosted, diffusion tracked
Phabricator: Updated on 23rd June.

Seems like if there is a 'Deleted' file in the SVN commit, the problem is observed.
Commit revision 71588 had 5 deleted files and 8 modified files.

[25-Jun-2015 10:30:04 Asia/Kolkata]   #0 <#2> PhutilErrorHandler::handleError(integer, string, string, integer, array) called at [<phutil>/src/utils/utils.php:36]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #1 <#2> idx(NULL, string) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:32]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #2 <#2> PhabricatorApplicationTransactionPublishWorker::loadObject() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:17]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #3 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:91]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #4 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:162]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #5 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #6 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:183]
[25-Jun-2015 10:30:04 Asia/Kolkata]   #7 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:125]
[25-Jun-2015 10:35:05 Asia/Kolkata] [2015-06-25 10:35:05] EXCEPTION: (PhutilProxyException) Error while executing Task ID 136757. {>} (InvalidArgumentException) Argument 1 passed to idx() must be of the type array, null given, called in /home/tester/phabricator/phabricator/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php on line 32 and defined at [<phutil>/src/error/PhutilErrorHandler.php:200]
[25-Jun-2015 10:35:05 Asia/Kolkata] arcanist(head=master, ref.master=5b5629959d60), phabricator(head=master_copy, ref.master=9513fc3571c0, ref.master_copy=87bbda549fc0), phutil(head=master, ref.master=6fedd82a29a0)
[25-Jun-2015 10:35:05 Asia/Kolkata]   #0 <#2> PhutilErrorHandler::handleError(integer, string, string, integer, array) called at [<phutil>/src/utils/utils.php:36]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #1 <#2> idx(NULL, string) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:32]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #2 <#2> PhabricatorApplicationTransactionPublishWorker::loadObject() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:17]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #3 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:91]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #4 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:162]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #5 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #6 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:183]
[25-Jun-2015 10:35:05 Asia/Kolkata]   #7 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:125]
[25-Jun-2015 10:40:06 Asia/Kolkata] [2015-06-25 10:40:06] EXCEPTION: (PhutilProxyException) Error while executing Task ID 136757. {>} (InvalidArgumentException) Argument 1 passed to idx() must be of the type array, null given, called in /home/tester/phabricator/phabricator/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php on line 32 and defined at [<phutil>/src/error/PhutilErrorHandler.php:200]
[25-Jun-2015 10:40:06 Asia/Kolkata] arcanist(head=master, ref.master=5b5629959d60), phabricator(head=master_copy, ref.master=9513fc3571c0, ref.master_copy=87bbda549fc0), phutil(head=master, ref.master=6fedd82a29a0)
[25-Jun-2015 10:40:06 Asia/Kolkata]   #0 <#2> PhutilErrorHandler::handleError(integer, string, string, integer, array) called at [<phutil>/src/utils/utils.php:36]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #1 <#2> idx(NULL, string) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:32]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #2 <#2> PhabricatorApplicationTransactionPublishWorker::loadObject() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:17]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #3 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:91]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #4 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:162]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #5 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #6 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:183]
[25-Jun-2015 10:40:06 Asia/Kolkata]   #7 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:125]
mysql> (SELECT      * FROM     phabricator_worker.worker_activetask);
+--------+------------------------------------------------+----------------------------------+--------------+--------------+--------+-------------+----------+--------------------------------+
| id     | taskClass                                      | leaseOwner                       | leaseExpires | failureCount | dataID | failureTime | priority | objectPHID                     |
+--------+------------------------------------------------+----------------------------------+--------------+--------------+--------+-------------+----------+--------------------------------+
| 136757 | PhabricatorApplicationTransactionPublishWorker | 29539:1435224658:phabricator:296 |   1435224958 |          253 | 136755 |  1435224658 |     1000 | PHID-CMIT-rjfxs3iuxyzwf4resy4b |
+--------+------------------------------------------------+----------------------------------+--------------+--------------+--------+-------------+----------+--------------------------------+
1 row in set (0.00 sec)

mysql> (SELECT      * FROM     phabricator_worker.worker_archivetask WHERE id=136755 );
+--------+-----------------------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
| id     | taskClass                               | leaseOwner                         | leaseExpires | failureCount | dataID | result | duration | dateCreated | dateModified | priority | objectPHID |
+--------+-----------------------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
| 136755 | PhabricatorRepositoryCommitOwnersWorker | 27022:1435148802:phabricator:83987 |   1435156002 |            0 | 136753 |      0 |    19160 |  1435148802 |   1435148802 |     2000 | NULL       |
+--------+-----------------------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
1 row in set (0.00 sec)

mysql> (SELECT      * FROM     phabricator_worker.worker_archivetask WHERE id=136753 );
+--------+--------------------------------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
| id     | taskClass                                        | leaseOwner                         | leaseExpires | failureCount | dataID | result | duration | dateCreated | dateModified | priority | objectPHID |
+--------+--------------------------------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
| 136753 | PhabricatorRepositorySvnCommitChangeParserWorker | 27022:1435148800:phabricator:83986 |   1435235200 |            0 | 136751 |      0 |  2183335 |  1435148802 |   1435148802 |     2000 | NULL       |
+--------+--------------------------------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
1 row in set (0.00 sec)

mysql> (SELECT      * FROM     phabricator_worker.worker_archivetask WHERE id=136751 );
+--------+--------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
| id     | taskClass                | leaseOwner                         | leaseExpires | failureCount | dataID | result | duration | dateCreated | dateModified | priority | objectPHID |
+--------+--------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
| 136751 | PhabricatorMetaMTAWorker | 27022:1435148152:phabricator:83341 |   1435155352 |            0 | 136749 |      0 |  2776911 |  1435148154 |   1435148154 |     1000 | NULL       |
+--------+--------------------------+------------------------------------+--------------+--------------+--------+--------+----------+-------------+--------------+----------+------------+
1 row in set (0.00 sec)
mysql> select * from repository_commit where phid = "PHID-CMIT-rjfxs3iuxyzwf4resy4b"
    -> ;
+-------+--------------+--------------------------------+------------------+------------+----------------------+--------------------------------+-------------+-------------------------------------------------------------+--------------+
| id    | repositoryID | phid                           | commitIdentifier | epoch      | mailKey              | authorPHID                     | auditStatus | summary                                                     | importStatus |
+-------+--------------+--------------------------------+------------------+------------+----------------------+--------------------------------+-------------+-------------------------------------------------------------+--------------+
| 25193 |            3 | PHID-CMIT-rjfxs3iuxyzwf4resy4b | 71588            | 1435148799 | 624zhev76g6gctrhw6mq | PHID-USER-wr44plznucp4eqowtp7r |           0 | Porting cRNC TCs to mcRNC & vRNC & RNC_UE MT restructuring. |         1039 |
+-------+--------------+--------------------------------+------------------+------------+----------------------+--------------------------------+-------------+-------------------------------------------------------------+--------------+
1 row in set (0.00 sec)

PS: Used bin/worked cancel --id ID for multiple entries in worker_activetask table in the previous week.

Event Timeline

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

I think the root cause of this issue is non-utf8 rawDiffs failing to encode when being passed to the publisher.

I believe I get the same issue in my production environment
There's a difference, as I don't have any matching entries in the worker_archivetask table

Upgraded Jul 8th

I had to censor the hostname but I am available for troubleshooting, if it helps, and I have not cancelled any of these tasks.

daemons.log
[08-Jul-2015 14:35:26 UTC] [2015-07-08 14:35:26] EXCEPTION: (PhutilProxyException) Error while executing Task ID 351245. {>} (InvalidArgumentException) Argument 1 passed to idx() must be of the type array, null given, called in /var/www/phabricator/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php on line 32 and defined at [<phutil>/src/error/PhutilErrorHandler.php:200]
[08-Jul-2015 14:35:26 UTC] arcanist(head=master, ref.master=999eb9376568), phabricator(head=master, ref.master=0036670329cc), phutil(head=master, ref.master=aa6cd8f7e5e5)
[08-Jul-2015 14:35:26 UTC]   #0 <#2> PhutilErrorHandler::handleError(integer, string, string, integer, array) called at [<phutil>/src/utils/utils.php:36]
[08-Jul-2015 14:35:26 UTC]   #1 <#2> idx(NULL, string) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:32]
[08-Jul-2015 14:35:26 UTC]   #2 <#2> PhabricatorApplicationTransactionPublishWorker::loadObject() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:17]
[08-Jul-2015 14:35:26 UTC]   #3 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:91]
[08-Jul-2015 14:35:26 UTC]   #4 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:162]
[08-Jul-2015 14:35:26 UTC]   #5 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[08-Jul-2015 14:35:26 UTC]   #6 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:183]
[08-Jul-2015 14:35:26 UTC]   #7 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:125]
phabricator_worker.worker_activetask
mysql> SELECT * FROM phabricator_worker.worker_activetask;
+--------+------------------------------------------------+-----------------------------+--------------+--------------+--------+-------------+----------+--------------------------------+
| id     | taskClass                                      | leaseOwner                  | leaseExpires | failureCount | dataID | failureTime | priority | objectPHID                     |
+--------+------------------------------------------------+-----------------------------+--------------+--------------+--------+-------------+----------+--------------------------------+
| 327659 | PhabricatorApplicationTransactionPublishWorker | 10133:1436363402:XXXXXX:300 |   1436363702 |         8218 | 327657 |  1436363402 |     1000 | PHID-CMIT-f4zelumvcn2abq2immnz |
| 340316 | PhabricatorApplicationTransactionPublishWorker | 12333:1436363405:XXXXXX:3   |   1436363705 |         3994 | 340314 |  1436363405 |     1000 | PHID-CMIT-lrvr74ixvr4ofvhabpq3 |
| 344157 | PhabricatorApplicationTransactionPublishWorker | 12372:1436363408:XXXXXX:1   |   1436363708 |         3385 | 344155 |  1436363408 |     1000 | PHID-CMIT-gbmykzj23rujxr6umohu |
| 345035 | PhabricatorApplicationTransactionPublishWorker | 12413:1436363413:XXXXXX:1   |   1436363713 |         2274 | 345033 |  1436363413 |     1000 | PHID-CMIT-57yjwjafq645wtbagkbi |
| 346023 | PhabricatorApplicationTransactionPublishWorker | 12184:1436363398:XXXXXX:28  |   1436363698 |         1966 | 346021 |  1436363398 |     1000 | PHID-CMIT-uudlpeufglxcatb3xlx7 |
| 347201 | PhabricatorApplicationTransactionPublishWorker | 12388:1436363408:XXXXXX:1   |   1436363708 |         1648 | 347199 |  1436363408 |     1000 | PHID-CMIT-mnf3tvsndoyagf7fiekh |
| 349498 | PhabricatorApplicationTransactionPublishWorker | 12407:1436363410:XXXXXX:1   |   1436363710 |          500 | 349496 |  1436363410 |     1000 | PHID-CMIT-4i4d5mgwd3jeywt26rcz |
| 350603 | PhabricatorApplicationTransactionPublishWorker | 12409:1436363411:XXXXXX:1   |   1436363711 |          266 | 350601 |  1436363411 |     1000 | PHID-CMIT-ceucnslidfn6q2ksdt5t |
| 351245 | PhabricatorApplicationTransactionPublishWorker | 12411:1436363413:XXXXXX:1   |   1436363713 |          214 | 351243 |  1436363413 |     1000 | PHID-CMIT-gjxlbl37jxogizh4yw2q |
+--------+------------------------------------------------+-----------------------------+--------------+--------------+--------+-------------+----------+--------------------------------+
9 rows in set (0.00 sec)
phabricator_worker.worker_archivetask
mysql> SELECT * FROM phabricator_worker.worker_archivetask WHERE id IN (SELECT id FROM phabricator_worker.worker_activetask);
Empty set (0.01 sec)

@epriestley - I'm not sure, but perhaps my circumstances might be useful for debugging purposes. I thought I should share it with you.

My colleague:

  1. Recently installed Phabricator last week (as far as I know, a clean install, nothing crazy and no extensions)
  2. Added me as a superuser.
  3. Imported a (fairly large and very actively maintained) Git repo.
    1. Which made turn off the email notifications as the notifications of my own commits which made me go slighty crazy.

And since then we haven't touched Phabricator.
However, since then, every second the daemon.log is being appended with a log entry as such, flooding our (development) server:

[20-Jul-2015 12:11:06 Europe/Amsterdam] [2015-07-20 12:11:06] EXCEPTION: (PhutilProxyException) Error while executing Task ID 220725. {>} (InvalidArgumentException) Argument 1 passed to idx() must be of the type array, null given, called in /local.mnt/vol2/www/htdocs/coostodev/phabricator/phabricator/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php on line 32 and defined at [<phutil>/src/error/PhutilErrorHandler.php:200]
[20-Jul-2015 12:11:06 Europe/Amsterdam] arcanist(head=master, ref.master=d54cb072facd), phabricator(head=master, ref.master=d9ab267de601), phutil(head=master, ref.master=fffe7e4ef4c8)
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #0 <#2> PhutilErrorHandler::handleError(integer, string, string, integer, array) called at [<phutil>/src/utils/utils.php:36]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #1 <#2> idx(NULL, string) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:32]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #2 <#2> PhabricatorApplicationTransactionPublishWorker::loadObject() called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:17]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #3 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:91]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #4 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:162]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #5 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #6 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:183]
[20-Jul-2015 12:11:06 Europe/Amsterdam]   #7 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:125]

Note that the arcanist and phabricator ref.master differs with the example provided by @arielsalvo, but for the rest it seems identical.

(I've set the garbage collector to retain the deamon logs for 1 day for now...)

We have the same problem when importing existing git repositories:

EXCEPTION: (PhutilProxyException) Error while executing Task ID x. {>} (InvalidArgumentException) Argument 1 passed to idx() must be of type array, null given, called in /usr/share/phabricaor/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php on line 32

It's always the data property of the PhabricatorApplicationTransactionPublishWorker class, which is supposed to be an array but in the error case is null instead. There are countless tasks that fail because of this when importing large repositories and I am not sure if it is a good idea to manually cancel these tasks? We also have a small GitHub repository that triggers just a few of these errors and therefore should be perfect for reproducing the bug:

https://github.com/MITK/MITK-ProjectTemplate.git

Is this right?

--- a/src/applications/repository/worker/PhabricatorRepositoryCommitHeraldWorker.php
+++ b/src/applications/repository/worker/PhabricatorRepositoryCommitHeraldWorker.php
@@ -123,14 +123,16 @@ final class PhabricatorRepositoryCommitHeraldWorker
     if ($byte_limit && $size > $byte_limit) {
       $pretty_size = phutil_format_bytes($size);
       $pretty_limit = phutil_format_bytes($byte_limit);
       throw new Exception(pht(
         'Patch size of %s exceeds configured byte size limit (%s) of %s.',
         $pretty_size,
         $byte_key,
         $pretty_limit));
     }

+    $raw_diff = phutil_json_encode($raw_diff);
+
     return $raw_diff;
   }

 }

Wow, now that was quick @shrinidhirao. 🚀
At least for MITK-ProjectTemplate it works like a charm, thank you!

Macro happycat:

I have the same error with the latest code even after I applied the fix from @shrinidhirao.

OK, as @shrinidhirao suggested, the fix only works for new tasks. I canceled all failing tasks and wait to see how new tasks work.

well, I can still see the same error with new tasks.

epriestley claimed this task.

This appears to be resolved. It's been in master for about a week without issues and deployed to the cluster for about 48 hours.

Specifically, these behaviors are expected:

  1. Existing queued tasks with bad data will fail permanently.
  2. Commits with non-utf8 content will now survive being passed to the daemons.
  3. Future issues in this vein which cause encoding failures will fail immediately at the Editor site, instead of in the daemons.

The new behavior in (3) may produce new failures if we have other pathways which mishandle UTF8, but they'll be louder and more obvious and easier to correct. Let us know if you encounter any.