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

Timestamps missing for agent-based steps in Pipeline Job 2.26

    XMLWordPrintable

    Details

    • Similar Issues:
    • Released As:
      1.9

      Description

      After upgrading to Pipeline Job 2.26 earlier today, in the Console Log for pipeline builds, I only appear to have timestamps for the operations performed by the master node (i.e., the initial git checkout), but all remaining build steps that are performed on agent nodes lack timestamps entirely. The job properly recognizes that timestamps were enabled in the first place, so provides the typical "System clock time" vs., "Elapsed time" options on the left, but these only have an effect for the master node-occurring timestamps; timestamps for steps taking place on agent nodes are missing regardless.

        Attachments

          Issue Links

            Activity

            Hide
            framillien Florian Ramillien added a comment - - edited

            Hi, after upgrading to last Jenkins LTS with all plugin update (pipeline + timestamps) we fall on this missing timestamp + a hudge side effect : Windows builders disconnected and builds are aborted. (maybe linux too, but this project build only on windows)

            After many tests, this is related to log volume and timestamp plugin with pipeline job. We have some compiling task (step bat running python scripts) generating huge log volume (3-5Mo), and we see :

            • Slow down of log display on jenkins UI (maybe build is slow down too, but not sure)
            • Agent is disconnected

            Trying with some other configuration it's working:

            • Same log volume but without timestamp plugin
            • timestamp plugin with less log output
            • Same log volume + Timestamp, but on a "classic" job, not a pipeline job.

            I suspect that all logs for a timestamp are buffered somewhere and cause this issue. Fixing timestamp not handled on each output lines should fix this too.

            Error, we can see in traces are like:
            [Pipeline] End of PipelineERROR: script apparently exited with code 0 but asynchronous notification was lost
            Finished: FAILURE
            Or more random errors like:

            2018-10-23 15:01:30 Cannot contact win-xxxx-xx: java.lang.InterruptedException
            hudson.remoting.RequestAbortedException: java.nio.channels.ClosedChannelException

            We will try your patch and/or durable task configuration option described here. Do you want I open a new bug report for this ?

            Show
            framillien Florian Ramillien added a comment - - edited Hi, after upgrading to last Jenkins LTS with all plugin update (pipeline + timestamps) we fall on this missing timestamp + a hudge side effect : Windows builders disconnected and builds are aborted. (maybe linux too, but this project build only on windows) After many tests, this is related to log volume and timestamp plugin with pipeline job. We have some compiling task (step bat running python scripts) generating huge log volume (3-5Mo), and we see : Slow down of log display on jenkins UI (maybe build is slow down too, but not sure) Agent is disconnected Trying with some other configuration it's working: Same log volume but without timestamp plugin timestamp plugin with less log output Same log volume + Timestamp, but on a "classic" job, not a pipeline job. I suspect that all logs for a timestamp are buffered somewhere and cause this issue. Fixing timestamp not handled on each output lines should fix this too. Error, we can see in traces are like: [Pipeline] End of PipelineERROR: script apparently exited with code 0 but asynchronous notification was lost Finished: FAILURE Or more random errors like: 2018-10-23 15:01:30 Cannot contact win-xxxx-xx: java.lang.InterruptedException hudson.remoting.RequestAbortedException: java.nio.channels.ClosedChannelException We will try your patch and/or durable task configuration option described here. Do you want I open a new bug report for this ?
            Hide
            framillien Florian Ramillien added a comment - - edited

            Our tests results are:

            • Standard JOB + Timestamper 1.8.10 => Build OK in less than 10 mn with expected timestamp on each line
            • Pipeline Job without Timestamper => Build OK in less than 10 mn
            • Pipeline Job + Timestamper RC 1.8.11 => Build Reported Fail in 19 mn with expected timestamp on each line.
            • Pipeline Job + Timestamper RC 1.8.11 + USE_WATCHING=false => Build OK in less than 10 mn with expected timestamp

            I say "Reported fail" because if we look on slave, build is correct and in "durable-xxxx" directory we could see that :

            • job result is OK (jenkins-result.txt)
            • delta time between "jenkins-main.bat" and "jenkins-result.txt" is less than 10mn (expected build time).
            • Log file (jenkins-logs.txt) size for this step is 3.5 Mo

            Looking further on log on Jenkins UI, I could see that pipeline end in the middle of the log and 9 mn later some more logs are displayed (but not the full logs) and job fail:
            **

            2018-10-24 10:18:24 Some CPP compiler outputs
            2018-10-24 10:18:24 [Pipeline] }[Pipeline] // timestamps[Pipeline] }
            2018-10-24 10:27:34 Some CPP compiler outputs
            2018-10-24 10:27:34 [Pipeline] // sshagent Some CPP compiler outputs
            2018-10-24 10:27:34 Some CPP compiler outputs
            ... many outputs lines with time stamp ...
            2018-10-24 10:27:34 Some CPP compiler outputs
            ERROR: script apparently exited with code 0 but asynchronous notification was lost[ 2018-10-24T10:27:34.892Z
            Finished: FAILURE
            

             

            Show
            framillien Florian Ramillien added a comment - - edited Our tests results are: Standard JOB + Timestamper 1.8.10 => Build OK in less than 10 mn with expected timestamp on each line Pipeline Job without Timestamper => Build OK in less than 10 mn Pipeline Job + Timestamper RC 1.8.11 => Build Reported Fail in 19 mn with expected timestamp on each line. Pipeline Job + Timestamper RC 1.8.11 + USE_WATCHING=false => Build OK in less than 10 mn with expected timestamp I say "Reported fail" because if we look on slave, build is correct and in "durable-xxxx" directory we could see that : job result is OK (jenkins-result.txt) delta time between "jenkins-main.bat" and "jenkins-result.txt" is less than 10mn (expected build time). Log file (jenkins-logs.txt) size for this step is 3.5 Mo Looking further on log on Jenkins UI, I could see that pipeline end in the middle of the log and 9 mn later some more logs are displayed (but not the full logs) and job fail: ** 2018-10-24 10:18:24 Some CPP compiler outputs 2018-10-24 10:18:24 [Pipeline] }[Pipeline] // timestamps[Pipeline] } 2018-10-24 10:27:34 Some CPP compiler outputs 2018-10-24 10:27:34 [Pipeline] // sshagent Some CPP compiler outputs 2018-10-24 10:27:34 Some CPP compiler outputs ... many outputs lines with time stamp ... 2018-10-24 10:27:34 Some CPP compiler outputs ERROR: script apparently exited with code 0 but asynchronous notification was lost[ 2018-10-24T10:27:34.892Z Finished: FAILURE  
            Hide
            jglick Jesse Glick added a comment -

            Windows builders disconnected and builds are aborted

            Maybe JENKINS-53888.

            Show
            jglick Jesse Glick added a comment - Windows builders disconnected and builds are aborted Maybe JENKINS-53888 .
            Hide
            framillien Florian Ramillien added a comment -

            The result is the same, yes. But I don't think the cause was the same, in our case connection with agent is working unless some specific combinaison of components:

            • A long build with a simple task (ping during 20mn) is working
            • A shorter build (10mn) with hudge log generated by "bat" step, fail (see previous comment).
            • Removing "timestamps" step from pipeline fix this issue
            • Reverting from "push" to "pull" logs in "durable-task" fix this issue too.

            In our case, something occurs at the end of the job between master and slave, and master never receive the "OK" result from slave (nor the full logs). And after 9mn of inactivity build fail and agent is disconnected. It's always reproduced with hudge logs, but maybe logs size is just a factor triggering another hidden synchro/lock problem.

            For now "USE_WATCHING=false" is set in our Jenkins master and is an acceptable solution for us.

            Show
            framillien Florian Ramillien added a comment - The result is the same, yes. But I don't think the cause was the same, in our case connection with agent is working unless some specific combinaison of components: A long build with a simple task (ping during 20mn) is working A shorter build (10mn) with hudge log generated by "bat" step, fail (see previous comment). Removing "timestamps" step from pipeline fix this issue Reverting from "push" to "pull" logs in "durable-task" fix this issue too. In our case, something occurs at the end of the job between master and slave, and master never receive the "OK" result from slave (nor the full logs). And after 9mn of inactivity build fail and agent is disconnected. It's always reproduced with hudge logs, but maybe logs size is just a factor triggering another hidden synchro/lock problem. For now "USE_WATCHING=false" is set in our Jenkins master and is an acceptable solution for us.
            Hide
            jglick Jesse Glick added a comment -

            Florian Ramillien please discuss in JENKINS-53888.

            Show
            jglick Jesse Glick added a comment - Florian Ramillien please discuss in JENKINS-53888 .

              People

              • Assignee:
                jglick Jesse Glick
                Reporter:
                medianick Nick Jones
              • Votes:
                8 Vote for this issue
                Watchers:
                16 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: