Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-3567

ThreadContext in append() method of an Appender plugin?

    XMLWordPrintableJSON

Details

    • Question
    • Status: Resolved
    • Major
    • Resolution: Information Provided
    • 2.17.2
    • None
    • Appenders
    • None

    Description

      I recently converted a log4j1 implementation over to log4j2 v2.17.2 for a WebSphere Commerce application.  The log4j1 implementation used a custom appender which added thread info to MDC in the append method. With that implementation, every log statement had thread information logged. 

      For the log4j2 implementation, I developed an Appender plugin, overriding the append() method to add the ThreadContext map. With this implementation, roughly 10% of our log statements come through with no thread context.  At one point I added System.out.println()'s in the append() method to verify the thread info and noticed that it printed to sysout 100% of the time.

      I also developed a similar Console appender plugin, to rule out any socket server issues, but got the same results.

      With log4j2, is there any concern with adding to the ThreadContext map within an Appender Plugin's append() method?

      Here is the code for the Socket Appender plugin.  Note the append() override.:

      package com.foo.bar;
      
      import java.io.Serializable;
      import org.apache.logging.log4j.ThreadContext;
      import org.apache.logging.log4j.core.AbstractLifeCycle;
      import org.apache.logging.log4j.core.Appender;
      import org.apache.logging.log4j.core.Core;
      import org.apache.logging.log4j.core.Filter;
      import org.apache.logging.log4j.core.Layout;
      import org.apache.logging.log4j.core.LogEvent;
      import org.apache.logging.log4j.core.appender.SocketAppender;
      import org.apache.logging.log4j.core.config.Property;
      import org.apache.logging.log4j.core.config.plugins.Plugin;
      import org.apache.logging.log4j.core.config.plugins.PluginBuilderFactory;
      import org.apache.logging.log4j.core.net.AbstractSocketManager;
      import org.apache.logging.log4j.core.net.Advertiser;
      import org.apache.logging.log4j.core.net.Protocol;
      
      import com.ibm.commerce.ras.DDThreadContextManager;
      import com.ibm.websphere.management.AdminService;
      import com.ibm.websphere.management.AdminServiceFactory;
      
      /**
       * Overrides SocketAppender so that thread-local information can be
       * stored for a LoggingEvent before it is sent over the wire.
       * 
       */
      @Plugin(
                name = "MySocketAppender", 
                category = Core.CATEGORY_NAME,
                elementType = Appender.ELEMENT_TYPE,
                printObject = true)
      public class MySocketAppender extends SocketAppender {
          
          protected MySocketAppender(String name, Layout<? extends Serializable> layout, Filter filter, AbstractSocketManager manager, boolean ignoreExceptions, boolean immediateFlush, Advertiser advertiser, Property[] properties) {
              super(name, layout, filter, manager, ignoreExceptions, immediateFlush, advertiser, properties);
          }
          
          @PluginBuilderFactory
          public static Builder newBuilder() {
              return new Builder();
          }
          
          @Override
          public void append(LogEvent event) {
              ThreadContext.put("Thread ID", Thread.currentThread().getName() + DDThreadContextManager.getThreadTraceId());
              ThreadContext.put("Client ID", DDThreadContextManager.getThreadSessionId());
      
              AdminService adminService = AdminServiceFactory.getAdminService();
              String processName = (adminService != null) ? adminService.getProcessName() : "null";
              ThreadContext.put("App server", processName == null ? "null" : processName);
              
              super.append(event);
              
              ThreadContext.clearAll();
          }
          
          /**
           * Builds a MySocketAppender.
           */
          public static class Builder extends SocketAppender.Builder {        
              @Override
              public MySocketAppender build() {
                  boolean immediateFlush = isImmediateFlush();
                  final boolean bufferedIo = isBufferedIo();
                  final Layout<? extends Serializable> layout = getLayout();
                  if (layout == null) {
                      AbstractLifeCycle.LOGGER.error("No layout provided for MySocketAppender");
                      return null;
                  }            
      
                  final String name = getName();
                  if (name == null) {
                      AbstractLifeCycle.LOGGER.error("No name provided for MySocketAppender");
                      return null;
                  }
      
                  final Protocol protocol = getProtocol();
                  final Protocol actualProtocol = protocol != null ? protocol : Protocol.TCP;
                  if (actualProtocol == Protocol.UDP) {
                      immediateFlush = true;
                  }
      
                  final AbstractSocketManager manager = SocketAppender.createSocketManager(name, actualProtocol, getHost(), getPort(),
                          getConnectTimeoutMillis(), getSslConfiguration(), getReconnectDelayMillis(), getImmediateFail(), layout, getBufferSize(), getSocketOptions());
      
                  return new MySocketAppender(name, layout, getFilter(), manager, isIgnoreExceptions(),
                          !bufferedIo || immediateFlush, getAdvertise() ? getConfiguration().getAdvertiser() : null,
                          getPropertyArray());
              }
          }
      }
      

      log4j2.xml:

      <?xml version="1.0" encoding="UTF-8"?>
      <Configuration status="debug" packages="com.foo.bar">
          <Properties>
              <Property name="baseDir">C:/temp</Property>
          </Properties>
          
          <Appenders>
              <MySocketAppender name="socket" host="localhost" port="11005" reconnectionDelayMillis="1000" >
                  <JsonLayout properties="true" compact="true" />
              </MySocketAppender>
           
              <MyConsoleAppender name="console">
                  <PatternLayout pattern="%-5p %d{ISO8601} - %n%m%nThread ID: &lt;%X{Thread ID}&gt;%nClient ID: &lt;%X{Client ID}&gt;%nApp Server: &lt;%X{App server}&gt;%n%n" />
              </MyConsoleAppender>
          </Appenders>
          
          <Loggers>
              <Root level="DEBUG">
                   <Appender-Ref ref="socket" />
              </Root>
          </Loggers>
      </Configuration>
       

      This application runs with the 1.8 IBM VM. Version info:

      java version "1.8.0_321"
      Java(TM) SE Runtime Environment (build 8.0.7.5 - pxa6480sr7fp5-20220208_01(SR7 FP5))
      IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20220104_19630 (JIT enabled, AOT enabled)
      OpenJ9   - 2d4c7d9
      OMR      - 59845b7
      IBM      - 3c151c1)
      JCL - 20220120_01 based on Oracle jdk8u321-b07
      

      Attachments

        Activity

          People

            Unassigned Unassigned
            ccombar Curt Combar
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: