Without MDC, KeyValuePair Cannot be Used

[coderlol]

If no MDC is supplied and KeyValuePair is used, this is the error. I think it is due to the use of emptyMap() which is immutable.

Gradle suite > Gradle test > org.apache.logging.log4j.core.layout.LogStashJSONLayoutJacksonIT.BasicSimpleTest FAILED
java.lang.UnsupportedOperationException
at java.util.AbstractMap.put(AbstractMap.java:209)
at java.util.AbstractMap.putAll(AbstractMap.java:281)
at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:189)
at org.apache.logging.log4j.core.layout.LogStashJSONLayoutJacksonIT.BasicSimpleTest(LogStashJSONLayoutJacksonIT.java:101)

[StephenGoodall]

Did you ever find a way around this @coderlol ?

[bratwurzt]

Has this ever worked? You don't construct your own Log4jEvent and LogEventToLogStashLogEventConverter never gets used.

[majikthys]

It's used in the jackson serializer mixin

[coderlol]

@StephenGoodall, I think. Don't recall exactly what I did, but let's see if I can zip it all up and send it

[StephenGoodall]

Thanks @coderlol that would be great, I've been trying to use a ruby filter to convert log4j2's json event into "standard" json but this would be much neater

[bratwurzt]

@majikthys My mistake, LogEventToLogStashLogEventConverter is getting used. But additionalLogAttributes never get inserted into contextMap since like @coderlol mentioned Log4jLogEvent constructor initializes it like:
this.contextMap = contextMap == null?ThreadContext.EMPTY_MAP:contextMap;
which is immutable.

That is why LogStashJSONLayout.toSerializable throws java.lang.UnsupportedOperationException and short of using custom LogEventFactory I don't know how to use this otherwise very beautiful piece of code.

[majikthys]

In what circumstance is MDC of LogEvent null? I've added branch issue/27 with a proposed solution, please comment.

https://github.com/majikthys/log4j2-logstash-jsonevent-layout/tree/issue/27

5346ca1

[StephenGoodall]

If it helps, I wrote this as a quick test:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Log4J2Test {

    final static Logger logger = LoggerFactory.getLogger(Log4J2Test.class);

    public static void main(String[] args){

        logger.debug("START");

        MDC.put("cmap_http_headers","testingheaders");

        for(int i=1; i<10; i++){
            System.out.println("test output: " + i);
            logger.debug("Loop Count is: " + i);
            try {
                  Thread.sleep(500);
              } catch(InterruptedException ex) {
                  Thread.currentThread().interrupt();
              }
       }
        }
    }

This gives the following output in the log file:

{
  "@version" : "1",
  "@timestamp" : "2016-04-13T10:26:05.356+01:00",
  "timeMillis" : 1460539565356,
  "thread" : "main",
  "level" : "DEBUG",
  "loggerName" : "DatabaseChecker",
  "message" : "START",
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",
  "nanoTime" : 175679732364422
}`

And this in the console:
test output: 1
2016-04-13 10:28:15,893 ERROR An exception occurred processing Appender TestConsole3 java.lang.UnsupportedOperationException
    at java.util.Collections$UnmodifiableMap.putAll(Collections.java:1348)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:175)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:40)
    at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:71)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
    at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:732)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:700)
    at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:118)
    at Log4J2Test.main(Log4J2Test.java:17)

test output: 2
2016-04-13 10:28:16,394 ERROR An exception occurred processing Appender TestConsole3 java.lang.UnsupportedOperationException
    at java.util.Collections$UnmodifiableMap.putAll(Collections.java:1348)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:175)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:40)
    at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:71)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
    at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:732)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:700)
    at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:118)
    at Log4J2Test.main(Log4J2Test.java:17)

test output: 3
2016-04-13 10:28:16,896 ERROR An exception occurred processing Appender TestConsole3 java.lang.UnsupportedOperationException
    at java.util.Collections$UnmodifiableMap.putAll(Collections.java:1348)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:175)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:40)
    at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:71)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
    at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:732)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:700)
    at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:118)
    at Log4J2Test.main(Log4J2Test.java:17)

test output: 4
2016-04-13 10:28:17,398 ERROR An exception occurred processing Appender TestConsole3 java.lang.UnsupportedOperationException
    at java.util.Collections$UnmodifiableMap.putAll(Collections.java:1348)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:175)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:40)
    at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:71)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
    at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:732)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:700)
    at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:118)
    at Log4J2Test.main(Log4J2Test.java:17)

test output: 5
test output: 6
test output: 7
test output: 8
test output: 9

That was using this config:

<RollingRandomAccessFile name="TestConsole3"
   fileName="C:/Users/XXXXXXX/Desktop/log4j2-logstash-test.log"
   filePattern="C:/Users/XXXXXX/Desktop/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-test-%i.log.gz">
   <LogStashJSONLayout>
   </LogStashJSONLayout>
   <Policies>
    <TimeBasedTriggeringPolicy />
    <SizeBasedTriggeringPolicy size="1 KB" />
   </Policies>
   <DefaultRolloverStrategy max="100" />
  </RollingRandomAccessFile>

So i think it seems to work for the first line because at that point there is no MDC specified. So it outputs it to the log file, the rest of the time it fails to write to the log. Not sure why it doesn't try for the last 5 attempts though.

I'll try and build your latest version (issue 27) and see if it fixes the issue :)

[StephenGoodall]

I might not be doing it right but it failed with an error:

C:\Users\XXXXX\git\log4j2-logstash-jsonevent-layout\log4j2-logstash-jsonevent
-layout-issue-27\log4j2-logstash-jsonevent-layout-issue-27\src\main\java\org\apa
che\logging\log4j\core\layout\LogStashJSONLayout.java:166: error: constructor Lo
gStashJSONLayout in class LogStashJSONLayout cannot be applied to given types;
        return new LogStashJSONLayout(false, false, false, false, false, UTF_8,
new HashMap<>());
               ^
  required: boolean,boolean,boolean,boolean,boolean,Charset,Map<String,String>
  found: boolean,boolean,boolean,boolean,boolean,Charset,HashMap<Object,Object>
  reason: actual argument HashMap<Object,Object> cannot be converted to Map<Stri
ng,String> by method invocation conversion
1 error
:compileJava FAILED

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':compileJava'.
> Compilation failed; see the compiler error output for details.

* Try:
Run with --stacktrace option to get the stack trace. Run with --info or --debug
option to get more log output.

BUILD FAILED

Total time: 27.69 secs

I think it may be due to this line (166):

return new LogStashJSONLayout(false, false, false, false, false, UTF_8, new HashMap<>());

Should it be:

new HashMap<String, String>()

I changed it to the above and it seemed to build. Will try and use the jar now

[StephenGoodall]

I got this stacktrace:

Exception in thread "main" java.lang.NoSuchMethodError: org.apache.logging.log4j.core.LogEvent.getNanoTime()J
    at org.apache.logging.log4j.core.LogStashLogEvent.getNanoTime(LogStashLogEvent.java:125)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:654)
    at com.fasterxml.jackson.databind.ser.impl.SimpleBeanPropertyFilter.serializeAsField(SimpleBeanPropertyFilter.java:208)
    at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFieldsFiltered(BeanSerializerBase.java:725)
    at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:155)
    at com.fasterxml.jackson.databind.ser.std.StdDelegatingSerializer.serialize(StdDelegatingSerializer.java:169)
    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:130)
    at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1387)
    at com.fasterxml.jackson.databind.ObjectWriter._configAndWriteValue(ObjectWriter.java:1088)
    at com.fasterxml.jackson.databind.ObjectWriter.writeValueAsString(ObjectWriter.java:960)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:190)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:43)
    at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:71)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
    at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:732)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:700)
    at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:118)
    at Log4J2Test.main(Log4J2Test.java:14)

So changed LogStashLogEvent.java:125 to be:

return wrappedLogEvent.getTimeMillis();

This allowed it to run, but it threw the new error, and this stack trace again:

2016-04-13 10:57:45,269 ERROR You will only see this error once. No ContextMap set for LogEvent Logger=Log4J2Test Level=DEBUG Message=START
test output: 1
2016-04-13 10:57:45,377 ERROR An exception occurred processing Appender TestConsole3 java.lang.UnsupportedOperationException
    at java.util.Collections$UnmodifiableMap.putAll(Collections.java:1348)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:186)
    at org.apache.logging.log4j.core.layout.LogStashJSONLayout.toSerializable(LogStashJSONLayout.java:43)
    at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:71)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:108)
    at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:732)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:700)
    at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:118)
    at Log4J2Test.main(Log4J2Test.java:20)

Hopefully this is helpful.........i hope I haven't confused anything. Let me know if you want me to run some other tests or if I've done these wrong.

[StephenGoodall]

Hi @majikthys, is there any news on this? Did the tests I ran help at all? Happy to run some more if needed 😃

[majikthys]

@StephenGoodall go ahead and review 7dccf46 on branch https://github.com/majikthys/log4j2-logstash-jsonevent-layout/tree/issue/27-redux and let me know if that is a suitable approach.

[StephenGoodall]

@majikthys I get this error:
Exception in thread "main" java.lang.NoSuchMethodError: org.apache.logging.log4j.core.LogEvent.getNanoTime()

But when I change it to getTimeMillis() it seems to work but the MDC/contextMap doesn't get printed in the log file.

I added this as the config:

<LogStashJSONLayout>
   <KeyValuePair key="hostname" value="test"/>
   </LogStashJSONLayout>

and the hostname key:value pair wasn't printed in the logs either, here is an example of a log event in the log file:

{
  "@version" : "1",
  "@timestamp" : "2016-04-20T10:33:09.848+01:00",
  "timeMillis" : 1461144789848,
  "thread" : "main",
  "level" : "DEBUG",
  "loggerName" : "DatabaseChecker",
  "message" : "Loop Count is: 32",
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",
  "nanoTime" : 1461144789848
}

This is my log4j2.xml file:

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

 <Appenders>

  <File name="File" fileName="C:/Users/GoodallS/Desktop/log4j2.log">
   <JSONLayout eventEol="true" properties="true" />
  </File>

  <Console name="Console" target="SYSTEM_OUT">
   <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
  </Console>

  <RollingRandomAccessFile name="TestConsole2"
   fileName="C:/Users/GoodallS/Desktop/log4j2-logstash.log"
   filePattern="C:/Users/GoodallS/Desktop/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
   <JSONLayout eventEol="true" compact="true" properties="true" />
   <Policies>
    <TimeBasedTriggeringPolicy />
    <SizeBasedTriggeringPolicy size="1 KB" />
   </Policies>
   <DefaultRolloverStrategy max="100" />
  </RollingRandomAccessFile>


<RollingRandomAccessFile name="TestConsole3"
   fileName="C:/Users/GoodallS/Desktop/log4j2-logstash-test.log"
   filePattern="C:/Users/GoodallS/Desktop/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-test-%i.log.gz">
   <LogStashJSONLayout>
   <KeyValuePair key="hostname" value="test"/>
   </LogStashJSONLayout>
   <Policies>
    <TimeBasedTriggeringPolicy />
    <SizeBasedTriggeringPolicy size="1 MB" />
   </Policies>
   <DefaultRolloverStrategy max="100" />
  </RollingRandomAccessFile>

 </Appenders>

 <Loggers>

  <Root level="debug">
   <AppenderRef ref="TestConsole3" level="debug" />
   <AppenderRef ref="Console" level="debug" />
  </Root>

 </Loggers>

</Configuration>

Am I missing something from the config?
Thanks for updating this by the way, I'm sure it's not just me who will appreciate it :)

[osmancis]

@StephenGoodall were you able to resolve the map issue? I am having same issue at my end.

[StephenGoodall]

Hi @osmancis
The last thing I tested was above, I've been on holiday for the last 2 weeks but haven't done any further testing. The above tests made it print the log but not the MDC/context. This required changing:org.apache.logging.log4j.core.LogEvent.getNanoTime() to getTimeMillis()

[osmancis]

Hi @StephenGoodall Thanks for quick response. I was able to get around this issue by not using the overriden getContext (Meaning commenting it out) and add

public Map<String,String> getValueMap()
{
    return contextMap;
} 

[StephenGoodall]

Hi @osmancis was that inside the LogStashLogEvent class? I can see an overridden getContextMap but not getContext.
Was it on this branch or the master branch?
https://github.com/majikthys/log4j2-logstash-jsonevent-layout/tree/issue/27-redux

cheers

[buddhashrestha]

hi @StephenGoodall , were you able to put the MDC value in you json log?

[StephenGoodall]

Hi @buddhashrestha not yet, I haven't had any time to try it out recently.
Hopefully I'll get some time to look into it soon

[fabienmifsud]

Hi @StephenGoodall ,

This version is compiled with log4j2 2.5, check the version of log4j2 in your project. I've got the same kind of issue due to my 2.3 version of log4j2

[Diallos]

You can use this https://github.com/Diallos/logging-event-layout

It works for log4j, log4j2 and logback.

[osmancis]

Is there any way to make changes to context map in code (say - to rewrite a key value pair)

[dliscombch]

crikes, this has bitten us as well.
In my case, we just want to use the JsonLayout, with KeyValuePair