[
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.
*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.:
{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.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}
> 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.
> *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.:
> {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)
