search

oracle / graal

GraalVM compiles Java applications into native executables that start instantly, scale fast, and use fewer compute resources 🚀
https://www.graalvm.org
Other
19.99k stars 1.6k forks source link

Log4j2 issues #1209

Open vojkny opened 5 years ago

vojkny commented 5 years ago

(Possibly related with https://github.com/oracle/graal/issues/808)

Within our graal-compiled project we have issue with log4j2. When anything is to be logged, it gets to reflection issues.

https://gitlab.com/GoOutPublic/MicronautKotlinDemo/blob/master/

We have declared reflect-config.json as follows:

https://gitlab.com/GoOutPublic/MicronautKotlinDemo/blob/master/reflect-config.json

The error can be seen in this CI run:

https://gitlab.com/GoOutPublic/MicronautKotlinDemo/-/jobs/204230245

curl -v http://localhost:8080/logtest
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* About to connect() to localhost port 8080 (#0)
*   Trying ::1...
* Connected to localhost (::1) port 8080 (#0)
> GET /logtest HTTP/1.1
> User-Agent: curl/7.29.0
> Host: localhost:8080
> Accept: */*
> 
12:32:59.634 [nioEventLoopGroup-2-3] DEBUG i.m.h.server.netty.NettyHttpServer - Server runner-0277ea0f-project-12044576-concurrent-0:8080 Received Request: GET /logtest
12:32:59.634 [nioEventLoopGroup-2-3] DEBUG i.m.h.s.netty.RoutingInBoundHandler - Matching route GET - /logtest
12:32:59.635 [nioEventLoopGroup-2-3] DEBUG i.m.h.s.netty.RoutingInBoundHandler - Matched route GET - /logtest to controller class net.goout.micronaut.Log4jController
12:32:59.636 [pool-3-thread-1] DEBUG i.m.context.DefaultBeanContext - Finding candidate beans for type: class net.goout.micronaut.Log4jController
12:32:59.636 [pool-3-thread-1] DEBUG i.m.context.DefaultBeanContext - Resolved bean candidates [Definition: net.goout.micronaut.Log4jController] for type: class net.goout.micronaut.Log4jController
12:32:59.636 [pool-3-thread-1] DEBUG i.m.context.DefaultBeanContext - Finalized bean definitions candidates: [Definition: net.goout.micronaut.Log4jController]
12:32:59.636 [pool-3-thread-1] DEBUG i.m.context.DefaultBeanContext - Found concrete candidate [Definition: net.goout.micronaut.Log4jController] for type: net.goout.micronaut.Log4jController 
ERROR StatusLogger Unrecognized format specifier [d]
ERROR StatusLogger Unrecognized conversion specifier [d] starting at position 16 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [thread]
ERROR StatusLogger Unrecognized conversion specifier [thread] starting at position 25 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [level]
ERROR StatusLogger Unrecognized conversion specifier [level] starting at position 35 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [logger]
ERROR StatusLogger Unrecognized conversion specifier [logger] starting at position 47 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [msg]
ERROR StatusLogger Unrecognized conversion specifier [msg] starting at position 54 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [n]
ERROR StatusLogger Unrecognized conversion specifier [n] starting at position 56 in conversion pattern.
ERROR StatusLogger No Log4j 2 configuration file found. Using default configuration (logging only errors to the console), or user programmatically provided configurations. Set system property 'log4j2.debug' to show Log4j 2 internal initialization logging. See https://logging.apache.org/log4j/2.x/manual/configuration.html for instructions on how to configure Log4j 2
ERROR StatusLogger Unrecognized format specifier [d]
ERROR StatusLogger Unrecognized conversion specifier [d] starting at position 16 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [thread]
ERROR StatusLogger Unrecognized conversion specifier [thread] starting at position 25 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [level]
ERROR StatusLogger Unrecognized conversion specifier [level] starting at position 35 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [logger]
ERROR StatusLogger Unrecognized conversion specifier [logger] starting at position 47 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [msg]
ERROR StatusLogger Unrecognized conversion specifier [msg] starting at position 54 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [n]
ERROR StatusLogger Unrecognized conversion specifier [n] starting at position 56 in conversion pattern.
ERROR StatusLogger Could not unregister MBeans for org.apache.logging.log4j2:type=3546198d
 java.lang.NullPointerException
    at org.apache.logging.log4j.core.jmx.Server.unregisterAllMatching(Server.java:337)
    at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:261)
    at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:165)
    at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:141)
    at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:558)
    at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:619)
    at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:636)
    at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:231)
    at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:153)
    at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
    at org.apache.logging.log4j.LogManager.getContext(LogManager.java:194)
    at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:581)
    at net.goout.micronaut.Log4jController.<init>(Log4jController.kt:14)
    at net.goout.micronaut.$Log4jControllerDefinition.build(Unknown Source)
    at io.micronaut.context.DefaultBeanContext.doCreateBean(DefaultBeanContext.java:1474)
    at io.micronaut.context.DefaultBeanContext.createAndRegisterSingleton(DefaultBeanContext.java:2143)
    at io.micronaut.context.DefaultBeanContext.getBeanForDefinition(DefaultBeanContext.java:1829)
    at io.micronaut.context.DefaultBeanContext.getBeanInternal(DefaultBeanContext.java:1809)
    at io.micronaut.context.DefaultBeanContext.getBean(DefaultBeanContext.java:567)
    at io.micronaut.context.DefaultBeanContext$BeanExecutionHandle.getTarget(DefaultBeanContext.java:2661)
    at io.micronaut.context.DefaultBeanContext$BeanExecutionHandle.invoke(DefaultBeanContext.java:2682)
    at io.micronaut.web.router.AbstractRouteMatch.execute(AbstractRouteMatch.java:236)
    at io.micronaut.web.router.RouteMatch.execute(RouteMatch.java:122)
    at io.micronaut.http.server.netty.RoutingInBoundHandler.lambda$buildResultEmitter$17(RoutingInBoundHandler.java:1348)
    at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.Flowable.subscribe(Flowable.java:14752)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:37)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.Flowable.subscribe(Flowable.java:14752)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.internal.operators.flowable.FlowableSwitchIfEmpty.subscribeActual(FlowableSwitchIfEmpty.java:32)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.Flowable.subscribe(Flowable.java:14752)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.Flowable.subscribe(Flowable.java:14755)
    at io.micronaut.http.context.ServerRequestTracingPublisher.lambda$subscribe$0(ServerRequestTracingPublisher.java:52)
    at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:52)
    at io.micronaut.http.context.ServerRequestTracingPublisher.subscribe(ServerRequestTracingPublisher.java:52)
    at io.reactivex.internal.operators.flowable.FlowableFromPublisher.subscribeActual(FlowableFromPublisher.java:29)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.Flowable.subscribe(Flowable.java:14752)
    at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
    at io.reactivex.Flowable.subscribe(Flowable.java:14805)
    at io.reactivex.Flowable.subscribe(Flowable.java:14752)
    at io.reactivex.internal.operators.flowable.FlowableSubscribeOn$SubscribeOnSubscriber.run(FlowableSubscribeOn.java:82)
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:288)
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:253)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:473)
    at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)
remkop commented 5 years ago

@knyttl @cstancu FYI, this "Unrecognized format specifier" stuff is Log4j2 encountering a format specifier in the pattern that it does not have a converter for. Log4j2 registers converters (and all other configuration components) through an annotation-based plugin mechanism. This plugin mechanism reads components from META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat in the jar. The log4j2-core jar has configuration for the Log4j built-in components, apps may contribute custom components by having this file in their own jar. This file is produced by an annotation processor in the log4j-core jar.

The file is in binary format and contains a bunch of stuff for each component, including its fully qualified class name. During log4j2 initialization, it reads this Log4j2Plugins.dat file and creates a plugin registry. After that, log4j reads the log4j2.xml configuration file and looks up elements from that config file in the plugin registry. At this stage, the plugin classes are instantiated, using reflection.

It seems to me that what is needed is a way to generate a reflect-config.json from the META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat in the log4j-core jar and potentially in app jars that have custom Log4j2 components.

The cleanest place to do this is in the Log4j2 annotation processor. I created https://issues.apache.org/jira/browse/LOG4J2-2604 for this.

remkop commented 5 years ago

@knyttl I could be wrong but your reflection-config.json is missing allDeclaredConstructors = true for the log4j classes, also, are you sure these sections work?

"methods": [
      { "name": "<init>", "parameterTypes": [] }
    ]
sdeleuze commented 1 year ago

See my recent comment on log4j2 native support here.