Log4j 2
  1. Log4j 2
  2. LOG4J2-310

SMTPAppender does not send mails with error or fatal level without prior info event

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta7
    • Fix Version/s: 2.0-beta9
    • Component/s: Appenders, Filters
    • Labels:
      None
    • Environment:

      Description

      When using an SMTPAppender a mail is only delivered on a fatal event if there occured an info event before.
      Prior fatal events are ignored by SMTPAppender - other Appenders log them.

      A more detailed explanation/discussion including an example program can be found at:
      http://stackoverflow.com/questions/17657983/log4j2-smtpappender-does-not-send-mails-with-error-or-fatal-level

      1. log4j2-310.patch
        3 kB
        Olivier Lemasle

        Activity

        Hide
        Olivier Lemasle added a comment -

        Hi,

        I have found exactly the same bug (with Log4j2-beta8).

        I tried to track down the issue, and here is what I found.

        The issue is in org.apache.logging.log4j.core.net.SMTPManager, on lines 138-141:

        final LogEvent[] priorEvents = buffer.removeAll();
        if (priorEvents == null || priorEvents.length == 0) {
           return; // nothing to do, another thread already took all events
        }
        

        The "prior events" are first removed from the buffer. If the error event is the first event, there is nothing in this LogEvent array (no prior event), not even the current event (because events are added to the buffer only if they're filtered - see line 166 on org.apache.logging.log4j.core.appender.SMTPAppender).
        Then, the condition (priorEvents == null || priorEvents.length == 0) is true, and the mail is not sent.

        Show
        Olivier Lemasle added a comment - Hi, I have found exactly the same bug (with Log4j2-beta8). I tried to track down the issue, and here is what I found. The issue is in org.apache.logging.log4j.core.net.SMTPManager, on lines 138-141: final LogEvent[] priorEvents = buffer.removeAll(); if (priorEvents == null || priorEvents.length == 0) { return ; // nothing to do , another thread already took all events } The "prior events" are first removed from the buffer. If the error event is the first event, there is nothing in this LogEvent array (no prior event), not even the current event (because events are added to the buffer only if they're filtered - see line 166 on org.apache.logging.log4j.core.appender.SMTPAppender). Then, the condition (priorEvents == null || priorEvents.length == 0) is true, and the mail is not sent.
        Hide
        Olivier Lemasle added a comment -

        Hello,

        I've attached a very simple patch with unit test, which seems to fix the bug.

        But there was this comment "nothing to do, another thread already took all events" so I'm afraid I missed something... Could you please tell me if I can safely delete this condition?

        Thanks

        Show
        Olivier Lemasle added a comment - Hello, I've attached a very simple patch with unit test, which seems to fix the bug. But there was this comment "nothing to do, another thread already took all events" so I'm afraid I missed something... Could you please tell me if I can safely delete this condition? Thanks
        Hide
        Olivier Lemasle added a comment -

        Hi,

        Is it possible for a commiter to apply this patch? The SMTPAppender is currently not fully usable because of this bug.

        Thanks!

        Show
        Olivier Lemasle added a comment - Hi, Is it possible for a commiter to apply this patch? The SMTPAppender is currently not fully usable because of this bug. Thanks!
        Hide
        Remko Popma added a comment -

        The three lines you propose to remove were added to fix another problem.

        (committed in revision 1481278 2013/05/11 9:33)
        "check if LogEvents array removed from buffer is empty (may happen in concurrent scenarios) to avoid sending an empty email"

        Just removing those lines would revert back to the old problem.
        Unfortunately I cannot find the JIRA ticket for that issue and I cannot remember what that problem was exactly.

        Sorry this is not a complete answer...

        Show
        Remko Popma added a comment - The three lines you propose to remove were added to fix another problem. (committed in revision 1481278 2013/05/11 9:33) "check if LogEvents array removed from buffer is empty (may happen in concurrent scenarios) to avoid sending an empty email" Just removing those lines would revert back to the old problem. Unfortunately I cannot find the JIRA ticket for that issue and I cannot remember what that problem was exactly. Sorry this is not a complete answer...
        Hide
        Ralph Goers added a comment -

        I searched the mailing lists and don't really see anything that lines up. The only thing I see is LOG4J2-252 was created the day before this change was made. It is possible you made the change in response to that although it doesn't really address the problem reported there. In addition, that fix seems wrong as it means that events that should be logged won't be. Just because another thread has logged an error and published all the buffered events doesn't mean the current event should be ignored.

        Show
        Ralph Goers added a comment - I searched the mailing lists and don't really see anything that lines up. The only thing I see is LOG4J2-252 was created the day before this change was made. It is possible you made the change in response to that although it doesn't really address the problem reported there. In addition, that fix seems wrong as it means that events that should be logged won't be. Just because another thread has logged an error and published all the buffered events doesn't mean the current event should be ignored.
        Hide
        Olivier Lemasle added a comment -

        I see some concurrency considerations regarding the SMTPAppender in LOG4J2-149, but it was months before the addition of those three lines. After the fix to LOG4J2-149, it is stated that there is no more empty mails caused by multiple threads, so I cannot understand the issue fixed in May.

        Show
        Olivier Lemasle added a comment - I see some concurrency considerations regarding the SMTPAppender in LOG4J2-149 , but it was months before the addition of those three lines. After the fix to LOG4J2-149 , it is stated that there is no more empty mails caused by multiple threads, so I cannot understand the issue fixed in May.
        Hide
        Remko Popma added a comment -

        Well, you're both right. I obviously should have documented that change better...
        I guess the best way to move forward is to make the change Olivier is suggesting and if that causes any issue then deal with that separately.

        Show
        Remko Popma added a comment - Well, you're both right. I obviously should have documented that change better... I guess the best way to move forward is to make the change Olivier is suggesting and if that causes any issue then deal with that separately.
        Hide
        Remko Popma added a comment -

        Committed in revision 1518012.
        Please verify and close.

        Show
        Remko Popma added a comment - Committed in revision 1518012. Please verify and close.
        Hide
        Olivier Lemasle added a comment -

        For me, it's fixed, thanks. But I can not close the issue, as I'm not the reporter.

        Show
        Olivier Lemasle added a comment - For me, it's fixed, thanks. But I can not close the issue, as I'm not the reporter.
        Hide
        Matej Vitásek added a comment -

        Guys, is this going into beta9? Any ETA on it? Thanks!

        Show
        Matej Vitásek added a comment - Guys, is this going into beta9? Any ETA on it? Thanks!

          People

          • Assignee:
            Remko Popma
            Reporter:
            Jost Waldmann
          • Votes:
            1 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development