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

Failed to execute command Pipe.Flush

    Details

    • Type: Bug
    • Status: Resolved (View Workflow)
    • Priority: Minor
    • Resolution: Fixed
    • Labels:
      None
    • Environment:
      Running Jenkins in Docker on version 2.138.2.

      Running the Jenkins Slave Docker container using remoting version 3.27
    • Similar Issues:
    • Released As:
      workflow-api 2.33

      Description

      Seeing this in my logs but for the most part everything seems to be working fine. I am sort of unclear on whether my Jenkins master is compatible with this agent version so that may be the problem.

       

      SEVERE: This command is created here
      Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle
      SEVERE: Failed to execute command Pipe.Flush(-1) (channel Jenkins Agent (i-03788ba5fec517424))
      java.util.concurrent.ExecutionException: Invalid object ID -1 iota=263
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
      	at hudson.remoting.ExportTable.get(ExportTable.java:397)
      	at hudson.remoting.Channel.getExportedObject(Channel.java:780)
      	at hudson.remoting.ProxyOutputStream$Flush.execute(ProxyOutputStream.java:307)
      	at hudson.remoting.Channel$1.handle(Channel.java:565)
      	at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:87)
      Caused by: java.lang.Exception: Object appears to be deallocated at lease before Sat Nov 10 15:38:16 UTC 2018
      	at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:474)
      	... 5 more
      Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle
      SEVERE: This command is created here
      

        Attachments

          Issue Links

            Activity

            awiddersheim Andrew Widdersheim created issue -
            awiddersheim Andrew Widdersheim made changes -
            Field Original Value New Value
            Description Seeing this in my logs but for the most part everything seems to be working fine. I am sort of unclear on whether my Jenkins master is compatible with this agent version so that may be the problem.
            {noformat}
            Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle SEVERE: This command is created here Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle SEVERE: Failed to execute command Pipe.Flush(-1) (channel Jenkins Agent (i-03788ba5fec517424)) java.util.concurrent.ExecutionException: Invalid object ID -1 iota=263 at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478) at hudson.remoting.ExportTable.get(ExportTable.java:397) at hudson.remoting.Channel.getExportedObject(Channel.java:780) at hudson.remoting.ProxyOutputStream$Flush.execute(ProxyOutputStream.java:307) at hudson.remoting.Channel$1.handle(Channel.java:565) at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:87) Caused by: java.lang.Exception: Object appears to be deallocated at lease before Sat Nov 10 15:38:16 UTC 2018 at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:474) ... 5 more Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle SEVERE: This command is created here
            {noformat}
            Seeing this in my logs but for the most part everything seems to be working fine. I am sort of unclear on whether my Jenkins master is compatible with this agent version so that may be the problem.

             
            {noformat}
            SEVERE: This command is created here
            Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle
            SEVERE: Failed to execute command Pipe.Flush(-1) (channel Jenkins Agent (i-03788ba5fec517424))
            java.util.concurrent.ExecutionException: Invalid object ID -1 iota=263
            at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:478)
            at hudson.remoting.ExportTable.get(ExportTable.java:397)
            at hudson.remoting.Channel.getExportedObject(Channel.java:780)
            at hudson.remoting.ProxyOutputStream$Flush.execute(ProxyOutputStream.java:307)
            at hudson.remoting.Channel$1.handle(Channel.java:565)
            at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:87)
            Caused by: java.lang.Exception: Object appears to be deallocated at lease before Sat Nov 10 15:38:16 UTC 2018
            at hudson.remoting.ExportTable.diagnoseInvalidObjectId(ExportTable.java:474)
            ... 5 more
            Nov 10, 2018 3:58:44 PM hudson.remoting.Channel$1 handle
            SEVERE: This command is created here
            {noformat}
            Hide
            jglick Jesse Glick added a comment -

            This might not be diagnosable without seeing the stack trace immediately below This command is created here.

            Show
            jglick Jesse Glick added a comment - This might not be diagnosable without seeing the stack trace immediately below This command is created here .
            Hide
            xy_alan Alan Yang added a comment -

            I had the same problem.

            Show
            xy_alan Alan Yang added a comment - I had the same problem.
            Hide
            l55s Laurens Leeuwis added a comment - - edited

            I have the same problem as well. We had a single job which always gave this message in the logging. (the job containing lots of proprietary libraries. I tried to create a simpler reproduction to be able to share it here, but was not able to). When this job runs on master there is no problem.

            I've tried different versions of Jenkins (2.138.1, 2.138.2, 2.138.3) and different versions of remoting (3.25, 3.27).

            In the end I've slightly modified the remoting.jar so it logs more and did some digging around:

            I think it kind of makes sense that this fails. First you clean up ('garbage collect') the ProxyOutputStream and afterwards you try to flush it.

            I've logged some additional stacktraces at different places and saw:

            I'm in no way a Jenkins internals expert, but these seem to be related. I don't know in what way they are related (since DelayBufferedOutputStream inherits from BufferedOutputStream so it should flush that I presume, but I don't know how that is glued to a (remote?) ProxyOutputStream).

            Anyhow, downgrading the workflow-api-plugin to a pre 2.30 version (see in https://github.com/jenkinsci/workflow-api-plugin/tree/workflow-api-2.29/src/main/java/org/jenkinsci/plugins/workflow that the org.jenkinsci.plugins.workflow.log package doesn't even exist here) made this message disappear from the logs entirely (also after running the single job which always caused the issue).

            This also makes it seem log related. After doing some more digging we saw that the job which always gave the error message was not able to show logging for the steps it executed (only checked this in blue ocean).

            Hope this helps Jesse Glick!

            Additional note: this finalize then flush seems to be added in https://github.com/jenkinsci/workflow-api-plugin/commit/f8ef9d300cc85138bffb69e151b538e8dc163d6e which would mean that workflow-api 2.30 would be ok to use as well (2.31 and higher contain this commit). I haven't checked this personally.

            Show
            l55s Laurens Leeuwis added a comment - - edited I have the same problem as well. We had a single job which always gave this message in the logging. (the job containing lots of proprietary libraries. I tried to create a simpler reproduction to be able to share it here, but was not able to). When this job runs on master there is no problem. I've tried different versions of Jenkins (2.138.1, 2.138.2, 2.138.3) and different versions of remoting (3.25, 3.27). In the end I've slightly modified the remoting.jar so it logs more and did some digging around: I found that this problem happens when first the finalize method of the ProxyOutputStream is called ( https://github.com/jenkinsci/remoting/blob/remoting-3.27/src/main/java/hudson/remoting/ProxyOutputStream.java#L180),  which sets the oid to -1 but leaves the channel as is. After that the flush method is called ( https://github.com/jenkinsci/remoting/blob/remoting-3.27/src/main/java/hudson/remoting/ProxyOutputStream.java#L154). The 'Pipe.Flush(-1)' part of the error comes from https://github.com/jenkinsci/remoting/blob/remoting-3.27/src/main/java/hudson/remoting/ProxyOutputStream.java#L320 The rest of the message comes from https://github.com/jenkinsci/remoting/blob/remoting-3.27/src/main/java/hudson/remoting/Channel.java#L570 I think it kind of makes sense that this fails. First you clean up ('garbage collect') the ProxyOutputStream and afterwards you try to flush it. I've logged some additional stacktraces at different places and saw: The DelayBufferedOutputStream from the workflow-api-plugin seems to cause this. At  https://github.com/jenkinsci/workflow-api-plugin/blob/workflow-api-2.32/src/main/java/org/jenkinsci/plugins/workflow/log/DelayBufferedOutputStream.java#L100  it does the finalize first and flush afterwards. I'm in no way a Jenkins internals expert, but these seem to be related. I don't know in what way they are related (since DelayBufferedOutputStream inherits from BufferedOutputStream so it should flush that I presume, but I don't know how that is glued to a (remote?) ProxyOutputStream). Anyhow, downgrading the workflow-api-plugin to a pre 2.30 version (see in https://github.com/jenkinsci/workflow-api-plugin/tree/workflow-api-2.29/src/main/java/org/jenkinsci/plugins/workflow  that the org.jenkinsci.plugins.workflow.log package doesn't even exist here) made this message disappear from the logs entirely (also after running the single job which always caused the issue). This also makes it seem log related. After doing some more digging we saw that the job which always gave the error message was not able to show logging for the steps it executed (only checked this in blue ocean). Hope this helps Jesse Glick ! Additional note: this finalize then flush seems to be added in https://github.com/jenkinsci/workflow-api-plugin/commit/f8ef9d300cc85138bffb69e151b538e8dc163d6e  which would mean that workflow-api 2.30 would be ok to use as well (2.31 and higher contain this commit). I haven't checked this personally.
            jglick Jesse Glick made changes -
            Link This issue relates to JENKINS-38381 [ JENKINS-38381 ]
            jglick Jesse Glick made changes -
            Component/s workflow-api-plugin [ 21711 ]
            Component/s remoting [ 15489 ]
            jglick Jesse Glick made changes -
            Assignee Jeff Thompson [ jthompson ] Jesse Glick [ jglick ]
            Hide
            jglick Jesse Glick added a comment -

            it does the finalize first and flush afterwards

            Irrelevant since super.finalize() is a no-op. I think the issue is that, at random, ProxyOutputStream.finalize might be called before DelayBufferedOutputStream.finalize.

            Show
            jglick Jesse Glick added a comment - it does the finalize first and flush afterwards Irrelevant since super.finalize() is a no-op. I think the issue is that, at random, ProxyOutputStream.finalize might be called before DelayBufferedOutputStream.finalize .
            jglick Jesse Glick made changes -
            Status Open [ 1 ] In Progress [ 3 ]
            Hide
            jglick Jesse Glick added a comment -

            the job which always gave the error message was not able to show logging for the steps it executed

            Unlike the stack trace reported in the original description, which is merely log noise as far as I know, failure to actually show log output would be a real bug. What step is involved? If sh, are you running an up-to-date durable-task & workflow-durable-task-step?

            Show
            jglick Jesse Glick added a comment - the job which always gave the error message was not able to show logging for the steps it executed Unlike the stack trace reported in the original description, which is merely log noise as far as I know, failure to actually show log output would be a real bug. What step is involved? If sh , are you running an up-to-date durable-task & workflow-durable-task-step ?
            jglick Jesse Glick made changes -
            Component/s remoting [ 15489 ]
            jglick Jesse Glick made changes -
            Remote Link This issue links to "remoting PR 308 (Web Link)" [ 22034 ]
            jglick Jesse Glick made changes -
            Remote Link This issue links to "workflow-api PR 83 (Web Link)" [ 22035 ]
            jglick Jesse Glick made changes -
            Status In Progress [ 3 ] In Review [ 10005 ]
            Hide
            jglick Jesse Glick added a comment -

            Laurens Leeuwis if you are able to reproduce the Failed to execute command Pipe.Flush error, please try installing this build via Plugin Manager » Advanced. This plugin patch ought to try to flush a collected stream before its delegate is finalized. I also filed a separate fix for Remoting which would avoid the error in any event, but that could take much longer to appear in core builds.

            As an aside, my comment of 2018-11-13 can be disregarded: I found (and offered a fix for) a buglet in Remoting that it sometimes printed a message suggesting that it was about to display an explanatory stack trace, even if there was no further stack trace to display.

            Show
            jglick Jesse Glick added a comment - Laurens Leeuwis if you are able to reproduce the Failed to execute command Pipe.Flush error, please try installing this build via Plugin Manager » Advanced . This plugin patch ought to try to flush a collected stream before its delegate is finalized. I also filed a separate fix for Remoting which would avoid the error in any event, but that could take much longer to appear in core builds. As an aside, my comment of 2018-11-13 can be disregarded: I found (and offered a fix for) a buglet in Remoting that it sometimes printed a message suggesting that it was about to display an explanatory stack trace, even if there was no further stack trace to display.
            Hide
            l55s Laurens Leeuwis added a comment - - edited

            Jesse Glick Using the patched version of the workflow-api did make the Pipe.Flush(-1) log disappear! Great

            failure to actually show log output would be a real bug. What step is involved? If sh, are you running an up-to-date durable-task & workflow-durable-task-step?

            We still don't see some logging in blue ocean using the patched version of workflow-api (we do see the logging in the 'normal' Jenkins views). We are making extensive use of sh steps. We're using durable-task v1.27 and workflow-durable-task-step v2.26. I think it might not be related to this Pipe.Flush(-1) issue after all. I found that we're running an ancient version of blueocean (v1.0.0-b23). Might be best to ignore this for now.

             

            Show
            l55s Laurens Leeuwis added a comment - - edited Jesse Glick Using the patched version of the workflow-api  did make the Pipe.Flush(-1)  log disappear! Great failure to actually show log output would be a real bug. What step is involved? If  sh , are you running an up-to-date  durable-task  &  workflow-durable-task-step ? We still don't see some logging in blue ocean using the patched version of workflow-api (we do see the logging in the 'normal' Jenkins views). We are making extensive use of sh steps. We're using durable-task v1.27 and workflow-durable-task-step v2.26. I think it might not be related to this Pipe.Flush(-1) issue after all. I found that we're running an ancient version of blueocean (v1.0.0-b23). Might be best to ignore this for now.  
            Hide
            jglick Jesse Glick added a comment -

            Laurens Leeuwis you might be seeing an issue we suspect exists in Blue Ocean: individual step logs truncate output after >10k lines of text. Or it might be some unrelated issue. At any rate, if the log output is present in the classic UI then I doubt flush-related bugs would be the culprit.

            Show
            jglick Jesse Glick added a comment - Laurens Leeuwis you might be seeing an issue we suspect exists in Blue Ocean: individual step logs truncate output after >10k lines of text. Or it might be some unrelated issue. At any rate, if the log output is present in the classic UI then I doubt flush -related bugs would be the culprit.
            jglick Jesse Glick made changes -
            Link This issue relates to JENKINS-54603 [ JENKINS-54603 ]
            jglick Jesse Glick made changes -
            Status In Review [ 10005 ] In Progress [ 3 ]
            jglick Jesse Glick made changes -
            Status In Progress [ 3 ] Open [ 1 ]
            jglick Jesse Glick made changes -
            Status Open [ 1 ] Fixed but Unreleased [ 10203 ]
            Resolution Fixed [ 1 ]
            Released As toward 2.33
            Hide
            dnusbaum Devin Nusbaum added a comment -

            This error was fixed in version 2.33 of the Pipeline API plugin.

            Show
            dnusbaum Devin Nusbaum added a comment - This error was fixed in version 2.33 of the Pipeline API plugin.
            dnusbaum Devin Nusbaum made changes -
            Status Fixed but Unreleased [ 10203 ] Resolved [ 5 ]
            Released As toward 2.33 workflow-api 2.33

              People

              • Assignee:
                jglick Jesse Glick
                Reporter:
                awiddersheim Andrew Widdersheim
              • Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: