Page MenuHomeDevCentral

500 error when Phabricator sends a payload to the notifications center
Closed, ResolvedPublic

Description

Usually, when Phabricator posts a story to the notifications center, it gets a 500 HTTP response.
Sometimes, the payload is OK, like a task close.

Notifications Center log
[2022-04-20 15:20:44] production.INFO: [Gate] New payload. {"service":"Phabricator","door":"Nasqueron"}

That's the correct service and door information.

Notifications center stacktrace

2023-01-10 01:57:02] production.ERROR: RuntimeException: Can't reach Phabricator API endpoint: https://devcentral.nasqueron.org/api/maniphest.query in /var/wwwroot/default/app/Phabricator/PhabricatorAPI.php:157
Stack trace:
#0 /var/wwwroot/default/app/Phabricator/PhabricatorAPI.php(98): Nasqueron\Notifications\Phabricator\PhabricatorAPI::post('https://devcent...', Array)
#1 /var/wwwroot/default/app/Phabricator/PhabricatorStory.php(231): Nasqueron\Notifications\Phabricator\PhabricatorAPI->call('maniphest.query', Array)
#2 /var/wwwroot/default/app/Phabricator/PhabricatorStory.php(164): Nasqueron\Notifications\Phabricator\PhabricatorStory->getItemProjectsPHIDs('maniphest.query', 'PHID-TASK-5kfir...')
#3 /var/wwwroot/default/app/Phabricator/PhabricatorStory.php(296): Nasqueron\Notifications\Phabricator\PhabricatorStory->getProjectsPHIDs()
#4 /var/wwwroot/default/app/Phabricator/PhabricatorStory.php(284): Nasqueron\Notifications\Phabricator\PhabricatorStory->attachProjects()
#5 /var/wwwroot/default/app/Analyzers/Phabricator/PhabricatorPayloadAnalyzer.php(56): Nasqueron\Notifications\Phabricator\PhabricatorStory->getProjects()
#6 /var/wwwroot/default/app/Notifications/PhabricatorNotification.php(55): Nasqueron\Notifications\Analyzers\Phabricator\PhabricatorPayloadAnalyzer->getGroup()
#7 /var/wwwroot/default/app/Notifications/PhabricatorNotification.php(30): Nasqueron\Notifications\Notifications\PhabricatorNotification->getGroup()
#8 /var/wwwroot/default/app/Jobs/FirePhabricatorNotification.php(43): Nasqueron\Notifications\Notifications\PhabricatorNotification->__construct('Nasqueron', Object(Nasqueron\Notifications\Phabricator\PhabricatorStory))
#9 /var/wwwroot/default/app/Jobs/FirePhabricatorNotification.php(36): Nasqueron\Notifications\Jobs\FirePhabricatorNotification->createNotification()
#10 /var/wwwroot/default/app/Listeners/NotificationListener.php(52): Nasqueron\Notifications\Jobs\FirePhabricatorNotification->handle()
#11 [internal function]: Nasqueron\Notifications\Listeners\NotificationListener->onPhabricatorPayload(Object(Nasqueron\Notifications\Events\PhabricatorPayloadEvent))
#12 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(354): call_user_func_array(Array, Array)
#13 [internal function]: Illuminate\Events\Dispatcher->Illuminate\Events\{closure}(Object(Nasqueron\Notifications\Events\PhabricatorPayloadEvent))
#14 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(221): call_user_func_array(Object(Closure), Array)
#15 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php(237): Illuminate\Events\Dispatcher->fire('Nasqueron\\Notif...')
#16 /var/wwwroot/default/app/Http/Controllers/Gate/PhabricatorGateController.php(70): Illuminate\Support\Facades\Facade::__callStatic('fire', Array)
#17 /var/wwwroot/default/app/Http/Controllers/Gate/PhabricatorGateController.php(45): Nasqueron\Notifications\Http\Controllers\Gate\PhabricatorGateController->onPayload()
#18 [internal function]: Nasqueron\Notifications\Http\Controllers\Gate\PhabricatorGateController->onPost('Nasqueron')
#19 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Controller.php(55): call_user_func_array(Array, Array)
#20 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/ControllerDispatcher.php(44): Illuminate\Routing\Controller->callAction('onPost', Array)
#21 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Route.php(189): Illuminate\Routing\ControllerDispatcher->dispatch(Object(Illuminate\Routing\Route), Object(Nasqueron\Notifications\Http\Controllers\Gate\PhabricatorGateController), 'onPost')
#22 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Route.php(144): Illuminate\Routing\Route->runController()
#23 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Router.php(653): Illuminate\Routing\Route->run(Object(Illuminate\Http\Request))
#24 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Routing\Router->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#25 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(104): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#26 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Router.php(655): Illuminate\Pipeline\Pipeline->then(Object(Closure))
#27 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Router.php(629): Illuminate\Routing\Router->runRouteWithinStack(Object(Illuminate\Routing\Route), Object(Illuminate\Http\Request))
#28 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Router.php(607): Illuminate\Routing\Router->dispatchToRoute(Object(Illuminate\Http\Request))
#29 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Foundation/Http/Kernel.php(268): Illuminate\Routing\Router->dispatch(Object(Illuminate\Http\Request))
#30 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Foundation\Http\Kernel->Illuminate\Foundation\Http\{closure}(Object(Illuminate\Http\Request))
#31 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Foundation/Http/Middleware/CheckForMaintenanceMode.php(46): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#32 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(137): Illuminate\Foundation\Http\Middleware\CheckForMaintenanceMode->handle(Object(Illuminate\Http\Request), Object(Closure))
#33 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(33): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#34 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(104): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#35 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Foundation/Http/Kernel.php(150): Illuminate\Pipeline\Pipeline->then(Object(Closure))
#36 /var/wwwroot/default/vendor/laravel/framework/src/Illuminate/Foundation/Http/Kernel.php(117): Illuminate\Foundation\Http\Kernel->sendRequestThroughRouter(Object(Illuminate\Http\Request))
#37 /var/wwwroot/default/public/index.php(53): Illuminate\Foundation\Http\Kernel->handle(Object(Illuminate\Http\Request))
#38 {main}

Phabricator daemon log stacktrace

The stacktrace confirms a 500 error occurs at Notifications Center and it's triggered by the expected FeedPublisherHTTPWorker class.

[20-Apr-2022 15:20:44 UTC] [2022-04-20 15:20:44] EXCEPTION: (PhutilProxyException) Error while executing Task ID 1564849.
{>} (HTTPFutureHTTPResponseStatus) [HTTP/500] Internal Server Error at [<arcanist>/src/future/http/BaseHTTPFuture.php:384]
[20-Apr-2022 15:20:44 UTC] arcanist(head=master, ref.master=b50a646a3f49), phabricator(head=production, ref.production=110c5657e272)
[20-Apr-2022 15:20:44 UTC]   #0 <#2> BaseHTTPFuture::parseRawHTTPResponse(string) called at [<arcanist>/src/future/http/HTTPSFuture.php:545]                
[20-Apr-2022 15:20:44 UTC]   #1 <#2> HTTPSFuture::isReady() called at [<arcanist>/src/future/Future.php:63]
[20-Apr-2022 15:20:44 UTC]   #2 <#2> Future::updateFuture() called at [<arcanist>/src/future/FutureIterator.php:224]
[20-Apr-2022 15:20:44 UTC]   #3 <#2> FutureIterator::next() called at [<arcanist>/src/future/FutureIterator.php:190]
[20-Apr-2022 15:20:44 UTC]   #4 <#2> FutureIterator::rewind()
[20-Apr-2022 15:20:44 UTC]   #5 <#2> iterator_to_array(FutureIterator) called at [<arcanist>/src/future/FutureIterator.php:84]                                                                                                                [20-Apr-2022 15:20:44 UTC]   #6 <#2> FutureIterator::resolveAll() called at [<arcanist>/src/future/Future.php:47]
[20-Apr-2022 15:20:44 UTC]   #7 <#2> Future::resolve() called at [<arcanist>/src/future/http/BaseHTTPFuture.php:302]
[20-Apr-2022 15:20:44 UTC]   #8 <#2> BaseHTTPFuture::resolvex() called at [<phabricator>/src/applications/feed/worker/FeedPublisherHTTPWorker.php:37]
[20-Apr-2022 15:20:44 UTC]   #9 <#2> FeedPublisherHTTPWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:124]
[20-Apr-2022 15:20:44 UTC]   #10 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:160]
[20-Apr-2022 15:20:44 UTC]   #11 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]                                                               
[20-Apr-2022 15:20:44 UTC]   #12 PhabricatorTaskmasterDaemon::run() called at [<phabricator>/src/infrastructure/daemon/PhutilDaemon.php:219]

Example of payload correctly processed

{
  "storyID": "25897",
  "storyType": "PhabricatorApplicationTransactionFeedStory",
  "storyData": {
    "objectPHID": "PHID-DREV-sazqrae6zislmsictvw2",
    "transactionPHIDs": {
      "PHID-XACT-DREV-lormfebwbs4qghl": "PHID-XACT-DREV-lormfebwbs4qghl"
    }
  },
  "storyAuthorPHID": "PHID-USER-fnetlprx7zdotfm2hdrz",
  "storyText": "dereckson added a comment to D2675: Use correct class and filename for RouteServiceProviderTest.",
  "epoch": "1650467490"
}

Other correct payload should exists, as we got "null" debug information on Wearg when a payload doesn't have a value associated with the storyText field.

Event Timeline

dereckson added a project: User-Dereckson.
dereckson moved this task from Backlog to Bugs on the Notifications center board.
dereckson moved this task from Backlog to Next on the User-Dereckson board.
dereckson moved this task from Backlog to Config on the DevCentral board.

I'm not sure can still a reliable way create a map between project PHID and name. That should be the first thing to investigate.

For example, php artisan phabricator:projectsmap is suspiciously instantaneous.

Disabled Sentry, so we can have a correct log of the stacktrace, and updated description accordingly.

https://devcentral.nasqueron.org/api/maniphest.query can't be reached:

$ curl https://devcentral.nasqueron.org/api/maniphest.query
curl: (60) SSL certificate problem: certificate has expired
More details here: http://curl.haxx.se/docs/sslcerts.html

curl performs SSL certificate verification by default, using a "bundle"
 of Certificate Authority (CA) public keys (CA certs). If the default
 bundle file isn't adequate, you can specify an alternate file
 using the --cacert option.
If this HTTPS server uses a certificate signed by a CA represented in
 the bundle, the certificate verification probably failed due to a
 problem with the certificate (it might be expired, or the name might
 not match the domain name in the URL).
If you'd like to turn off curl's verification of the certificate, use
 the -k (or --insecure) option.

A side issue is maniphest.query has been deprecated in favour of maniphest.search, so it's a candidate for update.

Container still runs on Jessie, we need to deploy new @DorianWinty work on recent Debian PHP 8 container, with correct certificates.

dereckson claimed this task.

I've regenerated /usr/share/ca-certificates and /etc/ssl/certs based on a "recent" Debian ca-certificates package against Debian Sid, version 20211016. Works like a charm now.