Log4j 2
  1. Log4j 2
  2. LOG4J2-149

SMTPManager buffer access not synchronized; can result in empty emails

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta4
    • Fix Version/s: 2.0-beta4
    • Component/s: Appenders
    • Labels:
      None
    • Environment:

      N/A

      Description

      If multiple error events are logged against the same SMTPAppender/Manager at the same time, one email will contain both error messages, while the second will be empty (no events).

      The original SMTPAppender patch included synchronization against the CyclicBuffer to prevent such simultaneous access from multiple threads. This appears to have been lost in the merge/refactor. Patch (to follow shortly) re-introduces synchronization against the CyclicBuffer in the narrowest possible scope.

        Activity

        Hide
        Scott Severtson added a comment -

        We can confirm that at least one log message appears in every email.

        Show
        Scott Severtson added a comment - We can confirm that at least one log message appears in every email.
        Hide
        Ralph Goers added a comment -

        Patch applied. Please verify and close.

        Show
        Ralph Goers added a comment - Patch applied. Please verify and close.
        Hide
        Ralph Goers added a comment -

        My fault. I hadn't done the svn up to pick up Gary's changes.

        Show
        Ralph Goers added a comment - My fault. I hadn't done the svn up to pick up Gary's changes.
        Hide
        Scott Severtson added a comment -

        Maybe. I just checked out a clean copy of log4j2 trunk, and the patch applied cleanly for me.

        Show
        Scott Severtson added a comment - Maybe. I just checked out a clean copy of log4j2 trunk, and the patch applied cleanly for me.
        Hide
        Gary Gregory added a comment -

        FWIW: The version of SMTPManager on my machine is 1433252.

        Could this be a sync issue between the EU and US version of the repo?

        Gary

        Show
        Gary Gregory added a comment - FWIW: The version of SMTPManager on my machine is 1433252. Could this be a sync issue between the EU and US version of the repo? Gary
        Hide
        Scott Severtson added a comment -

        The patch was generated against SVN revision #1433251, and "svn update" found no additional changes beyond that. I compared the previously attached patch with a regenerated patch, and there were no differences. Not sure what you're seeing?

        Show
        Scott Severtson added a comment - The patch was generated against SVN revision #1433251, and "svn update" found no additional changes beyond that. I compared the previously attached patch with a regenerated patch, and there were no differences. Not sure what you're seeing?
        Hide
        Ralph Goers added a comment -

        Your patch looks correct but it looks like Gary made some updates to the file and your patch won't apply. Can you please update to the latest source and regenerate the patch?

        Show
        Ralph Goers added a comment - Your patch looks correct but it looks like Gary made some updates to the file and your patch won't apply. Can you please update to the latest source and regenerate the patch?
        Hide
        Scott Severtson added a comment -

        The only downside with that approach is that the message can contain CyclicBuffer.ring.length + 1 messages (i.e. one more than the configured buffer size). However, that's the approach I ended up settling on as well. Patch above.

        Show
        Scott Severtson added a comment - The only downside with that approach is that the message can contain CyclicBuffer.ring.length + 1 messages (i.e. one more than the configured buffer size). However, that's the approach I ended up settling on as well. Patch above.
        Hide
        Scott Severtson added a comment -

        Patch to always log the triggering event.

        Show
        Scott Severtson added a comment - Patch to always log the triggering event.
        Hide
        Ralph Goers added a comment -

        I had already started making the changes for approach # 2 this morning but $work got in the way. I'm headed to the airport in a few hours and will be in a class the next two days so won't be very prompt with emails from 9-5 Pacific time. However, my approach to #2 sounds a little different as the triggering event is never added to the cyclic buffer but is instead passed to the writeContent method where it is written after the buffer. I suspect adding the event to the buffer as you describe will result in a race condition.

        Show
        Ralph Goers added a comment - I had already started making the changes for approach # 2 this morning but $work got in the way. I'm headed to the airport in a few hours and will be in a class the next two days so won't be very prompt with emails from 9-5 Pacific time. However, my approach to #2 sounds a little different as the triggering event is never added to the cyclic buffer but is instead passed to the writeContent method where it is written after the buffer. I suspect adding the event to the buffer as you describe will result in a race condition.
        Hide
        Scott Severtson added a comment -

        So, we came up with two possible approaches to solve this issue:

        1. Make CyclicBuffer smarter, replacing .removeAll() with .removeTo(T item). This would allow SMTPManager to only remove events up to the triggering event, leaving anything appended after in the buffer. However, this has a couple issues:
        a. Empty or nonsensical emails (not containing the target event) could still occur, if the CyclicBuffer is too small, and more events are written to the buffer between the .isFiltered call and the .append call. This is actually an issue with the current implementation as well.
        b. Log4jLogEvent would need to (at a minimum) implement a .equals method, so we can actually find the target event in the CyclicBuffer. I'm not sure if .equals was omitted purposefully.
        b. The .removeTo code would be a bit more complex than the current .removeAll implementation.

        2. Don't append non-filtered items in the .isFiltered method; instead, wait and append them to the buffer just before the current .removeAll call. This would ensure that at least the triggering event is reported. However, this also has an issue: Currently, CyclicBuffer claims to be thread-safe, as all mutating methods are synchronized. As .add would be called just before .removeAll, the calling code in SMTPManager would need to instead hold a synchronization lock (similar to my previous bad patch for this issue). Alternatively, .removeAll() could become an atomic .removeAllAndInclude(T item), preserving the thread-safety of CyclicBuffer, at the cost of some reusability of the class (the method doesn't seem to make sense for general use cases).

        I've done a proof of concept with #2, which only required changing a few lines in a couple files. I did not yet make an atomic .removeAllAndInclude, but could if this alternative is desired.

        Thoughts?

        Show
        Scott Severtson added a comment - So, we came up with two possible approaches to solve this issue: 1. Make CyclicBuffer smarter, replacing .removeAll() with .removeTo(T item). This would allow SMTPManager to only remove events up to the triggering event, leaving anything appended after in the buffer. However, this has a couple issues: a. Empty or nonsensical emails (not containing the target event) could still occur, if the CyclicBuffer is too small, and more events are written to the buffer between the .isFiltered call and the .append call. This is actually an issue with the current implementation as well. b. Log4jLogEvent would need to (at a minimum) implement a .equals method, so we can actually find the target event in the CyclicBuffer. I'm not sure if .equals was omitted purposefully. b. The .removeTo code would be a bit more complex than the current .removeAll implementation. 2. Don't append non-filtered items in the .isFiltered method; instead, wait and append them to the buffer just before the current .removeAll call. This would ensure that at least the triggering event is reported. However, this also has an issue: Currently, CyclicBuffer claims to be thread-safe, as all mutating methods are synchronized. As .add would be called just before .removeAll, the calling code in SMTPManager would need to instead hold a synchronization lock (similar to my previous bad patch for this issue). Alternatively, .removeAll() could become an atomic .removeAllAndInclude(T item), preserving the thread-safety of CyclicBuffer, at the cost of some reusability of the class (the method doesn't seem to make sense for general use cases). I've done a proof of concept with #2, which only required changing a few lines in a couple files. I did not yet make an atomic .removeAllAndInclude, but could if this alternative is desired. Thoughts?
        Hide
        Ralph Goers added a comment -

        Yeah. The way to handle this is to only add messages that match the filter to the buffer.

        Show
        Ralph Goers added a comment - Yeah. The way to handle this is to only add messages that match the filter to the buffer.
        Hide
        Scott Severtson added a comment -

        Ralph is correct - the patch doesn't actually solve the problem. Sorry for the false start.

        FYI, I removed the parameter from a few methods to make it more clear what was being synchronized on (the SMTPManager.buffer instance variable), versus synchronizing on the passed-in variable. I didn't catch that synchronization had been moved to the CyclicBuffer itself.

        I'll do what I can to create a test app later. However, it's easy to describe the problem:
        Thread 1: App sends log message #1
        Thread 1: Log4J calls isFiltered(message #1) (appends to buffer)
        Thread 2: App sends log message #2
        Thread 2: Log4J calls isFiltered(message #2) (appends to buffer)
        Thread 1: Log4J calls append(message #1) (clears buffer, delivers both messages)
        Thread 2: Log4J calls append(message #2) (empty buffer, delivers no messages)

        Any thoughts on a possible approach to preventing the above scenario?

        Show
        Scott Severtson added a comment - Ralph is correct - the patch doesn't actually solve the problem. Sorry for the false start. FYI, I removed the parameter from a few methods to make it more clear what was being synchronized on (the SMTPManager.buffer instance variable), versus synchronizing on the passed-in variable. I didn't catch that synchronization had been moved to the CyclicBuffer itself. I'll do what I can to create a test app later. However, it's easy to describe the problem: Thread 1: App sends log message #1 Thread 1: Log4J calls isFiltered(message #1) (appends to buffer) Thread 2: App sends log message #2 Thread 2: Log4J calls isFiltered(message #2) (appends to buffer) Thread 1: Log4J calls append(message #1) (clears buffer, delivers both messages) Thread 2: Log4J calls append(message #2) (empty buffer, delivers no messages) Any thoughts on a possible approach to preventing the above scenario?
        Hide
        Ralph Goers added a comment -

        It took me by surprise too when I first saw how the SMTPAppender worked, but I understand what it is trying to do. There isn't any danger of the isFilter method being called twice - that is only going to happen in the AppenderControl. Note that this will NOT capture events that have been filtered by a global Filter, Logger Filter or Appender-ref Filter as they will never make it this far. You would have to create a special global filter to capture the events if you really want to capture everything.

        As for the patch, I'm not sure what it is accomplishing. The CyclicBuffer add and removeAll methods are synchronized so wrapping those calls in a synchronized block doesn't do anything useful. Removing buffer as a parameter from two methods and then having writeBuffer just reference the member variable also should accomplish nothing. So I'm not ready to apply this patch until I understand how it fixes the problem.

        It would also be helpful to have a test that demonstrates the problem.

        Show
        Ralph Goers added a comment - It took me by surprise too when I first saw how the SMTPAppender worked, but I understand what it is trying to do. There isn't any danger of the isFilter method being called twice - that is only going to happen in the AppenderControl. Note that this will NOT capture events that have been filtered by a global Filter, Logger Filter or Appender-ref Filter as they will never make it this far. You would have to create a special global filter to capture the events if you really want to capture everything. As for the patch, I'm not sure what it is accomplishing. The CyclicBuffer add and removeAll methods are synchronized so wrapping those calls in a synchronized block doesn't do anything useful. Removing buffer as a parameter from two methods and then having writeBuffer just reference the member variable also should accomplish nothing. So I'm not ready to apply this patch until I understand how it fixes the problem. It would also be helpful to have a test that demonstrates the problem.
        Hide
        Scott Severtson added a comment -

        Probably a question for Ralph - I'm not entirely sure.

        Show
        Scott Severtson added a comment - Probably a question for Ralph - I'm not entirely sure.
        Hide
        Gary Gregory added a comment -

        Ah... I see, I need to go back to filter school it seems. I see how filters play in the big picture now.

        Reading https://logging.apache.org/log4j/2.x/manual/filters.html I have this follow up.

        No matter what happens with other filters in steps 1-4, the appender isFilter method will always be called? If yes, then all is well because the log event will be added.

        Show
        Gary Gregory added a comment - Ah... I see, I need to go back to filter school it seems. I see how filters play in the big picture now. Reading https://logging.apache.org/log4j/2.x/manual/filters.html I have this follow up. No matter what happens with other filters in steps 1-4, the appender isFilter method will always be called? If yes, then all is well because the log event will be added.
        Hide
        Scott Severtson added a comment -

        It's re-creating the functionality from Log4J 1.x - previous (lower priority) log events are buffered, but only events above the filter theshold trigger an alert email (containing both the triggering event, and the previous X log events).

        Show
        Scott Severtson added a comment - It's re-creating the functionality from Log4J 1.x - previous (lower priority) log events are buffered, but only events above the filter theshold trigger an alert email (containing both the triggering event, and the previous X log events).
        Hide
        Gary Gregory added a comment -

        It does not sound right that if the log event is added to the manager not matter what is isFiltered returns.

        If isFiltered returns true, then append is called and all is well.

        If isFiltered return false, the log event should not make it to the manager.

        Am I missing something here?

        I realize that this is now a different issue than I originally wondered about...

        Gary

        Show
        Gary Gregory added a comment - It does not sound right that if the log event is added to the manager not matter what is isFiltered returns. If isFiltered returns true, then append is called and all is well. If isFiltered return false, the log event should not make it to the manager. Am I missing something here? I realize that this is now a different issue than I originally wondered about... Gary
        Hide
        Scott Severtson added a comment - - edited

        But, if the event is filtered by .isFiltered, then .append is never called. Is there a better place to intercept all messages (only once)?

        Show
        Scott Severtson added a comment - - edited But, if the event is filtered by .isFiltered, then .append is never called. Is there a better place to intercept all messages (only once)?
        Hide
        Gary Gregory added a comment -

        Well, yeah, I've read that much

        I would have thought that the appender's append would add the event and that the manager would flush itself when the buffer reaches some threshold.

        Instead adding the event during the isFiltered call fells like a hack because if you call isFiltered more than once for a given event, you'll get two log events in the buffer. The buffer itself could easily check for that condition of course, but then it would be carrying more complex semantics than a "cyclic buffer".

        Gary

        Show
        Gary Gregory added a comment - Well, yeah, I've read that much I would have thought that the appender's append would add the event and that the manager would flush itself when the buffer reaches some threshold. Instead adding the event during the isFiltered call fells like a hack because if you call isFiltered more than once for a given event, you'll get two log events in the buffer. The buffer itself could easily check for that condition of course, but then it would be carrying more complex semantics than a "cyclic buffer". Gary
        Hide
        Scott Severtson added a comment -

        It is in the JavaDoc.

        /**

        • Capture all events in CyclicBuffer
          */

        --Scott

        Show
        Scott Severtson added a comment - It is in the JavaDoc. /** Capture all events in CyclicBuffer */ --Scott
        Hide
        Gary Gregory added a comment - - edited

        The question is likely for Ralph.

        It seems wrong that SMTPAppender.isFiltered(LogEvent) adds the log event to the cyclic buffer.

        Perhaps a touch of comments would help

        Gary

        Show
        Gary Gregory added a comment - - edited The question is likely for Ralph. It seems wrong that SMTPAppender.isFiltered(LogEvent) adds the log event to the cyclic buffer. Perhaps a touch of comments would help Gary
        Hide
        Scott Severtson added a comment -

        BTW, this issue is not hypothetical - we experienced this twice today on a highly-threaded component of our software.

        Show
        Scott Severtson added a comment - BTW, this issue is not hypothetical - we experienced this twice today on a highly-threaded component of our software.
        Hide
        Scott Severtson added a comment -

        Re-introduce CyclicBuffer synchronization to prevent empty error emails.

        Show
        Scott Severtson added a comment - Re-introduce CyclicBuffer synchronization to prevent empty error emails.

          People

          • Assignee:
            Ralph Goers
            Reporter:
            Scott Severtson
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development