CODEWITHSUNDEEP
javalogbacksmtpappender
djechlin
djechlin

Reputation: 60768

logback SMTPAppender is duplicating pattern on different threads

I haven't been able to reproduce this quite consistently. I do suspect this is a bug in logback, but obviously that sounds unlikely and I will need a clean reproducible test case before I submit, so I'm asking SO in case anyone has seen similar behavior.

Essentially I have an SMTPAppender that looks like this:

<appender name="QA-SMTP"
    class="ch.qos.logback.classic.net.SMTPAppender">
            <!-- SMTP appends a default evaluator of on error, this is the simplest evaluator I found to implement -->
    <evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
        <marker>me.unroll.logging.loggers.InfoEmail.QA</marker>
    </evaluator>

    <smtpHost>smtp.gmail.com</smtpHost>
    <smtpPort>465</smtpPort>
    <SSL>true</SSL>
    <username>test</username>
    <password>test</password>
    <from>test</from>
    <to>test</to>
    <subject>%message</subject>
    <layout>
        <pattern>hello! thread: %thread</pattern>
    </layout>
</appender>

And am getting emails that look like this. This hasn't happened 1) if logger.error(...) is called on the main thread, or 2) when I just made a test pool and submitted on that, although it has often - but not consistently - happened in my actual production case where I discovered it (which is on a callback from MINA).

hello! thread: mainhello! thread: NioProcessor-2

Another case matched against another appender, omitted for brevity:

Action was taken was created for user / .

Created by machine: ip-10-212-90-140.ec2.internal Timestamp: February 19, 2013, 02:48:09.747 Logger source: me.unroll.logging.loggers.InfoEmail In application: Monitoring Client yahoo ============================Action was taken for user 12345 / [email protected]

Created by machine: ip-10-212-90-140.ec2.internal Timestamp: February 19, 2013, 15:24:06.016

The "user id / email" is taken from MDC - this is why I had the idea to explicitly print the thread. Essentially it looks like the same log event was created, one from the main thread (how on earth did logback manage to annex my main thread? dunno) and one from the actual thread in question.

Has anyone seen this behavior or know how to fix?

Upvotes: 4

Views: 481

Answers (1)

kan
kan

Reputation: 28951

Maybe I misunderstood your question, but as I see you are telling that logback sometimes sends two events in one email. It is by design, there is a bufferSize which allows to collect packs of events if they come very fast. There is a quote from the documentation:

The SMTPAppender accumulates logging events in one or more fixed-size buffers and sends the contents of the appropriate buffer in an email after a user-specified event occurs. SMTP email transmission (sending) is performed asynchronously. By default, the email transmission is triggered by a logging event of level ERROR.

You changed evaluator to the marker-based. It means previous events appended to the logger will sit in a buffer until a markered event will come.

Also pay attention how the evaluator triggers email transmission.

Thus, the number of logging events delivered in any e-mail sent by SMTPAppender is upper-bounded by 256.

If you want to have single event per email you should change the buffer size to 1. But I suspect it will throw away messages if they will come faster than emails could be send:

The SMTPAppender keeps only the last 256 logging events in its cyclic buffer, throwing away older events when its buffer becomes full.

But as I understand you could change asynchronousSending to false so it will block logging statements until message is sent.

Maybe you could just add "%n" at the end of the pattern so it will separate logging events by a new line, so it will be readable.

Disclaimer: I just was reading the documentation and never tried myself, so don't believe it, just do try this at home.

Upvotes: 1

Related Questions