Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 4 commits into from
Mar 7, 2018

Conversation

gabloe
Copy link
Contributor

@gabloe gabloe commented Feb 28, 2018

PowerShell output consists of 6 separate streams (success, error, warning, debug, verbose, and information), but only the success stream is conventionally considered to be stdout. The usage of returnStdout option of the PowerShell pipeline step should disregard all streams except the success stream to be consistent with other pipeline steps (bat, sh, etc.)

This PR prevents the warning, debug, verbose, or information streams from polluting stdout.

Caveats:
Normally in PowerShell when you use one of the various Write-* cmdlets, such as Write-Verbose or Write-Warning, the stream designation is prepended to the output. For example:
Write-Verbose "This is some verbose output"
Would yield:

VERBOSE: This is some verbose output

There is a known issue when you invoke a PowerShell script and redirect the various streams to disk where this stream designation is omitted from the output. The solution for this is to wrap the execution of the script, which causes all of the non-error streams to be merged with stdout along with their corresponding designations. However, this adds the side effect of treating all streams as normal stdout, which is undesirable when using returnStdout. So, with this change the stream designations will not be provided in the console log if using returnStdout. If not using returnStdout then the behavior remains the same as it is now.

I've also added a few extra unit tests to ensure that verbose, warning, and debug output continue to be correct.

@gabloe
Copy link
Contributor Author

gabloe commented Feb 28, 2018

@svanoort @jtnord I'm not able to request reviews for some reason

@gabloe gabloe changed the title Fixed JENKINS-49754 [Fixed JENKINS-49754] - Prevent PowerShell stdout pollution when using returnStdout Mar 1, 2018
@@ -124,7 +124,7 @@
}

@Test public void implicitError() throws Exception {
Controller c = new PowershellScript("MyBogus-Cmdlet").launch(new EnvVars(), ws, launcher, listener);
Controller c = new PowershellScript("$ErrorActionPreference = 'Stop'; MyBogus-Cmdlet").launch(new EnvVars(), ws, launcher, listener);
Copy link
Member

@jtnord jtnord Mar 2, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

does this mean that people have to change all their scripts as this code was removed?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No. No changes should be required here. The issue is that regardless of the value of $ErrorActionPreference or the ErrorAction parameter provided by all cmdlets a job would fail even if the error was non fatal. Fatal errors should be controlled via ErrorAction, and this is the standard practice in PowerShell. So, this is definitely a bug.

c.writeLog(ws, baos);
assertTrue(c.exitStatus(ws, launcher, listener).intValue() == 0);
assertThat(baos.toString(), containsString("Hello, World!"));
assertEquals("Success\r\n", new String(c.getOutput(ws, launcher)));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

does powershell on Linux use \r\n or just \n (ie will this test fail if run on Linux?)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point. I will verify this and update the PR if needed.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PowerShell on Linux uses \n. I'll update these tests.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In a related note it would be nice if PowerShell core could be installed on the Linux VM's used in testing with a symlink added for powershell->pwsh, because as it stands right now the tests are skipped on Linux.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@gabloe That can be raised as a Jenkins INFRA ticket for action by the community infra maintainers. Be aware though that turnaround times may very because the number of people who can handle those tickets is limited and their time is heavily committed usually.

c.cleanup(ws);
}

@Test public void verboseNegativeTest() throws Exception {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how is this a negative test (negative tests generally check for error handling)?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's right. This is poorly named. I am trying to ensure that when using returnStdout another PowerShell output stream does not get mixed in. I'll rename the test.

@jakauppila
Copy link

Was there any other changes left for this before it can be merged?

We're looking to upgrade a number of other plugins in our Jenkins environment for bug fixes, but due to the dependency matrix between them, we're kind of stuck until we have a working version of the Durable Task Plugin.

@gabloe
Copy link
Contributor Author

gabloe commented Mar 6, 2018

I'd like to see the automated tests come back successful. It looks like the Linux tests (non-powershell) are aborting early, which is causing an early failure of all parallel branches. @svanoort do you know why this is happening?

@svanoort
Copy link
Member

svanoort commented Mar 6, 2018

I'd like to see a clean test pass too and a confirmation from @jtnord that this looks sane. I don't feel comfortable signing off on Powershell logic myself due to lack of familiarity (I'm heavily rooted in Linux land and more likely to use the new Linux subsystem for Windows). @gabloe

Stacktrace
java.lang.AssertionError
at org.junit.Assert.fail(Assert.java:86)
at org.junit.Assert.assertTrue(Assert.java:41)
at org.junit.Assert.assertTrue(Assert.java:52)
at org.jenkinsci.plugins.durabletask.PowershellScriptTest.implicitError(PowershellScriptTest.java:133)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at org.jvnet.hudson.test.JenkinsRule$1.evaluate(JenkinsRule.java:548)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
Standard Output
=== Starting implicitError(org.jenkinsci.plugins.durabletask.PowershellScriptTest)
[ws] Running PowerShell script
Standard Error
0.010 [id=206] INFO o.jvnet.hudson.test.JenkinsRule#createWebServer: Running on http://localhost:49366/jenkins/
0.018 [id=212] INFO jenkins.InitReactorRunner$1#onAttained: Started initialization
0.020 [id=222] INFO jenkins.InitReactorRunner$1#onAttained: Listed all plugins
0.092 [id=222] INFO jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
0.093 [id=213] INFO jenkins.InitReactorRunner$1#onAttained: Started all plugins
0.094 [id=215] INFO jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
0.639 [id=213] INFO jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
0.657 [id=219] INFO o.j.main.modules.sshd.SSHD#start: Started SSHD at port 49389
0.657 [id=219] INFO jenkins.InitReactorRunner$1#onAttained: Completed initialization
4.721 [id=206] INFO jenkins.model.Jenkins#cleanUp: Stopping Jenkins
4.725 [id=206] INFO jenkins.model.Jenkins$21#onAttained: Started termination
4.725 [id=206] INFO jenkins.model.Jenkins$21#onAttained: Completed termination
4.726 [id=206] INFO jenkins.model.Jenkins#_cleanUpDisconnectComputers: Starting node disconnection
4.727 [id=248] INFO h.TcpSlaveAgentListener$ConnectionHandler#run: Accepted connection #5 from /10.0.0.4:49393
4.728 [id=206] INFO jenkins.model.Jenkins#_cleanUpShutdownPluginManager: Stopping plugin manager
4.728 [id=206] INFO jenkins.model.Jenkins#_cleanUpPersistQueue: Persisting build queue
4.730 [id=206] INFO jenkins.model.Jenkins#_cleanUpAwaitDisconnects: Waiting for node disconnection completion
4.730 [id=206] INFO jenkins.model.Jenkins#cleanUp: Jenkins stopped

@svanoort
Copy link
Member

svanoort commented Mar 6, 2018

@jakauppila For the same reasons why it's important to you that Durable tasks be reliable, we're generally cautious about merging changes. Please have patience -- a slower but stable release of Durable Task is much better than cutting frequent but buggy releases.

@gabloe
Copy link
Contributor Author

gabloe commented Mar 6, 2018

@svanoort That failure likely has to do with the bugfix that I've added to rely on ErrorActionPreference when failing the task. The frustration with this particular change is that PowerShell 5 has a different behavior from PowerShell 3-4, and $LASTEXITCODE can be 0 even if an exception has been thrown, and if an exception has been thrown the exception may not be exposed in the wrapping PowerShell script depending on the version of PowerShell. So in PowerShell 4 the process may have failed and $LASTEXITCODE could be zero and the thrown exception may be hidden, which results in a false positive.

I will revert that bugfix and bring it in as a separate PR.

@gabloe
Copy link
Contributor Author

gabloe commented Mar 7, 2018

The error handling bug fix has been sent in another PR:
#67

Copy link
Member

@jtnord jtnord left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems logical AFAICT (although I am no powershell guru)

long live clink

@svanoort
Copy link
Member

svanoort commented Mar 7, 2018

Thanks @jtnord ! Okay, I'm going ahead and merging, and will aim to cut a release soonishly.

@svanoort svanoort merged commit fb3cf82 into jenkinsci:master Mar 7, 2018
@jakauppila
Copy link

Thanks for all your help everyone, really appreciate it!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants