Find root cause of failed connection listener thread

[Andrey Babushkin]

Hi all,

Today we've faced very strange issue that was preventing agents dynamic creation (via Kubernetes plugin). Here's the log:

SEVERE: Uncaught exception in TcpSlaveAgentListener ConnectionHandler Thread[TCP agent connection handler #67453 with /10.125.230.216:46240,5,main]

java.lang.UnsupportedOperationException: Network layer is not supposed to call isSendOpen

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.isSendOpen(ProtocolStack.java:730)

        at org.jenkinsci.remoting.protocol.FilterLayer.isSendOpen(FilterLayer.java:340)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.isSendOpen(ProtocolStack.java:738)

        at org.jenkinsci.remoting.protocol.FilterLayer.isSendOpen(FilterLayer.java:340)

        at org.jenkinsci.remoting.protocol.impl.SSLEngineFilterLayer.isSendOpen(SSLEngineFilterLayer.java:237)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.isSendOpen(ProtocolStack.java:738)

        at org.jenkinsci.remoting.protocol.FilterLayer.isSendOpen(FilterLayer.java:340)

        at org.jenkinsci.remoting.protocol.impl.ConnectionHeadersFilterLayer.isSendOpen(ConnectionHeadersFilterLayer.java:514)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.doSend(ProtocolStack.java:690)

        at org.jenkinsci.remoting.protocol.ApplicationLayer.write(ApplicationLayer.java:157)

        at org.jenkinsci.remoting.protocol.impl.ChannelApplicationLayer.start(ChannelApplicationLayer.java:230)

        at org.jenkinsci.remoting.protocol.ProtocolStack.init(ProtocolStack.java:201)

        at org.jenkinsci.remoting.protocol.ProtocolStack.access$700(ProtocolStack.java:106)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Builder.build(ProtocolStack.java:554)

        at org.jenkinsci.remoting.engine.JnlpProtocol4Handler.handle(JnlpProtocol4Handler.java:153)

        at jenkins.slaves.JnlpSlaveAgentProtocol4.handle(JnlpSlaveAgentProtocol4.java:203)

        at hudson.TcpSlaveAgentListener$ConnectionHandler.run(TcpSlaveAgentListener.java:272)


Nov 21, 2019 8:47:46 PM hudson.TcpSlaveAgentListener$1 run

WARNING: Connection handler failed, restarting listener

java.lang.UnsupportedOperationException: Network layer is not supposed to call isSendOpen

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.isSendOpen(ProtocolStack.java:730)

        at org.jenkinsci.remoting.protocol.FilterLayer.isSendOpen(FilterLayer.java:340)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.isSendOpen(ProtocolStack.java:738)

        at org.jenkinsci.remoting.protocol.FilterLayer.isSendOpen(FilterLayer.java:340)

        at org.jenkinsci.remoting.protocol.impl.SSLEngineFilterLayer.isSendOpen(SSLEngineFilterLayer.java:237)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.isSendOpen(ProtocolStack.java:738)

        at org.jenkinsci.remoting.protocol.FilterLayer.isSendOpen(FilterLayer.java:340)

        at org.jenkinsci.remoting.protocol.impl.ConnectionHeadersFilterLayer.isSendOpen(ConnectionHeadersFilterLayer.java:514)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.doSend(ProtocolStack.java:690)

        at org.jenkinsci.remoting.protocol.ApplicationLayer.write(ApplicationLayer.java:157)

        at org.jenkinsci.remoting.protocol.impl.ChannelApplicationLayer.start(ChannelApplicationLayer.java:230)

        at org.jenkinsci.remoting.protocol.ProtocolStack.init(ProtocolStack.java:201)

        at org.jenkinsci.remoting.protocol.ProtocolStack.access$700(ProtocolStack.java:106)

        at org.jenkinsci.remoting.protocol.ProtocolStack$Builder.build(ProtocolStack.java:554)

        at org.jenkinsci.remoting.engine.JnlpProtocol4Handler.handle(JnlpProtocol4Handler.java:153)

        at jenkins.slaves.JnlpSlaveAgentProtocol4.handle(JnlpSlaveAgentProtocol4.java:203)

        at hudson.TcpSlaveAgentListener$ConnectionHandler.run(TcpSlaveAgentListener.java:272)

And despite it said it was restarted later in logs we see that our JNLP connection port (50000) is down:

Nov 21, 2019 8:52:01 PM hudson.remoting.jnlp.Main createEngine

INFO: Setting up agent: ci-master-run-tests-60037-6qpk4-qq2tz

Nov 21, 2019 8:52:01 PM hudson.remoting.jnlp.Main$CuiListener <init>

INFO: Jenkins agent is running in headless mode.

Nov 21, 2019 8:52:01 PM hudson.remoting.Engine startEngine

INFO: Using Remoting version: 3.28

Nov 21, 2019 8:52:01 PM hudson.remoting.Engine startEngine

WARNING: No Working Directory. Using the legacy JAR Cache location: /home/jenkins/.jenkins/cache/jars

Nov 21, 2019 8:52:01 PM hudson.remoting.jnlp.Main$CuiListener status

INFO: Locating server among [http://jenkins.example.com/]

Nov 21, 2019 8:52:06 PM org.jenkinsci.remoting.engine.JnlpAgentEndpointResolver resolve

INFO: Remoting server accepts the following protocols: [JNLP4-connect, Ping]

Nov 21, 2019 8:52:06 PM org.jenkinsci.remoting.engine.JnlpAgentEndpointResolver isPortVisible

WARNING: Connection refused (Connection refused)

Nov 21, 2019 8:52:06 PM hudson.remoting.jnlp.Main$CuiListener error

SEVERE: http://jenkins.example.com/ provided port:50000 is not reachable

java.io.IOException: http://jenkins.example.com/ provided port:50000 is not reachable

        at org.jenkinsci.remoting.engine.JnlpAgentEndpointResolver.resolve(JnlpAgentEndpointResolver.java:287)

        at hudson.remoting.Engine.innerRun(Engine.java:523)

        at hudson.remoting.Engine.run(Engine.java:474)

When we've found this (this occurred at night) we had changed JNLP port in Jenkins -> Configure Jenkins -> Confgure Global Security -> Agents -> TCP port for inbound agents -> Fixed from 50000 to 50001 and back to 50000 and then everything was working again (we use fixed port because we need to specify it in docker run settings when running Jenkins). It is reproducible on Jenkins 2.176.4.

How can I find the root cause of this? May be there are some debug options I can use or so...  I've added logs listeners on classes I've seen in the logs and waiting when this will happen again.