[JENKINS-13135] Very large console logs will cause Jenkins to crash or behave erratically

Type: Bug
Resolution: Incomplete
Priority: Major
Component/s: core
Labels:
None
Environment:

Hide
Linux, FC13
Java: Java(TM) SE Runtime Environment, 1.6.0_21-b06
JVM: Java HotSpot(TM) 64-Bit Server VM, 17.0-b16, mixed mode
Server: Apache Tomcat/6.0.20
JVM arguments: -Xms1024m
-Xmx4096m
-Dhudson.model.WorkspaceCleanupThread.disabled=true
-Dcatalina.base=/usr/share/tomcat6
-Dcatalina.home=/usr/share/tomcat6
-Djava.endorsed.dirs=
-Djava.io.tmpdir=/var/cache/tomcat6/temp
-Djava.util.logging.config.file=/usr/share/tomcat6/conf/logging.properties
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager

Show
Linux, FC13 Java: Java(TM) SE Runtime Environment, 1.6.0_21-b06 JVM: Java HotSpot(TM) 64-Bit Server VM, 17.0-b16, mixed mode Server: Apache Tomcat/6.0.20 JVM arguments: -Xms1024m -Xmx4096m -Dhudson.model.WorkspaceCleanupThread.disabled=true -Dcatalina.base=/usr/share/tomcat6 -Dcatalina.home=/usr/share/tomcat6 -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat6/temp -Djava.util.logging.config.file=/usr/share/tomcat6/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager

Similar Issues:
Powered by SuggestiMate

Show

When console logs are exceptionally large (due to user parameters we've had a 3Gb log go through at some point), and somebody tries to view this log, Jenkins will throw an exception there, and may also deny allocations to other threads - side effects being disconnected slave nodes, jobs failing to finish up correctly.

Exception from catalina log:

Mar 16, 2012 4:45:30 PM hudson.ExpressionFactory2$JexlExpression evaluate
WARNING: Caught exception evaluating: item.why. Reason: java.lang.reflect.InvocationTargetException
java.lang.reflect.InvocationTargetException
        at sun.reflect.GeneratedMethodAccessor321.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.commons.jexl.util.PropertyExecutor.execute(PropertyExecutor.java:125)
        at org.apache.commons.jexl.util.introspection.UberspectImpl$VelGetterImpl.invoke(UberspectImpl.java:314)
        at org.apache.commons.jexl.parser.ASTArrayAccess.evaluateExpr(ASTArrayAccess.java:185)
        at org.apache.commons.jexl.parser.ASTIdentifier.execute(ASTIdentifier.java:75)
        at org.apache.commons.jexl.parser.ASTReference.execute(ASTReference.java:83)
        at org.apache.commons.jexl.parser.ASTReference.value(ASTReference.java:57)
        at org.apache.commons.jexl.parser.ASTReferenceExpression.value(ASTReferenceExpression.java:51)
        at org.apache.commons.jexl.ExpressionImpl.evaluate(ExpressionImpl.java:80)
        at hudson.ExpressionFactory2$JexlExpression.evaluate(ExpressionFactory2.java:72)
        at org.apache.commons.jelly.expression.ExpressionSupport.evaluateRecurse(ExpressionSupport.java:61)
        at org.apache.commons.jelly.expression.ExpressionSupport.evaluateAsString(ExpressionSupport.java:46)
        at org.apache.commons.jelly.expression.CompositeExpression.evaluateAsString(CompositeExpression.java:256)
        at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.buildAttributes(ReallyStaticTagLibrary.java:111)
        at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:95)
        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.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:270)
        at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
        at org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
        at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
        at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
        at org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:98)
        at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        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.CallTagLibScript.run(CallTagLibScript.java:119)
        at org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:98)
        at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
        at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
        at org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
        at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
        at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        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.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
        at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:63)
        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:92)
        at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:561)
        at org.kohsuke.stapler.Stapler.invoke(Stapler.java:646)
        at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:612)
        at org.kohsuke.stapler.Stapler.invoke(Stapler.java:646)
        at org.kohsuke.stapler.Stapler.invoke(Stapler.java:477)
        at org.kohsuke.stapler.Stapler.service(Stapler.java:159)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:94)
        at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:185)
        at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:159)
        at net.bull.javamelody.PluginMonitoringFilter.doFilter(PluginMonitoringFilter.java:86)
        at org.jvnet.hudson.plugins.monitoring.HudsonMonitoringFilter.doFilter(HudsonMonitoringFilter.java:84)
        at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:97)
        at hudson.plugins.greenballs.GreenBallFilter.doFilter(GreenBallFilter.java:74)
        at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:97)
        at hudson.plugins.audit_trail.AuditTrailFilter.doFilter(AuditTrailFilter.java:66)
        at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:97)
        at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:86)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:47)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:84)
        at hudson.security.UnwrapSecurityExceptionFilter.doFilter(UnwrapSecurityExceptionFilter.java:51)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at org.acegisecurity.ui.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:166)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at org.acegisecurity.providers.anonymous.AnonymousProcessingFilter.doFilter(AnonymousProcessingFilter.java:125)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at org.acegisecurity.ui.rememberme.RememberMeProcessingFilter.doFilter(RememberMeProcessingFilter.java:142)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:271)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at org.acegisecurity.ui.basicauth.BasicProcessingFilter.doFilter(BasicProcessingFilter.java:173)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:249)
        at hudson.security.HttpSessionContextIntegrationFilter2.doFilter(HttpSessionContextIntegrationFilter2.java:66)
        at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
        at hudson.security.ChainedServletFilter.doFilter(ChainedServletFilter.java:76)
        at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:164)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:433)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
        at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:859)
        at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:574)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1527)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
        at java.util.Arrays.copyOfRange(Arrays.java:3209)
        at java.lang.String.<init>(String.java:215)
        at java.lang.StringBuilder.toString(StringBuilder.java:430)
        at hudson.model.Run.getUrl(Run.java:784)
        at sun.reflect.GeneratedMethodAccessor142.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.commons.jexl.util.PropertyExecutor.execute(PropertyExecutor.java:125)
        at org.apache.commons.jexl.util.introspection.UberspectImpl$VelGetterImpl.invoke(UberspectImpl.java:314)
        at org.apache.commons.jexl.parser.ASTArrayAccess.evaluateExpr(ASTArrayAccess.java:185)
        at org.apache.commons.jexl.parser.ASTIdentifier.execute(ASTIdentifier.java:75)
        at org.apache.commons.jexl.parser.ASTReference.execute(ASTReference.java:83)
        at org.apache.commons.jexl.parser.ASTReference.value(ASTReference.java:57)
        at org.apache.commons.jexl.parser.ASTReferenceExpression.value(ASTReferenceExpression.java:51)
        at org.apache.commons.jexl.ExpressionImpl.evaluate(ExpressionImpl.java:80)
        at hudson.ExpressionFactory2$JexlExpression.evaluate(ExpressionFactory2.java:72)
        at org.apache.commons.jelly.expression.ExpressionSupport.evaluateRecurse(ExpressionSupport.java:61)
        at org.apache.commons.jelly.expression.ExpressionSupport.evaluateAsString(ExpressionSupport.java:46)
        at org.apache.commons.jelly.expression.CompositeExpression.evaluateAsString(CompositeExpression.java:256)
        at org.apache.commons.jelly.expression.CompositeExpression.evaluate(CompositeExpression.java:248)
        at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:58)
        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.TagSupport.invokeBody(TagSupport.java:161)
        at org.apache.commons.jelly.tags.core.WhenTag.doTag(WhenTag.java:46)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)
        at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
        at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
        at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38)
        at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:270)

This occurred twice (the user tried to refresh the browser to view the raw log when it failed the first time). Following this:

Mar 16, 2012 4:45:33 PM hudson.remoting.Channel$ReaderThread run
SEVERE: I/O error in channel platform_test_slave_hudsonmaster1
java.io.IOException: Unexpected termination of the channel
        at hudson.remoting.Channel$ReaderThread.run(Channel.java:1037)
Caused by: java.io.EOFException
        at java.io.ObjectInputStream$BlockDataInputStream.peekByte(ObjectInputStream.java:2554)
        at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1297)
        at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
        at hudson.remoting.Channel$ReaderThread.run(Channel.java:1031)
Mar 16, 2012 4:45:36 PM hudson.remoting.ProxyOutputStream$Chunk$1 run
WARNING: Failed to ack the stream
java.io.IOException: SSH channel is closed. (Close requested by remote)
        at com.trilead.ssh2.channel.ChannelManager.sendData(ChannelManager.java:383)
        at com.trilead.ssh2.channel.ChannelOutputStream.write(ChannelOutputStream.java:63)
        at java.io.ObjectOutputStream$BlockDataOutputStream.drain(ObjectOutputStream.java:1838)
        at java.io.ObjectOutputStream$BlockDataOutputStream.setBlockDataMode(ObjectOutputStream.java:1747)
        at java.io.ObjectOutputStream.writeNonProxyDesc(ObjectOutputStream.java:1249)
        at java.io.ObjectOutputStream.writeClassDesc(ObjectOutputStream.java:1203)
        at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1387)
        at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1150)
        at java.io.ObjectOutputStream.writeFatalException(ObjectOutputStream.java:1538)
        at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:329)
        at hudson.remoting.Channel.send(Channel.java:491)
        at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:226)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)

Mar 16, 2012 4:45:53 PM hudson.model.AbstractBuild$AbstractRunner performAllBuildSteps
WARNING: Publisher hudson.tasks.junit.JUnitResultArchiver aborted due to exception
java.lang.NullPointerException
        at hudson.tasks.junit.JUnitParser.parse(JUnitParser.java:83)
        at hudson.tasks.junit.JUnitResultArchiver.parse(JUnitResultArchiver.java:123)
        at hudson.tasks.junit.JUnitResultArchiver.perform(JUnitResultArchiver.java:135)
        at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:19)
        at hudson.model.AbstractBuild$AbstractRunner.perform(AbstractBuild.java:682)
        at hudson.model.AbstractBuild$AbstractRunner.performAllBuildSteps(AbstractBuild.java:657)
        at hudson.model.AbstractBuild$AbstractRunner.performAllBuildSteps(AbstractBuild.java:635)
        at hudson.model.Build$RunnerImpl.post2(Build.java:161)
        at hudson.model.AbstractBuild$AbstractRunner.post(AbstractBuild.java:604)
        at hudson.model.Run.run(Run.java:1400)
        at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
        at hudson.model.ResourceController.execute(ResourceController.java:88)
        at hudson.model.Executor.run(Executor.java:175)
Mar 16, 2012 4:46:38 PM hudson.slaves.SlaveComputer tryReconnect
INFO: Attempting to reconnect platform_test_slave_hudsonmaster1
Mar 16, 2012 4:47:51 PM hudson.remoting.Channel$ReaderThread run
SEVERE: I/O error in channel platform_test_slave_hudsonmaster1
java.io.IOException: Unexpected termination of the channel
        at hudson.remoting.Channel$ReaderThread.run(Channel.java:1037)
Caused by: java.io.EOFException
        at java.io.ObjectInputStream$BlockDataInputStream.peekByte(ObjectInputStream.java:2554)
        at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1297)
        at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
        at hudson.remoting.Channel$ReaderThread.run(Channel.java:1031)
Mar 16, 2012 4:48:12 PM hudson.slaves.SlaveComputer tryReconnect
INFO: Attempting to reconnect platform_test_slave_hudsonmaster1

evernat added a comment - 2013-03-19 09:59

Is it reproduced with a recent Jenkins version?

evernat added a comment - 2013-03-19 09:59 Is it reproduced with a recent Jenkins version?

evernat added a comment - 2014-03-18 13:06

No response from the reporter, so resolving as incomplete.

evernat added a comment - 2014-03-18 13:06 No response from the reporter, so resolving as incomplete.

Danny Staple added a comment - 2014-03-18 13:50

We no longer reproduce this as we worked around it by redirecting the output somewhere. It is far less likely we will see it as we've internalised this as a standard thing - we only allow small bits of glue code output to the main log, and archive the redirected output.
Where there are non-concurrent jobs, this also means it can be observed in the workspace.

Where we allow concurrent jobs and slave node labels, we have placed apache servers pointing at the workspace directories so we can easily view the in progress logs, and write the link to them out in the main console log when it starts up.

Danny Staple added a comment - 2014-03-18 13:50 We no longer reproduce this as we worked around it by redirecting the output somewhere. It is far less likely we will see it as we've internalised this as a standard thing - we only allow small bits of glue code output to the main log, and archive the redirected output. Where there are non-concurrent jobs, this also means it can be observed in the workspace. Where we allow concurrent jobs and slave node labels, we have placed apache servers pointing at the workspace directories so we can easily view the in progress logs, and write the link to them out in the main console log when it starts up.

evernat added a comment - 2014-03-18 15:37

ok, thanks for those ideas.

evernat added a comment - 2014-03-18 15:37 ok, thanks for those ideas.

Details

Description

Attachments

Activity

Collapse comment: evernat added a comment - 2013-03-19 09:59

Expand comment: evernat added a comment - 2013-03-19 09:59

Collapse comment: evernat added a comment - 2014-03-18 13:06

Expand comment: evernat added a comment - 2014-03-18 13:06

Collapse comment: Danny Staple added a comment - 2014-03-18 13:50

Expand comment: Danny Staple added a comment - 2014-03-18 13:50

Collapse comment: evernat added a comment - 2014-03-18 15:37

Expand comment: evernat added a comment - 2014-03-18 15:37

People

Dates