More diagnostics for FileDescriptorLimitTest flake

[jglick]

Continuing #483. Observed a flake again

java.lang.AssertionError: 
worked on agent
Expected: a string containing "All open files"
     but: was "slave0
======

N/A: Either no connection to node or no cached result
"
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at com.cloudbees.jenkins.support.impl.FileDescriptorLimitTest.agentContentFilter(FileDescriptorLimitTest.java:99)

No obvious explanation in controller logs other than that the channel seems to be closed by this point:

…
   1.363 [id=134]	INFO	jenkins.InitReactorRunner$1#onAttained: Completed initialization
   1.417 [id=115]	INFO	o.jvnet.hudson.test.JenkinsRule#waitOnline: Launching slave0…
   2.479 [id=67]	INFO	o.j.h.test.SimpleCommandLauncher#launch: agent launched for slave0
   2.480 [id=115]	INFO	o.jvnet.hudson.test.JenkinsRule#waitOnline: …finished launching slave0.
   2.529 [id=115]	FINER	c.c.j.support.AsyncResultCache#get: com.cloudbees.jenkins.support.impl.FileDescriptorLimit$GetUlimit@3699b57f on master succeeded
   3.052 [id=115]	FINER	c.c.j.support.AsyncResultCache#get: Could not retrieve file descriptor info from slave0
java.util.concurrent.TimeoutException
	at hudson.remoting.Request$1.get(Request.java:322)
	at hudson.remoting.Request$1.get(Request.java:240)
	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:66)
	at com.cloudbees.jenkins.support.AsyncResultCache.get(AsyncResultCache.java:66)
	at com.cloudbees.jenkins.support.AsyncResultCache.get(AsyncResultCache.java:33)
	at com.cloudbees.jenkins.support.impl.FileDescriptorLimit$1.printTo(FileDescriptorLimit.java:98)
	at com.cloudbees.jenkins.support.api.PrefilteredPrintedContent.writeTo(PrefilteredPrintedContent.java:63)
	at com.cloudbees.jenkins.support.SupportPlugin.writeBundle(SupportPlugin.java:416)
	at com.cloudbees.jenkins.support.SupportPlugin.writeBundle(SupportPlugin.java:353)
	at com.cloudbees.jenkins.support.impl.FileDescriptorLimitTest.agentContentFilter(FileDescriptorLimitTest.java:92)
	at …
   3.082 [id=111]	INFO	hudson.remoting.Request$2#run: Failed to send back a reply to the request RPCRequest:hudson.remoting.RemoteClassLoader$IClassLoader.fetch3[java.lang.String](2): hudson.remoting.ChannelClosedException: Channel "hudson.remoting.Channel@240c5840:slave0": channel is already closed
   3.071 [id=161]	FINE	c.c.j.support.AsyncResultCache#run: Could not retrieve file descriptor info from slave0 for caching
Command Close created at
	at hudson.remoting.Command.<init>(Command.java:70)
	at hudson.remoting.Channel$CloseCommand.<init>(Channel.java:1306)
	at hudson.remoting.Channel.close(Channel.java:1480)
	at hudson.remoting.Channel.close(Channel.java:1447)
	at hudson.remoting.Channel$CloseCommand.execute(Channel.java:1312)
Caused: hudson.remoting.Channel$OrderlyShutdown
Caused: hudson.remoting.RequestAbortedException
	at hudson.remoting.Request.abort(Request.java:346)
	at hudson.remoting.Channel.terminate(Channel.java:1080)
	at hudson.remoting.Channel$CloseCommand.execute(Channel.java:1313)
	at hudson.remoting.Channel$1.handle(Channel.java:606)
	at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:81)
Caused: java.util.concurrent.ExecutionException
	at hudson.remoting.Request$1.get(Request.java:325)
	at hudson.remoting.Request$1.get(Request.java:240)
	at hudson.remoting.FutureAdapter.get(FutureAdapter.java:66)
	at com.cloudbees.jenkins.support.AsyncResultCache.run(AsyncResultCache.java:107)
	at …
   3.084 [id=115]	INFO	hudson.lifecycle.Lifecycle#onStatusUpdate: Stopping Jenkins
…

(The test output also shows normal agent logs, but these are only printed during createOnlineSlave and stop thereafter.)

Was able to produce a similar error from

diff --git a/src/main/java/com/cloudbees/jenkins/support/AsyncResultCache.java b/src/main/java/com/cloudbees/jenkins/support/AsyncResultCache.java
index 69c5401..3d7f205 100644
--- a/src/main/java/com/cloudbees/jenkins/support/AsyncResultCache.java
+++ b/src/main/java/com/cloudbees/jenkins/support/AsyncResultCache.java
@@ -3,6 +3,7 @@ package com.cloudbees.jenkins.support;
 import com.cloudbees.jenkins.support.util.CallAsyncWrapper;
 import hudson.model.Computer;
 import hudson.model.Node;
+import hudson.model.Slave;
 import hudson.remoting.Callable;
 import hudson.remoting.VirtualChannel;
 import jenkins.model.Jenkins;
(1/2) Stage this hunk [y,n,q,a,d,j,J,g,/,e,?]? n
@@ -63,6 +64,9 @@ public class AsyncResultCache<T> implements Runnable {
             future = CallAsyncWrapper.callAsync(channel, operation);
         }
         try {
+            if (node instanceof Slave) {
+                node.getChannel().close();
+            }
             final V result = future.get(SupportPlugin.REMOTE_OPERATION_TIMEOUT_MS, TimeUnit.MILLISECONDS);
             synchronized (cache) {
                 cache.put(node, result);

So, enhancing failure message to show complete agent logs up to that point, in the hope that this will give some clue. (Perhaps the CI machine runs out of memory and kills the agent JVM?!)

[Dohbedoh]

Thanks for the help narrowing this down!

[jglick]

Did not help unfortunately:

$ "…/java"  -Djava.awt.headless=true -Xmx512m -XX:+PrintCommandLineFlags -jar "…/support-core-plugin/target/jenkins-for-test/WEB-INF/lib/remoting-….jar"
Picked up JAVA_TOOL_OPTIONS: -Xmx1g …
<===[JENKINS REMOTING CAPACITY]===>&#0;&#0;&#0;channel started
Remoting version: …
Launcher: SimpleCommandLauncher
Communication Protocol: Standard in/out
This is a Unix agent
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by jenkins.slaves.StandardOutputSwapper$ChannelSwapper to constructor java.io.FileDescriptor(int)
WARNING: Please consider reporting this to the maintainers of jenkins.slaves.StandardOutputSwapper$ChannelSwapper
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
Evacuated stdout
Agent successfully connected and online