[JIRA] (JENKINS-54566) Failed to execute command Pipe.Flush

6 views
Skip to first unread message

awiddersheim@hotmail.com (JIRA)

unread,
Nov 10, 2018, 12:01:02 PM11/10/18
to jenkinsc...@googlegroups.com
Andrew Widdersheim created an issue
 
Jenkins / Bug JENKINS-54566
Failed to execute command Pipe.Flush
Issue Type: Bug Bug
Assignee: Jeff Thompson
Components: remoting
Created: 2018-11-10 17:00
Environment: Running Jenkins in Docker on version 2.138.2.

Running the Jenkins Slave Docker container using remoting version 3.27
Priority: Minor Minor
Reporter: Andrew Widdersheim

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.

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
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v7.11.2#711002-sha1:fdc329d)

awiddersheim@hotmail.com (JIRA)

unread,
Nov 10, 2018, 1:34:02 PM11/10/18
to jenkinsc...@googlegroups.com
Andrew Widdersheim updated an issue
Change By: Andrew Widdersheim
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}

jglick@cloudbees.com (JIRA)

unread,
Nov 13, 2018, 2:14:02 PM11/13/18
to jenkinsc...@googlegroups.com
Jesse Glick commented on Bug JENKINS-54566
 
Re: Failed to execute command Pipe.Flush

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

alanlhy@gmail.com (JIRA)

unread,
Nov 14, 2018, 9:56:02 PM11/14/18
to jenkinsc...@googlegroups.com

laurens.leeuwis@gmail.com (JIRA)

unread,
Nov 15, 2018, 9:26:02 AM11/15/18
to jenkinsc...@googlegroups.com

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!

laurens.leeuwis@gmail.com (JIRA)

unread,
Nov 15, 2018, 9:37:02 AM11/15/18
to jenkinsc...@googlegroups.com
Laurens Leeuwis edited a comment on Bug JENKINS-54566
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 [~jglick]!

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@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 6:13:01 PM11/15/18
to jenkinsc...@googlegroups.com
Jesse Glick updated an issue
 
Change By: Jesse Glick
Component/s: workflow-api-plugin
Component/s: remoting

jglick@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 6:13:03 PM11/15/18
to jenkinsc...@googlegroups.com
Jesse Glick assigned an issue to Jesse Glick
Change By: Jesse Glick
Assignee: Jeff Thompson Jesse Glick

jglick@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 6:24:03 PM11/15/18
to jenkinsc...@googlegroups.com

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@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 6:45:02 PM11/15/18
to jenkinsc...@googlegroups.com
Jesse Glick started work on Bug JENKINS-54566
 
Change By: Jesse Glick
Status: Open In Progress

jglick@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 6:47:02 PM11/15/18
to jenkinsc...@googlegroups.com

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@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 6:52:01 PM11/15/18
to jenkinsc...@googlegroups.com
Jesse Glick updated an issue
Change By: Jesse Glick
Component/s: remoting

jglick@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 9:35:02 PM11/15/18
to jenkinsc...@googlegroups.com

jglick@cloudbees.com (JIRA)

unread,
Nov 15, 2018, 9:57:02 PM11/15/18
to jenkinsc...@googlegroups.com
 
Re: Failed to execute command Pipe.Flush

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.

laurens.leeuwis@gmail.com (JIRA)

unread,
Nov 16, 2018, 1:56:02 AM11/16/18
to jenkinsc...@googlegroups.com

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.

 

laurens.leeuwis@gmail.com (JIRA)

unread,
Nov 16, 2018, 1:57:02 AM11/16/18
to jenkinsc...@googlegroups.com
Laurens Leeuwis edited a comment on Bug JENKINS-54566
[~jglick] Using the patched version of the {{workflow-api}} did make the {{Pipe.Flush(-1)}} log disappear! Great :)
{quote}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}}?
{quote}
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 .

 

jglick@cloudbees.com (JIRA)

unread,
Nov 16, 2018, 9:37:02 AM11/16/18
to jenkinsc...@googlegroups.com

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@cloudbees.com (JIRA)

unread,
Nov 19, 2018, 3:47:03 PM11/19/18
to jenkinsc...@googlegroups.com

jglick@cloudbees.com (JIRA)

unread,
Nov 19, 2018, 3:47:04 PM11/19/18
to jenkinsc...@googlegroups.com
Change By: Jesse Glick
Status: Open Fixed but Unreleased
Resolution: Fixed
Released As: toward 2.33

jglick@cloudbees.com (JIRA)

unread,
Nov 19, 2018, 3:47:04 PM11/19/18
to jenkinsc...@googlegroups.com
Jesse Glick stopped work on Bug JENKINS-54566
 
Change By: Jesse Glick
Status: In Progress Open

dnusbaum@cloudbees.com (JIRA)

unread,
Nov 19, 2018, 4:07:02 PM11/19/18
to jenkinsc...@googlegroups.com
Devin Nusbaum updated Bug JENKINS-54566
 

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

Change By: Devin Nusbaum
Status: Fixed but Unreleased Resolved
Released As: toward workflow-api 2.33
Reply all
Reply to author
Forward
0 new messages