monolog-bundle icon indicating copy to clipboard operation
monolog-bundle copied to clipboard

Existence of a custom log handler causes sending of extra email

Open pauljura opened this issue 4 years ago • 15 comments

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.

pauljura avatar Apr 14 '21 02:04 pauljura

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

# (...)

quentint avatar May 13 '21 20:05 quentint

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

virtualize avatar May 26 '21 08:05 virtualize

Still no solution?

AlexeyKosov avatar Feb 21 '22 19:02 AlexeyKosov

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

jonathantullett avatar Mar 07 '22 17:03 jonathantullett

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 avatar Mar 15 '22 15:03 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 avatar Mar 15 '22 15:03 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

raziel057 avatar Mar 16 '22 11:03 raziel057

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

YoukeZhang avatar Apr 07 '22 10:04 YoukeZhang

Same issue here

gponty avatar Apr 13 '22 09:04 gponty

same issue!

geoffroyp avatar Apr 27 '22 09:04 geoffroyp

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.

mpoiriert avatar Sep 25 '23 17:09 mpoiriert

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.

CITjakob avatar Oct 05 '23 15:10 CITjakob

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

gremo avatar Feb 13 '24 11:02 gremo