Capture messenger exceptions

[emarref]

Errors that occur when handling Messenger messages asynchronously (e.g. background queue) are not captured or flushed to Sentry. This pull request addresses two issues;

Firstly, exceptions thrown during the execution of the Worker class are caught and logged, and therefore never captured by Sentry.

Secondly, captured messages are never flushed to Sentry unless the worker is configured to run with a limit (i.e. --time-limit=3600 or --limit=10).

When a handler fails when executed via the Worker, Messenger dispatches an event. This pull request listens for this WorkerMessageFailedEvent, and captures the exception, then flushes immediately.

Addresses #259 and #811.

[Jean85]

Thank you a lot for this PR! I surely will have to work a bit to make the CI work. Also, can you add a changelog entry?

I would love to also have an end2end test for this... But I'm not sure it's feasible; I would leave it to the end.

[Jean85]

One last small nitpick remains (plus fixing the CI), great job!

[Jean85]

Thanks you so much for your contribution! I've added some non-code commits, now it's ready to merge!

[rogamoore]

Thanks for this PR! :)
Is there an estimate when this will be released?

[Jean85]

I'm waiting for #322 to be merged before preparing the 3.5 release.

[B-Galati]

HandlerFailedException handles a collection of exceptions so getting only the previous may lose some information along the way.

[Jean85]

What's the use case there? What's the situation where the handler will report multiple exceptions?

[emarref]

https://github.com/symfony/messenger/blob/master/Middleware/HandleMessageMiddleware.php#L56-L69

Looks like when a command has multiple handlers, they will all run. Any throwable is caught and the next handler is continued.

So here, we should iterate over $error->getNestedExceptions() and capture them all.

[B-Galati]

Or just capture HandlerFailedException? Not sure about the pros and cons.

[Jean85]

Since HandlerFailedException is not naturally comprehensible to Sentry, capturing it isn't ideal, it shouldn't work out of the box: the event will not show enough information on the specific handlers nor the specific errors.

Just to be sure that I understood this correctly: multiple handlers will run together only if they are all sync and not async, right? If that's the case, at least it should be a non-so-common use case, so we don't have to rush the patch.

Opening #338 to track this issue.

[B-Galati]

Just to be sure that I understood this correctly: multiple handlers will run together only if they are all sync and not async, right?

No, I don't think so by reading the code and from what I understand about Messenger. Sync or Async does not matter. The only thing that matter is if there are multiple handlers for a Message or not.

[emarref]

Sync or Async does not matter. The only thing that matter is if there are multiple handlers for a Message or not.

Correct. Each handler for a command will be run either to completion or to an exception. Subsequent handlers will be executed and previous exceptions aggregated and added to the HandlerFailedException. So even if one handler succeeds, another handler may fail and raise the exception.

[Jean85]

Sorry, maybe I did not explain myself completely. For sync and async I was referring to the transport: if it's sync, the message is handled in the same request/process, and so it requires special handling on Sentry's side. If it's async, it should go through a queue (Rabbit? SQS?) so it will be executed inside a different process, and it's isolated as far as Sentry is concerned.

Does this still hold?

[emarref]

Yeah if a command has multiple handlers, sync or async won’t matter. The handle middleware will execute them all in the same process, catching and aggregating errors as they’re thrown, to be later raised in the handler failed exception.

[Jean85]

@emarref is the capture_soft_fails: false working for you? I just enabled it but I'm still receiving errors...

[emarref]

Yeah I've just confirmed it's working as expected for me. symfony/symfony:4.4.8, sentry/sentry-symfony:3.5.1, sentry/sdk:2.1.0.

[Jean85]

Ok great. I discovered that the issue is in the fact that willRetry stays false when you use the message:failed:retry command, even if it will be retried later.

[Jean85]

Oh crap, issue found: willRetry is populated in AFTER this listener runs, here: https://github.com/symfony/symfony/blob/5c056c18fc64d187c232ef0f0f0f7a2cc6da4d04/src/Symfony/Component/Messenger/EventListener/SendFailedMessageForRetryListener.php#L54-L58

$ bin/console debug:eve Symfony\\Component\\Messenger\\Event\\WorkerMessageFailedEvent

Registered Listeners for "Symfony\Component\Messenger\Event\WorkerMessageFailedEvent" Event
===========================================================================================

 ------- ---------------------------------------------------------------------------------------------------------- ---------- 
  Order   Callable                                                                                                   Priority  
 ------- ---------------------------------------------------------------------------------------------------------- ---------- 
  #1      Sentry\SentryBundle\EventListener\MessengerListener::onWorkerMessageFailed()                               128       
  #2      Symfony\Component\Messenger\EventListener\SendFailedMessageForRetryListener::onMessageFailed()             100       
  #3      Symfony\Component\Messenger\EventListener\SendFailedMessageToFailureTransportListener::onMessageFailed()   -100      
 ------- ---------------------------------------------------------------------------------------------------------- ---------- 

@emarref what do you get if you call bin/console debug:eve Symfony\\Component\\Messenger\\Event\\WorkerMessageFailedEvent? Did you customize the priority?

[Jean85]

I've opened #353 to dig further, it seems something changed between 4.3 and 4.4.

[emarref]

Did you customize the priority?

No I haven't.

what do you get if you call bin/console debug:eve Symfony\Component\Messenger\Event\WorkerMessageFailedEvent?

"Symfony\Component\Messenger\Event\WorkerMessageFailedEvent" event
------------------------------------------------------------------

 ------- ---------------------------------------------------------------------------------------------------------- ---------- 
  Order   Callable                                                                                                   Priority  
 ------- ---------------------------------------------------------------------------------------------------------- ---------- 
  #1      Sentry\SentryBundle\EventListener\MessengerListener::onWorkerMessageFailed()                               128       
  #2      Symfony\Component\Messenger\EventListener\SendFailedMessageForRetryListener::onMessageFailed()             100       
  #3      Symfony\Bridge\Doctrine\Messenger\DoctrineClearEntityManagerWorkerSubscriber::onWorkerMessageFailed()      0         
  #4      Symfony\Component\Messenger\EventListener\SendFailedMessageToFailureTransportListener::onMessageFailed()   -100      
 ------- ---------------------------------------------------------------------------------------------------------- ---------- 

I am definitely seeing the error thrown in my handler appearing multiple times in Sentry for a single run. But the listeners don't seem to be in the right order as you've shown. I will take a look when I get more time over the next few days.

Thanks for opening the PR.