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

Timeout exceptions in jenkins log when jenkins-cli executes a long-running command

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Minor
    • Resolution: Fixed
    • Component/s: cli
    • Labels:
    • Environment:
    • Similar Issues:
    • Released As:
      jenkins-2.199

      Description

      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 -s http://localhost:8080/ -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.

        Attachments

          Issue Links

            Activity

            Hide
            danielbeck Daniel Beck added a comment -

            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?

            Show
            danielbeck Daniel Beck added a comment - 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?
            Hide
            puetzk Kevin Puetz added a comment -

            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.

             

            Show
            puetzk Kevin Puetz added a comment - 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.  

              People

              • Assignee:
                Unassigned
                Reporter:
                puetzk Kevin Puetz
              • Votes:
                1 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: