[JENKINS-46386] Agent sometimes fails to launch in custom cloud provider

timja commented 7 years ago

(previously posted about this on mailing list https://groups.google.com/forum/#!topic/jenkinsci-dev/Zte6nExHM8w was encouraged to file a ticket also)

I'm developing a cloud provider plugin and have run into an intermittent issue with launching agents. In the computer launch log I get this series of errors:

openjdk full version "1.8.0_141-b16"
 Copying slave.jar
 Launching slave agent: java -jar /tmp/slave.jar -workDir .
 Both error and output logs will be printed to ./remoting
 <===[JENKINS REMOTING CAPACITY]===>Slave.jar version: 3.10
 This is a Unix agent
 Evacuated stdout
 java.io.IOException: Remote call on testnode failed
 at hudson.remoting.Channel.call(Channel.java:847)
 at org.jenkinsci.modules.slave_installer.impl.ComputerListenerImpl.onOnline(ComputerListenerImpl.java:32)
 at hudson.slaves.SlaveComputer.setChannel(SlaveComputer.java:582)
 at hudson.slaves.SlaveComputer.setChannel(SlaveComputer.java:390)
 at sfoster.jenkins.plugins.onecloud.OneComputerLauncher.launch(OneComputerLauncher.java:141)
 at hudson.slaves.SlaveComputer$1.call(SlaveComputer.java:262)
 at jenkins.util.ContextResettingExecutorService$2.call(ContextResettingExecutorService.java:46)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
 Caused by: java.lang.LinkageError: Failed to load jenkins.util.SystemProperties
 at hudson.remoting.RemoteClassLoader.loadClassFile(RemoteClassLoader.java:385)
 at hudson.remoting.RemoteClassLoader.findClass(RemoteClassLoader.java:293)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
 at hudson.FilePath.(FilePath.java:2363)
 at sun.misc.Unsafe.ensureClassInitialized(Native Method)
 at sun.reflect.UnsafeFieldAccessorFactory.newFieldAccessor(UnsafeFieldAccessorFactory.java:43)
 at sun.reflect.ReflectionFactory.newFieldAccessor(ReflectionFactory.java:156)
 at java.lang.reflect.Field.acquireFieldAccessor(Field.java:1088)
 at java.lang.reflect.Field.getFieldAccessor(Field.java:1069)
 at java.lang.reflect.Field.getLong(Field.java:611)
 at java.io.ObjectStreamClass.getDeclaredSUID(ObjectStreamClass.java:1707)
 at java.io.ObjectStreamClass.access$700(ObjectStreamClass.java:72)
 at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:484)
 at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:472)
 at java.security.AccessController.doPrivileged(Native Method)
 at java.io.ObjectStreamClass.(ObjectStreamClass.java:472)
 at java.io.ObjectStreamClass.lookup(ObjectStreamClass.java:369)
 at java.io.ObjectStreamClass.initNonProxy(ObjectStreamClass.java:598)
 at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1843)
 at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
 at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2245)
 at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2169)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2027)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
 at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
 at hudson.remoting.UserRequest.deserialize(UserRequest.java:245)
 at hudson.remoting.UserRequest.perform(UserRequest.java:159)
 at hudson.remoting.UserRequest.perform(UserRequest.java:52)
 at hudson.remoting.Request$2.run(Request.java:336)
 at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
 at ......remote call to testnode(Native Method)
 at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1554)
 at hudson.remoting.UserResponse.retrieve(UserRequest.java:281)
 at hudson.remoting.Channel.call(Channel.java:839)
 ... 10 more
 Caused by: java.lang.NoClassDefFoundError: javax/servlet/ServletContextListener
 at java.lang.ClassLoader.defineClass1(Native Method)
 at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
 at java.lang.ClassLoader.defineClass(ClassLoader.java:642)
 at hudson.remoting.RemoteClassLoader.loadClassFile(RemoteClassLoader.java:381)
 at hudson.remoting.RemoteClassLoader.findClass(RemoteClassLoader.java:293)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
 at hudson.FilePath.(FilePath.java:2363)
 at sun.misc.Unsafe.ensureClassInitialized(Native Method)
 at sun.reflect.UnsafeFieldAccessorFactory.newFieldAccessor(UnsafeFieldAccessorFactory.java:43)
 at sun.reflect.ReflectionFactory.newFieldAccessor(ReflectionFactory.java:156)
 at java.lang.reflect.Field.acquireFieldAccessor(Field.java:1088)
 at java.lang.reflect.Field.getFieldAccessor(Field.java:1069)
 at java.lang.reflect.Field.getLong(Field.java:611)
 at java.io.ObjectStreamClass.getDeclaredSUID(ObjectStreamClass.java:1707)
 at java.io.ObjectStreamClass.access$700(ObjectStreamClass.java:72)
 at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:484)
 at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:472)
 at java.security.AccessController.doPrivileged(Native Method)
 at java.io.ObjectStreamClass.(ObjectStreamClass.java:472)
 at java.io.ObjectStreamClass.lookup(ObjectStreamClass.java:369)
 at java.io.ObjectStreamClass.initNonProxy(ObjectStreamClass.java:598)
 at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1843)
 at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1713)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2000)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
 at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2245)
 at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2169)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2027)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1535)
 at java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
 at hudson.remoting.UserRequest.deserialize(UserRequest.java:245)
 at hudson.remoting.UserRequest.perform(UserRequest.java:159)
 at hudson.remoting.UserRequest.perform(UserRequest.java:52)
 at hudson.remoting.Request$2.run(Request.java:336)
 at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
 ... 4 more
 Caused by: java.lang.ClassNotFoundException: javax.servlet.ServletContextListener
 at hudson.remoting.RemoteClassLoader$ClassLoaderProxy.fetch(RemoteClassLoader.java:788)
 at sun.reflect.GeneratedMethodAccessor110.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:498)
 at hudson.remoting.RemoteInvocationHandler$RPCRequest.perform(RemoteInvocationHandler.java:896)
 at hudson.remoting.Request$2.run(Request.java:336)
 at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
 at org.jenkinsci.remoting.CallableDecorator.call(CallableDecorator.java:19)
 at hudson.remoting.CallableDecoratorList$1.call(CallableDecoratorList.java:21)
 at jenkins.util.ContextResettingExecutorService$2.call(ContextResettingExecutorService.java:46)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
 at ......remote call to channel(Native Method)
 at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1554)
 at hudson.remoting.Request.call(Request.java:172)
 at hudson.remoting.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:260)
 at com.sun.proxy.$Proxy5.fetch(Unknown Source)
 at hudson.remoting.RemoteClassLoader.findClass(RemoteClassLoader.java:301)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
 ... 40 more
 ERROR: Connection terminated
 java.io.EOFException
 at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2638)
 at java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:3113)
 at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:853)
 at java.io.ObjectInputStream.(ObjectInputStream.java:349)
 at hudson.remoting.ObjectInputStreamEx.(ObjectInputStreamEx.java:48)
 at hudson.remoting.AbstractSynchronousByteArrayCommandTransport.read(AbstractSynchronousByteArrayCommandTransport.java:35)
 at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:59)
 Caused: java.io.IOException: Unexpected termination of the channel
 at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:73)

This doesn't happen every time. If the failure does happen, it seems to work if I manually relaunch the agent through the UI. In the remoting/logs on the agent itself, all it has is the ERROR: Connection terminated stuff towards the bottom

Originally reported by stevenfoster, imported from: Agent sometimes fails to launch in custom cloud provider

assignee: oleg_nenashev
status: Resolved
priority: Minor
resolution: Fixed
resolved: 2018-03-26T11:43:55+00:00
imported: 2022/01/10

timja commented 7 years ago

stevenfoster:

oleg_nenashev ping from IRC

timja commented 7 years ago

jglick:

Well-known symptom of the mistake here, affecting setups where the agent JVM is unable to load the same javax.servlet.* classes as the master. Typical trigger for the bug is using a nonstandard servlet container. Try just using the built-in Jetty.

timja commented 7 years ago

stevenfoster:

I am currently testing using mvn hpi:run, would this be interfering with the servlet classes?

timja commented 7 years ago

stevenfoster:

Tentative update:

Ran through a list of testing changes and eventually tried installing the .hpi of my plugin onto a regular jenkins in docker instead of testing from mvn hpi:run. Haven't seen any problems since doing that... so far

Thanks for your comment, I wouldn't have considered this kind of interference at all otherwise.

timja commented 7 years ago

jglick:

Not sure why there would be a failure using hpi:run, which does use Jetty (though sometimes a different version than jenkins.war). If there is a complete, self-contained demo reproducing the problem it would assist diagnosis.

timja commented 7 years ago

scm_issue_link:

Code changed in jenkins
User: Oleg Nenashev
Path:
core/src/main/java/hudson/FilePath.java
http://jenkins-ci.org/commit/jenkins/27e5943050846d353a0b257237a73925d3726360
Log:
Merge pull request #3067 from KostyaSha/fixRemotingFilePathmkdirs

~~JENKINS-46386~~ - Don't use unloadable things in remoting mkdirs calls.

Compare: https://github.com/jenkinsci/jenkins/compare/be0238644911...27e594305084

timja commented 7 years ago

danielbeck:

oleg_nenashev Does the merged change by integer resolve this issue?

timja commented 6 years ago

jglick:

No, that may have fixed things at one point, but it regressed again with ~~JENKINS-47324~~ I think. This is reproducible in trunk as follows:

Build core master.
Create an empty plugin from archetype.
Update its parent to 3.6, and the jenkins.version to 2.112-SNAPSHOT.
hpi:run it.
Install command-launcher.
Create an agent running: docker run -i --rm --init --name agent jenkinsci/slave java -jar /usr/share/jenkins/slave.jar
Create a freestyle project tied to that node, but with no other configuration.
Build it ⇒ boom:

Started by user unknown or anonymous
Building remotely on docker in workspace /…/workspace/…
java.lang.ClassNotFoundException: javax.servlet.ServletContextListener
    at hudson.remoting.RemoteClassLoader$ClassLoaderProxy.fetch(RemoteClassLoader.java:808)
    at …
Caused: java.lang.NoClassDefFoundError: javax/servlet/ServletContextListener
    at java.lang.ClassLoader.defineClass1(Native Method)
    at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
    at java.lang.ClassLoader.defineClass(ClassLoader.java:642)
    at hudson.remoting.RemoteClassLoader.loadClassFile(RemoteClassLoader.java:373)
Also:   hudson.remoting.Channel$CallSiteStackTrace: Remote call to docker
        at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1740)
        at hudson.remoting.UserResponse.retrieve(UserRequest.java:314)
        at hudson.remoting.Channel.call(Channel.java:955)
        at hudson.FilePath.act(FilePath.java:997)
        at hudson.FilePath.act(FilePath.java:986)
        at hudson.FilePath.mkdirs(FilePath.java:1174)
        at hudson.model.AbstractProject.checkout(AbstractProject.java:1202)
        at hudson.model.AbstractBuild$AbstractBuildExecution.defaultCheckout(AbstractBuild.java:574)
        at jenkins.scm.SCMCheckoutStrategy.checkout(SCMCheckoutStrategy.java:86)
        at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:499)
        at hudson.model.Run.execute(Run.java:1727)
        at …
Caused: java.lang.LinkageError: Failed to load jenkins.util.SystemProperties
    at hudson.remoting.RemoteClassLoader.loadClassFile(RemoteClassLoader.java:377)
    at hudson.remoting.RemoteClassLoader.findClass(RemoteClassLoader.java:285)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at hudson.Util.(Util.java:1674)
    at hudson.FilePath.mkdirs(FilePath.java:3058)
    at hudson.FilePath.access$900(FilePath.java:207)
    at hudson.FilePath$Mkdirs.invoke(FilePath.java:1182)
    at hudson.FilePath$Mkdirs.invoke(FilePath.java:1178)
    at hudson.FilePath$FileCallableWrapper.call(FilePath.java:2873)
    at hudson.remoting.UserRequest.perform(UserRequest.java:153)
    at …Caused: java.io.IOException: Remote call on docker failed
    at hudson.remoting.Channel.call(Channel.java:961)
    at hudson.FilePath.act(FilePath.java:997)
Caused: java.io.IOException: remote file operation failed: /…/workspace/… at hudson.remoting.Channel@…:docker
    at hudson.FilePath.act(FilePath.java:1004)
    at hudson.FilePath.act(FilePath.java:986)
    at hudson.FilePath.mkdirs(FilePath.java:1174)
    at hudson.model.AbstractProject.checkout(AbstractProject.java:1202)
    at …
Finished: FAILURE

timja commented 6 years ago

jglick:

Filed alternate hotfix as PR 3362.

timja commented 6 years ago

scm_issue_link:

Code changed in jenkins
User: Jesse Glick
Path:
core/src/main/java/jenkins/util/SystemProperties.java
test/src/test/java/jenkins/util/SystemPropertiesTest.java
war/src/main/webapp/WEB-INF/web.xml
http://jenkins-ci.org/commit/jenkins/7948315142cd8ac82ee69ab42416ea8af574860b
Log:
~~JENKINS-46386~~ Make SystemProperties safe to call from agent JVMs.

timja commented 6 years ago

scm_issue_link:

Code changed in jenkins
User: Oleg Nenashev
Path:
core/src/main/java/jenkins/util/SystemProperties.java
test/src/test/java/jenkins/util/SystemPropertiesTest.java
war/src/main/webapp/WEB-INF/web.xml
http://jenkins-ci.org/commit/jenkins/63a58031624f196b18d93aef00c76a10543ec95f
Log:
Merge pull request #3362 from jglick/SystemProperties-~~JENKINS-46386~~

~~JENKINS-46386~~ Make SystemProperties safe to call from agent JVMs

Compare: https://github.com/jenkinsci/jenkins/compare/9e667a2f4fcd...63a58031624f

timja commented 6 years ago

oleg_nenashev:

The patch from jglick has been released in 2.113.
I am closing this issue, because now the general use-case is addressed

timja commented 6 years ago

scm_issue_link:

Code changed in jenkins
User: Jesse Glick
Path:
core/src/main/java/jenkins/util/SystemProperties.java
test/src/test/java/jenkins/util/SystemPropertiesTest.java
war/src/main/webapp/WEB-INF/web.xml
http://jenkins-ci.org/commit/jenkins/615c3b1f616b9ba4aa5dd2c348b61b3546edf882
Log:
~~JENKINS-46386~~ Make SystemProperties safe to call from agent JVMs.

(cherry picked from commit 7948315142cd8ac82ee69ab42416ea8af574860b)

timja commented 2 years ago

[Originally depends on: JENKINS-26677]

timja / jenkins-gh-issues-poc-06-18

[JENKINS-46386] Agent sometimes fails to launch in custom cloud provider #9318