Error viewing notifications

Reproduction Instructions
We see the same issue as described in link when we try to open past notifications. We applied the patch in D21577 to fix this issue. That works well. And so we planned to update from 2021 Week 9 (Very Late February) to 2021 Week 10 (Early March) as it contains this fix but after the updated, we can’t open notifications at all. When I open https://phabricator.example.com/notification/, it throws this error:

exception

I catched the PHP error:

==> /var/log/apache2/phabricator.error.log <==
[Mon Mar 08 18:28:03.046431 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672] [2021-03-08 19:28:03] EXCEPTION: (RuntimeException) Undefined offset: 6937306324749153720 at [<arcanist>/src/error/PhutilErrorHandler.php:257]
[Mon Mar 08 18:28:03.047218 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672] arcanist(head=stable, ref.stable=2d6452acb5f1), phabricator(head=stable, ref.stable=bfe7cdc5a2af)
[Mon Mar 08 18:28:03.047255 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #0 <#2> PhutilErrorHandler::handleError(integer, string, string, integer, array) called at [<phabricator>/src/applications/notification/query/PhabricatorNotificationQuery.php:80]
[Mon Mar 08 18:28:03.047273 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #1 <#2> PhabricatorNotificationQuery::loadPage() called at [<phabricator>/src/infrastructure/query/policy/PhabricatorPolicyAwareQuery.php:251]
[Mon Mar 08 18:28:03.047279 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #2 <#2> PhabricatorPolicyAwareQuery::execute() called at [<phabricator>/src/infrastructure/query/policy/PhabricatorCursorPagedPolicyAwareQuery.php:379]
[Mon Mar 08 18:28:03.047285 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #3 <#2> PhabricatorCursorPagedPolicyAwareQuery::executeWithCursorPager(AphrontCursorPagerView) called at [<phabricator>/src/applications/search/engine/PhabricatorApplicationSearchEngine.php:1038]
[Mon Mar 08 18:28:03.047291 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #4 <#2> PhabricatorApplicationSearchEngine::executeQuery(PhabricatorNotificationQuery, AphrontCursorPagerView) called at [<phabricator>/src/applications/search/controller/PhabricatorApplicationSearchController.php:256]
[Mon Mar 08 18:28:03.047298 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #5 <#2> PhabricatorApplicationSearchController::processSearchRequest() called at [<phabricator>/src/applications/search/controller/PhabricatorApplicationSearchController.php:91]
[Mon Mar 08 18:28:03.047304 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #6 <#2> PhabricatorApplicationSearchController::processRequest() called at [<phabricator>/src/aphront/AphrontController.php:29]
[Mon Mar 08 18:28:03.047310 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #7 <#2> AphrontController::handleRequest(AphrontRequest) called at [<phabricator>/src/aphront/AphrontController.php:71]
[Mon Mar 08 18:28:03.047347 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #8 <#2> AphrontController::delegateToController(PhabricatorApplicationSearchController) called at [<phabricator>/src/applications/notification/controller/PhabricatorNotificationListController.php:14]
[Mon Mar 08 18:28:03.047358 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #9 <#2> PhabricatorNotificationListController::handleRequest(AphrontRequest) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:288]
[Mon Mar 08 18:28:03.047365 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #10 phlog(RuntimeException) called at [<phabricator>/src/aphront/handler/PhabricatorDefaultRequestExceptionHandler.php:41]
[Mon Mar 08 18:28:03.047371 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #11 PhabricatorDefaultRequestExceptionHandler::handleRequestThrowable(AphrontRequest, RuntimeException) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:752]
[Mon Mar 08 18:28:03.047377 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #12 AphrontApplicationConfiguration::handleThrowable(RuntimeException) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:300]
[Mon Mar 08 18:28:03.047498 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #13 AphrontApplicationConfiguration::processRequest(AphrontRequest, PhutilDeferredLog, AphrontPHPHTTPSink, MultimeterControl) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:208]
[Mon Mar 08 18:28:03.047507 2021] [php7:notice] [pid 13551] [client 2001:DB8:::45672]   #14 AphrontApplicationConfiguration::runHTTPRequest(AphrontPHPHTTPSink) called at [<phabricator>/webroot/index.php:35]

==> /var/log/apache2/phabricator.access.log <==
2001:DB8:: - - [08/Mar/2021:18:28:02 +0000] "GET /notification/ HTTP/1.1" 500 6275 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.72 Safari/537.36"

and I also catched the related SQL query where you can notice the value 6937306324749153720 in the second row in the chronologicalKey column that appeared in the error message above (the full output is on pastebin.com):

MariaDB [(none)]> SELECT story.*, notification.hasViewed FROM `phabricator_feed`.`feed_storynotification` notification
    ->          JOIN `phabricator_feed`.`feed_storydata` story ON notification.chronologicalKey = story.chronologicalKey
    ->          WHERE (notification.userPHID IN ('PHID-USER-xxxxxxxxxxxxxxxit5dh'))
    ->          ORDER BY notification.chronologicalKey DESC
    ->          LIMIT 101
    -> ;
+---------+--------------------------------+---------------------+--------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+-------------+--------------+-----------+
| id      | phid                           | chronologicalKey    | storyType                                  | storyData                                                                                                                                                                                                                                                                  | authorPHID                                   | dateCreated | dateModified | hasViewed |
+---------+--------------------------------+---------------------+--------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+-------------+--------------+-----------+
| 1539512 | PHID-STRY-xxxxxxxxxxxxxxxfrw2w | 6937306337556198553 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxht72r","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxx2hdcr":"PHID-XACT-DREV-xxxxxxxxxxxxxxx2hdcr"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxxyrikz               |  1615217499 |   1615217499 |         1 |
| 1539510 | PHID-STRY-xxxxxxxxxxxxxxxmxyd3 | 6937306324749153720 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxoxu66","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxxijddl":"PHID-XACT-DREV-xxxxxxxxxxxxxxxijddl"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxx6avgs               |  1615217496 |   1615217496 |         1 |
| 1539511 | PHID-STRY-xxxxxxxxxxxxxxxresmz | 6937306322192316885 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxuf2jg","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxxid3a3":"PHID-XACT-DREV-xxxxxxxxxxxxxxxid3a3"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxx6avgs               |  1615217496 |   1615217496 |         1 |
| 1539509 | PHID-STRY-xxxxxxxxxxxxxxxsutlx | 6937306319423559849 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxddqvx","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxxa7l75":"PHID-XACT-DREV-xxxxxxxxxxxxxxxa7l75"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxxxuxbn               |  1615217495 |   1615217495 |         1 |
| 1539508 | PHID-STRY-xxxxxxxxxxxxxxxjpsny | 6937306315179243931 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxm5ve3","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxxzyrbm":"PHID-XACT-DREV-xxxxxxxxxxxxxxxzyrbm"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxxm35wo               |  1615217494 |   1615217494 |         1 |
| 1539507 | PHID-STRY-xxxxxxxxxxxxxxxb74cc | 6937306312757923558 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxlkgo7","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxxv3tr4":"PHID-XACT-DREV-xxxxxxxxxxxxxxxv3tr4"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxx5hdih               |  1615217494 |   1615217494 |         1 |
| 1539506 | PHID-STRY-xxxxxxxxxxxxxxxdozjx | 6937306305832336561 | PhabricatorApplicationTransactionFeedStory | {"objectPHID":"PHID-DREV-xxxxxxxxxxxxxxxetead","transactionPHIDs":{"PHID-XACT-DREV-xxxxxxxxxxxxxxx67pbh":"PHID-XACT-DREV-xxxxxxxxxxxxxxx67pbh"}}                                                                                                                                     | PHID-USER-xxxxxxxxxxxxxxxksyls               |  1615217492 |   1615217492 |         1 |
***output ommited***
+---------+--------------------------------+---------------------+--------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+-------------+--------------+-----------+
101 rows in set (0.01 sec)

Phabricator/Arcanist Version
I updated Phabricator from the previous stable release 2021 Week 9 (Very Late February) to the latest 2021 Week 10 (Early March). I updated both arcanist and phabricator:

  • arcanist: from b177e489b4c8a to e745e770fe6b
  • phabricator: from 5c8f0362f8f9 to e7a40f84697

I tried to reproduce this issue on a fresh instance with generating multiple notifications that are sent to multiple users but unsuccessfully. It’s probably related to our current data. We run Phabricator for years already. I can provide you more information if needed.

Thank you for your time!

Thanks. I think this should be fixed by https://secure.phabricator.com/D21603, now in master.

I believe the reproduction case requires you to have a notification about an object you can no longer see. For example:

  • Create a task.
  • Add Alice as a subscriber, generating a notification for her.
  • Prevent Alice from seeing the task: change the “View Policy”; or “bin/remove destroy” the task.
  • As Alice, load notifications.

Hi @epriestley, thanks for update.

I tried to apply the fix from ⚙ D21603 Fix an error when users receive notifications about objects they can no longer see but I’m getting another error when I try to load notifications.

image

[Fri Mar 12 11:25:52.409445 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508] [2021-03-12 12:25:52] EXCEPTION: (Error) Call to a member function getChronologicalKey() on array at [<phabricator>/src/applications/notification/query/PhabricatorNotificationQuery.php:184]
[Fri Mar 12 11:25:52.410564 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508] arcanist(head=stable, ref.stable=2d6452acb5f1), phabricator(head=stable, ref.stable=bfe7cdc5a2af)
[Fri Mar 12 11:25:52.410616 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508]   #0 phlog(Error) called at [<phabricator>/src/aphront/handler/PhabricatorDefaultRequestExceptionHandler.php:41]
[Fri Mar 12 11:25:52.410631 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508]   #1 PhabricatorDefaultRequestExceptionHandler::handleRequestThrowable(AphrontRequest, Error) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:752]
[Fri Mar 12 11:25:52.410639 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508]   #2 AphrontApplicationConfiguration::handleThrowable(Error) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:300]
[Fri Mar 12 11:25:52.410645 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508]   #3 AphrontApplicationConfiguration::processRequest(AphrontRequest, PhutilDeferredLog, AphrontPHPHTTPSink, MultimeterControl) called at [<phabricator>/src/aphront/configuration/AphrontApplicationConfiguration.php:208]
[Fri Mar 12 11:25:52.410652 2021] [php7:notice] [pid 22971] [client 2001:db8::::43508]   #4 AphrontApplicationConfiguration::runHTTPRequest(AphrontPHPHTTPSink) called at [<phabricator>/webroot/index.php:35]

Could you please take a look on that?

Oops, sorry! This issue should be fixed by https://secure.phabricator.com/D21609, now in master.

Great, I can open notifications with this fix, but the next button at the bottom of the notification page disappeared so I can go through the past notifications. This is the button what I mean:

image

Do I need to apply more changes from master or what could cause it?

I can’t reproduce that.

Note that notifications are garbage collected (by default, after 90 days), so it’s normal to not have a “Next” button if you have 100 or fewer notifications from the last 90 days.

That’s weird. I updated to the latest stable release 2021 Week 11 (Mid March) but still no “Next” button. I see the last notification from Fri, Feb 26, 11:13 AM and there must be some older for sure that hasn’t been cleaned yet.

I looked for the chronologicalKey field of the last notification on /notification/ page at Fri, Feb 26, 11:13 AM and tried to query later notifications by going to /notification/?after=6939235197221546263. I see the same list of notifications where the first one is missing and as the last one is one more older notification at Fri, Feb 26, 11:12 AM (created a minute before the last notification on /notification/). These navigation buttons appeared on this page:

image

But still I can’t go to older notifications. So I looked for the chronologicalKey of notification that just appeared on /notification/?after=6939235197221546263 and again manually tried to looked for older notifications by going to /notification/?after=6933513254410079379.

And voila, navigation buttons are back, I can see older notifications properly until I click on the |<< First button of couse what directs me to /notification/ where are no navigation buttons. So there is something wrong with one notification that somehow breaks it.


By the way, I noticed that notifications are probably not cleared at all. The oldest notification in the database is from 2015. How the cleaning of old notifications can be configured? I would to check it.

MariaDB [(none)]> select dateCreated, DATE_FORMAT(FROM_UNIXTIME(`dateCreated`), '%Y %D %M %H:%i:%s') AS 'dateCreated_formatted' from phabricator_feed.feed_storydata limit 1;
+-------------+--------------------------+
| dateCreated | dateCreated_formatted    |
+-------------+--------------------------+
|  1429527025 | 2015 20th April 10:50:25 |
+-------------+--------------------------+
1 row in set (0.00 sec)