LTS upgrade 2.204.5 > 2.222.3 ClassNotFoundException on JnlpProtocol1Handler

[Brian Ray]

On upgrade of our production LTS core from 2.204.5 to 2.222.3 the master UI stack traced immediately thus, not even displaying logon fields.

java.lang.ClassNotFoundException: org.jenkinsci.remoting.engine.JnlpProtocol1Handler ...

Full stack trace is down at the end.

I understand the proximate cause. Deprecated protocols JNLP 1 through 3 were removed in Remoting 3.40 (core 2.222.1).

After rollback of the core I'm stuck in troubleshooting the ultimate cause. I am reasonably certain that I upgraded all JNLP agents to protocol 4 circa core 2.138.1. Our WMI Windows Agents Plugin is up to date at version 1.6. A quick and dirty Script Console query shows all our online Windows agents connected with protocol 4.

So ...

1. Is it possible that some other plugin is looking for this JNLP 1 class?

2. Is it possible that a node running an old agent JAR is trying to connect via JNLP 1?

3. And most importantly, how could I squeeze more information out of the reactor startup processing to find the culprit(s)? Are there some loggers that might cough up that information with more verbose logging?

Thanks!

---

java.lang.ClassNotFoundException: org.jenkinsci.remoting.engine.JnlpProtocol1Handler
    at java.net.URLClassLoader.findClass(URLClassLoader.java:382)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:418)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
    at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:543)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
Caused: java.lang.NoClassDefFoundError: Lorg/jenkinsci/remoting/engine/JnlpProtocol1Handler;
    at java.lang.Class.getDeclaredFields0(Native Method)
    at java.lang.Class.privateGetDeclaredFields(Class.java:2583)
    at java.lang.Class.getDeclaredFields(Class.java:1916)
    at com.google.inject.spi.InjectionPoint.getInjectionPoints(InjectionPoint.java:675)
    at com.google.inject.spi.InjectionPoint.forInstanceMethodsAndFields(InjectionPoint.java:380)
    at com.google.inject.internal.MembersInjectorStore.createWithListeners(MembersInjectorStore.java:93)
    at com.google.inject.internal.MembersInjectorStore.access$000(MembersInjectorStore.java:37)
    at com.google.inject.internal.MembersInjectorStore$1.create(MembersInjectorStore.java:45)
    at com.google.inject.internal.MembersInjectorStore$1.create(MembersInjectorStore.java:42)
    at com.google.inject.internal.FailableCache$1.load(FailableCache.java:37)
    at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3568)
    at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2350)
    at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2313)
    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2228)
Caused: com.google.common.util.concurrent.ExecutionError
    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2232)
    at com.google.common.cache.LocalCache.get(LocalCache.java:3965)
    at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3969)
    at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4829)
    at com.google.common.cache.LocalCache$LocalManualCache.getUnchecked(LocalCache.java:4834)
    at com.google.inject.internal.FailableCache.get(FailableCache.java:48)
    at com.google.inject.internal.MembersInjectorStore.get(MembersInjectorStore.java:68)
    at com.google.inject.internal.ConstructorInjectorStore.createConstructor(ConstructorInjectorStore.java:74)
    at com.google.inject.internal.ConstructorInjectorStore.access$000(ConstructorInjectorStore.java:29)
    at com.google.inject.internal.ConstructorInjectorStore$1.create(ConstructorInjectorStore.java:37)
    at com.google.inject.internal.ConstructorInjectorStore$1.create(ConstructorInjectorStore.java:33)
    at com.google.inject.internal.FailableCache$1.load(FailableCache.java:37)
    at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3568)
    at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2350)
    at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2313)
    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2228)
Caused: com.google.common.util.concurrent.ExecutionError
    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2232)
    at com.google.common.cache.LocalCache.get(LocalCache.java:3965)
    at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3969)
    at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4829)
    at com.google.common.cache.LocalCache$LocalManualCache.getUnchecked(LocalCache.java:4834)
    at com.google.inject.internal.FailableCache.get(FailableCache.java:48)
    at com.google.inject.internal.ConstructorInjectorStore.get(ConstructorInjectorStore.java:50)
    at com.google.inject.internal.ConstructorBindingImpl.initialize(ConstructorBindingImpl.java:136)
    at com.google.inject.internal.InjectorImpl.initializeBinding(InjectorImpl.java:533)
    at com.google.inject.internal.AbstractBindingProcessor$Processor$1.run(AbstractBindingProcessor.java:160)
    at com.google.inject.internal.ProcessedBindingData.initializeBindings(ProcessedBindingData.java:44)
    at com.google.inject.internal.InternalInjectorCreator.initializeStatically(InternalInjectorCreator.java:123)
    at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:107)
    at com.google.inject.Guice.createInjector(Guice.java:96)
    at com.google.inject.Guice.createInjector(Guice.java:73)
    at com.google.inject.Guice.createInjector(Guice.java:62)
    at hudson.ExtensionFinder$GuiceFinder.<init>(ExtensionFinder.java:290)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at java.lang.Class.newInstance(Class.java:442)
    at net.java.sezpoz.IndexItem.instance(IndexItem.java:181)
    at hudson.ExtensionFinder$Sezpoz._find(ExtensionFinder.java:704)
    at hudson.ExtensionFinder$Sezpoz.find(ExtensionFinder.java:690)
    at hudson.ClassicPluginStrategy.findComponents(ClassicPluginStrategy.java:344)
    at hudson.ExtensionList.load(ExtensionList.java:381)
    at hudson.ExtensionList.ensureLoaded(ExtensionList.java:317)
    at hudson.ExtensionList.getComponents(ExtensionList.java:183)
    at jenkins.model.Jenkins$6.onInitMilestoneAttained(Jenkins.java:1152)
    at jenkins.InitReactorRunner$1.onAttained(InitReactorRunner.java:83)
    at org.jvnet.hudson.reactor.ReactorListener$Aggregator.lambda$onAttained$3(ReactorListener.java:102)
    at org.jvnet.hudson.reactor.ReactorListener$Aggregator.run(ReactorListener.java:109)
    at org.jvnet.hudson.reactor.ReactorListener$Aggregator.onAttained(ReactorListener.java:102)
    at org.jvnet.hudson.reactor.Reactor$1.run(Reactor.java:177)
    at org.jvnet.hudson.reactor.Reactor$Node.run(Reactor.java:117)
    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: org.jvnet.hudson.reactor.ReactorException
    at org.jvnet.hudson.reactor.Reactor.execute(Reactor.java:282)
    at jenkins.InitReactorRunner.run(InitReactorRunner.java:48)
    at jenkins.model.Jenkins.executeReactor(Jenkins.java:1155)
    at jenkins.model.Jenkins.<init>(Jenkins.java:966)
    at hudson.model.Hudson.<init>(Hudson.java:85)
    at hudson.model.Hudson.<init>(Hudson.java:81)
    at hudson.WebAppMain$3.run(WebAppMain.java:233)
Caused: hudson.util.HudsonFailedToLoad
    at hudson.WebAppMain$3.run(WebAppMain.java:250)

[Brian Ray]

As luck would have it I re-upgraded without issue. No recurrence of the protocol handler classload exception.

But in the meantime I did hit upon a logging configuration that might have pointed to the culprit. Here's a logging.properties file you can feed to Jenkins via the method at the end of this wiki page. My suspicion is that using the System Log link would not work in the situation I ran into because the stack trace blocked logon outright. You would never be able to get back to the custom logger(s) set up in the UI.

handlers=java.util.logging.FileHandler, java.util.logging.ConsoleHandler

.level=WARNING

java.util.logging.FileHandler.level=FINE
java.util.logging.FileHandler.pattern=c:/Jenkins/troubleshoot%g.log
java.util.logging.FileHandler.limit=1048576
java.util.logging.FileHandler.count=10
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

java.util.logging.ConsoleHandler.level=WARNING
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

java.util.logging.SimpleFormatter.format=[%1$tF %1$tT %1$tz] [%4$s] %2$s %5$s%6$s%n

jenkins.InitReactorRunner.level=FINE
hudson.ExtensionFinder$GuiceFinder.level=FINE