Something is killing my launcher after 90-100 seconds

[Ivan Fernandez Calvo]

Hi,

I am implementing a new launcher based on the Apache Mina SSHD library, I can connect the Agent, I can launch jobs, and the agent is stable in jobs that run for hours. so far so good, but not, if the agent does not have IO something is killing the agent. In the beginning I thought that was something in the SSH connection implementation, but to discard that I have made some unit test that can be connected for more than 5 min without issues. then I though that was related to the pingThread because there were traces of it on the logs but finally I have discarded it too. So I can stabilise a SSH connection and open a channel but after 90-100 seconds of inactivity the channel is closed with and EOF error, the test always fail more or less at the same time.

This is the test of the classes outside Jenkins https://github.com/kuisathaverat/ssh-slaves-plugin/blob/apache_mina/src/test/java/io/jenkins/plugins/sshbuildagents/ssh/agents/ClientRSA512ConnectionTest.java#L121

This is the long connection test on Jenkins that fails after 90-100 seconds https://github.com/kuisathaverat/ssh-slaves-plugin/blob/apache_mina/src/test/java/io/jenkins/plugins/sshbuildagents/ssh/agents/ClientRSA512ConnectionTest.java#L121

this is the branch with the new launcher https://github.com/kuisathaverat/ssh-slaves-plugin/tree/apache_mina

I am using Jenkins core 2.303

These are the latest lines of the long in FINE level Jenkins logs, on the Agent there is no errors (it is also on FINE level).

 Dec 10, 2021 5:16:38 PM org.apache.sshd.common.session.helpers.AbstractSession request

FINE: request(ClientSessionImpl[jenkins@localhost/127.0.0.1:55135]) request=keepalive@jenkins.io, timeout=59995ms, requestSeqNo=19333, result received=true
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.util.logging.LoggingUtils error
SEVERE: pumpInputStream(ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135]) Caught IOException : Pipe broken
java.io.IOException: Pipe broken
at java.base/java.io.PipedInputStream.read(PipedInputStream.java:321)
at java.base/java.io.PipedInputStream.read(PipedInputStream.java:377)
at org.apache.sshd.client.channel.ChannelSession.securedRead(ChannelSession.java:203)
at org.apache.sshd.client.channel.ChannelSession.pumpInputStream(ChannelSession.java:171)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)

Dec 10, 2021 5:16:57 PM org.apache.sshd.common.util.closeable.AbstractCloseable close
FINE: close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135]) Closing gracefully
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.channel.AbstractChannel preClose
FINE: close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135]) no EOF sent
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.channel.Window close
FINE: Closing Window[client/local](ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135])
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.channel.Window close
FINE: Closing Window[client/remote](ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135])
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.channel.AbstractChannel sendEof
FINE: sendEof(ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135]) SSH_MSG_CHANNEL_EOF (state=Graceful)
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.session.helpers.AbstractSession encode
FINE: encode(ClientSessionImpl[jenkins@localhost/127.0.0.1:55135]) packet #19334 sending command=96[SSH_MSG_CHANNEL_EOF] len=5
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.io.nio2.Nio2Session writeBuffer
FINE: writeBuffer(Nio2Session[local=/127.0.0.1:65447, remote=localhost/127.0.0.1:55135]) writing 68 bytes
Dec 10, 2021 5:16:57 PM hudson.remoting.SynchronousCommandTransport$ReaderThread run
INFO: I/O error in channel ssh-agent-rsa512
java.io.IOException: Unexpected termination of the channel
at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:75)
Caused by: java.io.EOFException
at java.base/java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2872)
at java.base/java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:3367)
at java.base/java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:936)
at java.base/java.io.ObjectInputStream.<init>(ObjectInputStream.java:379)
at hudson.remoting.ObjectInputStreamEx.<init>(ObjectInputStreamEx.java:49)
at hudson.remoting.Command.readFrom(Command.java:142)
at hudson.remoting.Command.readFrom(Command.java:128)
at hudson.remoting.AbstractSynchronousByteArrayCommandTransport.read(AbstractSynchronousByteArrayCommandTransport.java:35)
at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:61)

Dec 10, 2021 5:16:57 PM org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable close
FINE: close(ChannelExec[id=0, recipient=0]-ClientSessionImpl[jenkins@localhost/127.0.0.1:55135])[immediately=false] processing
Dec 10, 2021 5:16:57 PM org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable close

Have anybody any idea what it is going on or how I can debug the error? I am completely desperate after a bunch of hours trying to find the issue. 

Thanks

Ivan

[Ivan Fernandez Calvo]

the link to the test that fails is wrong, this is the test that fails after 90-100 seconds

https://github.com/kuisathaverat/ssh-slaves-plugin/blob/apache_mina/src/test/java/io/jenkins/plugins/sshbuildagents/ssh/agents/AgentRSA512ConnectionTest.java#L48

[Ivan Fernandez Calvo]

finally, I found my ghost, it is not related to the launcher nor the remoting, there is a timeout of 180 seconds in the JenkinsRule, when this timeout happens usually see a message in logs informing that you reached that timeout, in my case the stop of Jenkins causes an IO exception in remoting and that message is not shown, it can be a good idea to inform about that timeout when the JenkinsRule starts.

It is possible to remove this timeout if you set the property jenkins.test.timeout

<build>

  <plugins>

  <plugin>
    <artifactId>maven-surefire-plugin</artifactId>
      <configuration>
        <systemPropertyVariables>
          <jenkins.test.timeout>-1</jenkins.test.timeout>
        </systemPropertyVariables>
      </configuration>
    </plugin>
  </plugins>
</build>

    

[Markus Winter]

to set a timeout of 5 minutes in plain JUnit you can do
@Test(timeout = 1000 * 300)  //in milliseconds

When you have a JenkinsRule, the you need to use
@WithTimeout(300)  // in seconds

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/0845de9b-6680-4089-9ebe-a9923aeed445n%40googlegroups.com.