Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Auto-reloading .jar fails #1106

Closed
kryger opened this issue Jun 16, 2014 · 27 comments
Closed

Auto-reloading .jar fails #1106

kryger opened this issue Jun 16, 2014 · 27 comments
Labels
status: duplicate A duplicate of another issue

Comments

@kryger
Copy link
Contributor

kryger commented Jun 16, 2014

Looks like the .jar file auto-reloads which was kind of surprising to me, especially since it doesn't seem to be handled very well - ugly zip-related exception in the log.

Steps to reproduce:

  1. Create a Maven project (Jar) with only "Web" style ticked on http://start.spring.io
  2. Unpack, do an mvn package, go to target/ and run: java -jar demo-0.0.1-SNAPSHOT.jar
  3. Project works and runs on localhost:8080 (by "works" I mean that it serves the error 404, but that's not the point here)
  4. With project still running directly from target/ do an mvn package again - the original .jar file will get overwritten
  5. Prod localhost:8080 again: you'll get a stacktrace in the log:
Exception in thread "http-nio-8080-exec-10" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:121)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.log(Logger.java:788)
    at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:224)
    at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:301)
    at java.util.logging.Logger.log(Logger.java:616)
    at java.util.logging.Logger.doLog(Logger.java:641)
    at java.util.logging.Logger.logp(Logger.java:841)
    at org.apache.juli.logging.DirectJDKLog.log(DirectJDKLog.java:185)
    at org.apache.juli.logging.DirectJDKLog.error(DirectJDKLog.java:151)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1771)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1679)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:744)
Exception in thread "ContainerBackgroundProcessor[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[]]" java.lang.NoClassDefFoundError: org/apache/tomcat/util/ExceptionUtils
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1532)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1540)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1519)
    at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.ClassNotFoundException: org.apache.tomcat.util.ExceptionUtils
    at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:425)
    at org.springframework.boot.loader.LaunchedURLClassLoader.doLoadClass(LaunchedURLClassLoader.java:161)
    at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:131)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:358)
    ... 4 more
Caused by: java.io.EOFException: Unexpected end of ZLIB input stream
    at java.util.zip.InflaterInputStream.fill(InflaterInputStream.java:240)
    at org.springframework.boot.loader.jar.ZipInflaterInputStream.fill(ZipInflaterInputStream.java:62)
    at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:158)
    at org.springframework.boot.loader.jar.ZipInflaterInputStream.read(ZipInflaterInputStream.java:52)
    at sun.misc.Resource.getBytes(Resource.java:124)
    at java.net.URLClassLoader.defineClass(URLClassLoader.java:444)
    at java.net.URLClassLoader.access$100(URLClassLoader.java:71)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:361)
    ... 11 more

In my applicatiton this makes the application stop responding, but this simplified example still happily serves the 404 - hopefully you won't need an example app that shows it. The stack trace is also slightly different:

Exception in thread "http-nio-8080-Acceptor-0" java.lang.NoClassDefFoundError: org/apache/tomcat/util/ExceptionUtils
    at org.apache.tomcat.util.net.NioEndpoint$Acceptor.run(NioEndpoint.java:840)
    at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.ClassNotFoundException: org.apache.tomcat.util.ExceptionUtils
    at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:425)
    at org.springframework.boot.loader.LaunchedURLClassLoader.doLoadClass(LaunchedURLClassLoader.java:161)
    at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:131)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:358)
    ... 2 more
Caused by: java.util.zip.ZipException: invalid distance too far back
    at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:164)
    at org.springframework.boot.loader.jar.ZipInflaterInputStream.read(ZipInflaterInputStream.java:52)
    at sun.misc.Resource.getBytes(Resource.java:124)
    at java.net.URLClassLoader.defineClass(URLClassLoader.java:444)
    at java.net.URLClassLoader.access$100(URLClassLoader.java:71)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:361)
    ... 9 more

Example app also fails with Jetty, the stacktrace doesn't mention zip though:

Exception in thread "qtp2113070601-15" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:121)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.log(Logger.java:788)
    at org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:607)
    at org.eclipse.jetty.util.log.JettyAwareLogger.warn(JettyAwareLogger.java:431)
    at org.eclipse.jetty.util.log.Slf4jLog.warn(Slf4jLog.java:69)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:726)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
    at java.lang.Thread.run(Thread.java:744)
Exception in thread "qtp2113070601-16" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:121)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.log(Logger.java:788)
    at org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:607)
    at org.eclipse.jetty.util.log.JettyAwareLogger.warn(JettyAwareLogger.java:431)
    at org.eclipse.jetty.util.log.Slf4jLog.warn(Slf4jLog.java:69)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:726)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
    at java.lang.Thread.run(Thread.java:744)
@dsyer
Copy link
Member

dsyer commented Jun 16, 2014

I wouldn't expect this to work really, and it doesn't seem like you did either. Is it a feature request?

@kryger
Copy link
Contributor Author

kryger commented Jun 16, 2014

Ah, forgot to add the actual question: is there a way to disable this reloading behaviour or is it something that java -jar just does and it's out of Boot's control? Not reloading would make the deployment script a bit easier to set up in Jenkins as there would be no need to stop the app before scp-ing.

@dsyer
Copy link
Member

dsyer commented Jun 16, 2014

Good question. I doubt there's much we can do. Did you try running a simple (non-Boot launched) jar and see if that would ever work? Also interesting to know would be if it works with a Boot jar that isn't a webapp I guess. Switching it off might be possible if it is an artifact of the Boot classloader (hence the answers to the questions above might be interesting).

@kryger
Copy link
Contributor Author

kryger commented Jun 16, 2014

I tried Dropwizard's example app and it doesn't seem to even attempt to reload the .jar file, it serves the old contents after the file is overwritten. This suggests it's something that Boot does explicitly, right?

I could try with a non-web Boot app, but I've already used up all my investigation time for this issue for today, will do this later this week as it's not a stopper for me (...yet!). Thanks for quick reaction.

@philwebb
Copy link
Member

The exception is most probably caused by the ground moving underneath the feet of the fat jar support. We have a somewhat unique implementation where we scan the contents of the nested JARs and work out where within the actual file the contents of an entry begins.

When you read a file or class from a nested JAR we actually seek to the relevant position in the file and read the contents. This allows us to have fat jars that look nice (i.e. all the classes from the nested aren't repackaged) and that don't need to unpack things to temporary directories.

When the jar is repackaged, the positions of the nested jars changes but the previously calculated index is not updated. Hence the ZLIB input stream exceptions.

One option would be for us to check the timestamp and size of the JAR whenever an entry is read to see if we need to reindex. I'm not too keen to add this additional logic, especially as most users seem to be running using springBoot:run during development time.

@toolforger
Copy link

Is it possible to put a write lock on the jar while the app is running?
Does the Spring Boot plugin rewrite the file in place? If so, it shouldn't, it could delete and recreate the jar; on Windows, it will fail if Boot's classloader keeps the file open (as it should), on Linux, the classloader will simply continue serving from the old, deleted file.

@markfisher markfisher added this to the 1.1.4 milestone Jul 3, 2014
@markfisher markfisher reopened this Jul 3, 2014
@philwebb philwebb removed this from the 1.1.4 milestone Jul 3, 2014
@wilkinsona wilkinsona removed the status: waiting-for-feedback We need additional information before we can continue label May 12, 2015
@sincang
Copy link

sincang commented Jun 19, 2015

Was this issue resolve? Last February, 2014 I attemted to used the maven jar plugin but did not work. Just today, I am thinking I can employ this again in our application because this feature is really neat. Unfortunately, I get same error I had a year ago.

java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy

@dsyer
Copy link
Member

dsyer commented Jun 19, 2015

I think you can probably see that the issue is still open. I don't really know what you mean by "this feature" though. What did you do and what happened and what did you think might happen?

@sincang
Copy link

sincang commented Jun 19, 2015

I meant the jarlauncher is really neat because makes our application deployment into production simpler. BTW, the only thing that I observed is the one jar is deplyed in a network folder. After the application been running for several minutes, the error above comes out.

@sincang
Copy link

sincang commented Jun 19, 2015

I have not tried yet to deploy it in a local folder. I will try later and see if the error will still come out.

@toolforger
Copy link

toolforger commented Jun 20, 2015 via email

@snicoll snicoll added the icebox label Oct 27, 2015
@atorstling
Copy link

I have had issues on Amazon Linux where spring boot seemingly sporadically tries to re-load the jar and subsequently fails. I haven't been able to figure out what is triggering the re-loads, the mtime of the jar and temp folders seemed unchanged. Perhaps files are touched by some sort of scanner in a way which isn't immediately obvious. Anyway, for these cases it would be great to be able to disable the auto-reloading with a flag.

@ghost
Copy link

ghost commented Feb 23, 2016

Which case is responsible for reloading of the JAR on the fly? My application which is based on spring-boot 1.2.3 had been working fine for a couple of days when this exception was thrown, suddenly.

Exception in thread "Application-Executor-24" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
        at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:121)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
        at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:433)
        at ch.qos.logback.classic.Logger.error(Logger.java:551)
...
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
        at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
        at org.springframework.boot.loader.LaunchedURLClassLoader.doLoadClass(LaunchedURLClassLoader.java:170)
        at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:136)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        ... 31 more

My observations:

  1. I didn't replace the JAR.
  2. I didn't repackaged the JAR since it was created with maven.
  3. The application had been logging something many times for a couple of days. It wasn't the first using of logback error(...) method.
  4. I started this application at virtual machine environment (VMVare). I have never seen this exception on my physical server.

@snicoll
Copy link
Member

snicoll commented Feb 23, 2016

Reminds me of #4968

@dsyer
Copy link
Member

dsyer commented Feb 23, 2016

Network storage again?

@turu
Copy link

turu commented Mar 6, 2016

I'm having a very similiar issue to that described by @MarcinMiotk. We have a spring-boot (1.3.0.RELEASE) worker running on production, which collapses randomly, after having run for many hours (sometimes even days), without any trouble. The application is deployed on a virtual machine, started with java -jar and the jar is not - in any way - replaced or altered, while the application is running.

At some point, various application threads start to throw:

Exception in thread "pastillGenerationTaskExecutor-1" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
        at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:121)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
        at ch.qos.logback.classic.Logger.error(Logger.java:555)
        at pl.dreamlab.bigdata.clickpastiller.aggregation.pastills.FileBasedPastillsFactory.createFileForPastill(FileBasedPastillsFactory.java:70)
        at pl.dreamlab.bigdata.clickpastiller.aggregation.pastills.FileBasedPastillsFactory.create(FileBasedPastillsFactory.java:47)
        at pl.dreamlab.bigdata.clickpastiller.aggregation.PastillGeneratingWorker.initializePastillIFNoneActive(PastillGeneratingWorker.java:62)
        at pl.dreamlab.bigdata.clickpastiller.aggregation.PastillGeneratingWorker.run(PastillGeneratingWorker.java:46)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
        at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:425)
        at org.springframework.boot.loader.LaunchedURLClassLoader.doLoadClass(LaunchedURLClassLoader.java:166)
        at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:130)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:358)
        ... 11 more

and the worker dies eventually. This seems like a very serious issue.

@dsyer @snicoll @atorstling @toolforger @philwebb Do you see any fix or a possible workaround? Since, we are deploying it onto a virtual machine (managed via proxmox), there isn't really any "local storage" available to us.

@turu
Copy link

turu commented Mar 6, 2016

I did some digging into the root cause of this particular exception. It happened, when a call to File.createNewFile() threw an IOException (most probably due to a temporary network issue). The IOException was then about to be handled by (among other things) calling org.slf4j.Logger.error(). That call caused the above exception.

@wilkinsona
Copy link
Member

@turu The same temporary network issue is likely to also be the cause of ThrowableProxy failing to load. This doesn't really have anything to do with Spring Boot. You really need to fix the underlying network issue to fix this problem.

You may be able to work around the problem by aggressively loading classes when the application first starts. This will cache them in memory making your application less vulnerable to temporary network problems that make the file system inaccessible.

@wgorder
Copy link

wgorder commented Mar 20, 2016

I just started seeing this running locally after running for awhile. I have a couple IntelliJ windows running spring boot apps as WARs in non-embedded tomcat. Everything is fine then one app or the other starts failing with this.

@davydotcom
Copy link

seeing the same thing in a grails 3.1.6 app on a 12" macbook pro and jenkins but not on a 15" using gradle 2.13 seems awfully suspicious

@davydotcom
Copy link

its almost as if something packaging the war file is not properly flushing it before closing

@priyeshgpatel
Copy link

priyeshgpatel commented Aug 9, 2016

We started seeing this
(java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy)
exception in our spring boot app because we found that our app was not closing the file handles after opening them for reading.

Sometimes but not always the error would be proceeded by

org.apache.tomcat.util.net.NioEndpoint : Socket accept failed
java.io.IOException: Too many open files

@philwebb philwebb added for: stackoverflow A question that's better suited to stackoverflow.com and removed icebox for: stackoverflow A question that's better suited to stackoverflow.com labels Aug 30, 2016
@philwebb
Copy link
Member

philwebb commented Aug 30, 2016

I think #6683 may have been the root cause of this and has been fixed in 1.3.8

@snicoll snicoll added status: duplicate A duplicate of another issue and removed type: enhancement A general enhancement labels Aug 30, 2016
@ebuildy
Copy link

ebuildy commented Sep 15, 2017

Still here, with 1.5.6. Using a ZIP layout, with execute: true.

@wilkinsona
Copy link
Member

@ebuildy If that's the case, can you please open a new issue and provide a sample that reproduces the problem?

@jbrant
Copy link

jbrant commented Nov 23, 2017

Same issue, seemingly randomly, during spring batch jobs on spring boot 2.0.0M3.

@snicoll
Copy link
Member

snicoll commented Nov 23, 2017

@jbrant could you please have considered the comment just above yours before commenting?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: duplicate A duplicate of another issue
Projects
None yet
Development

No branches or pull requests