Adjusted TaskListener flushing in remote code #3961

jglick · 2019-04-02T18:30:30Z

Amends #3563 a bit. See discussion in jenkinsci/workflow-api-plugin#81.

A StreamTaskListener created on the master does not set the PrintStream.autoFlush flag. So why would we do so on the remote side? That merely produces a flurry of ProxyOutputStream.Flush packets. We expect that code flushes a stream when it is done with it. In fact from 2.121.x → 2.138.x for freestyle builds running Shell I see introduced flush packets, from [JENKINS-52729] Launcher.ProcStarter.stdout(TaskListener) discards remotability #3563 I presume, which this PR corrects again.
Conversely, RemoteLaunchCallable on the agent side produces a LocalLauncher which produces a LocalProc which uses StreamCopyThread to forward stdout/stderr of the process. Yet as far as I can tell, this never flushed its sink unless you pass the closeOut flag (which no code in core does), meaning the tail end of log output could be lost if the sink were buffered. Freestyle builds have unbuffered logs, so probably this never mattered, but for JEP-210 I am finding that some buffering for Pipeline with local log storage is useful for performance reasons, and definitely for cloud log storage it is expected. Launcher is not used in this way for durable tasks like sh, but various SynchronousNonBlockingStepExecutions (and thus also SimpleBuildSteps) use it.

(The main pieces originally filed in #3703, but with a feature flag added.)

Proposed changelog entries

Adjusted stream flushing behavior for code running remotely on agents for better performance. This may lead to loss of messages for plugins which print to a build log from the agent machine but do not flush their output. Use -Dhudson.util.StreamTaskListener.AUTO_FLUSH=true to restore the previous behavior for freestyle builds. Note that Pipeline builds always expect remote flush.
API: SystemProperties may now be used from agent-side code.

Desired reviewers

@jenkinsci/code-reviewers

(cherry picked from commit 213cc0d)

(cherry picked from commit 83361ae)

jglick · 2019-04-02T18:31:45Z

core/src/main/java/hudson/Launcher.java

@@ -761,6 +761,7 @@ protected final void printCommandLine(@Nonnull String[] cmd, @CheckForNull FileP
                buf.append(c);
        }
        listener.getLogger().println(buf.toString());
+        listener.getLogger().flush();


If this is commented out, ArgumentListBuilder2Test.slaveMask fails (gets a blank string)—unless you start the test with

static { System.setProperty("hudson.util.StreamTaskListener.AUTO_FLUSH", "true"); }

in which case it passes, demonstrating the effectiveness of the flag on the remote side.

core/src/main/java/hudson/util/StreamTaskListener.java

test/src/test/java/hudson/util/ArgumentListBuilder2Test.java

jglick · 2019-04-02T18:33:58Z

core/src/main/java/jenkins/util/SystemProperties.java

@@ -376,27 +462,4 @@ public static Long getLong(String name, Long def, Level logLevel) {
        return def;
    }

-    @CheckForNull
-    private static String tryGetValueFromContext(String key) {
-        if (!JenkinsJVM.isJenkinsJVM()) {


Inverting control. This was always a bit hackish anyway. Amends #3362 to make agent-side calls work, not merely not crash.

jglick · 2019-04-02T18:35:38Z

core/src/main/java/jenkins/util/SystemProperties.java

 */
-//TODO: Define a correct design of this engine later. Should be accessible in libs (remoting, stapler) and Jenkins modules too


Fixed for agents, and Jenkins modules should be able to use this already. If the need arises, we could move this into a standalone library usable from Remoting and Stapler, though I think these do well enough for now using Java Platform methods.

jglick · 2019-04-02T18:36:31Z

core/src/main/java/hudson/util/StreamTaskListener.java

    private void readObject(ObjectInputStream in) throws IOException, ClassNotFoundException {
-        out = new PrintStream((OutputStream)in.readObject(),true);
+        out = new PrintStream((OutputStream)in.readObject(), AUTO_FLUSH);


The meat of the change: switching auoFlush on the remote copy from true to (by default) false.

core/src/main/java/hudson/util/StreamCopyThread.java

test/src/test/java/hudson/util/ArgumentListBuilder2Test.java

dwnusbaum · 2019-04-02T19:42:35Z

core/src/main/java/jenkins/util/SystemProperties.java

+                // Take a snapshot of all system properties and context variables available on the master at the time the agent starts.
+                allStrings = new HashMap<>();
+                allStrings.putAll(handler.getAllStrings());
+                allStrings.putAll((Map) System.getProperties()); // these take precedence


If I understand correctly, this would mean that calling SystemProperties.getString("file.separator") on the agent would actually get you the value from the master, which could be problematic if the agent is running a different OS than the master. Not necessarily a huge problem as long as anyone using SystemProperties on an agent is careful to avoid reading machine/OS dependent properties, and the API is @Restricted(NoExternalUse.class), but maybe it would be safer to only copy properties whose keys contain hudson or jenkins in the name?

calling SystemProperties.getString("file.separator") on the agent would actually get you the value from the master

No, because getString will first check the local system properties. This snapshot is only used for fallbacks of variables not set on the agent.

I don't think this should be a problem, since even on master you would get weird results today if part of your code relied on the System property value alone for a given key, while the rest takes into account the context variable. If the former is undefined, SystemProperties might still have a value but System.getProperty won't.

core/src/main/java/hudson/util/StreamTaskListener.java

core/src/main/java/hudson/util/StreamCopyThread.java

core/src/main/java/jenkins/util/SystemProperties.java

…h this has been explicitly indicated as safe.

jglick · 2019-04-11T01:32:32Z

INFO	hudson.slaves.ChannelPinger$1#onDead: Ping failed. Terminating the channel slave0.
java.util.concurrent.TimeoutException: No ping
	at hudson.slaves.PingThreadTest.failedPingThreadResetsComputerChannel(PingThreadTest.java:78)
java.lang.AssertionError
	at hudson.slaves.PingThreadTest.failedPingThreadResetsComputerChannel(PingThreadTest.java:90)

in one branch looks like a flake to me.

batmat · 2019-04-11T10:25:33Z

After checking the master branch, I don't seem to be able to find similar test failure, so I am going to retrigger to have another data point. But it could also be actually related to the change here I suppose.

FTR

batmat · 2019-04-11T12:28:34Z

FWIW, I ran mvn test -Dtest=PingThreadTest 220 times locally in a loop. It failed only twice, both for a test timeout:

[INFO] Running hudson.slaves.PingThreadTest
=== Starting failedPingThreadResetsComputerChannel(hudson.slaves.PingThreadTest)
[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 180.734 s <<< FAILURE! - in hudson.slaves.PingThreadTest
[ERROR] failedPingThreadResetsComputerChannel(hudson.slaves.PingThreadTest)  Time elapsed: 180.113 s  <<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 180 seconds
        at java.lang.Object.wait(Native Method)
        at hudson.remoting.Request.call(Request.java:177)
        at hudson.remoting.Channel.call(Channel.java:956)
        at hudson.slaves.PingThreadTest.failedPingThreadResetsComputerChannel(PingThreadTest.java:81)
        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.jvnet.hudson.test.JenkinsRule$1.evaluate(JenkinsRule.java:556)
        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)

So, AFAICT not even the failure seen in CI. We'll see how the currently ongoing build goes.

batmat · 2019-04-11T13:15:33Z

So the PR build succeeed, so given the PR build for this PR in ci.jenkins.io was blue almost for all builds but one, I am going to merge this.

batmat · 2019-04-11T13:17:05Z

core/src/main/java/jenkins/util/SystemProperties.java

 */
-//TODO: Define a correct design of this engine later. Should be accessible in libs (remoting, stapler) and Jenkins modules too
+@SuppressFBWarnings(value = "ST_WRITE_TO_STATIC_FROM_INSTANCE_METHOD", justification = "Currently Jenkins instance may have one ond only one context")


I think just @oleg-nenashev’s grammar, moved as is from line 85.

jglick · 2019-04-11T19:22:08Z

220 times locally in a loop

I suspect the flake manifests itself only under heavy load conditions, which would not be simulated by rerunning the test serially.

This appears to be behaviour that manifests itself in Pipeline builds, and was fixed by jenkinsci/jenkins#3961. To ensure we don't lose buffered logs on Jenkins versions before 2.173, we now ensure the log is flushed after use on the remote agent.

jglick added 4 commits April 2, 2019 10:54

Adjusted flushing behavior of remote code using TaskListener.

7ee034e

(cherry picked from commit 213cc0d)

ArgumentListBuilder2Test.slaveMask failure.

86348bb

(cherry picked from commit 83361ae)

Made SystemProperties usable from agent code.

0525f98

StreamTaskListener.AUTO_FLUSH

ceda3d9

jglick requested review from dwnusbaum and oleg-nenashev April 2, 2019 18:30

jglick commented Apr 2, 2019

View reviewed changes

test/src/test/java/hudson/util/ArgumentListBuilder2Test.java Outdated Show resolved Hide resolved

dwnusbaum reviewed Apr 2, 2019

View reviewed changes

Picking up release of jenkinsci/jenkins-test-harness#127.

9ed1168

dwnusbaum approved these changes Apr 2, 2019

View reviewed changes

core/src/main/java/hudson/util/StreamTaskListener.java Outdated Show resolved Hide resolved

jglick added 2 commits April 2, 2019 20:04

Avoid unnecessary Throwable.fillInStackTrace.

7bcfbd2

Merge branch 'master' into TaskListener-flush

d489437

jglick requested a review from dwnusbaum April 8, 2019 17:01

dwnusbaum approved these changes Apr 8, 2019

View reviewed changes

jglick added the ready-for-merge The PR is ready to go, and it will be merged soon if there is no negative feedback label Apr 8, 2019

daniel-beck reviewed Apr 8, 2019

View reviewed changes

core/src/main/java/hudson/util/StreamCopyThread.java Show resolved Hide resolved

core/src/main/java/jenkins/util/SystemProperties.java Outdated Show resolved Hide resolved

daniel-beck removed the ready-for-merge The PR is ready to go, and it will be merged soon if there is no negative feedback label Apr 8, 2019

jglick commented Apr 8, 2019

View reviewed changes

core/src/main/java/jenkins/util/SystemProperties.java Outdated Show resolved Hide resolved

jglick added the work-in-progress The PR is under active development, not ready to the final review label Apr 8, 2019

jglick added 4 commits April 8, 2019 14:01

Merge branch 'master' into TaskListener-flush

92c5fe6

@daniel-beck suggested a documentation improvement.

a21f83f

Rename suggested by @daniel-beck.

2298216

Limiting system properties transmitted to the agent to those for whic…

56107ea

…h this has been explicitly indicated as safe.

jglick requested review from daniel-beck and dwnusbaum April 8, 2019 18:30

jglick removed the work-in-progress The PR is under active development, not ready to the final review label Apr 8, 2019

dwnusbaum approved these changes Apr 8, 2019

View reviewed changes

daniel-beck approved these changes Apr 8, 2019

View reviewed changes

jglick mentioned this pull request Apr 11, 2019

[JENKINS-46680] Disconnect computer on ping timeout #3005

Merged

6 tasks

jglick added the ready-for-merge The PR is ready to go, and it will be merged soon if there is no negative feedback label Apr 11, 2019

batmat closed this Apr 11, 2019

batmat reopened this Apr 11, 2019

batmat self-assigned this Apr 11, 2019

batmat approved these changes Apr 11, 2019

View reviewed changes

batmat merged commit 850168f into jenkinsci:master Apr 11, 2019

jglick deleted the TaskListener-flush branch April 11, 2019 19:23

jglick mentioned this pull request Jul 23, 2019

Fix missing logs in showAgentLogs jenkinsci/jenkins-test-harness#149

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adjusted TaskListener flushing in remote code #3961

Adjusted TaskListener flushing in remote code #3961

jglick commented Apr 2, 2019

jglick Apr 2, 2019

jglick Apr 2, 2019

jglick Apr 2, 2019

jglick Apr 2, 2019

dwnusbaum Apr 2, 2019 •

edited

Loading

jglick Apr 2, 2019

daniel-beck Apr 8, 2019

jglick commented Apr 11, 2019

batmat commented Apr 11, 2019

batmat commented Apr 11, 2019

batmat commented Apr 11, 2019 •

edited

Loading

batmat Apr 11, 2019

jglick Apr 11, 2019

jglick commented Apr 11, 2019

		*/
		//TODO: Define a correct design of this engine later. Should be accessible in libs (remoting, stapler) and Jenkins modules too

Adjusted TaskListener flushing in remote code #3961

Adjusted TaskListener flushing in remote code #3961

Conversation

jglick commented Apr 2, 2019

Proposed changelog entries

Desired reviewers

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dwnusbaum Apr 2, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jglick commented Apr 11, 2019

batmat commented Apr 11, 2019

batmat commented Apr 11, 2019

batmat commented Apr 11, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jglick commented Apr 11, 2019

dwnusbaum Apr 2, 2019 •

edited

Loading

batmat commented Apr 11, 2019 •

edited

Loading