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

EnvInject mask passwords interferes with timestamper

    XMLWordPrintable

    Details

    • Similar Issues:

      Description

      When using EnvInject's option
      "Inject passwords to the build as environment variables" with password parameter masking
      and timestamper the timestamps in the console log are shifted by two lines (and the last two lines don'T have timestamps).
      These two lines are probably
      [EnvInject] - Inject global passwords.
      [EnvInject] - Mask passwords passed as build parameters.

      But why do they cause a shift?

      The second problem ist, when viewing the log while the job is still running newly added lines do not get timestamps. I have to reload the page to see timestamps.

      Both problems are gone for jobs without EnvInject passwords.

        Attachments

          Activity

          Hide
          oleg_nenashev Oleg Nenashev added a comment -

          Please specify versions of the Jenkins core and both plugins. Is it a regression after an update?

          Show
          oleg_nenashev Oleg Nenashev added a comment - Please specify versions of the Jenkins core and both plugins. Is it a regression after an update?
          Hide
          wolterhis Lars added a comment -

          I added the version numbers.
          I don't know whether it is a regression, because I have just started to use both plugins together.

          Show
          wolterhis Lars added a comment - I added the version numbers. I don't know whether it is a regression, because I have just started to use both plugins together.
          Hide
          stevengbrown Steven G Brown added a comment -

          Lars, can you attach a log file from one of the affected builds?

          Show
          stevengbrown Steven G Brown added a comment - Lars, can you attach a log file from one of the affected builds?
          Hide
          wolterhis Lars added a comment -

          OK, to illustrate it I built a job executing the shell script
          for i in $(seq 1 10); do echo time: `date +%H:%M:%S`; sleep 1; done

          As you can see the console output should show Timestamper's timestamps next to the timestamps from the shell script. Both timestamps should be equal.
          At first the console output with no EnvInject enabled:
          20:04:01 Gestartet durch Benutzer
          20:04:01 [EnvInject] - Loading node environment variables.
          20:04:01 Baue in Arbeitsbereich /var/lib/jenkins/jobs/XYZ/workspace
          20:04:01 [workspace] $ /bin/bash -e /tmp/hudson5525335093485642436.sh
          20:04:01 time: 20:04:01
          20:04:02 time: 20:04:02
          20:04:03 time: 20:04:03
          20:04:04 time: 20:04:04
          20:04:05 time: 20:04:05
          20:04:06 time: 20:04:06
          20:04:07 time: 20:04:07
          20:04:08 time: 20:04:08
          20:04:09 time: 20:04:09
          20:04:10 time: 20:04:10
          20:04:11 Finished: SUCCESS

          Everything OK. Then I enabled 'Inject passwords to the build as environment variables' and 'Global passwords' and the output was:
          20:03:39 [EnvInject] - Inject global passwords.
          20:03:39 [EnvInject] - Mask passwords passed as build parameters.
          20:03:39 Gestartet durch Benutzer
          20:03:39 [EnvInject] - Loading node environment variables.
          20:03:39 Baue in Arbeitsbereich /var/lib/jenkins/jobs/XYZ/workspace
          20:03:40 [workspace] $ /bin/bash -e /tmp/hudson2882475315826943329.sh
          20:03:41 time: 20:03:39
          20:03:42 time: 20:03:40
          20:03:43 time: 20:03:41
          20:03:44 time: 20:03:42
          20:03:45 time: 20:03:43
          20:03:46 time: 20:03:44
          20:03:47 time: 20:03:45
          20:03:48 time: 20:03:46
          20:03:49 time: 20:03:47
          time: 20:03:48
          Finished: SUCCESS

          Now the timestamps are shifted.

          Show
          wolterhis Lars added a comment - OK, to illustrate it I built a job executing the shell script for i in $(seq 1 10); do echo time: `date +%H:%M:%S`; sleep 1; done As you can see the console output should show Timestamper's timestamps next to the timestamps from the shell script. Both timestamps should be equal. At first the console output with no EnvInject enabled: 20:04:01 Gestartet durch Benutzer 20:04:01 [EnvInject] - Loading node environment variables. 20:04:01 Baue in Arbeitsbereich /var/lib/jenkins/jobs/XYZ/workspace 20:04:01 [workspace] $ /bin/bash -e /tmp/hudson5525335093485642436.sh 20:04:01 time: 20:04:01 20:04:02 time: 20:04:02 20:04:03 time: 20:04:03 20:04:04 time: 20:04:04 20:04:05 time: 20:04:05 20:04:06 time: 20:04:06 20:04:07 time: 20:04:07 20:04:08 time: 20:04:08 20:04:09 time: 20:04:09 20:04:10 time: 20:04:10 20:04:11 Finished: SUCCESS Everything OK. Then I enabled 'Inject passwords to the build as environment variables' and 'Global passwords' and the output was: 20:03:39 [EnvInject] - Inject global passwords. 20:03:39 [EnvInject] - Mask passwords passed as build parameters. 20:03:39 Gestartet durch Benutzer 20:03:39 [EnvInject] - Loading node environment variables. 20:03:39 Baue in Arbeitsbereich /var/lib/jenkins/jobs/XYZ/workspace 20:03:40 [workspace] $ /bin/bash -e /tmp/hudson2882475315826943329.sh 20:03:41 time: 20:03:39 20:03:42 time: 20:03:40 20:03:43 time: 20:03:41 20:03:44 time: 20:03:42 20:03:45 time: 20:03:43 20:03:46 time: 20:03:44 20:03:47 time: 20:03:45 20:03:48 time: 20:03:46 20:03:49 time: 20:03:47 time: 20:03:48 Finished: SUCCESS Now the timestamps are shifted.
          Hide
          oleg_nenashev Oleg Nenashev added a comment -

          Hmm, it's just a processing delay. Since you run the job on the Jenkins master, it cannot be caused by communication delays. EnvInject password adds an additional console annotator, so maybe a behavior in the core changes in such case.

          Needs to be investigated, but I'm not sure such time difference is a bug. Timestamper annotates logs once it gets info on the master side, so there are data propagation delays by design. Even OS may cause such difference on a high-loaded system

          Show
          oleg_nenashev Oleg Nenashev added a comment - Hmm, it's just a processing delay. Since you run the job on the Jenkins master, it cannot be caused by communication delays. EnvInject password adds an additional console annotator, so maybe a behavior in the core changes in such case. Needs to be investigated, but I'm not sure such time difference is a bug. Timestamper annotates logs once it gets info on the master side, so there are data propagation delays by design. Even OS may cause such difference on a high-loaded system
          Hide
          wolterhis Lars added a comment -

          There was no load on the system when I ran the test from my previous comment.

          For me these time differences are a bug, because in some cases the timestamps don't help when they are shifted.
          And since it's a constant two-line-shift with EnvInject enabled and not a random occurrence, I wouldn't think it's something that's caused by delays or load.

          Show
          wolterhis Lars added a comment - There was no load on the system when I ran the test from my previous comment. For me these time differences are a bug, because in some cases the timestamps don't help when they are shifted. And since it's a constant two-line-shift with EnvInject enabled and not a random occurrence, I wouldn't think it's something that's caused by delays or load.
          Hide
          stevengbrown Steven G Brown added a comment -

          Thanks for the clarification, Lars. I've submitted a pull request to fix it: https://github.com/jenkinsci/envinject-plugin/pull/87

          Show
          stevengbrown Steven G Brown added a comment - Thanks for the clarification, Lars. I've submitted a pull request to fix it: https://github.com/jenkinsci/envinject-plugin/pull/87
          Hide
          wolterhis Lars added a comment -

          But no one seems to care about merging and releasing it

          Show
          wolterhis Lars added a comment - But no one seems to care about merging and releasing it
          Hide
          scm_issue_link SCM/JIRA link daemon added a comment -

          Code changed in jenkins
          User: Steven Brown
          Path:
          src/main/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordWrapper.java
          src/test/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordTest.java
          http://jenkins-ci.org/commit/envinject-plugin/f56667ca7a5ee60e90fb2e1c7fc752b16605fd2e
          Log:
          [FIXED JENKINS-30028] Remove logging from password wrapper decorateLogger

          Move it into the setUp method instead. Writing to the OutputStream within
          the decorateLogger method causes the written message to bypass the other
          build wrappers, which have not yet wrapped the OutputStream.

          For example, it prevents the Timestamper plugin from applying timestamps
          to these lines.

          Show
          scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Steven Brown Path: src/main/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordWrapper.java src/test/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordTest.java http://jenkins-ci.org/commit/envinject-plugin/f56667ca7a5ee60e90fb2e1c7fc752b16605fd2e Log: [FIXED JENKINS-30028] Remove logging from password wrapper decorateLogger Move it into the setUp method instead. Writing to the OutputStream within the decorateLogger method causes the written message to bypass the other build wrappers, which have not yet wrapped the OutputStream. For example, it prevents the Timestamper plugin from applying timestamps to these lines.
          Hide
          scm_issue_link SCM/JIRA link daemon added a comment -

          Code changed in jenkins
          User: StevenGBrown
          Path:
          src/main/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordWrapper.java
          src/test/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordTest.java
          http://jenkins-ci.org/commit/envinject-plugin/586ec0829bd676ec5b2e64b2133a9931ee1cf678
          Log:
          Merge pull request #87 from StevenGBrown/JENKINS-30028

          [FIXED JENKINS-30028] Remove logging from password wrapper decorateLogger

          Compare: https://github.com/jenkinsci/envinject-plugin/compare/80b96650c0a4...586ec0829bd6

          Show
          scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: StevenGBrown Path: src/main/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordWrapper.java src/test/java/org/jenkinsci/plugins/envinject/EnvInjectPasswordTest.java http://jenkins-ci.org/commit/envinject-plugin/586ec0829bd676ec5b2e64b2133a9931ee1cf678 Log: Merge pull request #87 from StevenGBrown/ JENKINS-30028 [FIXED JENKINS-30028] Remove logging from password wrapper decorateLogger Compare: https://github.com/jenkinsci/envinject-plugin/compare/80b96650c0a4...586ec0829bd6
          Hide
          oleg_nenashev Oleg Nenashev added a comment -

          Released in 1.93

          Show
          oleg_nenashev Oleg Nenashev added a comment - Released in 1.93

            People

            • Assignee:
              stevengbrown Steven G Brown
              Reporter:
              wolterhis Lars
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: