JUL-based logging performed during close of application context is lost

[Artur-]

Using Spring Boot 1.5.4

In my application I accidentally added a non serializable class to the HTTP session. When reloading the application (using dev tools and changing a class -> autoredeploy or by restarting a Tomcat server), I would expect to see a NotSerializableException in the console, telling that session serialization failed and the session will not be restored.

What I see in my application is absolutely nothing on shutdown of the server but on startup I see

java.lang.ClassCastException: java.lang.StackTraceElement cannot be cast to java.lang.String
	at java.io.ObjectInputStream.readTypeString(ObjectInputStream.java:1421) ~[na:1.8.0_112]

	at java.io.ObjectStreamClass.readNonProxy(ObjectStreamClass.java:719) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readClassDescriptor(ObjectInputStream.java:833) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1609) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1521) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1781) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1353) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2018) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1942) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1808) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1353) ~[na:1.8.0_112]
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:373) ~[na:1.8.0_112]
	at org.apache.catalina.session.StandardSession.doReadObject(StandardSession.java:1611) ~[tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.session.StandardSession.readObjectData(StandardSession.java:1077) ~[tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.session.StandardManager.doLoad(StandardManager.java:218) ~[tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.session.StandardManager.load(StandardManager.java:162) ~[tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.session.StandardManager.startInternal(StandardManager.java:356) ~[tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5224) [tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1419) [tomcat-embed-core-8.5.15.jar:8.5.15]
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1409) [tomcat-embed-core-8.5.15.jar:8.5.15]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_112]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_112]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_112]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_112]

Debugging the issue reveals that a NotSerializableException is properly thrown but ends up in org.apache.catalina.session.StandardSession:1707

                manager.getContext().getLogger().warn(
                        sm.getString("standardSession.notSerializable", saveNames.get(i), id), e);

Unfortunately this message is not logged anywhere and I can't see that this would be related to my configuration.

[wilkinsona]

Can you please provide a small sample that reproduces the problem?

[Artur-]

Example project at https://github.com/Artur-/spring-tutorial

Tested in Eclipse by

1. Launching TutorialApplication (Run as -> Java Application)
2. Opening http://localhost:8080/ in a browser
3. Adding a newline to TutorialApplication.java and save to force an application reload

If you add a breakpoint on NotSerializableException you will see it happening and how it gets to the logger, which ignores it

There is no ClassCastException on startup in this example, so that one is probably related to where in the serialization chain the problem occurs

[wilkinsona]

Thanks for the sample. The problem is due to Spring Boot's logging system removing the SLF4JBridgeHandler in response to the ContextClosedEvent. This event is published very early in the restart and, crucially, before Tomcat attempts to serialise the HTTP session. As a result, when it logs the warning, there's no handler to route the log record correctly and it's lost.

[wilkinsona]

I'm not sure what is the best way to fix this. I think our best option might be to use a disposable bean to clean up the logging system. The other option might be to override onClose() but that relies on the user not having configured a custom application context class.

I think we need some more time to consider our options. Moving to 1.5.6.

[wilkinsona]

We think we need a change in Spring Framework to fix this one nicely. @snicoll is going to raise it.

[pleku]

Hello. While this is not a critical issue, it does cause some confusion for Vaadin users who run into this as they struggle to understand what is going on and what they should do about it.