Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Too early resetting services in messenger #43114

Closed
upyx opened this issue Sep 20, 2021 · 0 comments · Fixed by #43133
Closed

Too early resetting services in messenger #43114

upyx opened this issue Sep 20, 2021 · 0 comments · Fixed by #43133

Comments

@upyx
Copy link
Contributor

upyx commented Sep 20, 2021

Symfony version(s) affected: 5.4.x

Description
I use a new feature added in #41163 with UidProcessor from Monolog. Recently I've realized the last INFO log from the messenger ("{class} was handled successfully (acknowledging to transport)") has a uid from the following message in a queue. It happens because that log message writes after the WorkerMessageHandledEvent that triggers resetting. It sounds silly, but I've spent hours trying to understand why a wrong message has a positive acknowledgment.

How to reproduce
Register service:

services:
    Monolog\Processor\UidProcessor:
        tags: [ 'monolog.processor' ]

Configure messenger:

framework:
    messenger:
        transports:
            async:
                dsn: '%env(MESSENGER_TRANSPORT_DSN)%'
                reset_on_message: true
        routing:
            App\Message: async

Consume some message:

bin/console messenger:consume async -vv

Example output:

19:50:03 INFO [messenger] Received message App\Message ["class" => "App\Message"] ["uid" => "4f9fa66"]
19:50:03 INFO [messenger] Message App\Message handled by App\Handler::__invoke ["class" => "App\Message","handler" => "App\Handler::__invoke"] ["uid" => "4f9fa66"]
19:50:03 INFO [messenger] App\Message was handled successfully (acknowledging to transport). ["class" => "App\Message"] ["uid" => "17280ae"]
19:50:04 INFO [messenger] Received message App\Message ["class" => "App\Message"] ["uid" => "17280ae"]
19:50:04 INFO [messenger] Message App\Message handled by App\Handler::__invoke ["class" => "App\Message","handler" => "App\Handler::__invoke"] ["uid" => "17280ae"]
19:50:04 INFO [messenger] App\Message was handled successfully (acknowledging to transport). ["class" => "App\Message"] ["uid" => "b3d9ee5"]

Possible Solution
I think the service resetting should be the last thing in a handling loop: after logging, after acknowledging. The actual event for that is WorkerRunningEvent. The event doesn't have a transport name, but it's trivial to fix. Nevertheless, I have doubts about all of this.

@upyx upyx added the Bug label Sep 20, 2021
@fabpot fabpot closed this as completed Sep 27, 2021
fabpot added a commit that referenced this issue Sep 27, 2021
…ledging (upyx)

This PR was merged into the 5.4 branch.

Discussion
----------

[Messenger] Move container resetting after receiver acknowledging

| Q             | A
| ------------- | ---
| Branch?       | 5.4
| Bug fix?      | yes
| New feature?  | no
| Deprecations? | no
| Tickets       | Fix #43114
| License       | MIT
| Doc PR        | nope

It fixes the #43114 issue and similar potential bugs. The `ResetServicesListener` lean on events sequence: the `AbstractWorkerMessageEvent` to save the actual receiver name, then the `WorkerRunningEvent` to check that name and reset the container. It may look fragile, so let's discuss it in the issue.

Commits
-------

fc85aef [Messenger] Move container resetting after receiver acknowledging (in command)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants