Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-56446

IOException in FileLogStorage maybeFlush

    Details

    • Similar Issues:

      Description

      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)

       

      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)

        Attachments

          Activity

          Hide
          johnlengeling John Lengeling added a comment -

          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)}}

          ```

           

           

          Show
          johnlengeling John Lengeling added a comment - 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)}} ```    

            People

            • Assignee:
              Unassigned
              Reporter:
              rshade Robert Shade
            • Votes:
              4 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated: