You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Curt Combar (Jira)" <ji...@apache.org> on 2022/08/04 13:05:00 UTC

[jira] [Updated] (LOG4J2-3567) ThreadContext in append() method of an Appender plugin?

     [ https://issues.apache.org/jira/browse/LOG4J2-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Curt Combar updated LOG4J2-3567:
--------------------------------
    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. Here is the code for the Socket Appender plugin.  Note the append() override. 

 
{code:java}
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());
        }
    }
}
{code}
 

 

This application runs with the 1.8 IBM VM. Version info:
{noformat}
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
{noformat}

  was:
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. Here is the code for the Socket Appender plugin.  Note the append() override. 

 
{code:java}
 package com.ibm.wcsx.llbean.common.utilities;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.
 * 
 * 2022-04-20 - Curt Combar - Converted to log4j2 implementation
 * 
 * @author John LaFortune
 */
@Plugin(
          name = "LLBSocketAppender", 
          category = Core.CATEGORY_NAME,
          elementType = Appender.ELEMENT_TYPE,
          printObject = true)
public class LLBSocketAppender extends SocketAppender {
    
    protected LLBSocketAppender(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 LLBSocketAppender.
     */
    public static class Builder extends SocketAppender.Builder {        @Override
        public LLBSocketAppender build() {
            boolean immediateFlush = isImmediateFlush();
            final boolean bufferedIo = isBufferedIo();
            final Layout<? extends Serializable> layout = getLayout();
            if (layout == null) {
                AbstractLifeCycle.LOGGER.error("No layout provided for LLBSocketAppender");
                return null;
            }            final String name = getName();
            if (name == null) {
                AbstractLifeCycle.LOGGER.error("No name provided for LLBSocketAppender");
                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 LLBSocketAppender(name, layout, getFilter(), manager, isIgnoreExceptions(),
                    !bufferedIo || immediateFlush, getAdvertise() ? getConfiguration().getAdvertiser() : null,
                    getPropertyArray());
        }
    }
}
{code}
 

 

This application runs with the 1.8 IBM VM. Version info:
{noformat}
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
{noformat}


> ThreadContext in append() method of an Appender plugin?
> -------------------------------------------------------
>
>                 Key: LOG4J2-3567
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-3567
>             Project: Log4j 2
>          Issue Type: Question
>          Components: Appenders
>    Affects Versions: 2.17.2
>            Reporter: Curt Combar
>            Priority: Major
>
> 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. Here is the code for the Socket Appender plugin.  Note the append() override. 
>  
> {code:java}
> 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());
>         }
>     }
> }
> {code}
>  
>  
> This application runs with the 1.8 IBM VM. Version info:
> {noformat}
> 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
> {noformat}



--
This message was sent by Atlassian Jira
(v8.20.10#820010)