[JIRA] (JENKINS-56446) IOException in FileLogStorage maybeFlush

[robert.shade@gmail.com (JIRA)]

Robert Shade created an issue

Jenkins / JENKINS-56446 IOException in FileLogStorage maybeFlush Issue Type: Bug Assignee: Unassigned Components: workflow-api-plugin Created: 2019-03-06 16:32 Priority: Minor Reporter: Robert Shade Some jobs get stuck in a state where they're unable to continue to write data to the console log.  The system log contains multiple entries of the following form until the job ends:   failed to flush /net/users/jenkins/configuration/jobs/XXX/builds/5/log java.io.IOException: Stream Closed at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at org.jenkinsci.plugins.workflow.log.DelayBufferedOutputStream$FlushControlledOutputStream.write(DelayBufferedOutputStream.java:134) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at java.io.FilterOutputStream.flush(FilterOutputStream.java:140) at org.jenkinsci.plugins.workflow.log.FileLogStorage.maybeFlush(FileLogStorage.java:190) at org.jenkinsci.plugins.workflow.log.FileLogStorage.overallLog(FileLogStorage.java:198) at org.jenkinsci.plugins.workflow.job.WorkflowRun.getLogText(WorkflowRun.java:1018) at org.jenkinsci.plugins.workflow.job.WorkflowRun.getLogInputStream(WorkflowRun.java:1026) at org.jenkinsci.plugins.gwt.GenericWebhookEnvironmentContributor.notLogged(GenericWebhookEnvironmentContributor.java:54) at org.jenkinsci.plugins.gwt.GenericWebhookEnvironmentContributor.buildEnvironmentFor(GenericWebhookEnvironmentContributor.java:30) at hudson.model.Run.getEnvironment(Run.java:2373) at org.jenkinsci.plugins.workflow.job.WorkflowRun.getEnvironment(WorkflowRun.java:468) at org.jenkinsci.plugins.workflow.cps.EnvActionImpl.getEnvironment(EnvActionImpl.java:86) at org.jenkinsci.plugins.workflow.cps.EnvActionImpl.getEnvironment(EnvActionImpl.java:67) at org.jenkinsci.plugins.workflow.support.DefaultStepContext.get(DefaultStepContext.java:72) at org.jenkinsci.plugins.workflow.steps.durable_task.DurableTaskStep$Execution.start(DurableTaskStep.java:305) at org.jenkinsci.plugins.workflow.cps.DSL.invokeStep(DSL.java:268) at org.jenkinsci.plugins.workflow.cps.DSL.invokeMethod(DSL.java:176) at org.jenkinsci.plugins.workflow.cps.CpsScript.invokeMethod(CpsScript.java:122) at sun.reflect.GeneratedMethodAccessor387.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93) at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325) at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1213) at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1022) at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.call(PogoMetaClassSite.java:42) at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48) at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113) at org.kohsuke.groovy.sandbox.impl.Checker$1.call(Checker.java:157) at org.kohsuke.groovy.sandbox.GroovyInterceptor.onMethodCall(GroovyInterceptor.java:23) at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxInterceptor.onMethodCall(SandboxInterceptor.java:155) at org.kohsuke.groovy.sandbox.impl.Checker$1.call(Checker.java:155) at org.kohsuke.groovy.sandbox.impl.Checker.checkedCall(Checker.java:159) at org.kohsuke.groovy.sandbox.impl.Checker.checkedCall(Checker.java:129) at com.cloudbees.groovy.cps.sandbox.SandboxInvoker.methodCall(SandboxInvoker.java:17) at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:57) at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:109) at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:82) at sun.reflect.GeneratedMethodAccessor384.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72) at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:103) at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:82) at sun.reflect.GeneratedMethodAccessor384.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72) at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:60) at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:109) at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:82) at sun.reflect.GeneratedMethodAccessor384.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72) at com.cloudbees.groovy.cps.impl.ConstantBlock.eval(ConstantBlock.java:21) at com.cloudbees.groovy.cps.Next.step(Next.java:83) at com.cloudbees.groovy.cps.Continuable$1.call(Continuable.java:174) at com.cloudbees.groovy.cps.Continuable$1.call(Continuable.java:163) at org.codehaus.groovy.runtime.GroovyCategorySupport$ThreadCategoryInfo.use(GroovyCategorySupport.java:129) at org.codehaus.groovy.runtime.GroovyCategorySupport.use(GroovyCategorySupport.java:268) at com.cloudbees.groovy.cps.Continuable.run0(Continuable.java:163) at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.access$101(SandboxContinuable.java:34) at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.lambda$run0$0(SandboxContinuable.java:59) at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.GroovySandbox.runInSandbox(GroovySandbox.java:121) at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.run0(SandboxContinuable.java:58) at org.jenkinsci.plugins.workflow.cps.CpsThread.runNextChunk(CpsThread.java:182) at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.run(CpsThreadGroup.java:332) at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.access$200(CpsThreadGroup.java:83) at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:244) at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:232) at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$2.call(CpsVmExecutorService.java:64) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:131) at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28) at jenkins.security.ImpersonatingExecutorService$1.run(ImpersonatingExecutorService.java:59) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Add Comment

This message was sent by Atlassian Jira (v7.11.2#711002-sha1:fdc329d)

[robert.shade@gmail.com (JIRA)]

Robert Shade updated an issue

Jenkins / JENKINS-56446 IOException in FileLogStorage maybeFlush

Change By: Robert Shade Environment: workflow-api-plugin v2.33 Jenkins v2.150.3

Add Comment

[robert.shade@gmail.com (JIRA)]

Robert Shade updated an issue

Jenkins / JENKINS-56446 IOException in FileLogStorage maybeFlush Change By: Robert Shade

When enabling DelayBufferedOutputStream logging, we also see this in the log: null

java.io.IOException: Stream Closed at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at org.jenkinsci.plugins.workflow.log.DelayBufferedOutputStream$FlushControlledOutputStream.write(DelayBufferedOutputStream.java:134) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)

at org.jenkinsci.plugins.workflow.log.DelayBufferedOutputStream.flushBuffer(DelayBufferedOutputStream.java:82) at org.jenkinsci.plugins.workflow.log.DelayBufferedOutputStream.flushAndReschedule(DelayBufferedOutputStream.java:91) at org.jenkinsci.plugins.workflow.log.DelayBufferedOutputStream$Flush.run(DelayBufferedOutputStream.java:114) at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266)

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)

Add Comment

[robert.shade@gmail.com (JIRA)]

Robert Shade updated an issue

Jenkins / JENKINS-56446 IOException in FileLogStorage maybeFlush

Change By: Robert Shade Priority: Minor Critical

Add Comment

[john.lengeling@gmail.com (JIRA)]

John Lengeling commented on JENKINS-56446

Re: IOException in FileLogStorage maybeFlush Ran into this issue under Jenkins 2.176.3 with workflow-api 2.37, mailer 1.27 , email-ext 2.66.   It occurred thou in the job post section trying to send an email notification.   Over a couple of days, the stacktraces filled up the partition since it outputs about every 30s-60s. Tried to abort the job but it would not die.   Tried to kill the thread from Melody but it would not die.   Had to restart Jenkins and the job started running again after the restart.  Then I quickly killed it.   ``` {{Sep 25, 2019 8:22:34 AM org.jenkinsci.plugins.workflow.log.FileLogStorage maybeFlush WARNING: failed to flush /opt/apache/.jenkins/jobs/Reprogramming/jobs/verify/branches/master/builds/604/log

java.io.IOException: Stream Closed at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326)

at org.jenkinsci.plugins.workflow.log.DelayBufferedOutputStream$FlushControlledOutputStream.write(DelayBufferedOutputStream.java:129)

at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at java.io.FilterOutputStream.flush(FilterOutputStream.java:140) at org.jenkinsci.plugins.workflow.log.FileLogStorage.maybeFlush(FileLogStorage.java:190) at org.jenkinsci.plugins.workflow.log.FileLogStorage.overallLog(FileLogStorage.java:198)

at org.jenkinsci.plugins.workflow.job.WorkflowRun.getLogText(WorkflowRun.java:1019) at hudson.plugins.emailext.AttachmentUtils$LogFileDataSource.getInputStream(AttachmentUtils.java:100) at javax.mail.internet.MimeUtility.getEncoding(MimeUtility.java:197) at javax.mail.internet.MimeUtility.getEncoding(MimeUtility.java:256) at javax.mail.internet.MimeBodyPart.updateHeaders(MimeBodyPart.java:1366) at javax.mail.internet.MimeBodyPart.updateHeaders(MimeBodyPart.java:1021) at javax.mail.internet.MimeMultipart.updateHeaders(MimeMultipart.java:419) at javax.mail.internet.MimeBodyPart.updateHeaders(MimeBodyPart.java:1345) at javax.mail.internet.MimeMessage.updateHeaders(MimeMessage.java:2106) at javax.mail.internet.MimeMessage.saveChanges(MimeMessage.java:2074) at javax.mail.internet.MimeMessage.writeTo(MimeMessage.java:1769) at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1099) at hudson.plugins.emailext.ExtendedEmailPublisher.sendMail(ExtendedEmailPublisher.java:484) at hudson.plugins.emailext.EmailExtStep$EmailExtStepExecution.run(EmailExtStep.java:224) at hudson.plugins.emailext.EmailExtStep$EmailExtStepExecution.run(EmailExtStep.java:163) at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1$1.call(AbstractSynchronousNonBlockingStepExecution.java:47) at hudson.security.ACL.impersonate(ACL.java:290) at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1.run(AbstractSynchronousNonBlockingStepExecution.java:44)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)}}

```

Add Comment

This message was sent by Atlassian Jira (v7.13.6#713006-sha1:cc4451f)

[dnusbaum@cloudbees.com (JIRA)]

Devin Nusbaum updated an issue

Jenkins / JENKINS-56446 IOException in FileLogStorage maybeFlush

Change By: Devin Nusbaum Labels: pipeline

Add Comment