[JENKINS-20618] upgrade from LTS 1.509.4 to LTS 1.532.1-SNAPSHOT -- layout.jelly java.io.IOException

[timja]

Running from: /usr/lib/jenkins/jenkins.war   
Nov 16, 2013 8:05:06 PM winstone.Logger logInternal  
INFO: Beginning extraction from war file     
Jenkins home directory: /var/lib/jenkins found at: System.getProperty("JENKINS_HOME")
Nov 16, 2013 8:05:14 PM winstone.Logger logInternal  
INFO: HTTP Listener started: port=8080       
Nov 16, 2013 8:05:14 PM winstone.Logger logInternal  
INFO: AJP13 Listener started: port=8009      
Nov 16, 2013 8:05:14 PM winstone.Logger logInternal  
INFO: Winstone Servlet Engine v0.9.10 running: controlPort=disabled  
Nov 16, 2013 8:05:15 PM jenkins.InitReactorRunner$1 onAttained       
INFO: Started initialization 
Nov 16, 2013 8:05:58 PM jenkins.InitReactorRunner$1 onAttained       
INFO: Listed all plugins     
Nov 16, 2013 8:05:58 PM hudson.plugins.greenballs.PluginImpl start   
INFO: Green Balls!   
Nov 16, 2013 8:05:58 PM jenkins.InitReactorRunner$1 onAttained       
INFO: Prepared all plugins   
Nov 16, 2013 8:05:59 PM jenkins.InitReactorRunner$1 onAttained       
INFO: Started all plugins    
Nov 16, 2013 8:06:08 PM jenkins.InitReactorRunner$1 onAttained       
INFO: Augmented all extensions       
Nov 16, 2013 8:10:02 PM jenkins.InitReactorRunner$1 onAttained    
INFO: Loaded all jobs
Nov 16, 2013 8:10:02 PM jenkins.InitReactorRunner$1 onAttained
INFO: Completed initialization
Nov 16, 2013 8:10:04 PM winstone.Logger logInternal
WARNING: Untrapped Error in Servlet
javax.servlet.ServletException: org.apache.commons.jelly.JellyTagException: jar:file:/var/cache/jenkins/war/WEB-INF/lib/jenkins-core-1.532.1-SNAPSHOT.jar!/lib/layout/layout.jelly:75:72:  failed to deflate
at org.kohsuke.stapler.jelly.JellyFacet$1.dispatch(JellyFacet.java:103)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:685)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:799)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:587)
at hudson.init.impl.InstallUncaughtExceptionHandler$1.reportException(InstallUncaughtExceptionHandler.java:25)
at org.kohsuke.stapler.compression.CompressionFilter.reportException(CompressionFilter.java:63)
at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
at winstone.FilterConfiguration.execute(FilterConfiguration.java:194)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366)
at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
at winstone.FilterConfiguration.execute(FilterConfiguration.java:194)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366)
at winstone.RequestDispatcher.forward(RequestDispatcher.java:331)
at winstone.RequestHandlerThread.processRequest(RequestHandlerThread.java:227)
at winstone.RequestHandlerThread.run(RequestHandlerThread.java:150)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
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:744)
Caused by: org.apache.commons.jelly.JellyTagException: jar:file:/var/cache/jenkins/war/WEB-INF/lib/jenkins-core-1.532.1-SNAPSHOT.jar!/lib/layout/layout.jelly:75:72:  failed to deflate
at org.apache.commons.jelly.impl.TagScript.handleException(TagScript.java:726)
at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:279)
at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
at org.apache.commons.jelly.tags.core.ForEachTag.doTag(ForEachTag.java:150)
at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:98)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:119)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:81)
at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:63)
at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:53)
at org.kohsuke.stapler.jelly.JellyFacet$1.dispatch(JellyFacet.java:95)
... 20 more
Caused by: java.io.IOException: failed to deflate
at com.jcraft.jzlib.DeflaterOutputStream.deflate(DeflaterOutputStream.java:140)
at com.jcraft.jzlib.DeflaterOutputStream.write(DeflaterOutputStream.java:102)
at org.kohsuke.stapler.compression.FilterServletOutputStream.write(FilterServletOutputStream.java:31)
at org.kohsuke.stapler.jelly.DefaultScriptInvoker$1.write(DefaultScriptInvoker.java:99)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
at java.io.BufferedWriter.flush(BufferedWriter.java:254)
at org.dom4j.io.XMLWriter.flush(XMLWriter.java:276)
at org.apache.commons.jelly.XMLOutput.flush(XMLOutput.java:127)
at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:271)
... 34 more

Nov 16, 2013 8:10:05 PM winstone.Logger logInternal
SEVERE: Error in the error servlet
javax.servlet.ServletException: org.apache.commons.jelly.JellyTagException: jar:file:/var/cache/jenkins/war/WEB-INF/lib/jenkins-core-1.532.1-SNAPSHOT.jar!/lib/layout/layout.jelly:140:68:  Could not write to XMLOutput
at org.kohsuke.stapler.jelly.JellyRequestDispatcher.forward(JellyRequestDispatcher.java:60)
at hudson.util.HudsonIsLoading.doDynamic(HudsonIsLoading.java:45)
at sun.reflect.GeneratedMethodAccessor99.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.kohsuke.stapler.Function$InstanceFunction.invoke(Function.java:297)
at org.kohsuke.stapler.Function.bindAndInvoke(Function.java:160)
at org.kohsuke.stapler.Function.bindAndInvokeAndServeResponse(Function.java:95)
at org.kohsuke.stapler.MetaClass$11.dispatch(MetaClass.java:361)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:685)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:799)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:587)
at org.kohsuke.stapler.Stapler.service(Stapler.java:218)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:45)
at winstone.ServletConfiguration.execute(ServletConfiguration.java:248)
at winstone.RequestDispatcher.include(RequestDispatcher.java:199)
at winstone.RequestHandlerThread.processRequest(RequestHandlerThread.java:251)
at winstone.RequestHandlerThread.run(RequestHandlerThread.java:150)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run    at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
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:744)
Caused by: org.apache.commons.jelly.JellyTagException: jar:file:/var/cache/jenkins/war/WEB-INF/lib/jenkins-core-1.532.1-SNAPSHOT.jar!/lib/layout/layout.jelly:140:68:  Could not write to XMLOutput
at org.apache.commons.jelly.impl.ExpressionScript.run(ExpressionScript.java:72)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:81)
at org.kohsuke.stapler.jelly.IncludeTag.doTag(IncludeTag.java:146)
at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
at org.apache.commons.jelly.tags.core.ForEachTag.doTag(ForEachTag.java:150)
at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:119)
at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:81)
at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:63)
at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:53)
at org.kohsuke.stapler.jelly.JellyRequestDispatcher.forward(JellyRequestDispatcher.java:55)
... 23 more
Caused by: org.xml.sax.SAXException: Failed to write to client
winstone.ClientSocketException: Failed to write to client
at org.dom4j.io.XMLWriter.handleException(XMLWriter.java:1888)
at org.dom4j.io.XMLWriter.characters(XMLWriter.java:791)
at org.apache.commons.jelly.XMLOutput.characters(XMLOutput.java:590)
at org.apache.commons.jelly.XMLOutput.write(XMLOutput.java:249)
at org.apache.commons.jelly.XMLOutput.objectData(XMLOutput.java:874)
at org.apache.commons.jelly.impl.ExpressionScript.run(ExpressionScript.java:70)
... 46 more
Caused by: winstone.ClientSocketException: Failed to write to client
at winstone.ClientOutputStream.write(ClientOutputStream.java:41)
at winstone.WinstoneOutputStream.commit(WinstoneOutputStream.java:182)
at winstone.WinstoneOutputStream.commit(WinstoneOutputStream.java:118)
at winstone.WinstoneOutputStream.write(WinstoneOutputStream.java:111)
at org.kohsuke.stapler.jelly.DefaultScriptInvoker$1.write(DefaultScriptInvoker.java:99)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
at java.io.OutputStreamWriter.write(OutputStreamWriter.java:207)
at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:129)
at java.io.BufferedWriter.write(BufferedWriter.java:230)
at javtainFreshBeanFactory
INFO: Bean factory for application context [org.springframework.web.context.support.StaticWebApplicationContext@501185c9]: org.springframework.beans.factory.support.DefaultListableBeanFactory@34270e4d
Nov 16, 2013 8:10:10 PM org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons
INFO: Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@34270e4d: defining beans [filter,legacy]; root of factory hierarchy
Nov 16, 2013 8:10:10 PM hudson.slaves.SlaveComputer tryReconnect
INFO: Attempting to reconnect slave-1
Nov 16, 2013 8:10:10 PM org.jenkinsci.plugins.skipcert.ItemListenerImpl onLoaded
INFO: Bypassing certificate check
Nov 16, 2013 8:10:10 PM hudson.WebAppMain$3 run
INFO: Jenkins is fully up and running

---

Originally reported by jieryn, imported from: upgrade from LTS 1.509.4 to LTS 1.532.1-SNAPSHOT -- layout.jelly java.io.IOException

• status: Resolved
• priority: Minor
• resolution: Cannot Reproduce
• resolved: 2016-12-16T23:29:10+00:00
• imported: 2022/01/10

[timja]

danielbeck:

Error message seems to be incomplete: at javtainFreshBeanFactory

[timja]

kohsuke:

I suspect this is just a result of a client disconnecting before the server has finished writing (for example when the user presses 'X' button on the browser while the page is loading.)

We've changed the gzip library and so it must have changed the failure mode. We try to swallow this kind of error since it's not useful.

Double checking now.

Looking at DeflaterOutputStream, it's clear that this is not a result of a failed write to the nested OutputStream. Java port of zlib is encourintering a problem, but unfortunately the code doesn't report the error code.

I'm going to patch the code so that we can see what is causing it.

It's unlikely that this is related to the upgrade. The problem presumably happens with any version of Jenkins that uses jzlib, and possibly affected only by the pattern of OutputStream.write()/flush() calls.

[timja]

kohsuke:

"Freestyle project" -> "OK" - hangs forever " class="issue-link" data-issue-key="JENKINS-20114">JENKINS-20114, while unrelated, has the same stack trace in its report.

[timja]

kohsuke:

I filed https://github.com/ymnk/jzlib/pull/11 to better understand the problem.

[timja]

kohsuke:

This appears to be a problem in jzlib and not a regression in LTS.

As such, I'm targeting this for the main line, and I'm not going to block LTS releases because of this.

maybe it's failing to recover gracefully in case the wrapped OutputStream starts throwing IOException?

[timja]

scm_issue_link:

Code changed in jenkins
User: Kohsuke Kawaguchi
Path:
changelog.html
core/pom.xml
http://jenkins-ci.org/commit/jenkins/06bdbed5c45ad6cbfc32c1b554142f542e33c3d6
Log:
JENKINS-20618

Added a patched version of jzlib from
https://github.com/kohsuke/jzlib/tree/jzlib-1.1.3-kohsuke-1 to better
understand the deflate problem.

[timja]

dogfood:

Integrated in jenkins_main_trunk #3068
JENKINS-20618 (Revision 06bdbed5c45ad6cbfc32c1b554142f542e33c3d6)

Result = SUCCESS
kohsuke : 06bdbed5c45ad6cbfc32c1b554142f542e33c3d6
Files :

• changelog.html
• core/pom.xml

[timja]

ymnk:

https://github.com/ymnk/jzlib/pull/11 has been merged to jzlib's master branch.
Is that exception "failed to deflate" easily reproducible?

[timja]

jieryn:

Only 2 occurrences in my log file.

[timja]

jieryn:

Is there a way I can flush cached/compiled jelly on a running Jenkins without restarting the server?

[timja]

jglick:

@jieryn try a System.gc(); JellyClassLoaderTearOff.taglibs is a WeakReference so if this is in fact what keeps compiled Jelly scripts (which I am not sure of), that could work to flush it.

[timja]

scm_issue_link:

Code changed in jenkins
User: Jesse Glick
Path:
core/pom.xml
http://jenkins-ci.org/commit/jenkins/2ae83f6ab099d46d01a2f70c77be069d3050267d
Log:
Corrected a (now-)misleading comment.
JENKINS-20618 diagnostics (also in 1.532.2) are on top of jzlib 1.1.3.

[timja]

gboucherie:

I have the same problem on 1.554.1, some time (maybe the first request after a restart) the home page take a long time to load and in log I see a stacktrace related to deflate (see attached file: stacktrace.txt)

[timja]

jglick:

Try running with -Dorg.kohsuke.stapler.jelly.DefaultScriptInvoker.compress=false to see if that suppresses the problem.

[timja]

danielbeck:

Is this issue still a problem on recent versions of Jenkins? Did Jesse's recommendation in the preceding comment help?

[timja]

danielbeck:

No response to comment in >1 year, so assuming this is long obsolete.

[timja]

[Originally related to: JENKINS-20114]