Any idea what could cause Jenkins console output to be mixed like this in a pipeline job?

[Daniel Anechitoaie]

For some reason the console output seems to be all mixed. Like the output from on step is present in other step.

Notice how "(BeginCheckRun)" stage started, yet the output from (Git) stage is not finished, and part of the (Git) stage is also printed after (BeginCheckRun) stage started.

Any idea what's going on?

myPlugin() is a Step plugin I did that "extends SynchronousNonBlockingStepExecution"

If I don't call myPlugin() in my Jenkinsfile then the output is ok.

Any idea what could cause this to happen?

Here's my Jenkinsfile

---

node {

    stage('Cleanup') {

        cleanWs()

    }

    stage('Git') {

        dir('scm') {

            git(...)

        }

    }

    stage('BeginCheckRun') {

        dir('scm') {

            myPlugin()

        }

    }

}

---

And the console output:

---

[2019-04-16T09:06:27.056Z] Started by user Daniel Anechitoaie

[2019-04-16T09:06:27.057Z] Running in Durability level: PERFORMANCE_OPTIMIZED

[2019-04-16T09:06:27.381Z] [Pipeline] Start of Pipeline

[2019-04-16T09:06:27.414Z] [Pipeline] node

[2019-04-16T09:06:27.432Z] Running on wrkr1 in /var/lib/jenkins/workspace/some/test

[2019-04-16T09:06:27.432Z] [Pipeline] {

[2019-04-16T09:06:27.449Z] [Pipeline] stage

[2019-04-16T09:06:27.452Z] [Pipeline] { (Cleanup)

[2019-04-16T09:06:27.552Z] [Pipeline] cleanWs

[2019-04-16T09:06:27.564Z] [WS-CLEANUP] Deleting project workspace...

[2019-04-16T09:06:27.564Z] [WS-CLEANUP] Deferred wipeout is used...

[2019-04-16T09:06:27.912Z] [WS-CLEANUP] done

[2019-04-16T09:06:27.914Z] [Pipeline] }

[2019-04-16T09:06:27.918Z] [Pipeline] // stage

[2019-04-16T09:06:27.933Z] [Pipeline] stage

[2019-04-16T09:06:27.935Z] [Pipeline] { (Git)

[2019-04-16T09:06:27.945Z] [Pipeline] dir

[2019-04-16T09:06:27.946Z] Running in /var/lib/jenkins/workspace/some/test/scm

[2019-04-16T09:06:27.946Z] [Pipeline] {

[2019-04-16T09:06:27.973Z] [Pipeline] git

[2019-04-16T09:06:27.996Z] using credential 86595008-12db-46b4-b1a3-e79de2f0e2af

[2019-04-16T09:06:28.289Z] Cloning the remote Git repository

[2019-04-16T09:06:28.292Z] Cloning repository g...@github.com:some/test.git

[2019-04-16T09:06:28.292Z]  > git init /var/lib/jenkins/workspace/some/test/scm # timeout=10

[2019-04-16T09:06:28.718Z] Fetching upstream changes from g...@github.com:some/test.git

[2019-04-16T09:06:28.719Z]  > git --version # timeout=10

[2019-04-16T09:06:28.724Z] using GIT_SSH to set credentials some_test

[2019-04-16T09:06:28.726Z]  > git fetch --tags --progress g...@github.com:some/test.git +refs/heads/*:refs/remotes/origin/*

[2019-04-16T09:06:30.130Z]  > git config remote.origin.url g...@github.com:some/test.git # timeout=10

[2019-04-16T09:06:30.135Z]  > git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10

[2019-04-16T09:06:30.142Z]  > git config remote.origin.url g...@github.com:some/test.git # timeout=10

[2019-04-16T09:06:30.150Z] Fetching upstream changes from g...@github.com:some/test.git

[2019-04-16T09:06:30.150Z] using GIT_SSH to set credentials some_test

[2019-04-16T09:06:30.151Z]  > git fetch --tags --progress g...@github.com:some/test.git +refs/heads/*:refs/remotes/origin/*

[2019-04-16T09:06:31.222Z] Checking out Revision bf7221352765115631b4326fa6b0603ff0f19637 (origin/feature/pr1)

[2019-04-16T09:06:31.269Z] Commit message: "Update README.md"

[2019-04-16T09:06:31.300Z] [Pipeline] }

[2019-04-16T09:06:31.302Z] [Pipeline] // dir

[2019-04-16T09:06:31.331Z] [Pipeline] }

[2019-04-16T09:06:31.362Z] [Pipeline] // stage

[2019-04-16T09:06:31.376Z] [Pipeline] stage

[2019-04-16T09:06:31.380Z] [Pipeline] { (BeginCheckRun)

[2019-04-16T09:06:31.485Z] [Pipeline] dir

[2019-04-16T09:06:31.485Z] Running in /var/lib/jenkins/workspace/some/test/scm

[2019-04-16T09:06:31.486Z] [Pipeline] {

[2019-04-16T09:06:31.541Z] [Pipeline] myPlugin

[2019-04-16T09:06:31.208Z] Seen branch in repository origin/feature/pr1

[2019-04-16T09:06:31.208Z] Seen branch in repository origin/master

[2019-04-16T09:06:31.208Z] Seen 2 remote branches

[2019-04-16T09:06:31.211Z]  > git show-ref --tags -d # timeout=10

[2019-04-16T09:06:31.224Z]  > git config core.sparsecheckout # timeout=10

[2019-04-16T09:06:31.229Z]  > git checkout -f bf7221352765115631b4326fa6b0603ff0f19637

[2019-04-16T09:06:31.244Z]  > git branch -a -v --no-abbrev # timeout=10

[2019-04-16T09:06:31.249Z]  > git checkout -b feature/pr1 bf7221352765115631b4326fa6b0603ff0f19637

[2019-04-16T09:06:31.272Z]  > git rev-list --no-walk bf7221352765115631b4326fa6b0603ff0f19637 # timeout=10

[2019-04-16T09:06:32.989Z] [Pipeline] }

[2019-04-16T09:06:32.995Z] [Pipeline] // dir

[2019-04-16T09:06:33.063Z] [Pipeline] }

[2019-04-16T09:06:33.089Z] [Pipeline] // stage

[2019-04-16T09:06:33.127Z] [Pipeline] }

[2019-04-16T09:06:33.138Z] [Pipeline] // node

[2019-04-16T09:06:33.165Z] [Pipeline] End of Pipeline

---

[Daniel Anechitoaie]

The strange thing is that this part of the log that appears under the other stage:

---

[2019-04-16T09:06:31.211Z]  > git show-ref --tags -d # timeout=10

[2019-04-16T09:06:31.224Z]  > git config core.sparsecheckout # timeout=10

[2019-04-16T09:06:31.229Z]  > git checkout -f bf7221352765115631b4326fa6b0603ff0f19637

[2019-04-16T09:06:31.244Z]  > git branch -a -v --no-abbrev # timeout=10

[2019-04-16T09:06:31.249Z]  > git checkout -b feature/pr1 bf7221352765115631b4326fa6b0603ff0f19637

[2019-04-16T09:06:31.272Z]  > git rev-list --no-walk bf7221352765115631b4326fa6b0603ff0f19637 # timeout=10

---

Doesn't seem to even be present if I replace the call to "myPlugin()" with "sh(ls)" for example in (BeginCheckRun) stage.

What could cause the git plugin to have extra output and to have outside of its stage, in the next stage.

[Daniel Anechitoaie]

And if you look at the timestamp:

[2019-04-16T09:06:31.541Z] [Pipeline] myPlugin

[2019-04-16T09:06:31.208Z] Seen branch in repository origin/feature/pr1

[2019-04-16T09:06:31.208Z] Seen branch in repository origin/master

[2019-04-16T09:06:31.208Z] Seen 2 remote branches

the logs that appear after the second stage started even have the timestamp in ms less than the second stage.

So kind of weird that a message that was generated before appears after.

[Jesse Glick]

On Tue, Apr 16, 2019 at 5:16 AM Daniel Anechitoaie
<danie...@gmail.com> wrote:
> Any idea what's going on?

Check whether it happens in Jenkins 2.173. If not, there is a backport
to LTS I could propose. If it still does, then I suspect something in
`git` or `git-client` will need to do a `flush()` somewhere. The code
here is nonstandard and problematic (JENKINS-21342) but nobody dares
touch it. Might suffice for `GitCommandMasterToSlaveCallable` to call
some new `GitClient.flush()` method defined on `CliGitAPIImpl`. If you
have a consistent way to reproduce this it would be helpful.

[Daniel Anechitoaie]

This seems too be happening only wen I run Jenkins in a Master/Slave setup (2 servers).

If I only have the master it seems there's no problem with the output.

I'll try to see if I can setup 2.173 the same way (master + slave) to see if it's still reproducible.

[Jesse Glick]

On Tue, Apr 16, 2019 at 12:57 PM Daniel Anechitoaie
<danie...@gmail.com> wrote:
> This seems too be happening only wen I run Jenkins in a Master/Slave setup (2 servers).
> If I only have the master it seems there's no problem with the output.

Yes, this is specific to use of Remoting.

[Martin Weber]

Could this cause JENKINS-55215 https://issues.jenkins-ci.org/browse/
JENKINS-55215 ?

--
E-Mails sollten Text sein, Text und nur Text.
Wenn Gott gewollt hätte, dass E-Mails in HTML geschrieben würden,
endeten Gebete traditionell mit </amen>.

[Jesse Glick]

On Wed, Apr 17, 2019 at 3:53 PM Martin Weber <enten...@gmx.de> wrote:
> Could this cause JENKINS-55215?

Unlikely. That is just using the normal
`ProcStarter.stdout(TaskListener)` which should not need any special
`flush` call, either before or after

https://github.com/jenkinsci/jenkins/pull/3961