Existence of a custom log handler causes sending of extra email

[pauljura]

I am following instructions here https://symfony.com/doc/current/logging/monolog_email.html to email critical errors.

This by itself works just fine.

But when I add a custom log handler, any error that triggers the mailer will cause a second email to be delivered as well. This second email has 2 messages in it:

1. DEBUG Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" stopping
2. DEBUG Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" stopped

The custom log handler is defined at the bottom of my monolog.yaml file like so :

        new_relic_notifier:
            level: critical
            type: service
            id: Shared\Symfony\LogHandler\NewRelicNotifier

It extends from AbstractProcessingHandler. The exact details of the custom error handler are not important. It has nothing to do with the mailer. I could define it with an empty write() method that does nothing. I'm actually using multiple custom log handlers, but the bug occurs if any one of them are registered.

If I remove the custom handler, an error will trigger one email as expected. If one or more custom handlers exist, I get 2 emails.

This only started happening for me since Symfony 5.2.6, previously I was on 5.2.3 and it worked as expected.

[quentint]

Experiencing the same issue.
Here's my Monolog configuration (no custom handler in my case):

# config/packages/prod/monolog.yaml
monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
            handler:      grouped
            excluded_http_codes: [404, 405]
        grouped:
            type:    group
            members: [streamed, deduplicated]
        streamed:
            type:  stream
            path:  '%kernel.logs_dir%/%kernel.environment%.log'
            level: debug
        deduplicated:
            type:    deduplication
            handler: symfony_mailer
        symfony_mailer:
            type:         symfony_mailer
            from_email:   '[email protected]'
            to_email:     '[email protected]'
            subject:      '🐾 %%message%%'
            level:        debug
            formatter:    monolog.formatter.html
            content_type: text/html
        console:
            type: console
            process_psr_3_messages: false
            channels: [ "!event", "!doctrine" ]
        deprecation_filter:
            type: filter
            handler: deprecation
            max_level: info
            channels: [ "php" ]
        deprecation:
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%.deprecations.log"

And:

# config/packages/sentry.yaml

# (...)

monolog:
    handlers:
        sentry:
            type: sentry
            level: !php/const Monolog\Logger::ERROR
            hub_id: Sentry\State\HubInterface

# (...)

[virtualize]

The extra mail with this content is even sent if you apply the default configuration from the docs to a newly created symfony demo (symfony new --demo) in production mode.

# config/packages/prod/monolog.yaml
monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: critical
            handler:      deduplicated
        deduplicated:
            type:    deduplication
            handler: symfony_mailer
        symfony_mailer:
            type:       symfony_mailer
            from_email: '[email protected]'
            to_email:   '[email protected]'
            subject:    'An Error Occurred! %%message%%'
            level:      debug

First mail contains the error message as usual, the second mail contains only this:

[2021-05-26T10:49:47.683298+02:00] app.DEBUG: Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" stopping [] []
[2021-05-26T10:49:47.722980+02:00] app.DEBUG: Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" stopped [] []

Tried Symfony Versions 5.2.1 / 5.2.9 / 5.3.0-RC1, running PHP 7.4.13

EDIT: I've created a corresponding Stackoverflow question
https://stackoverflow.com/questions/67702288/monolog-send-error-logs-by-mail-causes-an-extra-mail-for-every-error-sent

[AlexeyKosov]

Still no solution?

[jonathantullett]

I still see this happening for the latest and greatest, and causes double the noise/traffic when these alerts fire.

[raziel057]

I also encounter the exact same issue using Symfony 5.4.6, running on PHP 8.0.x.
I don't have the issue using SwiftMailer rather than Symfony Mailer.

[raziel057]

The issue comes from the debug log used in stop method.

https://github.com/symfony/symfony/blob/6.1/src/Symfony/Component/Mailer/Transport/Smtp/SmtpTransport.php

As this log is generated after sending of first email containig the stack trace, a second email is sent.

[raziel057]

Please note that with same config in "dev" env, I receive only one email, which is not the case in "prod" env.

As a workaround I exclude the "mailer" channel:

monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: critical
            handler:      grouped
            channels:     ["!mailer"]
        grouped:
            type:    group
            members: [streamed, deduplicated]
        streamed:
            type:  stream
            path:  "%kernel.logs_dir%/%kernel.environment%.log"
            level: debug
        deduplicated:
            type:    deduplication
            handler: symfony_mailer
        symfony_mailer:
            type:       symfony_mailer
            from_email: "%mailer_app_sender%"
            to_email:   "%mailer_team_receiver%"
            subject:    "An Error Occurred!"
            level:      debug

[YoukeZhang]

If the error occurred in Command or email send async, the extra email is not sent.
https://symfony.com/doc/current/mailer.html#sending-messages-async

[gponty]

Same issue here

[geoffroyp]

same issue!

[mpoiriert]

Workaround doesn't work for me because I am doing a query to the database in the email sending flow.

So I am getting this line:

{"message":"Disconnecting","context":{},"level":200,"level_name":"INFO","channel":"doctrine","datetime":"2023-09-25T16:37:22.465597+00:00","extra":{"token":null,"delay":"0.20","uid":"55a1d86","memory_usage":"24 MB","memory_peak_usage":"28.58 MB"}}

I cannot ignore the "doctrine" channel since error can come from there.

[CITjakob]

I have the same issue even without a custom log handler. For some reason the workaround
channels: ["!mailer"]
does not work for me. I still get two emails, one of them clearly from the mailer channel.

[gremo]

Same problem here, workaround not working... any update?

[n-valverde]

Hey there, as a workaround try setting stop_buffering: false to your fingers_crossed handler definition. By default, fingers_crossed turns into a stream handler once action_level has been reached. Since the SmtpTransport is generating additional log records below activation_level, keeping the buffer on should prevent those additional records to reach the handler unless they reach activation_level again. That's not ideal but should work.

[Seldaek]

Yes IMO stop_buffering:false is good, or alternatively you can add a buffering handler before the mailer, so that the mailer handler receives all the log entries at the end of the request when the buffer handler flushes.