Pinpoint: Log4j2 plugin

[emeroad]

Add Log4j2 pluign

[yjqg6666]

You may review PR #5969. Agent-IT need to be checked.

[minwoo-jung]

@yjqg6666
OK I will improve #5969, #5405 issue myself.
Because #5969 code have some problems.
The reason is described in detail in issue #5489.

If I solve the problem, I'll explain.

[yjqg6666]

Agent-IT, updated.
Now the test code for versions 2.0~2.5 are OK, but not working with log4j 2.6+(2.6 included). But it's working with all my applications, TxId & PspanId logged.

When debugging with Intellij Idea, it's stuck after:

019-09-06 16:00:35 INFO pinpoint agent started normally.
Listening for transport dt_socket at address: 1296
2019-09-06 16:00:38 WARN request timed out while waiting for response.

[emeroad]

@yjqg6666 Hi~
ITTest creates additional child process, so you must use a remote debugger.

[yjqg6666]

Working on it.

[emeroad]

👍 Good

[yjqg6666]

Just revisited the log4j2 code, the instrument class should be the impl. classes of org.apache.logging.log4j.spi.ExtendedLogger. Just the interception of the logMessage method would be enough.
org.apache.logging.log4j.core.async.AsyncLogger has been transformed in the PR code.
Just some refactoring will work for all.

[yjqg6666]

Update: now it's working for log4j2 2.0~2.12.0. I will check why the latest version version 2.12.1 is not working.

[yjqg6666]

Now all the versions of log4j2 are supported.

[minwoo-jung]

@yjqg6666

First of all I thank you for your hard work.^^
I also analyzed to find the class to be profiled.

I think LogEventFactory's implementation class is most appropriate.

• org.apache.logging.log4j.core.impl.DefaultLogEventFactory
• org.apache.logging.log4j.core.impl.ReusableLogEventFactory

I've briefly explained this before. comment

I haven't tested it yet, but it won't cause any problems.
There is no need to enter the target class from the user in pinpoint.config.

It's not wrong to enter a Logger object directly, but it can't be used easily if the user doesn't understand the logger object.
So we should be able to profile automatically as possible.

I hope you will wait until I have completed the development.
Then I hope you review my code and send me a PR about it.
I want to explain to you in detail how to profile, but it takes too long, so I'll develop some.

[yjqg6666]

Thanks for your reply. Good to know. I will wait for the official support for log4j2.

It's configurable, coz some app. have their own implementation for the logger interface. The default configuration should be ok for the most of the users.

[minwoo-jung]

@yjqg6666
I will push the code soon. The test is already done.
I will finish the official support for this time.^^

[minwoo-jung]

Hi @yjqg6666

I've merged code.

As I developed, I tested using the test code(Log4j2IT.java) you developed.
Your code is all good except for the profiler target class.
Also the code that checks the libaray version of the code you committed in the past gave us a new idea.
Although not used by the log4j2 plugin, this is a good idea to help develop other plugins.

Your test code will be ready to use without modification.
This is because you executed the Log4j2IT code with debugging yourself.
If you modify the test code and send me a PR, I would like to merge.
Can you send me a PR? If you don't want, I'll push the code myself.^^

I will include the log4j2 plugin in the 1.8.5 release.

[yjqg6666]

So glad that it's done and would be available in the stable version 1.8.5.

[minwoo-jung]

@yjqg6666
After build check, I will merge your PR.
I've already run the log4j2 plugin test several times in my application and it should be fine.
But can you test it in your application to double check it?
Since you understand the logic correctly, I want to make sure it works in your application.

[yjqg6666]

@minwoo-jung
It's not working with async logger.
It can be enabled by setting

-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

and addition of dependency below

        <dependency>
            <groupId>com.lmax</groupId>
            <artifactId>disruptor</artifactId>
            <version>3.4.2</version>
        </dependency>

It's working in other situations.

[yjqg6666]

@minwoo-jung You can test it with my simplified repo .

[minwoo-jung]

@yjqg6666
i tested Asyncappender, Syncappender.
I didn't know all aync function for log4j2 new feature.

i will analysis all async function.

[yjqg6666]

ThreadContext is fetched when this method is called.

org.apache.logging.log4j.core.async.AsyncLogger#initTranslator(org.apache.logging.log4j.core.async.RingBufferLogEventTranslator, java.lang.String, java.lang.StackTraceElement, org.apache.logging.log4j.Level, org.apache.logging.log4j.Marker, org.apache.logging.log4j.message.Message, java.lang.Throwable)

[yjqg6666]

Here is the call stack:

getImmutableStack:407, ThreadContext (org.apache.logging.log4j)
initTranslator:267, AsyncLogger (org.apache.logging.log4j.core.async)
logWithThreadLocalTranslator:223, AsyncLogger (org.apache.logging.log4j.core.async)
access$000:67, AsyncLogger (org.apache.logging.log4j.core.async)
log:152, AsyncLogger$1 (org.apache.logging.log4j.core.async)
log:136, AsyncLogger (org.apache.logging.log4j.core.async)
tryLogMessage:2190, AbstractLogger (org.apache.logging.log4j.spi)
logMessageTrackRecursion:2144, AbstractLogger (org.apache.logging.log4j.spi)
logMessageSafely:2127, AbstractLogger (org.apache.logging.log4j.spi)
logMessage:2003, AbstractLogger (org.apache.logging.log4j.spi)
logIfEnabled:1975, AbstractLogger (org.apache.logging.log4j.spi)
warn:2651, AbstractLogger (org.apache.logging.log4j.spi)
config:19, TestController (com.example.test)
invoke0:-1, NativeMethodAccessorImpl (sun.reflect)
invoke:62, NativeMethodAccessorImpl (sun.reflect)
invoke:43, DelegatingMethodAccessorImpl (sun.reflect)
invoke:498, Method (java.lang.reflect)
doInvoke:190, InvocableHandlerMethod (org.springframework.web.method.support)
invokeForRequest:138, InvocableHandlerMethod (org.springframework.web.method.support)
invokeAndHandle:104, ServletInvocableHandlerMethod (org.springframework.web.servlet.mvc.method.annotation)
invokeHandlerMethod:892, RequestMappingHandlerAdapter (org.springframework.web.servlet.mvc.method.annotation)
handleInternal:797, RequestMappingHandlerAdapter (org.springframework.web.servlet.mvc.method.annotation)
handle:87, AbstractHandlerMethodAdapter (org.springframework.web.servlet.mvc.method)
doDispatch:1039, DispatcherServlet (org.springframework.web.servlet)
doService:942, DispatcherServlet (org.springframework.web.servlet)
processRequest:1005, FrameworkServlet (org.springframework.web.servlet)
doGet:897, FrameworkServlet (org.springframework.web.servlet)
service:634, HttpServlet (javax.servlet.http)
service:882, FrameworkServlet (org.springframework.web.servlet)
service:741, HttpServlet (javax.servlet.http)
internalDoFilter:231, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilter:53, WsFilter (org.apache.tomcat.websocket.server)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:99, RequestContextFilter (org.springframework.web.filter)
doFilter:118, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:92, FormContentFilter (org.springframework.web.filter)
doFilter:118, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:93, HiddenHttpMethodFilter (org.springframework.web.filter)
doFilter:118, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
doFilterInternal:200, CharacterEncodingFilter (org.springframework.web.filter)
doFilter:118, OncePerRequestFilter (org.springframework.web.filter)
internalDoFilter:193, ApplicationFilterChain (org.apache.catalina.core)
doFilter:166, ApplicationFilterChain (org.apache.catalina.core)
invoke:202, StandardWrapperValve (org.apache.catalina.core)
invoke:96, StandardContextValve (org.apache.catalina.core)
invoke:490, AuthenticatorBase (org.apache.catalina.authenticator)
invoke:139, StandardHostValve (org.apache.catalina.core)
invoke:92, ErrorReportValve (org.apache.catalina.valves)
invoke:74, StandardEngineValve (org.apache.catalina.core)
service:343, CoyoteAdapter (org.apache.catalina.connector)
service:408, Http11Processor (org.apache.coyote.http11)
process:66, AbstractProcessorLight (org.apache.coyote)
process:853, AbstractProtocol$ConnectionHandler (org.apache.coyote)
doRun:1587, NioEndpoint$SocketProcessor (org.apache.tomcat.util.net)
run:49, SocketProcessorBase (org.apache.tomcat.util.net)
runWorker:1149, ThreadPoolExecutor (java.util.concurrent)
run:624, ThreadPoolExecutor$Worker (java.util.concurrent)
run:61, TaskThread$WrappingRunnable (org.apache.tomcat.util.threads)
run:748, Thread (java.lang)

[yjqg6666]

Add additional target class ?

[minwoo-jung]

@yjqg6666
Thank you for further analysis.
I'm sorry. Today I have no time to look further. I will see and tell you tomorrow.
I will take a look at the class you mentioned first.

[minwoo-jung]

Hi @yjqg6666

I found a way to support async Logger. commit
We will be able to support all cases.
I've already tested it on versions 2.11 and 2.7 and it worked fine.

There are two things I would like to suggest.

1. I hope you double check in your application. And let me know the result.

1. Now we have to develop test code for using async Logger, How about you do it?

To give you a hint..
use JvmArgument annotation. and add custom log4j2 configuration file.

If you take a long time or do not understand, I will do it myself. please answer about my question.^^

@RunWith(PinpointPluginTestSuite.class)
@PinpointAgent(AgentPath.PATH)
@PinpointConfig("pinpoint-spring-bean-test.config")
@JvmArgument("-Dlog4j.configuration=com/navercorp/pinpoint/log4j2/log4j2-forAysncLogger.xml -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector")
@Dependency({"org.apache.logging.log4j:log4j-core:[2.0,)", "com.lmax:disruptor:[3.4.2]"})
public class Log4j2ForAsyncLoggerIT {

    @Test
    public void test() {
        Logger logger = LogManager.getLogger();
        logger.error("for log4j2 plugin test");

        Assert.assertNotNull(ThreadContext.get("PtxId"));
        Assert.assertNotNull(ThreadContext.get("PspanId"));
    }
}

[yjqg6666]

You could just push your test code. It's fine.　I will check it soon.

[yjqg6666]

It works like a charm. It's working in all my projects. Waiting for the port to the stable version.

[minwoo-jung]

@yjqg6666
good! I will check your test code.
Your code doesn't seem to have a problem, so I merge it.

[yjqg6666]

I backport-ed to 1.8.x and checked.

[minwoo-jung]

@yjqg6666
Good! You make everything work smooth.^^
Have you ever tested log4j2 using 1.8.5-snapshot in your application?

[minwoo-jung]

I'll double check using your branch 1.8.x-log4j2-pr in our project.
Sometimes it can't work because of changes in internal apis.

[minwoo-jung]

@yjqg6666
Now let's close the issue.

Thank you for your hard work and contribution.
The response and follow up was so fast that it was so good.^^