[JIRA] (JENKINS-59267) Timeout exceptions in jenkins log when jenkins-cli executes a long-running command

23 views
Skip to first unread message

puetzk@puetzk.org (JIRA)

unread,
Sep 6, 2019, 8:51:03 PM9/6/19
to jenkinsc...@googlegroups.com
Kevin Puetz created an issue
 
Jenkins / Bug JENKINS-59267
Timeout exceptions in jenkins log when jenkins-cli executes a long-running command
Issue Type: Bug Bug
Assignee: Unassigned
Components: cli
Created: 2019-09-07 00:50
Environment: Jenkins 2.193, installed from https://pkg.jenkins.io/debian

Ubuntu 16.04 amd64
openjdk version "1.8.0_222"
OpenJDK Runtime Environment (build 1.8.0_222-8u222-b10-1ubuntu1~16.04.1-b10)
OpenJDK 64-Bit Server VM (build 25.222-b10, mixed mode)

Jenkins is self-hosting in Jetty: /usr/bin/java -Djava.awt.headless=true -jar /usr/share/jenkins/jenkins.war --webroot=/var/cache/jenkins/war --httpPort=8080
Priority: Minor Minor
Reporter: Kevin Puetz

Whenever a long-running command is run via jenkins-cli -s http://localhost:8080 -auth ..., the jenkins.log will show a timeout error, and echo back all the bytes of the input command as well. e.g.

 

$ echo 'println "hello"; sleep 6000; println "world"' | jenkins-cli -auth ... groovy =

will log a message like

2019-09-07 00:26:20.912+0000 [id=201]   WARNING h.c.PlainCLIProtocol$EitherSide$Reader#run
Also:   java.lang.Throwable: HttpInput failure
                at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:831)
                at org.eclipse.jetty.server.HttpConnection$BlockingReadCallback.failed(HttpConnection.java:661)
                at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:138)
                at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:406)
java.util.concurrent.TimeoutException: Idle timeout expired: 5000/5000 ms
        at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
        at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
        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)
Caused: java.io.IOException
        at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1085)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:318)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:256)
        at org.apache.commons.io.input.ProxyInputStream.read(ProxyInputStream.java:59)
        at hudson.cli.FlightRecorderInputStream.read(FlightRecorderInputStream.java:88)
        at java.io.DataInputStream.readInt(DataInputStream.java:387)
        at hudson.cli.PlainCLIProtocol$EitherSide$Reader.run(PlainCLIProtocol.java:110)
Caused: hudson.cli.DiagnosedStreamCorruptionException
Read back: 0x00 0x00 0x00 0x08 0x00 0x00 0x06 'groovy' 0x00 0x00 0x00 0x03 0x00 0x00 0x01 '=' 0x00 0x00 0x00 0x07 0x02 0x00 0x05 'UTF-8' 0x00 0x00 0x00 0x07 0x01 0x00 0x05 'en_US' 0x00 0x00 0x00 0x00 0x03 0x00 0x00 0x00 0x01 0x05 'p' 0x00 0x00 0x00 0x01 0x05 'r' 0x00 0x00 0x00 0x01 0x05 'i' 0x00 0x00 0x00 0x01 0x05 'n' 0x00 0x00 0x00 0x01 0x05 't' 0x00 0x00 0x00 0x01 0x05 'l' 0x00 0x00 0x00 0x01 0x05 'n' 0x00 0x00 0x00 0x01 0x05 ' ' 0x00 0x00 0x00 0x01 0x05 '"' 0x00 0x00 0x00 0x01 0x05 'h' 0x00 0x00 0x00 0x01 0x05 'e' 0x00 0x00 0x00 0x01 0x05 'l' 0x00 0x00 0x00 0x01 0x05 'l' 0x00 0x00 0x00 0x01 0x05 'o' 0x00 0x00 0x00 0x01 0x05 '"' 0x00 0x00 0x00 0x01 0x05 ';' 0x00 0x00 0x00 0x01 0x05 ' ' 0x00 0x00 0x00 0x01 0x05 's' 0x00 0x00 0x00 0x01 0x05 'l' 0x00 0x00 0x00 0x01 0x05 'e' 0x00 0x00 0x00 0x01 0x05 'e' 0x00 0x00 0x00 0x01 0x05 'p' 0x00 0x00 0x00 0x01 0x05 ' ' 0x00 0x00 0x00 0x01 0x05 '6' 0x00 0x00 0x00 0x01 0x05 '0' 0x00 0x00 0x00 0x01 0x05 '0' 0x00 0x00 0x00 0x01 0x05 '0' 0x00 0x00 0x00 0x01 0x05 ';' 0x00 0x00 0x00 0x01 0x05 ' ' 0x00 0x00 0x00 0x01 0x05 'p' 0x00 0x00 0x00 0x01 0x05 'r' 0x00 0x00 0x00 0x01 0x05 'i' 0x00 0x00 0x00 0x01 0x05 'n' 0x00 0x00 0x00 0x01 0x05 't' 0x00 0x00 0x00 0x01 0x05 'l' 0x00 0x00 0x00 0x01 0x05 'n' 0x00 0x00 0x00 0x01 0x05 ' ' 0x00 0x00 0x00 0x01 0x05 '"' 0x00 0x00 0x00 0x01 0x05 'w' 0x00 0x00 0x00 0x01 0x05 'o' 0x00 0x00 0x00 0x01 0x05 'r' 0x00 0x00 0x00 0x01 0x05 'l' 0x00 0x00 0x00 0x01 0x05 'd' 0x00 0x00 0x00 0x01 0x05 '"' 0x00 0x00 0x00 0x01 0x05 0x0a
0x00 0x00 0x00 0x00 0x06
Read ahead:
Diagnosis problem:
    java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 5000/5000 ms
        at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1085)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:318)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:256)
        at org.apache.commons.io.input.ProxyInputStream.read(ProxyInputStream.java:59)
        at hudson.cli.FlightRecorderInputStream$1.run(FlightRecorderInputStream.java:59)
    Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 5000/5000 ms
        at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
        at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
        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)
        Suppressed: java.lang.Throwable: HttpInput failure
                at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:831)
                at org.eclipse.jetty.server.HttpConnection$BlockingReadCallback.failed(HttpConnection.java:661)
                at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:138)
                at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:406)
                ... 9 more
        at hudson.cli.FlightRecorderInputStream.analyzeCrash(FlightRecorderInputStream.java:82)
        at hudson.cli.PlainCLIProtocol$EitherSide$Reader.run(PlainCLIProtocol.java:145)

However, both the "hello" and "world" println functions are run and eventually returned to stdout, so the command was not actually aborted. I'm not sure if there's an actual consequence to the timeout error (besides the log spam) or not; there's no obvious actual failure to complete.

This timeout seems to be controllable by adjusting -httpKeepAliveTimeout=, i.e. launching jenkins.jar with -httpKeepAliveTimeout=6000 gave me instead:

java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 6000/6000 ms

I found JENKINS-46659 which is somewhat similar, and suggests there is now a keepalive ping from jenkins-cli every 10s, though this is of course not sufficient with a 5s timeout. So I tried --httpKeepAliveTimeout=15000 and was then unable to provoke any timeout, even with the script upped to

echo 'println "hello"; sleep 30000; println "world"' | jenkins-cli -auth ... groovy =

So it seems like the mechanism to fix this robustly is in place, jut the default timeout and the default keepalive ping rates are not well-aligned; either the default ping rate in jenkins-cli (seems to be at https://github.com/jenkinsci/jenkins/blob/26c8523052baa4f009d7ed88d5f92b4d00b5f6f5/cli/src/main/java/hudson/cli/CLI.java#L338) should be quicker or the default timeout longer (which I found some other discussion of at at JENKINS-42513.
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v7.11.2#711002-sha1:fdc329d)

puetzk@puetzk.org (JIRA)

unread,
Sep 6, 2019, 8:52:03 PM9/6/19
to jenkinsc...@googlegroups.com
Kevin Puetz updated an issue
Change By: Kevin Puetz
Whenever a long-running command is run via {{ jenkins-cli -s [ http://localhost:8080 |http: / /localhost:8080/] -auth ... }} , the jenkins.log will show a timeout error, and echo back all the bytes of the input command as well. e.g.
 
{noformat}
$ echo 'println "hello"; sleep 6000; println "world"' | jenkins-cli - s http://localhost:8080/ - auth ... groovy =
{noformat}

will log a message like
{noformat}
        at hudson.cli.PlainCLIProtocol$EitherSide$Reader.run(PlainCLIProtocol.java:145){noformat}

However, both the "hello" and "world" println functions are run and eventually returned to stdout, so the command was not actually aborted. I'm not sure if there's an actual consequence to the timeout error (besides the log spam) or not; there's no obvious actual failure to complete.

This timeout seems to be controllable by adjusting {{--httpKeepAliveTimeout=-}}, i.e. launching jenkins.jar with {{-httpKeepAliveTimeout=6000}} gave me instead:
{noformat}
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 6000/6000 ms{noformat}

I found JENKINS-46659 which is somewhat similar, and suggests there is now a keepalive ping from jenkins-cli every 10s, though this is of course not sufficient with a 5s timeout. So I tried {{--httpKeepAliveTimeout=15000}} and was then unable to provoke any timeout, even with the script upped to
{noformat}
echo 'println "hello"; sleep 30000; println "world"' | jenkins-cli -auth ... groovy ={noformat}
So it seems like the mechanism to fix this robustly is in place, jut the default timeout and the default keepalive ping rates are not well-aligned; either the default ping rate in jenkins-cli (seems to be at [https://github.com/jenkinsci/jenkins/blob/26c8523052baa4f009d7ed88d5f92b4d00b5f6f5/cli/src/main/java/hudson/cli/CLI.java#L338]) should be quicker or the default timeout longer (which I found some other discussion of at at JENKINS-42513.

dbeck@cloudbees.com (JIRA)

unread,
Oct 4, 2019, 8:42:03 AM10/4/19
to jenkinsc...@googlegroups.com
Daniel Beck started work on Bug JENKINS-59267
 
Change By: Daniel Beck
Status: Open In Progress
This message was sent by Atlassian Jira (v7.13.6#713006-sha1:cc4451f)
Atlassian logo

dbeck@cloudbees.com (JIRA)

unread,
Oct 4, 2019, 8:43:02 AM10/4/19
to jenkinsc...@googlegroups.com
Daniel Beck commented on Bug JENKINS-59267
 
Re: Timeout exceptions in jenkins log when jenkins-cli executes a long-running command

PR is up at https://github.com/jenkinsci/jenkins/pull/4263 and proposes a change to 3 seconds.

Kevin Puetz Could you try the CLI from the PR build to see whether that fixes things for you?

jsoref+jenkins@gmail.com (JIRA)

unread,
Oct 4, 2019, 5:08:04 PM10/4/19
to jenkinsc...@googlegroups.com
Josh Soref updated an issue
 
Change By: Josh Soref
Whenever a long-running command is run via {{jenkins-cli -s http://localhost:8080/ -auth ...}}, the jenkins.log will show a timeout error, and echo back all the bytes of the input command as well. e.g.
 
{noformat}
$ echo 'println "hello"; sleep 6000; println "world"' | jenkins-cli -s http://localhost:8080/ -auth ... groovy =
{noformat}
This timeout seems to be controllable by adjusting {{ \ - \ -httpKeepAliveTimeout= \ -}}, i.e. launching jenkins.jar with {{-httpKeepAliveTimeout=6000}} gave me instead:

{noformat}
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 6000/6000 ms{noformat}
I found JENKINS-46659 which is somewhat similar, and suggests there is now a keepalive ping from jenkins-cli every 10s, though this is of course not sufficient with a 5s timeout. So I tried {{--httpKeepAliveTimeout=15000}} and was then unable to provoke any timeout, even with the script upped to
{noformat}
echo 'println "hello"; sleep 30000; println "world"' | jenkins-cli -auth ... groovy ={noformat}
So it seems like the mechanism to fix this robustly is in place, jut the default timeout and the default keepalive ping rates are not well-aligned; either the default ping rate in jenkins-cli (seems to be at [https://github.com/jenkinsci/jenkins/blob/26c8523052baa4f009d7ed88d5f92b4d00b5f6f5/cli/src/main/java/hudson/cli/CLI.java#L338]) should be quicker or the default timeout longer (which I found some other discussion of at at JENKINS-42513.

jsoref+jenkins@gmail.com (JIRA)

unread,
Oct 4, 2019, 5:09:02 PM10/4/19
to jenkinsc...@googlegroups.com
This timeout seems to be controllable by adjusting {{\- \- httpKeepAliveTimeout= \- }}, i.e. launching jenkins.jar with {{ \ -httpKeepAliveTimeout=6000}} gave me instead:

{noformat}
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 6000/6000 ms{noformat}
I found JENKINS-46659 which is somewhat similar, and suggests there is now a keepalive ping from jenkins-cli every 10s, though this is of course not sufficient with a 5s timeout. So I tried {{--httpKeepAliveTimeout=15000}} and was then unable to provoke any timeout, even with the script upped to
{noformat}
echo 'println "hello"; sleep 30000; println "world"' | jenkins-cli -auth ... groovy ={noformat}
So it seems like the mechanism to fix this robustly is in place, jut the default timeout and the default keepalive ping rates are not well-aligned; either the default ping rate in jenkins-cli (seems to be at [https://github.com/jenkinsci/jenkins/blob/26c8523052baa4f009d7ed88d5f92b4d00b5f6f5/cli/src/main/java/hudson/cli/CLI.java#L338]) should be quicker or the default timeout longer (which I found some other discussion of at at JENKINS-42513.

jsoref+jenkins@gmail.com (JIRA)

unread,
Oct 4, 2019, 5:10:03 PM10/4/19
to jenkinsc...@googlegroups.com
This timeout seems to be controllable by adjusting {{\- \- httpKeepAliveTimeout=}}, i.e. launching jenkins.jar with {{\- \- httpKeepAliveTimeout=6000}} gave me instead:

{noformat}
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 6000/6000 ms{noformat}
I found JENKINS-46659 which is somewhat similar, and suggests there is now a keepalive ping from jenkins-cli every 10s, though this is of course not sufficient with a 5s timeout. So I tried {{--httpKeepAliveTimeout=15000}} and was then unable to provoke any timeout, even with the script upped to
{noformat}
echo 'println "hello"; sleep 30000; println "world"' | jenkins-cli -auth ... groovy ={noformat}
So it seems like the mechanism to fix this robustly is in place, jut the default timeout and the default keepalive ping rates are not well-aligned; either the default ping rate in jenkins-cli (seems to be at [https://github.com/jenkinsci/jenkins/blob/26c8523052baa4f009d7ed88d5f92b4d00b5f6f5/cli/src/main/java/hudson/cli/CLI.java#L338]) should be quicker or the default timeout longer (which I found some other discussion of at at JENKINS-42513.

dbeck@cloudbees.com (JIRA)

unread,
Oct 7, 2019, 4:10:04 AM10/7/19
to jenkinsc...@googlegroups.com
Daniel Beck closed an issue as Fixed
Change By: Daniel Beck
Status: In Progress Closed
Resolution: Fixed
Released As: jenkins-2.199

o.v.nenashev@gmail.com (JIRA)

unread,
Oct 7, 2019, 8:14:03 PM10/7/19
to jenkinsc...@googlegroups.com
Oleg Nenashev updated an issue
Change By: Oleg Nenashev
Labels: lts-candidate

ogondza@gmail.com (JIRA)

unread,
Oct 8, 2019, 8:39:04 AM10/8/19
to jenkinsc...@googlegroups.com
Oliver Gondža updated an issue
Change By: Oliver Gondža
Labels: lts 2.190.2 - candidate fixed

puetzk@puetzk.org (JIRA)

unread,
Oct 10, 2019, 12:09:03 AM10/10/19
to jenkinsc...@googlegroups.com
Kevin Puetz commented on Bug JENKINS-59267
 
Re: Timeout exceptions in jenkins log when jenkins-cli executes a long-running command

Looks good to me, I see the 3s pings in -logger FINE and I no longer seem timeouts using default settings.

Obviously I can still provoke a timeout if I set Jenkins shorter (e.g. 1s), without adjusting jenkins-cli accordingly, but that's to be expected and the defaults now seem to be well-behaved.

 
Reply all
Reply to author
Forward
0 new messages