[KIEKER-1978] Document / Fix Spring Monitoring

[rju]

JIRA Issue: KIEKER-1978 Document / Fix Spring Monitoring
Original Reporter: David Georg Reichelt

---

Currently, I’m trying to get Micro-company (https://github.com/idugalic/micro-company ) running with Kieker. This is a microservice example application that has been used in some case studies.

Unfortunately, monitoring does not work and Kiekers slf4j-versions block logging, so I also do not get any error messages. After building my fork (https://github.com/DaGeRe/micro-company ) on the master branch (mvn clean install -DskipTests), the application can be started regularly in monolithic/target/docker using java -cp monolithic-0.0.1-SNAPSHOT.jar org.springframework.boot.loader.JarLauncher.

Adding the javaagent with default configurations ends with no logs:

java -javaagent:kieker-1.15.4-aspectj.jar -cp monolithic-0.0.1-SNAPSHOT.jar org.springframework.boot.loader.JarLauncher

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

and with a lot of logging data, that are only spring of logback data:

reicheltreichelt-desktop:~/nvme/workspaces/kiekerworkspace/micro-company/monolithic/target/docker$ cat /tmp/kieker-20240315-144756-21219659539625-UTC--KIEKER-SINGLETON/kieker*dat | wc -l
7928688

These records are mostly spring-internal things, e.g., org.springframework.boot.loader.jar.JarFileEntries.swap

After these ~7 million records, nothing happens (no more kieker entries, no response from the application via http, no logs). The application is not started in this configuration, so for some reason, adding the javaagent to a spring application in this context stops the spring application from being executed.

To overcome this, I tried to only instrument the idugalic package thing, with the following kieker.aop.xml:

<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.aspectj.org/dtd/aspectj_1_5_0.dtd">
<aspectj>
{{ <weaver options="-verbose">}}
{{ <include within="com.idugalic..*" />}}
{{ </weaver>}}
{{ <aspects>}}
{{ <aspect}}
{{ name="kieker.monitoring.probe.aspectj.operationExecution.OperationExecutionAspectFull" />}}
{{ </aspects>}}
</aspectj>

Using this, the application is functional from the outside, but still does not get logs (not even /tmp/kieker-XYZ is created - logfile is attached).

For debugging the AspectJ behavior, I think its necessary to get the logging right. Unfortunately, spring (or the 1.5.3 version, which is used here) does not work together with Kieker, even when just adding Kieker to the classpath (java -cp monolithic-0.0.1-SNAPSHOT.jar:kieker-1.15.4-aspectj.jar org.springframework.boot.loader.JarLauncher), the logging stops to work. Also adding the slf4j and logback libraries in the version that are normally used (java -cp monolithic-0.0.1-SNAPSHOT.jar:BOOT-INF/lib/slf4j-api-1.7.25.jar:BOOT-INF/lib/logback-core-1.1.11.jar:BOOT-INF/lib/logback-classic-1.1.11.jar org.springframework.boot.loader.JarLauncher) does not fix this problem.

According to new relic, adding a javaagent directly to spring should just work (https://docs.newrelic.com/docs/apm/agents/java-agent/additional-installation/include-java-agent-jvm-argument/ ), the documentation about spring instrumentation with Kieker is unfortunately empty (https://kieker-monitoring.readthedocs.io/en/latest/instrumenting-software/java/Instrumentation-of-Spring.html ).

Is there any way to get Kieker runnable with an older slf4j / spring version, and if yes, how?

[rju]

author DaGeRe -- Fri, 15 Mar 2024 16:40:42 +0100

Update: I’ve tried it with Kieker 1.13, when using this, the logs don’t disappear: [^c03c41bf-6182-4d45-9562-495c250f5616]

However, no kieker traces are created. Since it says

INFORMATION: Using Kieker's AspectJLoader. This is not recommended for multi-classloader environments such as JavaEE and OSGI. Use the additional VM parameter '-Dkieker.monitoring.skipDefaultAOPConfiguration=true'. to disable Kieker's AspectJLoader

I’ve tried it using this configuration, but this doesn’t change anything, besides the message disappearing - still, no kieker trace is created, not even a folder (which indicates that instrumentation doesn’t seem to work at all).

[rju]

author DaGeRe -- Fri, 15 Mar 2024 17:30:21 +0100

Having a further look at this, this is not only related to micro-company, but there seems to be some problem with Kiekers packaging.

In the following demo project: https://github.com/DaGeRe/spring-demo if we start this with kiekers javaagent, it seems like logback somehow got into the agent:

{{reicheltreichelt-desktop:~/nvme/workspaces/kiekerworkspace/spring-demo$ java -Dorg.aspectj.weaver.loadtime.configuration=kieker.aop.xml -javaagent:kieker-1.15.4-aspectj.jar -jar target/demo-0.0.1-SNAPSHOT.jar }}
{{SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder". SLF4J: Defaulting to no-operation (NOP) logger implementation SLF4J: See }}http://www.slf4j.org/codes.html#StaticLoggerBinder{{ for further details. }}
{{Exception in thread "main" java.lang.reflect.InvocationTargetException }}
{{ at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) }}
{{ at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) }}
{{ at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) }}
{{ at java.base/java.lang.reflect.Method.invoke(Method.java:568) }}
{{ at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:91) }}
{{ at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:53) }}
{{ at org.springframework.boot.loader.launch.JarLauncher.main(JarLauncher.java:58) }}
Caused by: java.lang.IllegalArgumentException: LoggerFactory is not a Logback LoggerContext but Logback is on the classpath. Either remove Logback or the competing implementation (class org.slf4j.helpers.NOPLogg
erFactory loaded from file:/home/reichelt/nvme/workspaces/kiekerworkspace/spring-demo/kieker-1.15.4-aspectj.jar). If you are using WebLogic you will need to add 'org.slf4j' to prefer-application-packages in WEB-
{{INF/weblogic.xml: org.slf4j.helpers.NOPLoggerFactory }}
{{ at org.springframework.util.Assert.instanceCheckFailed(Assert.java:592) }}
{{ at org.springframework.util.Assert.isInstanceOf(Assert.java:511) }}
{{ at org.springframework.boot.logging.logback.LogbackLoggingSystem.getLoggerContext(LogbackLoggingSystem.java:396)}}
{{ at org.springframework.boot.logging.logback.LogbackLoggingSystem.beforeInitialize(LogbackLoggingSystem.java:124) }}
{{ at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationStartingEvent(LoggingApplicationListener.java:238) }}
{{ at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:220) }}
{{ at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:185)}}
{{ at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:178)}}
{{ at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:156)}}
{{ at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:138)}}
{{ at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136)}}
{{ at org.springframework.boot.context.event.EventPublishingRunListener.starting(EventPublishingRunListener.java:75)}}
{{ at org.springframework.boot.SpringApplicationRunListeners.lambda$starting$0(SpringApplicationRunListeners.java:54)}}
{{ at java.base/java.lang.Iterable.forEach(Iterable.java:75) }}
{{ at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)}}
{{ at org.springframework.boot.SpringApplicationRunListeners.starting(SpringApplicationRunListeners.java:54)}}
{{ at org.springframework.boot.SpringApplication.run(SpringApplication.java:326) }}
{{ at org.springframework.boot.SpringApplication.run(SpringApplication.java:1354) }}
{{ at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) }}
{{ at net.kiekertest.demo.DemoApplication.main(DemoApplication.java:10) }}
{{ ... 7 more }}

Lets discuss this at the next meeting.

[rju]

author DaGeRe -- Mon, 8 Apr 2024 18:16:22 +0200

The current spring demo works, but it doesn’t use spring boot, so this is not really compatible. Nevertheless, I’ve updated the versions here, and everything seems to run fine.

[rju]

author DaGeRe -- Tue, 9 Apr 2024 17:24:18 +0200

I made some progress here:

• spring-boot-starter-aop and kieker spring needs to be added:https://github.com/DaGeRe/spring-demo/blob/5ff62c111b9dcd1726f490189462a492ac15b9e2/pom.xml#L24
• To activate spring interception, a spring-config.xml is necessary: https://github.com/DaGeRe/spring-demo/blob/main/src/main/resources/config/spring-config.xml
• When starting the application, the configuration needs to be specified (as its done with kiekers own spring demo: https://github.com/DaGeRe/spring-demo/blob/5ff62c111b9dcd1726f490189462a492ac15b9e2/src/main/java/net/kiekertest/demo/DemoApplication.java#L13 )
• This requires definition of an own spring jar:

  kieker/build.gradle

  Line 734 in 33928d9

  task springJar(type: Jar, dependsOn: springSubprojects.tasks["build"], group: "build",

Currently, this initializes the OperationExecutionMethodInvocationInterceptor , but does not call the invoke method.

Additionally, if kieker includes slf4j-api 1.7.30, Spring always fails. Updating to 2.0.12 fixes this (and is the version currently used by spring), but I’m not sure whether this will have side effects on other projects. As far as I understand https://www.slf4j.org/faq.html#changesInVersion200 , it shouldn’t be a problem.

[shinhyungyang]

Hi @DaGeRe
Currently the builds of of the two pull requests fails. I looked into the log for both.

Please see that both logs have this:

[LaunchedURLClassLoader@3eb07fd3] error The specified aspect 'kieker.monitoring.probe.aspectj.operationExecution.OperationExecutionAspectFull' cannot be found

Also,
PR #621 uses gradle 8.8 (partially?)

PR: #621 (Jenkins log):

Executing Spring Boot Without Instrumentation...

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::               (v2.7.18)

1668 [main] INFO  com.example.demo.DemoApplication - Starting DemoApplication using Java 17.0.13 on e46aa71f124b with PID 7519 (/home/jenkins-agent/workspace/kieker-dev_PR-621@2/build/tmp.MMYssoEQAV/kieker-2.0.3-SNAPSHOT/examples/monitoring/probe-spring-boot/build/libs/demo-spring-boot-0.0.1-SNAPSHOT.jar started by ? in /home/jenkins-agent/workspace/kieker-dev_PR-621@2/build/tmp.MMYssoEQAV/kieker-2.0.3-SNAPSHOT/examples/monitoring/probe-spring-boot) 
1677 [main] INFO  com.example.demo.DemoApplication - No active profile set, falling back to 1 default profile: "default" 
3934 [main] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat initialized with port(s): 8080 (http) 
3957 [main] INFO  o.a.catalina.core.StandardService - Starting service [Tomcat] 
3957 [main] INFO  o.a.catalina.core.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.83] 
4121 [main] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext 
4121 [main] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 2315 ms 
[LaunchedURLClassLoader@3eb07fd3] info AspectJ Weaver Version 1.9.22.1 built on Friday May 10, 2024 at 23:23:16 PDT
[LaunchedURLClassLoader@3eb07fd3] info register classloader org.springframework.boot.loader.LaunchedURLClassLoader@3eb07fd3
[LaunchedURLClassLoader@3eb07fd3] info using configuration file:/home/jenkins-agent/workspace/kieker-dev_PR-621@2/build/tmp.MMYssoEQAV/kieker-2.0.3-SNAPSHOT/examples/monitoring/probe-spring-boot/build/libs/demo-spring-boot-0.0.1-SNAPSHOT.jar!/BOOT-INF/classes!/META-INF/aop.xml
[LaunchedURLClassLoader@3eb07fd3] info register aspect kieker.monitoring.probe.aspectj.operationExecution.OperationExecutionAspectFull
[LaunchedURLClassLoader@3eb07fd3] error The specified aspect 'kieker.monitoring.probe.aspectj.operationExecution.OperationExecutionAspectFull' cannot be found
[LaunchedURLClassLoader@3eb07fd3] warning javax.* types are not being woven because the weaver option '-Xset:weaveJavaxPackages=true' has not been specified
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
curl: (7) Failed to connect to localhost port 8080 after 2 ms: Could not connect to server
[error] Examples where not successful

PR: #597 (Jenkins log):

Executing Spring Boot Without Instrumentation...

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::               (v2.7.18)

1616 [main] INFO  com.example.demo.DemoApplication - Starting DemoApplication using Java 17.0.13 on 65637d1a5ab4 with PID 7470 (/home/jenkins-agent/workspace/kieker-dev_PR-597@2/build/tmp.XjTNRJbTKf/kieker-2.0.3-SNAPSHOT/examples/monitoring/probe-spring-boot/build/libs/demo-spring-boot-0.0.1-SNAPSHOT.jar started by ? in /home/jenkins-agent/workspace/kieker-dev_PR-597@2/build/tmp.XjTNRJbTKf/kieker-2.0.3-SNAPSHOT/examples/monitoring/probe-spring-boot) 
1625 [main] INFO  com.example.demo.DemoApplication - No active profile set, falling back to 1 default profile: "default" 
3899 [main] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat initialized with port(s): 8080 (http) 
3925 [main] INFO  o.a.catalina.core.StandardService - Starting service [Tomcat] 
3925 [main] INFO  o.a.catalina.core.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.83] 
4103 [main] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext 
4103 [main] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 2345 ms 
[LaunchedURLClassLoader@3eb07fd3] info AspectJ Weaver Version 1.9.22.1 built on Friday May 10, 2024 at 23:23:16 PDT
[LaunchedURLClassLoader@3eb07fd3] info register classloader org.springframework.boot.loader.LaunchedURLClassLoader@3eb07fd3
[LaunchedURLClassLoader@3eb07fd3] info using configuration file:/home/jenkins-agent/workspace/kieker-dev_PR-597@2/build/tmp.XjTNRJbTKf/kieker-2.0.3-SNAPSHOT/examples/monitoring/probe-spring-boot/build/libs/demo-spring-boot-0.0.1-SNAPSHOT.jar!/BOOT-INF/classes!/META-INF/aop.xml
[LaunchedURLClassLoader@3eb07fd3] info register aspect kieker.monitoring.probe.aspectj.operationExecution.OperationExecutionAspectFull
[LaunchedURLClassLoader@3eb07fd3] error The specified aspect 'kieker.monitoring.probe.aspectj.operationExecution.OperationExecutionAspectFull' cannot be found
[LaunchedURLClassLoader@3eb07fd3] warning javax.* types are not being woven because the weaver option '-Xset:weaveJavaxPackages=true' has not been specified
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
curl: (7) Failed to connect to localhost port 8080 after 2 ms: Could not connect to server
[error] Examples where not successful