[LOG4J2-1769] JsonLayout Throwing Exceptions And Producing Broken Logs

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.7
• Fix Version/s: 2.8
• Component/s: Layouts

Environment

All Platforms

• Assignee: Remko Popma
• Reporter: Brandon Goodin
• Created: 06/Jan/17 23:03
• Updated: 26/Mar/18 20:53
• Resolved: 07/Jan/17 13:54

Description

In a multithreaded environment JsonLayout is throwing exceptions and producing fragmented logs. We were able to produce a test that demonstrates this. The following exceptions and broken logging are being seen.

IllegalArgumentException

2017-01-06 16:57:59,173 Thread-98 ERROR An exception occurred processing Appender stdout java.lang.IllegalArgumentException
	at java.nio.Buffer.position(Buffer.java:244)
	at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:191)
	at org.apache.logging.log4j.core.layout.AbstractLayout.writeTo(AbstractLayout.java:179)
	at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:160)
	at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:36)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:176)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:169)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:447)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:432)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:416)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:402)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1988)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1960)
	at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1297)
	at org.apache.logging.log4j.JSONLayoutIssuesTest$LoggingThread.run(JSONLayoutIssuesTest.java:54)

BufferOverflowException

2017-01-06 16:57:59,194 Thread-99 ERROR An exception occurred processing Appender stdout java.nio.BufferOverflowException
	at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:189)
	at org.apache.logging.log4j.core.layout.AbstractLayout.writeTo(AbstractLayout.java:179)
	at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:160)
	at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:36)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:176)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:169)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:447)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:432)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:416)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:402)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1971)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1829)
	at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1287)
	at org.apache.logging.log4j.JSONLayoutIssuesTest$LoggingThread.run(JSONLayoutIssuesTest.java:53)

BrokenLogs

{"timeMillis":1483743479195,"thread":"Thread-49","level":"INFO","loggerName":"org.apache.logging.log4j.JSONLayoutIssuesTest","message":"This is simple text.","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","threadId":61,"threadPriority":5}
{"timeMillis":1483743479195,"thread":"Thread-42","level":"INFO","loggerName":"org.apache.logging.log4j.JSONLayoutIssuesTest","message":"This is simple text.","endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","threadId":54,"threadPriority":5}
hreadPriority":5}

Issue Links

• is related to: LOG4J2-2285 ConcurrentLoggingWithJsonLayoutTest does nothing