Log4j 2
  1. Log4j 2
  2. LOG4J2-625

Serialization error with SocketAppender and Asynch Logger

    Details

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

      Ubuntu 12.04, Java 7

      Description

      I'm testing a simple SocketAppender, which works fine until I switch to asynchronous loggers. Once I turn on async logging, I get:

      2014-04-29 21:17:26,029 ERROR Serialization of LogEvent failed. java.io.NotSerializableException: org.apache.logging.log4j.core.Logger$PrivateConfig
      at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1183)
      at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1547)
      at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1508)
      at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1431)
      at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1177)
      at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1547)
      at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1508)
      at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1431)
      at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1177)
      at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:347)
      at org.apache.logging.log4j.core.layout.SerializedLayout.toByteArray(SerializedLayout.java:64)
      at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:118)
      at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
      at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
      at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
      at org.apache.logging.log4j.core.Logger$PrivateConfig.logEvent(Logger.java:275)
      at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:289)
      at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:99)
      at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
      at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
      at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      at java.lang.Thread.run(Thread.java:744)

      My client is configured with:

      <?xml version="1.0" encoding="UTF-8"?>
      <Configuration status="INFO">
      <Appenders>
      <Console name="MyConsole" target="SYSTEM_OUT">
      <PatternLayout pattern="%d

      {HH:mm:ss.SSS} {EST} %5level %msg%n"/>
      </Console>
      <Socket name="MySocket" host="localhost" port="8888">
      <SerializedLayout />
      </Socket>
      </Appenders>
      <Loggers>
      <Root level="INFO">
      <AppenderRef ref="MyConsole"/>
      <AppenderRef ref="MySocket"/>
      </Root>
      </Loggers>
      </Configuration>

      My server is configured with:

      <?xml version="1.0" encoding="UTF-8"?>
      <Configuration status="INFO">
      <Appenders>
      <Console name="MyConsole" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{HH:mm:ss.SSS}{EST}

      %5level %msg%n"/>
      </Console>
      </Appenders>
      <Loggers>
      <Root level="INFO">
      <AppenderRef ref="MyConsole"/>
      </Root>
      </Loggers>
      </Configuration>

      The client just does a LogManager.getLogger().info("{}", "hello").

      The server just creates a SocketServer:
      SocketServer server = new SocketServer(8888);
      server.run();

      All works fine until I add this into the client:
      System.setProperty("Log4jContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");

      Am I missing something? Please advise.

      Thanks

        Activity

        Hide
        Bryan Hsueh added a comment -

        just tested with RC2 and worked, thanks!

        Show
        Bryan Hsueh added a comment - just tested with RC2 and worked, thanks!
        Hide
        Remko Popma added a comment -

        That is great to hear. Thanks for the confirmation.

        FYI, this change just made it into RC2. I didn't have time to verify, so I missed the window for updating the release notes, but the fix will be in included in RC2, which should be available in a few days.

        Show
        Remko Popma added a comment - That is great to hear. Thanks for the confirmation. FYI, this change just made it into RC2. I didn't have time to verify, so I missed the window for updating the release notes, but the fix will be in included in RC2, which should be available in a few days.
        Hide
        Scott Harrington added a comment -

        If it helps, I have compiled 1604433 and it works for me.

        Previously as a workaround I had placed a Rewrite in front of the Socket appender so that a new Log4jLogEvent would be created from each RingBufferLogEvent.

        I am now able to remove this workaround, and my "central" logging daemon is still able to filter, layout, and append all deserialized LogEvents as expected.

        Thank you all for your work toward RC2 (and before). Very impressive effort.

        Show
        Scott Harrington added a comment - If it helps, I have compiled 1604433 and it works for me. Previously as a workaround I had placed a Rewrite in front of the Socket appender so that a new Log4jLogEvent would be created from each RingBufferLogEvent. I am now able to remove this workaround, and my "central" logging daemon is still able to filter, layout, and append all deserialized LogEvents as expected. Thank you all for your work toward RC2 (and before). Very impressive effort.
        Hide
        Remko Popma added a comment -

        This is caused by RingBufferLogEvent having a non-transient field of type AsyncLogger.
        Making this field transient should fix the issue.

        Field was made transient in revision 1604433. I will try to test tomorrow.

        Show
        Remko Popma added a comment - This is caused by RingBufferLogEvent having a non-transient field of type AsyncLogger . Making this field transient should fix the issue. Field was made transient in revision 1604433. I will try to test tomorrow.
        Hide
        Ralph Goers added a comment -

        Can you please verify this still happens with the latest in trunk? I don't see how the Logger could be included in the serialized event.

        Show
        Ralph Goers added a comment - Can you please verify this still happens with the latest in trunk? I don't see how the Logger could be included in the serialized event.
        Hide
        Ralph Goers added a comment -

        After looking at this again this is not a duplicate of LOG4J2-542. That has to do with deserialization on a different server where the Exception class may not be available. I'm not sure what the cause of this is.

        Show
        Ralph Goers added a comment - After looking at this again this is not a duplicate of LOG4J2-542 . That has to do with deserialization on a different server where the Exception class may not be available. I'm not sure what the cause of this is.
        Hide
        Ralph Goers added a comment -

        Closed as a duplicate.

        Show
        Ralph Goers added a comment - Closed as a duplicate.

          People

          • Assignee:
            Remko Popma
            Reporter:
            Bryan Hsueh
          • Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development