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

Streams other than StdOut getting returned when using returnStdOut on PowerShell Step

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Done
    • Component/s: durable-task-plugin
    • Labels:
      None
    • Environment:
      Windows Server 2012 R2
      Jenkins 2.89.4
      Durable Task Plugin 1.18
    • Similar Issues:

      Description

      When executing the following pipeline with a verbose flag on a function and returnStdout specified, I am seeing the Verbose stream getting returned with Stdout.

      node{
        def psOutput = powershell(returnStdout: true, script: """
                            function Get-TestFunction {
                              [CmdletBinding()]
                              Param
                              (
                              )
      
                              Begin{
                              }
                              Process{
                                Write-Output 'hello'
                                Write-Verbose 'world'
                              }
                              End{
                              }
                            }
      
                            Get-TestFunction  -verbose
                        """)
        echo psOutput
      }
      

      Console Output:.

      Running in Durability level: MAX_SURVIVABILITY
      [Pipeline] node
      Running on Jenkins in D:\Jenkins-Windows\workspace\jaredtest
      [Pipeline] {
      [Pipeline] powershell
      [jaredtest] Running PowerShell script
      [Pipeline] echo
      hello
      VERBOSE: world
      
      [Pipeline] }
      [Pipeline] // node
      [Pipeline] End of Pipeline
      Finished: SUCCESS
      

      I would expect to see the Verbose stream getting written within the PowerShell script output. This is causing issues as we use the -verbose flag to see the details of things as they execute, but depend on Stdout to take action later on.

      If I perform the same pipeline on Durable Task Pipeline 1.14, I get the following output:

      [Pipeline] node
      Running on master in D:\Jenkins-Windows\workspace\jaredtest
      [Pipeline] {
      [Pipeline] powershell
      [jaredtest] Running PowerShell script
      world
      Cannot contact : java.nio.file.NoSuchFileException: D:\Jenkins-Windows\workspace\jaredtest@tmp\durable-7c2251e3\output.txt
      [Pipeline] echo
      hello
      
      [Pipeline] }
      [Pipeline] // node
      [Pipeline] End of Pipeline
      Finished: SUCCESS
      

        Attachments

          Activity

          Hide
          jakauppila Jared Kauppila added a comment -

          Gabriel Loewen It looks like durable-task-plugin#51 modified the streams output so everything is redirecting to 1 rather than everything else getting written to the result file.

          https://github.com/jenkinsci/durable-task-plugin/pull/51/files#diff-2ee2c814de2b034e34d312e8b7276e45L111

          Show
          jakauppila Jared Kauppila added a comment - Gabriel Loewen It looks like durable-task-plugin#51 modified the streams output so everything is redirecting to 1 rather than everything else getting written to the result file. https://github.com/jenkinsci/durable-task-plugin/pull/51/files#diff-2ee2c814de2b034e34d312e8b7276e45L111
          Hide
          gabloe Gabriel Loewen added a comment -

          Jared Kauppila I think this is a side effect caused by the bugfixes that just came in 1.18.  What is happening is that when PowerShell scripts are executed and the output is piped to the log files used by Jenkins for console and error output the stream designations are lost.  What I mean is that if you run the following script:

          // script.ps1
          $VerbosePreference = "Continue"
          Write-Output "Hello"
          Write-Verbose "World"
          

          ps> & script.ps1 *> result.txt

          You'll see the following output:

          Hello
          World
          

          Whereas what you'd expect to see is:

          Hello
          VERBOSE: World

          The fix for this was to wrap up the execution of this in another script.

          // wrapper.ps1
          & script.ps1
          

          ps> & wrapper.ps1 *> result.txt

          Which produces the result as you would expect, including the stream designation.  The side effect of this is that essentially all streams get merged into stdout except for the stderr, which of course is separate.

          Is this issue a major blocker for you?

          Thanks,

          Gabriel

           

          Show
          gabloe Gabriel Loewen added a comment - Jared Kauppila I think this is a side effect caused by the bugfixes that just came in 1.18.  What is happening is that when PowerShell scripts are executed and the output is piped to the log files used by Jenkins for console and error output the stream designations are lost.  What I mean is that if you run the following script: // script.ps1 $VerbosePreference = "Continue" Write-Output "Hello" Write-Verbose "World" ps> & script.ps1 *> result.txt You'll see the following output: Hello World Whereas what you'd expect to see is: Hello VERBOSE: World The fix for this was to wrap up the execution of this in another script. // wrapper.ps1 & script.ps1 ps> & wrapper.ps1 *> result.txt Which produces the result as you would expect, including the stream designation.  The side effect of this is that essentially all streams get merged into stdout except for the stderr, which of course is separate. Is this issue a major blocker for you? Thanks, Gabriel  
          Hide
          jakauppila Jared Kauppila added a comment - - edited

          Gabriel Loewen It is, yeah. When the Powershell step was initially introduced, we were able to write out those additional verbose/debug streams to the console output which gave visibility into the execution of the scripts while only capturing stdout which could actually be utilized elsewhere (we were writing out JSON which we then parsed from the stdout returned).

          Where it stands now, we'd have to decide on either having visibility into the execution by actually writing out those additional streams to the console or on utilizing the output of the script.

          Show
          jakauppila Jared Kauppila added a comment - - edited Gabriel Loewen It is, yeah. When the Powershell step was initially introduced, we were able to write out those additional verbose/debug streams to the console output which gave visibility into the execution of the scripts while only capturing stdout which could actually be utilized elsewhere (we were writing out JSON which we then parsed from the stdout returned). Where it stands now, we'd have to decide on either having visibility into the execution by actually writing out those additional streams to the console or on utilizing the output of the script.
          Hide
          gabloe Gabriel Loewen added a comment - - edited

          There are a couple things that can be done. 

          1. I can revert the change that wraps user scripts, but this will introduce a bug that strips out all stream designations from the output.  If you look at the non-pipeline PowerShell build step you'll see that they also create a wrapper script, and the behavior is the same.  The only difference is that there is obviously no returnStdout option, which is why the issue is now getting exposed in pipeline.
          2. I can intercept output right before it is written to the output file (which is what is read when you use returnStdout) to check for stream designations, and if the pattern match succeeds then I can easily pass the input through to the console log file. That check can be as easy as a simple regex:
            $keywordMatch = $Input -match "^(VERBOSE|WARNING|DEBUG):(.*)$"

            But, this would cause a side effect of misinterpreting regular console output as special streams. For instance:

            Write-Host "VERBOSE: This is actually not a verbose stream"
            

            Normally this would be sent to stdout, but now it would incorrectly be treated as a special stream.

          Both of these introduce a side effect.

          Sam Van Oort, Andrew Bayer, James Nord, do any of you have a preference for this issue?

          Thanks,

          Gabriel 

           

          Show
          gabloe Gabriel Loewen added a comment - - edited There are a couple things that can be done.  I can revert the change that wraps user scripts, but this will introduce a bug that strips out all stream designations from the output.  If you look at the non-pipeline PowerShell build step you'll see that they also create a wrapper script, and the behavior is the same.  The only difference is that there is obviously no returnStdout option, which is why the issue is now getting exposed in pipeline. I can intercept output right before it is written to the output file (which is what is read when you use returnStdout) to check for stream designations, and if the pattern match succeeds then I can easily pass the input through to the console log file. That check can be as easy as a simple regex: $keywordMatch = $Input -match "^(VERBOSE|WARNING|DEBUG):(.*)$" But, this would cause a side effect of misinterpreting regular console output as special streams. For instance: Write-Host "VERBOSE: This is actually not a verbose stream" Normally this would be sent to stdout, but now it would incorrectly be treated as a special stream. Both of these introduce a side effect. Sam Van Oort , Andrew Bayer , James Nord , do any of you have a preference for this issue? Thanks, Gabriel   
          Hide
          jakauppila Jared Kauppila added a comment -

          This seems to get the job done unless I'm missing something:

          // script.ps1
          $VerbosePreference = "Continue"
          
          Write-Host "This is written to host"
          Write-Output "This is written to Success output"
          Write-Error "This is an error"
          Write-Warning "This is a warning message"
          Write-Verbose "This is verbose output"
          Write-Debug "This is a debug message"
          

          With the following on the wrapper:

          $allOtherStreams = $($stdOut = & C:\temp\script.ps1) 2>&1 3>&1 4>&1 5>&1 6>&1
          
          Write-Output "Standard Out:" $stdOut
          Write-Output "All other streams:" $allOtherStreams
          

          Returns the following output:

          Standard Out:
          This is written to Success output
          All other streams:
          This is written to host
          C:\temp\script.ps1 : This is an error
          At line:1 char:32
          + $allOtherStreams = $($stdOut = & C:\temp\script.ps1) 2>&1 3>&1 4>&1 5 ...
          +                                ~~~~~~~~~~~~~~~~~~~~
              + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
              + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,script.ps1
           
          WARNING: This is a warning message
          VERBOSE: This is verbose output
          
          Show
          jakauppila Jared Kauppila added a comment - This seems to get the job done unless I'm missing something: // script.ps1 $VerbosePreference = "Continue" Write-Host "This is written to host" Write-Output "This is written to Success output" Write-Error "This is an error" Write-Warning "This is a warning message" Write-Verbose "This is verbose output" Write-Debug "This is a debug message" With the following on the wrapper: $allOtherStreams = $($stdOut = & C:\temp\script.ps1) 2>&1 3>&1 4>&1 5>&1 6>&1 Write-Output "Standard Out:" $stdOut Write-Output "All other streams:" $allOtherStreams Returns the following output: Standard Out: This is written to Success output All other streams: This is written to host C:\temp\script.ps1 : This is an error At line:1 char :32 + $allOtherStreams = $($stdOut = & C:\temp\script.ps1) 2>&1 3>&1 4>&1 5 ... + ~~~~~~~~~~~~~~~~~~~~ + CategoryInfo : NotSpecified: (:) [Write-Error], WriteErrorException + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,script.ps1 WARNING: This is a warning message VERBOSE: This is verbose output
          Hide
          gabloe Gabriel Loewen added a comment - - edited

          There are a few issues with your example. ">" is just an alias for "Out-File", which by default adds a UTF-8 BOM. PowerShell handles the BOM internally very nicely, but it is not good for cross compatibility between PowerShell and Java. Also, in your example you capture output from the script and buffer it into memory. Output has to be immediately piped to disk because we want to ensure that the job is responsive, and to prevent overuse of memory, etc. Yes, your example works, but not as it is intended to work in pipeline because once you modify your code slightly to write to disk you'll see that the output changes to the behavior that I am describing. For example, here is the same code, but with a simple piped output to disk:

          $(& C:\temp\script.ps1) 2>&1 3>&1 4>&1 5>&1 6>&1 | Out-File output.txt
          

          Which produces the following output.txt contents:

          This is written to host
          This is written to Success output
          C:\temp\script.ps1 : This is an error
          At line:1 char:3
          + $(& C:\temp\script.ps1) 2>&1 3>&1 4>&1 5>&1 6>&1 |  ...
          +   ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
              + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
              + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,test2.ps1
           
          This is a warning message
          This is verbose output
          

          If we were to take your example and buffer the output in memory before writing it to disk then we'd open ourselves up to a heap of new issues

          If you want to see how this is all working now you can take a look at the following script:

          https://github.com/jenkinsci/durable-task-plugin/blob/master/src/main/resources/org/jenkinsci/plugins/durabletask/powershellHelper.ps1

          Thanks,

          Gabriel

          Show
          gabloe Gabriel Loewen added a comment - - edited There are a few issues with your example. ">" is just an alias for "Out-File", which by default adds a UTF-8 BOM. PowerShell handles the BOM internally very nicely, but it is not good for cross compatibility between PowerShell and Java. Also, in your example you capture output from the script and buffer it into memory. Output has to be immediately piped to disk because we want to ensure that the job is responsive, and to prevent overuse of memory, etc. Yes, your example works, but not as it is intended to work in pipeline because once you modify your code slightly to write to disk you'll see that the output changes to the behavior that I am describing. For example, here is the same code, but with a simple piped output to disk: $(& C:\temp\script.ps1) 2>&1 3>&1 4>&1 5>&1 6>&1 | Out-File output.txt Which produces the following output.txt contents: This is written to host This is written to Success output C:\temp\script.ps1 : This is an error At line:1 char:3 + $(& C:\temp\script.ps1) 2>&1 3>&1 4>&1 5>&1 6>&1 | ... + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + CategoryInfo : NotSpecified: (:) [Write-Error], WriteErrorException + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,test2.ps1 This is a warning message This is verbose output If we were to take your example and buffer the output in memory before writing it to disk then we'd open ourselves up to a heap of new issues If you want to see how this is all working now you can take a look at the following script: https://github.com/jenkinsci/durable-task-plugin/blob/master/src/main/resources/org/jenkinsci/plugins/durabletask/powershellHelper.ps1 Thanks, Gabriel
          Hide
          jakauppila Jared Kauppila added a comment -

          Okay, figured it couldn't have been that easy

          I see more value in being able to write out those other streams directly to the console (hopefully live while the script is still running, is that still available?) without the stream designation and being able to capture and utilize stdout elsewhere within pipeline rather than just being able to see all output with the appropriate designations on it. 

          Show
          jakauppila Jared Kauppila added a comment - Okay, figured it couldn't have been that easy I see more value in being able to write out those other streams directly to the console (hopefully live while the script is still running, is that still available?) without the stream designation and being able to capture and utilize stdout elsewhere within pipeline rather than just being able to see all output with the appropriate designations on it. 
          Hide
          gabloe Gabriel Loewen added a comment - - edited

          What I can do is try to get the best of both worlds.  If the user wants stdout then I can redirect all other streams to the console log without stream designations, otherwise it can continue with the current behavior.  How does that sound?

          e.g.

          def stdout = powershell returnStdout:true, script: '''
             Write-Output "Hello, World!"
             Write-Verbose "Verbose output"
          '''
          println "stdout = $stdout"
          

          Would yield:

          Verbose output
          stdout = Hello, World!

          But,

          powershell '''
             Write-Output "Hello, World!"
             Write-Verbose "Verbose output"
          '''
          

          Would yield:

          Hello, World!
          VERBOSE: Verbose output

           

          Show
          gabloe Gabriel Loewen added a comment - - edited What I can do is try to get the best of both worlds.  If the user wants stdout then I can redirect all other streams to the console log without stream designations, otherwise it can continue with the current behavior.  How does that sound? e.g. def stdout = powershell returnStdout: true , script: ''' Write-Output "Hello, World!" Write-Verbose "Verbose output" ''' println "stdout = $stdout" Would yield: Verbose output stdout = Hello, World! But, powershell ''' Write-Output "Hello, World!" Write-Verbose "Verbose output" ''' Would yield: Hello, World! VERBOSE: Verbose output  
          Hide
          jakauppila Jared Kauppila added a comment -

          That sounds like a reasonable compromise.

          Show
          jakauppila Jared Kauppila added a comment - That sounds like a reasonable compromise.
          Show
          gabloe Gabriel Loewen added a comment - I've sent a PR:  https://github.com/jenkinsci/durable-task-plugin/pull/64
          Hide
          jakauppila Jared Kauppila added a comment -

          Thank you very much for the very prompt response!

          Show
          jakauppila Jared Kauppila added a comment - Thank you very much for the very prompt response!
          Hide
          gabloe Gabriel Loewen added a comment -

          You're welcome 

          Show
          gabloe Gabriel Loewen added a comment - You're welcome 
          Hide
          scm_issue_link SCM/JIRA link daemon added a comment -

          Code changed in jenkins
          User: gabloe
          Path:
          src/main/java/org/jenkinsci/plugins/durabletask/PowershellScript.java
          src/test/java/org/jenkinsci/plugins/durabletask/PowershellScriptTest.java
          http://jenkins-ci.org/commit/durable-task-plugin/7d40a5d772c752b8b580683815dbda40101d97d7
          Log:
          Fixing JENKINS-49754

          Show
          scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: gabloe Path: src/main/java/org/jenkinsci/plugins/durabletask/PowershellScript.java src/test/java/org/jenkinsci/plugins/durabletask/PowershellScriptTest.java http://jenkins-ci.org/commit/durable-task-plugin/7d40a5d772c752b8b580683815dbda40101d97d7 Log: Fixing JENKINS-49754
          Hide
          scm_issue_link SCM/JIRA link daemon added a comment -

          Code changed in jenkins
          User: Sam Van Oort
          Path:
          src/main/java/org/jenkinsci/plugins/durabletask/PowershellScript.java
          src/test/java/org/jenkinsci/plugins/durabletask/PowershellScriptTest.java
          http://jenkins-ci.org/commit/durable-task-plugin/fb3cf82462d8156824592afb2f5e98e2158afd21
          Log:
          Merge pull request #64 from gabloe/master

          [Fixed JENKINS-49754] - Prevent PowerShell stdout pollution when using returnStdout

          Compare: https://github.com/jenkinsci/durable-task-plugin/compare/6671b39e4f75...fb3cf82462d8

          Show
          scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: src/main/java/org/jenkinsci/plugins/durabletask/PowershellScript.java src/test/java/org/jenkinsci/plugins/durabletask/PowershellScriptTest.java http://jenkins-ci.org/commit/durable-task-plugin/fb3cf82462d8156824592afb2f5e98e2158afd21 Log: Merge pull request #64 from gabloe/master [Fixed JENKINS-49754] - Prevent PowerShell stdout pollution when using returnStdout Compare: https://github.com/jenkinsci/durable-task-plugin/compare/6671b39e4f75...fb3cf82462d8
          Hide
          svanoort Sam Van Oort added a comment -

          I hope you don't mind if I come back and clean up by marking this as released with durable-task v2.20

          Show
          svanoort Sam Van Oort added a comment - I hope you don't mind if I come back and clean up by marking this as released with durable-task v2.20

            People

            • Assignee:
              gabloe Gabriel Loewen
              Reporter:
              jakauppila Jared Kauppila
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: