inspectit-ocelot
inspectit-ocelot copied to clipboard
Published
20 hours ago •
inspectIT
inspectIT
Ocelot Trace ID Injection Using MDC causes IllegalStateException when stopping logback
Ocelot Trace ID Injection Using MDC causes IllegalStateException when stopping logback
Running as agent Version 1.3
Tomcat version: 9.0.34 Java: OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_252-b09) Test environment: Windows 10. But the staging environment that shows the same symptoms is running in a Linux container.
I am following these instruction to stop the Logback logger when the context is being stopped/undeployed: http://logback.qos.ch/manual/configuration.html#stopContext
import org.sflf4j.LoggerFactory;
import ch.qos.logback.classic.LoggerContext;
...
// assume SLF4J is bound to logback-classic in the current environment
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
loggerContext.stop();
And I am disabling the automatic injection of the LogbackServletContainerInitializer. Because it stops the logger to soon in our projects.
http://logback.qos.ch/manual/configuration.html#webShutdownHook
<web-app>
<context-param>
<param-name>logbackDisableServletContainerInitializer</param-name>
<param-value>true</param-value>
</context-param>
....
</web-app>
This doesn't play well when using InspectIT Ocelot Trace ID Injection Using MDC: https://inspectit.github.io/inspectit-ocelot/docs/tracing/log-correlation
Full InspectIT Ocelot config in test project
---
inspectit:
service-name: TEST
tracing:
enabled: False
log-correlation:
trace-id-mdc-injection:
enabled: true
I get the following stacktrace when I stop the context in Tomcat.
NOTE! You have to log at least once with a logger to get this error. If you stop the context before you use a simple logger.info("foo"). The error will not occur.
10-Jun-2020 16:07:25.182 INFO [inspectit-thread-0] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1385)
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1373)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1226)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
at java.lang.Class.getDeclaredMethods0(Native Method)
at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)
at java.lang.Class.getDeclaredMethod(Class.java:2128)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.lookup(WeakMethodReference.java:55)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.<init>(WeakMethodReference.java:28)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.create(WeakMethodReference.java:32)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.adapters.Slf4jMDCAdapter.get(Slf4jMDCAdapter.java:30)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.lambda$onNewClassesDiscovered$4(MDCAccess.java:91)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1556)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.onNewClassesDiscovered(MDCAccess.java:88)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$null$0(NewClassDiscoveryService.java:76)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$new$1(NewClassDiscoveryService.java:76)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.LogTraceCorrelatorImpl.lambda$wrap$1(LogTraceCorrelatorImpl.java:64)
at io.grpc.Context$1.run(Context.java:595)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
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:747)
2020-06-10 16:07:25,189 ERROR 32771 --- [inspectIT] [pectit-thread-0] r.i.o.c.i.correlation.log.MDCAccess : Error creating log-correlation MDC adapter for class org.slf4j.MDC
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1385)
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1373)
... 34 common frames omitted
Wrapped by: java.lang.ClassNotFoundException: Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1375)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1226)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
... 32 common frames omitted
Wrapped by: java.lang.NoClassDefFoundError: org/slf4j/MDC$MDCCloseable
at java.lang.Class.getDeclaredMethods0(Native Method)
at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)
at java.lang.Class.getDeclaredMethod(Class.java:2128)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.lookup(WeakMethodReference.java:55)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.<init>(WeakMethodReference.java:28)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.create(WeakMethodReference.java:32)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.adapters.Slf4jMDCAdapter.get(Slf4jMDCAdapter.java:30)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.lambda$onNewClassesDiscovered$4(MDCAccess.java:91)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1556)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.onNewClassesDiscovered(MDCAccess.java:88)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$null$0(NewClassDiscoveryService.java:76)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$new$1(NewClassDiscoveryService.java:76)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.LogTraceCorrelatorImpl.lambda$wrap$1(LogTraceCorrelatorImpl.java:64)
at io.grpc.Context$1.run(Context.java:595)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
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:747)
Fun facts
Sometimes I don't get this stack trace. Instead Tomcat reports a memory leak when using the button "Find leaks" after stopping the context. This is what started me looking into this. Once I got both the stacktrace and the memory leak alert...
If I disable trace injection dynamically (and wait for the confirmation from the agent) and then I stop the context. I don't get this error or alerts about memory leaks.
Full log from a simple test application
Test application: https://github.com/martonsz/inspectit-ocelot-logback-test Precompiled war file is available in the repo: https://github.com/martonsz/inspectit-ocelot-logback-test/tree/master/sample-war
The simple test application contains one WebServlet that logs Logging with logback when receiving a GET call. And a WebListener that stops the logger when the context is destroyed.
Using CATALINA_BASE: "D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34"
Using CATALINA_HOME: "D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34"
Using CATALINA_TMPDIR: "D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\temp"
Using JRE_HOME: "D:\building\marton_dev\apps\java\jdk8"
Using CLASSPATH: "D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\bin\bootstrap.jar;D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\bin\tomcat-juli.jar"
10-Jun-2020 16:06:52.198 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name: Apache Tomcat/9.0.34
10-Jun-2020 16:06:52.201 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Apr 3 2020 12:02:52 UTC
10-Jun-2020 16:06:52.201 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.34.0
10-Jun-2020 16:06:52.202 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Windows 10
10-Jun-2020 16:06:52.202 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 10.0
10-Jun-2020 16:06:52.202 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64
10-Jun-2020 16:06:52.202 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: D:\building\marton_dev\apps\java\jdk8\jre
10-Jun-2020 16:06:52.202 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 1.8.0_252-b09
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: AdoptOpenJDK
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\conf\logging.properties
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -DpropertiesFile=kubernetesStaging.properties
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -javaagent:D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\inspectit\inspectit-ocelot-agent-1.3.jar
10-Jun-2020 16:06:52.203 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Duser.language=en
10-Jun-2020 16:06:52.204 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Duser.region=US
10-Jun-2020 16:06:52.204 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Duser.country=SE
10-Jun-2020 16:06:52.204 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dfile.encoding=UTF-8
10-Jun-2020 16:06:52.204 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Duser.timezone=Europe/Stockholm
10-Jun-2020 16:06:52.207 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
10-Jun-2020 16:06:52.208 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34
10-Jun-2020 16:06:52.208 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34
10-Jun-2020 16:06:52.209 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\temp
10-Jun-2020 16:06:52.212 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [D:\building\marton_dev\apps\java\jdk8\bin;C:\Windows\Sun\Java\bi...
10-Jun-2020 16:06:52.406 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
10-Jun-2020 16:06:52.429 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [394] milliseconds
10-Jun-2020 16:06:52.451 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
10-Jun-2020 16:06:52.451 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.34]
10-Jun-2020 16:06:52.466 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\LogbackTest.war]
2020-06-10 16:06:52,517 INFO 99 --- [inspectIT] [ Thread-0] rocks.inspectit.ocelot.core.AgentImpl : Starting inspectIT Ocelot Agent...
2020-06-10 16:06:52,522 INFO 104 --- [inspectIT] [ Thread-0] rocks.inspectit.ocelot.core.AgentImpl :
Version: 1.3
2020-06-10 16:06:52,522 INFO 104 --- [inspectIT] [ Thread-0] rocks.inspectit.ocelot.core.AgentImpl :
Build Date: Thu May 07 13:59:13 UTC 2020
2020-06-10 16:06:52,523 INFO 105 --- [inspectIT] [ Thread-0] rocks.inspectit.ocelot.core.AgentImpl : OpenCensus was loaded in inspectIT classloader
10-Jun-2020 16:06:52.744 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
16:06:52,800 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
16:06:52,800 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
16:06:52,800 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/building/marton_dev/marton_load/tomcat/apache-tomcat-9.0.34/webapps/LogbackTest/WEB-INF/classes/logback.xml]
16:06:52,856 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/D:/building/marton_dev/marton_load/tomcat/apache-tomcat-9.0.34/webapps/LogbackTest/WEB-INF/classes/logback.xml]
16:06:52,857 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 30 seconds
16:06:52,859 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:06:52,863 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
16:06:52,870 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:06:52,904 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
16:06:52,904 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
16:06:52,906 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:06:52,907 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@42b3b079 - Registering current configuration as safe fallback point
16:06:52,784 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContainerInitializer@11c20519 - Due to deployment instructions will NOT register an instance of class ch.qos.logback.classic.servlet.LogbackServletContextListener to the current web-app
####### Wed Jun 10 16:06:52 CEST 2020 (System.out.println): Initialized
10-Jun-2020 16:06:52.921 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\LogbackTest.war] has finished in [455] ms
10-Jun-2020 16:06:52.921 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\host-manager]
10-Jun-2020 16:06:52.947 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
10-Jun-2020 16:06:52.951 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\host-manager] has finished in [30] ms
10-Jun-2020 16:06:52.952 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\manager]
10-Jun-2020 16:06:52.975 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
2020-06-10 16:06:53,026 INFO 608 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : initializing file based configuration from dir: D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\inspectit\config
2020-06-10 16:06:53,060 INFO 642 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : Registered Configuration Sources:
2020-06-10 16:06:53,061 INFO 643 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : systemProperties
2020-06-10 16:06:53,062 INFO 644 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : systemEnvironment
2020-06-10 16:06:53,062 INFO 644 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : fileBasedConfig
2020-06-10 16:06:53,062 INFO 644 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : fileBasedConfig/config.yaml
2020-06-10 16:06:53,062 INFO 644 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : inspectitDefaults
2020-06-10 16:06:53,062 INFO 644 --- [inspectIT] [ Thread-0] r.i.o.core.config.InspectitEnvironment : inspectitEnvironment
10-Jun-2020 16:06:53.386 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\manager] has finished in [434] ms
10-Jun-2020 16:06:53.387 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\ROOT]
10-Jun-2020 16:06:53.409 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
10-Jun-2020 16:06:53.411 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [D:\building\marton_dev\marton_load\tomcat\apache-tomcat-9.0.34\webapps\ROOT] has finished in [24] ms
10-Jun-2020 16:06:53.414 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
10-Jun-2020 16:06:53.423 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [992] milliseconds
2020-06-10 16:06:55,164 INFO 2746 --- [inspectIT] [ Thread-0] i.o.c.m.s.AbstractPollingMetricsRecorder : Enabling ClassLoaderMetricsRecorder.
2020-06-10 16:06:55,166 INFO 2748 --- [inspectIT] [ Thread-0] r.i.o.c.m.system.GCMetricsRecorder : Enabling GC metrics recorder
2020-06-10 16:06:55,167 INFO 2749 --- [inspectIT] [ Thread-0] i.o.c.m.s.AbstractPollingMetricsRecorder : Enabling DiskMetricsRecorder.
2020-06-10 16:06:55,168 INFO 2750 --- [inspectIT] [ Thread-0] i.o.c.m.s.AbstractPollingMetricsRecorder : Enabling ThreadMetricsRecorder.
2020-06-10 16:06:55,169 INFO 2751 --- [inspectIT] [ Thread-0] i.o.c.m.s.AbstractPollingMetricsRecorder : Enabling MemoryMetricsRecorder.
2020-06-10 16:06:55,171 INFO 2753 --- [inspectIT] [ Thread-0] r.i.o.c.m.s.ProcessorMetricsRecorder : 'getAverageLoad()' is not available on this system. Metric system/load/average/1m is unavailable.
2020-06-10 16:06:55,171 INFO 2753 --- [inspectIT] [ Thread-0] i.o.c.m.s.AbstractPollingMetricsRecorder : Enabling ProcessorMetricsRecorder.
2020-06-10 16:06:55,244 INFO 2826 --- [inspectIT] [ Thread-0] o.c.c.p.f.ConfigurationDirectoriesPoller : Starting config directory polling service..
2020-06-10 16:06:55,255 INFO 2837 --- [inspectIT] [ Thread-0] r.i.o.c.c.p.h.HttpConfigurationPoller : Starting HTTP configuration polling service.
2020-06-10 16:06:55,259 INFO 2841 --- [inspectIT] [ Thread-0] r.i.o.c.e.PrometheusExporterService : Starting Prometheus Exporter on 0.0.0.0:8888
####### Wed Jun 10 16:07:08 CEST 2020 (System.out.println): Stopping logger
10-Jun-2020 16:07:11.698 INFO [http-nio-8080-exec-10] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
16:07:11,717 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
16:07:11,717 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
16:07:11,717 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/building/marton_dev/marton_load/tomcat/apache-tomcat-9.0.34/webapps/LogbackTest/WEB-INF/classes/logback.xml]
16:07:11,765 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/D:/building/marton_dev/marton_load/tomcat/apache-tomcat-9.0.34/webapps/LogbackTest/WEB-INF/classes/logback.xml]
16:07:11,766 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 30 seconds
16:07:11,767 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
16:07:11,771 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
16:07:11,778 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
16:07:11,806 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
16:07:11,807 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
16:07:11,808 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
16:07:11,809 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1e7af251 - Registering current configuration as safe fallback point
16:07:11,703 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContainerInitializer@1a3a06f5 - Due to deployment instructions will NOT register an instance of class ch.qos.logback.classic.servlet.LogbackServletContextListener to the current web-app
####### Wed Jun 10 16:07:11 CEST 2020 (System.out.println): Initialized
2020-06-10 16:07:17.645 INFO s.l.f.TestServlet [http-nio-8080-exec-1] Logging with logback
####### Wed Jun 10 16:07:22 CEST 2020 (System.out.println): Stopping logger
10-Jun-2020 16:07:25.182 INFO [inspectit-thread-0] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1385)
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1373)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1226)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
at java.lang.Class.getDeclaredMethods0(Native Method)
at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)
at java.lang.Class.getDeclaredMethod(Class.java:2128)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.lookup(WeakMethodReference.java:55)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.<init>(WeakMethodReference.java:28)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.create(WeakMethodReference.java:32)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.adapters.Slf4jMDCAdapter.get(Slf4jMDCAdapter.java:30)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.lambda$onNewClassesDiscovered$4(MDCAccess.java:91)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1556)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.onNewClassesDiscovered(MDCAccess.java:88)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$null$0(NewClassDiscoveryService.java:76)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$new$1(NewClassDiscoveryService.java:76)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.LogTraceCorrelatorImpl.lambda$wrap$1(LogTraceCorrelatorImpl.java:64)
at io.grpc.Context$1.run(Context.java:595)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
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:747)
2020-06-10 16:07:25,189 ERROR 32771 --- [inspectIT] [pectit-thread-0] r.i.o.c.i.correlation.log.MDCAccess : Error creating log-correlation MDC adapter for class org.slf4j.MDC
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1385)
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1373)
... 34 common frames omitted
Wrapped by: java.lang.ClassNotFoundException: Illegal access: this web application instance has been stopped already. Could not load [org.slf4j.MDC$MDCCloseable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1375)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1226)
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
... 32 common frames omitted
Wrapped by: java.lang.NoClassDefFoundError: org/slf4j/MDC$MDCCloseable
at java.lang.Class.getDeclaredMethods0(Native Method)
at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)
at java.lang.Class.getDeclaredMethod(Class.java:2128)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.lookup(WeakMethodReference.java:55)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.<init>(WeakMethodReference.java:28)
at rocks.inspectit.ocelot.core.utils.WeakMethodReference.create(WeakMethodReference.java:32)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.adapters.Slf4jMDCAdapter.get(Slf4jMDCAdapter.java:30)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.lambda$onNewClassesDiscovered$4(MDCAccess.java:91)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1556)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.MDCAccess.onNewClassesDiscovered(MDCAccess.java:88)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$null$0(NewClassDiscoveryService.java:76)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at rocks.inspectit.ocelot.core.instrumentation.NewClassDiscoveryService.lambda$new$1(NewClassDiscoveryService.java:76)
at rocks.inspectit.ocelot.core.instrumentation.correlation.log.LogTraceCorrelatorImpl.lambda$wrap$1(LogTraceCorrelatorImpl.java:64)
at io.grpc.Context$1.run(Context.java:595)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
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:747)
