Page MenuHomePhabricator
Create Task
Maniphest T8503

Feed query may fail to progress while paging on 32-bit systems
Closed, ResolvedPublic
Actions

Description

After a token is granted, the next phabot feed poll starts generating errors like this in the apache logs:

[Wed Jun 10 13:31:28 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phutil>/src/parser/PhutilTypeSpec.php on line 1909
[Wed Jun 10 13:31:28 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phutil>/src/parser/PhutilTypeSpec.php:1909\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb
[Wed Jun 10 13:32:35 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phabricator>/src/applications/feed/story/PhabricatorFeedStory.php on line 52
[Wed Jun 10 13:33:42 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phutil>/src/parser/PhutilTypeSpec.php on line 1909
[Wed Jun 10 13:33:42 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phutil>/src/parser/PhutilTypeSpec.php:1909\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb
[Wed Jun 10 13:34:48 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phutil>/src/parser/PhutilTypeSpec.php on line 637
[Wed Jun 10 13:34:48 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phutil>/src/parser/PhutilTypeSpec.php:637\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb
[Wed Jun 10 13:35:55 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phabricator>/src/infrastructure/storage/lisk/LiskDAO.php on line 653
[Wed Jun 10 13:35:55 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:653\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb
[Wed Jun 10 13:37:01 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phutil>/src/parser/PhutilParserGenerator.php on line 871
[Wed Jun 10 13:37:01 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phutil>/src/parser/PhutilParserGenerator.php:871\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb
[Wed Jun 10 13:38:08 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phutil>/src/parser/PhutilTypeSpec.php on line 156
[Wed Jun 10 13:38:08 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phutil>/src/parser/PhutilTypeSpec.php:156\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb
[Wed Jun 10 13:39:16 2015] [error] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in <phutil>/src/parser/PhutilTypeSpec.php on line 451
[Wed Jun 10 13:39:16 2015] [error] >>> UNRECOVERABLE FATAL ERROR <<<\n\nMaximum execution time of 30 seconds exceeded\n\n<phutil>/src/parser/PhutilTypeSpec.php:451\n\n\n\xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb \xef\xb8\xb5 \xc2\xaf\\_(\xe3\x83\x84)_/\xc2\xaf \xef\xb8\xb5 \xe2\x94\xbb\xe2\x94\x81\xe2\x94\xbb

I can reproduce this reliably on our install. bin/phd restart generally fixes it. Here's the daemon log at the same time:

Token was awarded at 1:30 PM.

ConnectionUserMethodStatusErrorDurationDate
3758botfeed.query (via PhabricatorBot)Unstable150,976 usWed, Jun 10, 1:38 PM
3758botmacro.query (via PhabricatorBot)97,215 usWed, Jun 10, 1:38 PM
3758botconduit.connect (via PhabricatorBot)61,957 usWed, Jun 10, 1:38 PM
3757botfeed.query (via PhabricatorBot)Unstable147,731 usWed, Jun 10, 1:37 PM
3757botmacro.query (via PhabricatorBot)90,280 usWed, Jun 10, 1:37 PM
3757botconduit.connect (via PhabricatorBot)67,420 usWed, Jun 10, 1:37 PM
3756botfeed.query (via PhabricatorBot)Unstable140,734 usWed, Jun 10, 1:36 PM
3756botmacro.query (via PhabricatorBot)91,911 usWed, Jun 10, 1:36 PM
3756botconduit.connect (via PhabricatorBot)72,127 usWed, Jun 10, 1:36 PM
3755botfeed.query (via PhabricatorBot)Unstable134,998 usWed, Jun 10, 1:35 PM
3755botmacro.query (via PhabricatorBot)92,027 usWed, Jun 10, 1:34 PM
3755botconduit.connect (via PhabricatorBot)67,404 usWed, Jun 10, 1:34 PM
3754botfeed.query (via PhabricatorBot)Unstable148,287 usWed, Jun 10, 1:34 PM
3754botmacro.query (via PhabricatorBot)91,081 usWed, Jun 10, 1:33 PM
3754botconduit.connect (via PhabricatorBot)67,612 usWed, Jun 10, 1:33 PM
3753botfeed.query (via PhabricatorBot)Unstable138,011 usWed, Jun 10, 1:33 PM
3753botmacro.query (via PhabricatorBot)91,406 usWed, Jun 10, 1:32 PM
3753botconduit.connect (via PhabricatorBot)81,492 usWed, Jun 10, 1:32 PM
3752botfeed.query (via PhabricatorBot)Unstable130,401 usWed, Jun 10, 1:32 PM
3752botmacro.query (via PhabricatorBot)103,591 usWed, Jun 10, 1:31 PM
3752botconduit.connect (via PhabricatorBot)103,454 usWed, Jun 10, 1:31 PM
3751botfeed.query (via PhabricatorBot)Unstable324,290 usWed, Jun 10, 1:30 PM
3751botfeed.query (via PhabricatorBot)Unstable258,557 usWed, Jun 10, 1:30 PM
3751botfeed.query (via PhabricatorBot)Unstable282,964 usWed, Jun 10, 1:30 PM
3751botfeed.query (via PhabricatorBot)Unstable274,175 usWed, Jun 10, 1:30 PM
3751botfeed.query (via PhabricatorBot)Unstable263,751 usWed, Jun 10, 1:30 PM
3751botfeed.query (via PhabricatorBot)Unstable269,546 usWed, Jun 10, 1:29 PM
3751botfeed.query (via PhabricatorBot)Unstable264,452 usWed, Jun 10, 1:29 PM
3751botfeed.query (via PhabricatorBot)Unstable260,182 usWed, Jun 10, 1:29 PM
3751botfeed.query (via PhabricatorBot)Unstable261,021 usWed, Jun 10, 1:29 PM
3751botfeed.query (via PhabricatorBot)Unstable274,351 usWed, Jun 10, 1:29 PM
3751botfeed.query (via PhabricatorBot)Unstable273,942 usWed, Jun 10, 1:29 PM

Revisions and Commits

rP Phabricator
D13250rPc71873ed7b31 Fix feed query cursor-based pagination on 32-bit systems

Related Objects

Mentioned In
P1801 phabot timeouts

Event Timeline

staticshock created this task.Jun 10 2015, 5:49 PM
staticshock raised the priority of this task from to Needs Triage.
staticshock updated the task description. (Show Details)
staticshock added a project: Conduit.
staticshock mentioned this in P1801 phabot timeouts.
staticshock added subscribers: staticshock, epriestley.
cburroughs added a subscriber: cburroughs.Jun 10 2015, 7:59 PM
epriestley added a comment.Jun 10 2015, 8:06 PM

Can you reproduce this by calling feed.query manually from the web UI?

epriestley added a comment.Jun 10 2015, 8:07 PM

(If you can, set debug.time-limit to 10 and then repro it; it should give you a more useful stack trace.)

joshuaspence added a subscriber: joshuaspence.Jun 10 2015, 8:36 PM
staticshock added a comment.Jun 10 2015, 10:09 PM

Not really. But I cobbled something together via the bot, which suggests that this is this stack trace:

PhutilTypeSpec.parseTokens
PhutilTypeSpec.newFromString
PhutilTypeSpec.checkMap
PhabricatorCursorPagedPolicyAwareQuery.buildPagingClauseFromMultipleColumns
PhabricatorCursorPagedPolicyAwareQuery.buildPagingClause
PhabricatorFeedQuery.buildWhereClause
PhabricatorFeedQuery.loadPage
PhabricatorPolicyAwareQuery.execute
FeedQueryConduitAPIMethod.execute
ConduitAPIMethod.executeMethod
ConduitCall.executeMethod
ConduitCall.execute
PhabricatorConduitAPIController.processRequest
AphrontController.handleRequest
AphrontApplicationConfiguration.processRequest
AphrontApplicationConfiguration.runHTTPRequest

This stack showed up 7241 times in the span of several seconds under the same request handler, which makes me think that there's an infinite loop somewhere in there.

When it gets stuck in the infinite loop, print_r($tokens) in parseTokens() looks like this:

$tokens = Array
(
    [0] => Array ( [0] => opt [1] => optional [2] => )
    [1] => Array ( [0] => k [1] => string [2] => )
    [2] => Array ( [0] => | [1] => | [2] => )
    [3] => Array ( [0] => k [1] => null [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => k [1] => string [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => k [1] => wild [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => k [1] => string [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => opt [1] => optional [2] => )
    [1] => Array ( [0] => k [1] => bool [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => opt [1] => optional [2] => )
    [1] => Array ( [0] => k [1] => bool [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => opt [1] => optional [2] => )
    [1] => Array ( [0] => k [1] => string [2] => )
    [2] => Array ( [0] => | [1] => | [2] => )
    [3] => Array ( [0] => k [1] => null [2] => )
)

$tokens = Array
(
    [0] => Array ( [0] => opt [1] => optional [2] => )
    [1] => Array ( [0] => k [1] => bool [2] => )
)

...after that, it repeats until 30 seconds runs out.

staticshock added a comment.Jun 11 2015, 1:02 AM

Logging each function call, I'm seeing this:

PhabricatorConduitAPIController::processRequest
ConduitCall::execute
ConduitCall::executeMethod
ConduitAPIMethod::executeMethod
FeedQueryConduitAPIMethod::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
PhabricatorPolicyAwareQuery::execute
...

Capturing a stack trace every time PhabricatorPolicyAwareQuery::execute gets called, I'm seeing this:

PhabricatorPolicyAwareQuery::execute  <---
PhabricatorFeedStory::loadAllFromRows
PhabricatorFeedQuery::willFilterPage
PhabricatorPolicyAwareQuery::execute  <---
FeedQueryConduitAPIMethod::execute
ConduitAPIMethod::executeMethod
ConduitCall::executeMethod
ConduitCall::execute
PhabricatorConduitAPIController::processRequest
AphrontController::handleRequest
AphrontApplicationConfiguration::processRequest
AphrontApplicationConfiguration::runHTTPRequest

PhabricatorPolicyAwareQuery::execute  <---
PhabricatorFeedStory::loadAllFromRows
PhabricatorFeedQuery::willFilterPage
PhabricatorPolicyAwareQuery::execute  <---
FeedQueryConduitAPIMethod::execute
ConduitAPIMethod::executeMethod
ConduitCall::executeMethod
ConduitCall::execute
PhabricatorConduitAPIController::processRequest
AphrontController::handleRequest
AphrontApplicationConfiguration::processRequest
AphrontApplicationConfiguration::runHTTPRequest

PhabricatorPolicyAwareQuery::execute  <---
PhabricatorFeedStory::loadAllFromRows
PhabricatorFeedQuery::willFilterPage
PhabricatorPolicyAwareQuery::execute  <---
FeedQueryConduitAPIMethod::execute
ConduitAPIMethod::executeMethod
ConduitCall::executeMethod
ConduitCall::execute
PhabricatorConduitAPIController::processRequest
AphrontController::handleRequest
AphrontApplicationConfiguration::processRequest
AphrontApplicationConfiguration::runHTTPRequest

...

I think it's recursive, but I don't really understand why the stack stays so shallow each next time I capture it.

epriestley added a comment.Jun 11 2015, 1:11 PM

It's possible that the paging code is breaking somehow, although I still haven't been able to reproduce this and can't see any way it could. Can you log the value of $cursor passed to getPagingValueMap() each time through the loop? It should look like this:

string(19) "6157999999718374686"
string(19) "6155772809158046011"
string(19) "6148764180868254680"
string(19) "6145361718491376706"
string(19) "6141665117539514203"

That is, decreasing each time.

Oh, actually, I have a theory on this:

  • Can you show me the value of php -r 'echo PHP_INT_MAX;' from the command line?
  • Does this change fix it?
diff --git a/src/applications/feed/query/PhabricatorFeedQuery.php b/src/applications/feed/query/PhabricatorFeedQuery.php
index b9c7d09..13cfb26 100644
--- a/src/applications/feed/query/PhabricatorFeedQuery.php
+++ b/src/applications/feed/query/PhabricatorFeedQuery.php
@@ -101,7 +101,7 @@ final class PhabricatorFeedQuery
       'key' => array(
         'table' => $table,
         'column' => 'chronologicalKey',
-        'type' => 'int',
+        'type' => 'string',
         'unique' => true,
       ),
     );
staticshock added a comment.Jun 11 2015, 1:23 PM
$ php -r 'echo PHP_INT_MAX;'
2147483647

I'll hold off on the rest until the system is available for testing again.

epriestley added a comment.Jun 11 2015, 1:25 PM

Thanks! 99% sure that's the fix, then: you're on a 32-bit system and the 'int' type can't represent the 64-bit chronologicalKey.

epriestley renamed this task from Awarding a token breaks parts of conduit to Feed query may fail to progress while paging on 32-bit systems.Jun 11 2015, 4:43 PM
epriestley added a revision: D13250: Fix feed query cursor-based pagination on 32-bit systems.Jun 11 2015, 4:45 PM
epriestley added a comment.Jun 11 2015, 4:46 PM

Yell if that doesn't actually fix things once it lands, but I'm pretty confident it's the issue.

epriestley closed this task as Resolved by committing rPc71873ed7b31: Fix feed query cursor-based pagination on 32-bit systems.Jun 11 2015, 5:23 PM
epriestley added a commit: rPc71873ed7b31: Fix feed query cursor-based pagination on 32-bit systems.
staticshock added a comment.Jun 11 2015, 5:26 PM

Awesome! Yep, 'type' => 'string' fixed it.

Phabricator · Built by Phacility