[LOG4J2-2140] MutableLogEvent instances get reused before flushing when using a NoSql Appender with a bufferSize

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.9.1
• Fix Version/s: 2.10.0
• Component/s: Appenders

Environment

Windows 10 with MongoDB Server 3.4

• Flags: Important
• Assignee: Unassigned
• Reporter: Yasas Gunarathne
• Created: 04/Dec/17 04:46
• Updated: 04/Dec/17 07:50
• Resolved: 04/Dec/17 07:50

Description

When using NoSql Appender with a bufferSize configured MutableLogEvent instances get overwritten while they are still in the buffer of AbstractDatabaseManager. Here are the steps to recreate the issue.

log4j2.xml file I used is as below.

<?xml version="1.0" encoding="UTF-8"?>

<Configuration xmlns="http://logging.apache.org/log4j/2.0/config">
    <Loggers>
        <Logger name="test.TestOne" level="DEBUG">
            <AppenderRef ref="NoSql"/>
        </Logger>
    </Loggers>
    <Appenders>
        <NoSql name="NoSql" bufferSize="100">
            <MongoDb databaseName="test" collectionName="sampleLogs" server="localhost" />
        </NoSql>
    </Appenders>
</Configuration>

This is the sample program.

package test;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestOne {

    private static final Logger logger = LogManager.getLogger(TestOne.class);

    public static void main(String[] args) {
        for (int i = 0; i < 100; i++) {
            logger.debug("Test: " + i);
        }
    }
}

And here are some of the results I got when querying the MongoDB collection after running the above sample program.

{
  "_id": ObjectId(
  "5a24d2d332fc4edab1eceb21"
  ),
  "level": "DEBUG",
  "loggerName": "test.TestOne",
  "message": "Test: 99",
  "source": {
    "className": "test.TestOne",
    "methodName": "main",
    "fileName": "TestOne.java",
    "lineNumber": 12
  },
  "marker": null,
  "threadId": NumberLong(1),
  "threadName": "main",
  "threadPriority": 5,
  "millis": NumberLong(
  "1512362702533"
  ),
  "date": ISODate(
  "2017-12-04T04:45:02.533Z"
  ),
  "thrown": null,
  "contextMap": {},
  "contextStack": []
}
{
  "_id": ObjectId(
  "5a24d2d532fc4edab1eceb22"
  ),
  "level": "DEBUG",
  "loggerName": "test.TestOne",
  "message": "Test: 99",
  "source": {
    "className": "test.TestOne",
    "methodName": "main",
    "fileName": "TestOne.java",
    "lineNumber": 12
  },
  "marker": null,
  "threadId": NumberLong(1),
  "threadName": "main",
  "threadPriority": 5,
  "millis": NumberLong(
  "1512362702533"
  ),
  "date": ISODate(
  "2017-12-04T04:45:02.533Z"
  ),
  "thrown": null,
  "contextMap": {},
  "contextStack": []
}
{
  "_id": ObjectId(
  "5a24d2dc32fc4edab1eceb23"
  ),
  "level": "DEBUG",
  "loggerName": "test.TestOne",
  "message": "Test: 99",
  "source": {
    "className": "test.TestOne",
    "methodName": "main",
    "fileName": "TestOne.java",
    "lineNumber": 12
  },
  "marker": null,
  "threadId": NumberLong(1),
  "threadName": "main",
  "threadPriority": 5,
  "millis": NumberLong(
  "1512362702533"
  ),
  "date": ISODate(
  "2017-12-04T04:45:02.533Z"
  ),
  "thrown": null,
  "contextMap": {},
  "contextStack": []
}

Issue Links

• is related to: LOG4J2-2060 AbstactDatabase appender issue with AsyncLogger