I noticed a ticket that was closed a few months ago https://github.com/spring-projects/spring-boot/issues/38668
It seems there was no evidence that this was an issue except in obscure environments. I wanted to provide evidence in what I would consider a standard environment.
We have recently been profiing our application looking for any hotspots. After making many performance improvements we saw this particular call in logback taking up 7% of cpu.
I don't think it takes a strange use case to cause this... any logging with this enabled in volume does this expensive operation. It is unzipping the jar/war just to get this info and put it in stack traces.
I also just tried to disable it by adding:
<configuration debug="true" packagingData="false">
to the logback-spring.xml. It doesnt seem to honor it.
This might be useful to some people when debugging issues... but forcing all users to essentially add debug code seems extreme. Perhaps people who want this should enable it... instead of it being enabled by default. This also seems to be the best-practices that the logback project itself suggests.
Comment From: rwaite2
At the very least please let me know how I can disable this as we do not feel it is worth having in our production deployments.
Comment From: wilkinsona
Boot only enables packaging data when loading its defaults. If you're using a custom logback.xml or logback-spring.xml it shouldn't be enabled. For example, this logback-spring.xml does not produce any packaging data:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</configuration>
This was tested with Spring Boot 3.2.3. Can you please provide a minimal example that shows the packaging data being logged when it should not have been?
Comment From: rwaite2
This is what the beginning of our current logback-spring.xml looks like.. it is in the classpath and I dont see any other specially named config xmls in the classpath.
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" packagingData="false">
<springProfile name="dev">
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
<providers>
<timestamp>
<fieldName>@timestamp</fieldName>
</timestamp>
<globalCustomFields>
Here is a sample stacktrace showing up in our logs:
java.lang.NullPointerException: Cannot invoke "String.startsWith(String)" because "hostname" is null
at com.mobilitywarertb.client.http.impl.PooledHttpClient.makeCall(PooledHttpClient.java:237) ~[classes!/:na]
at com.mobilitywarertb.client.http.impl.PooledHttpClient.httpGetRequest(PooledHttpClient.java:79) ~[classes!/:na]
at com.mobilitywarertb.client.hystrix.HystrixHttpClient.run(HystrixHttpClient.java:152) ~[classes!/:na]
at com.mobilitywarertb.client.hystrix.HystrixHttpClient.run(HystrixHttpClient.java:30) ~[classes!/:na]
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:302) ~[hystrix-core-1.5.18.jar!/:1.5.18]
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:298) ~[hystrix-core-1.5.18.jar!/:1.5.18]
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:46) ~[rxjava-1.2.0.jar!/:1.2.0]
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:35) ~[rxjava-1.2.0.jar!/:1.2.0]
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48) ~[rxjava-1.2.0.jar!/:1.2.0]
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.2.0.jar!/:1.2.0]
Edit: we are on spring boot 2.7.14
Comment From: rwaite2
We do use the spring profiles... and those are set via:
spring.profiles.active=${ENVIRONMENT_NAME}
In application.properties.
Comment From: wilkinsona
OSS support Spring Boot 2.7.x is no longer available. That said, I can't reproduce the problem with 2.7.x either. Here's an app using the logback-spring.xml that I shared above:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.7.18)
2024-03-08 08:35:40.032 INFO 92917 --- [ main] com.example.gh39817.Gh39817Application : Starting Gh39817Application using Java 17.0.1 on wilkinsonaGMD6R.vmware.com with PID 92917 (/Users/awilkinson/Downloads/gh-39817/bin/main started by awilkinson in /Users/awilkinson/Downloads/gh-39817)
2024-03-08 08:35:40.034 INFO 92917 --- [ main] com.example.gh39817.Gh39817Application : No active profile set, falling back to 1 default profile: "default"
2024-03-08 08:35:40.404 INFO 92917 --- [ main] com.example.gh39817.Gh39817Application : Started Gh39817Application in 0.711 seconds (JVM running for 0.965)
2024-03-08 08:35:40.423 ERROR 92917 --- [ main] o.s.boot.SpringApplication : Application run failed
java.lang.NullPointerException: null
at com.example.gh39817.Gh39817Application.onStartup(Gh39817Application.java:31)
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.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:344)
at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:229)
at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:166)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:178)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:171)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:145)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:429)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:386)
at org.springframework.boot.context.event.EventPublishingRunListener.ready(EventPublishingRunListener.java:114)
at org.springframework.boot.SpringApplicationRunListeners.lambda$ready$6(SpringApplicationRunListeners.java:82)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
at org.springframework.boot.SpringApplicationRunListeners.ready(SpringApplicationRunListeners.java:82)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:323)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1300)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1289)
at com.example.gh39817.Gh39817Application.main(Gh39817Application.java:26)
I also cannot reproduce it with debug="true" in the Logback configuration. I suspect there must be something else in your app that's enabling packaging data that's out of Spring Boot's control. In the absence of any evidence that Spring Boot is forcing packaging data to be enabled when using custom Logback configuration, I'm going to close this issue. If you can share a complete reproducer, not just a partial snippet of config, with Spring Boot 3.1.x or later we can re-open it and take another look.