[
https://issues.apache.org/jira/browse/LOG4J2-2140?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Yasas Gunarathne updated LOG4J2-2140:
-------------------------------------
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.
{code:xml}
<?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>
{code}
This is the sample program.
{code:java}
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);
}
}
}
{code}
And here are some of the results I got when querying the MongoDB collection
after running the above sample program.
{color:#707070}{ "_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" : [ ] }
{ "_id" : ObjectId("5a24d2dc32fc4edab1eceb24"), "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("5a24d2dc32fc4edab1eceb25"), "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("5a24d2dc32fc4edab1eceb26"), "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("5a24d2dc32fc4edab1eceb27"), "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" : [ ] }{color}
was:
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.
{code:xml}
<?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>
{code}
This is the sample program.
{code:java}
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);
}
}
}
{code}
And here are some of the results I got when querying the MongoDB collection
after running the above sample program.
{color:#707070}{ "_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" : [ ] }
{ "_id" : ObjectId("5a24d2dc32fc4edab1eceb24"), "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("5a24d2dc32fc4edab1eceb25"), "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("5a24d2dc32fc4edab1eceb26"), "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("5a24d2dc32fc4edab1eceb27"), "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" : [ ] }{color}
> MutableLogEvent instances get overwritten before flushing when using a NoSql
> Appender with a bufferSize
> -------------------------------------------------------------------------------------------------------
>
> Key: LOG4J2-2140
> URL: https://issues.apache.org/jira/browse/LOG4J2-2140
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.9.1
> Environment: Windows 10 with MongoDB Server 3.4
> Reporter: Yasas Gunarathne
>
> 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.
> {code:xml}
> <?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>
> {code}
> This is the sample program.
> {code:java}
> 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);
> }
> }
> }
> {code}
> And here are some of the results I got when querying the MongoDB collection
> after running the above sample program.
> {color:#707070}{ "_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" : [ ] }
> { "_id" : ObjectId("5a24d2dc32fc4edab1eceb24"), "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("5a24d2dc32fc4edab1eceb25"), "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("5a24d2dc32fc4edab1eceb26"), "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("5a24d2dc32fc4edab1eceb27"), "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" : [ ] }{color}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
