[JIRA] [core] (JENKINS-28492) The server rejected the connection: *** is already connected to this master. Rejecting this connection.

151 views
Skip to first unread message

gaffey@msn.cn (JIRA)

unread,
May 19, 2015, 11:54:01 PM5/19/15
to jenkinsc...@googlegroups.com
gaffey he created an issue
 
Jenkins / Bug JENKINS-28492
The server rejected the connection: *** is already connected to this master. Rejecting this connection.
Issue Type: Bug Bug
Assignee: Unassigned
Attachments: jenkins-slave.err.log
Components: core
Created: 20/May/15 3:53 AM
Environment: Windows 7, Jenkins 1.613
Priority: Major Major
Reporter: gaffey he

I am running Jenkins 1.613.

i see the slaves log:
四月 15, 2015 10:15:02 上午 com.youdevise.hudson.slavestatus.SlaveListener call
信息: Slave-status listener starting
四月 15, 2015 10:15:02 上午 com.youdevise.hudson.slavestatus.SocketHTTPListener waitForConnection
信息: Slave-status listener ready on port 3141
四月 15, 2015 1:41:01 下午 hudson.remoting.jnlp.Main createEngine
信息: Setting up slave: 192.168.161.8
四月 15, 2015 1:41:01 下午 hudson.remoting.jnlp.Main$CuiListener <init>
信息: Jenkins agent is running in headless mode.
四月 15, 2015 1:41:01 下午 hudson.remoting.jnlp.Main$CuiListener status
信息: Locating server among http://192.168.95.37:8080/jenkins/
四月 15, 2015 1:41:01 下午 hudson.remoting.jnlp.Main$CuiListener status
信息: Connecting to 192.168.95.37:19994
四月 15, 2015 1:41:01 下午 hudson.remoting.jnlp.Main$CuiListener status
信息: Handshaking
四月 15, 2015 1:41:01 下午 hudson.remoting.jnlp.Main$CuiListener error
严重: The server rejected the connection: 192.168.161.8 is already connected to this master. Rejecting this connection.
java.lang.Exception: The server rejected the connection: 192.168.161.8 is already connected to this master. Rejecting this connection.
at hudson.remoting.Engine.onConnectionRejected(Engine.java:306)
at hudson.remoting.Engine.run(Engine.java:276)
Add Comment Add Comment
 
This message was sent by Atlassian JIRA (v6.4.2#64017-sha1:e244265)
Atlassian logo

sonukr666@gmail.com (JIRA)

unread,
Oct 29, 2015, 10:20:01 AM10/29/15
to jenkinsc...@googlegroups.com
sonu kumar updated an issue
Change By: sonu kumar
Priority: Major Blocker

sonukr666@gmail.com (JIRA)

unread,
Oct 29, 2015, 10:20:02 AM10/29/15
to jenkinsc...@googlegroups.com

slide.o.mix@gmail.com (JIRA)

unread,
Dec 8, 2015, 6:35:01 PM12/8/15
to jenkinsc...@googlegroups.com

Can you verify that you don't have another instance of the slave.jar running on your slave computer? Either that, or you may have two computers with the same IP address.

dbeck@cloudbees.com (JIRA)

unread,
Dec 10, 2015, 5:30:04 AM12/10/15
to jenkinsc...@googlegroups.com

I think the "IP address" here may be the slave name? If so, there may also be two machines claiming to be the same slave.

dmwjobs@isomedia.com (JIRA)

unread,
Mar 22, 2016, 1:59:03 PM3/22/16
to jenkinsc...@googlegroups.com

This issue is reporting the same symptoms as

JENKINS-5055 , which was thought to have been fixed back before the Hudson/Jenkins split, but now has multiple people reporting that the problem is back.

dmwjobs@isomedia.com (JIRA)

unread,
Mar 22, 2016, 2:08:02 PM3/22/16
to jenkinsc...@googlegroups.com

I am seeing the exact same thing with Jenkins 1.574.
We download the slave.jar from the master before every startup so we know it is current.
Both slaves and master are RHEL 6.4 Linux.
Slaves are started headless from an init script when the machine is booted.
Error occurs about 1/3 of the time.

dmwjobs@isomedia.com (JIRA)

unread,
Mar 22, 2016, 2:14:09 PM3/22/16
to jenkinsc...@googlegroups.com
Douglas Wooster edited a comment on Bug JENKINS-28492
I am seeing the exact same thing with Jenkins 1.574 , after reboot of the slave .

We download the slave.jar from the master before every startup so we know it is current.
Both slaves and master are RHEL 6.4 Linux.
Slaves are started headless from an init script when the machine is booted.
Error occurs about 1/3 of the time.

mmitche@microsoft.com (JIRA)

unread,
Mar 27, 2016, 2:52:02 PM3/27/16
to jenkinsc...@googlegroups.com

I'm also seeing this on Jenkins 1.642.1. In addition, if the connection is explicitly stopped on the slave side, the master still shows the slave as connected.

mmitche@microsoft.com (JIRA)

unread,
Mar 27, 2016, 2:53:01 PM3/27/16
to jenkinsc...@googlegroups.com
Matthew Mitchell edited a comment on Bug JENKINS-28492
I'm also seeing this on Jenkins 1.642. 1 3 .  In addition, if the connection is explicitly stopped on the slave side, the master still shows the slave as connected.

mmitche@microsoft.com (JIRA)

unread,
Mar 27, 2016, 2:54:01 PM3/27/16
to jenkinsc...@googlegroups.com

Also, we didn't use it see this at all, but there appears to be a large uptick in instances since moving towards more cloud allocated machines (azure-slave-plugin) though the Azure slave plugin machine do not ever see the issue.

mmitche@microsoft.com (JIRA)

unread,
Mar 27, 2016, 3:08:02 PM3/27/16
to jenkinsc...@googlegroups.com
Matthew Mitchell edited a comment on Bug JENKINS-28492
Also, we didn't use it see this at all, but there appears to be a large uptick in instances since moving towards more cloud allocated machines (azure-slave-plugin) though the Azure slave plugin machine do not ever see the issue.   I have also never seen it on SSH connected machines.

dbeck@cloudbees.com (JIRA)

unread,
Mar 27, 2016, 9:39:02 PM3/27/16
to jenkinsc...@googlegroups.com
Daniel Beck updated an issue
 
Change By: Daniel Beck
Component/s: remoting

mmitche@microsoft.com (JIRA)

unread,
Mar 28, 2016, 2:24:02 PM3/28/16
to jenkinsc...@googlegroups.com
Matthew Mitchell updated an issue
Change By: Matthew Mitchell
Attachment: channelclosedstack.txt

mmitche@microsoft.com (JIRA)

unread,
Mar 28, 2016, 2:25:01 PM3/28/16
to jenkinsc...@googlegroups.com
Matthew Mitchell commented on Bug JENKINS-28492
 
Re: The server rejected the connection: *** is already connected to this master. Rejecting this connection.

I got a full thread dump channelclosedstack.txt while this was happening and am invstigating, since for whatever reason this is hitting us full bore right now.

mmitche@microsoft.com (JIRA)

unread,
Mar 29, 2016, 1:38:01 AM3/29/16
to jenkinsc...@googlegroups.com

Douglass, do you know anything more about the intallations where we are seeing this? I think I am seeing a pattern in my repros that has to do with slave deletion (and maybe creation). I think for us this correlates with increased usage of the azure cloud plugin

mgaborit@invoke.fr (JIRA)

unread,
Mar 29, 2016, 6:28:02 AM3/29/16
to jenkinsc...@googlegroups.com

We are seeing the same issue with Jenkins 1.634.
The master is a Debian Jessie and the slave is a Windows Server 2012 R2 connected via JNLP.
After rebooting the Windows slave, it tries to connect to the master exactly 1030 times (we reproduced a few times). On the attempt 1031, it connects correctly.

In addition, as Matthew Mitchell said, the master doesn't seem to be notified that the slave was disconnected.

mgaborit@invoke.fr (JIRA)

unread,
Mar 29, 2016, 6:59:01 AM3/29/16
to jenkinsc...@googlegroups.com
Martin Gaborit edited a comment on Bug JENKINS-28492
We are seeing the same issue with Jenkins 1.634.
The master is a Debian Jessie and the slave is a Windows Server 2012 R2 connected via JNLP.
After rebooting the Windows slave, it tries to connect to the master exactly 1030 times (we reproduced a few times). On the attempt 1031, it connects correctly.

In addition, as [~mmitche] said, the master doesn't seem to be  notified  aware  that the slave was disconnected. 

dmwjobs@isomedia.com (JIRA)

unread,
Apr 4, 2016, 1:35:03 AM4/4/16
to jenkinsc...@googlegroups.com

Hi, Matthew,
Sorry I took so long - Jenkins-ci.org authentication server was down when I tried before.

Jenkins server is 1.574 running on Tomcat 7.0.63 in a virtual machine running RHEL 6.4 Linux. Slaves are also on RHEL 6.4. Mix of virtual machines and real physical machines. We do NOT use azure-cloud-plugin. We have one Windows slave defined, but we have not even started that slave in several months. All slaves run headless and are started by a script on the slave machines (script can be run manually or automatically during boot). I think we only see this problem when the machine the slave is running on is rebooted.

dmwjobs@isomedia.com (JIRA)

unread,
Apr 4, 2016, 1:41:02 AM4/4/16
to jenkinsc...@googlegroups.com
Douglas Wooster edited a comment on Bug JENKINS-28492
Hi, Matthew,
Sorry I took so long - Jenkins-ci.org authentication server was down when I tried before.

Jenkins server is 1.574 running on Tomcat 7.0.63 in a virtual machine running RHEL 6.4 Linux.  Slaves are also on RHEL 6.4.  Mix of virtual machines and real physical machines.   We do NOT use azure-   No cloud -plugin  involved .   We have one Windows slave defined, but we have not even started that slave in several months.   All slaves run headless and are started by a script on the slave machines (script can be run manually or automatically during boot).  I think we only see this problem when the machine the slave is running on is rebooted.

We do NOT use azure-cloud-plugin.  All of the slaves currently in use are on Linux.  We have one Windows slave defined, but we have not attempted to run that slave for several months.

We have been running Jenkins 1.574 for about two years.  The problem was first noticed when we added slave startup to boot autostart scripts in late 2015.

mmitche@microsoft.com (JIRA)

unread,
Apr 4, 2016, 2:22:01 PM4/4/16
to jenkinsc...@googlegroups.com

So I think what's going on is that certain kind of network outages (or maybe a reboot) are causing issues with the master realizing that the connection is closed.

I think I see one place where there is a bug:

https://github.com/jenkinsci/jenkins/blob/master/core/src/main/java/hudson/slaves/ChannelPinger.java#L111

I've seen the call into the PingFailureAnalyzer return NPE, causing us to miss the call to terminate the channel. However, unless I'm misunderstanding the code, I think that's executing on the client, which wouldn't cause the server to keep the channel open.

Do you have any special ping setting set on Jenkins startup?

dbeck@cloudbees.com (JIRA)

unread,
Apr 4, 2016, 8:38:01 PM4/4/16
to jenkinsc...@googlegroups.com

Oleg Nenashev Maybe worth it to take a look at this?

dmwjobs@isomedia.com (JIRA)

unread,
Apr 4, 2016, 9:44:01 PM4/4/16
to jenkinsc...@googlegroups.com

I'm not aware of any special ping setting on Master startup. How would I check?

There's no special operands on the slave startup. Just -jnlpUrl pointing the Master.

Looking at ChannelPinger.java, I think it executes on BOTH the slave and the master. See lines 88-104.

mmitche@microsoft.com (JIRA)

unread,
Apr 5, 2016, 12:17:02 PM4/5/16
to jenkinsc...@googlegroups.com

The Launcher code in remoting (that has all the client side options, also launches a pinger. So I think there is a pinger from both sides, but not the exact same code)

mmitche@microsoft.com (JIRA)

unread,
Apr 5, 2016, 12:28:01 PM4/5/16
to jenkinsc...@googlegroups.com

I'm trying to set up a fake repro for this where the client will always fail and attempt to close the channel to see whether I can get the master to have the same issue seen in the wild.

mmitche@microsoft.com (JIRA)

unread,
Apr 6, 2016, 2:04:02 PM4/6/16
to jenkinsc...@googlegroups.com

Alright, I was unable to get an exact repo, but I think I saw enough, plus combined with the logs, to figure out what happens:

1) The PingFailureAnalyzer call in onDead in ChannelPinger.java will occasionally fail for various reasons. NPE's, findClass failures. Not always, but sometimes. When this happens, the master will NOT call close on the channel.
2) Normally this appears to be fine. The channel is somehow replaced or null'd out through other means. I think in cases of process termination or other semi-orderly shutdowns the socket connection is notified.
3) However, let's say there is a network anomoly. Power outage, network cable unplugged, dropped connection not on the server/client side. In this case, the master will notice, potentially by noticing a failed ping. If it fails in the PingFailureAnalyzer code, it won't close the channel.
4) The slave comes back, say from a reboot, or the network cable is reinstalled, etc. and attempts to reconnect. The channel is not null, and we get the error.

I think the keys to the repro are the lack of a "Terminate" text in the slave log and the definite issue of not closing the channel when an exception is seen in the PFA. The lack of terminate indicates there was not an orderly shutdown of the channel on the client side.

So, the fix would be to wrap the call to the PFA in a try catch to ensure that channel.close() is in fact called.

The issues I was seeing in my installation have subsided, but this fix was made as they were tailing off, and I think I did not see any already connected errors after that.

lil2006@inbox.ru (JIRA)

unread,
Apr 7, 2016, 3:21:04 AM4/7/16
to jenkinsc...@googlegroups.com

Hi,
Run into same issue on Windows 2012 R2 and Slave.jar version: 2.49
Master Log:
<===[JENKINS REMOTING CAPACITY]===>Slave.jar version: 2.49
This is a Windows slave
Slave successfully connected and online
ERROR: Connection terminated
java.io.IOException: Connection aborted: org.jenkinsci.remoting.nio.NioChannelHub$MonoNioTransport@186a19a4[name=ALMNB]
at org.jenkinsci.remoting.nio.NioChannelHub$NioTransport.abort(NioChannelHub.java:211)
at org.jenkinsci.remoting.nio.NioChannelHub.run(NioChannelHub.java:631)
at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.util.concurrent.FutureTask.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(Unknown Source)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)
at sun.nio.ch.IOUtil.read(Unknown Source)
at sun.nio.ch.SocketChannelImpl.read(Unknown Source)
at org.jenkinsci.remoting.nio.FifoBuffer$Pointer.receive(FifoBuffer.java:136)
at org.jenkinsci.remoting.nio.FifoBuffer.receive(FifoBuffer.java:306)
at org.jenkinsci.remoting.nio.NioChannelHub.run(NioChannelHub.java:564)
... 6 more

Slave log:
Apr 07, 2016 9:41:00 AM hudson.remoting.jnlp.Main$CuiListener error
SEVERE: The server rejected the connection: <VMNAME> is already connected to this master. Rejecting this connection.
java.lang.Exception: The server rejected the connection: <VMNAME> is already connected to this master. Rejecting this connection.
at hudson.remoting.Engine.onConnectionRejected(Engine.java:306)
at hudson.remoting.Engine.run(Engine.java:276)

jenkins-slave.wrapper log :
each second start new process.

In system event :
The Jenkins Slave service terminated unexpectedly. It has done this 1 time(s). The following corrective action will be taken in 0 milliseconds: Restart the service.

Each second i see this log during

lil2006@inbox.ru (JIRA)

unread,
Apr 7, 2016, 3:23:01 AM4/7/16
to jenkinsc...@googlegroups.com
Igor Tere edited a comment on Bug JENKINS-28492
Each second i see this log during  1 min, then connection lost and back to online immediately  

lil2006@inbox.ru (JIRA)

unread,
Apr 7, 2016, 3:27:03 AM4/7/16
to jenkinsc...@googlegroups.com

In my case root can be in too fast reboot client and master cant detect that slave was in shutdown , in result after reboot client trying start connection while master see that client still online.
I made sleep before start service, that master can determine that slave already offline. will see is it helps or no.

lil2006@inbox.ru (JIRA)

unread,
Apr 7, 2016, 3:27:04 AM4/7/16
to jenkinsc...@googlegroups.com
Igor Tere edited a comment on Bug JENKINS-28492
Hi, 
Run into same issue on Windows 2012 R2 and Slave.jar version: 2.49
Master Log: 
<===[JENKINS REMOTING CAPACITY]===>Slave.jar version: 2.49
This is a Windows slave
Slave successfully connected and online
ERROR: Connection terminated
java.io.IOException: Connection aborted: org.jenkinsci.remoting.nio.NioChannelHub$MonoNioTransport@186a19a4[name= ALMNB ***** ]

phil.johnson@infinitecampus.com (JIRA)

unread,
May 11, 2016, 4:22:03 PM5/11/16
to jenkinsc...@googlegroups.com

Hello. I'm getting a similar issue.
Server Log:

May 11, 2016 2:39:30 PM hudson.slaves.ChannelPinger$1 onDead
INFO: Ping failed. Terminating the channel build7.
java.util.concurrent.TimeoutException: Ping started at 1462995330113 hasn't completed by 1462995570113
Seems (although certainly not absolute) network-ish ??

Client Log:
2016-05-11 14:39:45 - Stopping jenkinsslave-D__Jenkins
2016-05-11 14:39:45 - ProcessKill 3608
2016-05-11 14:39:45 - Found child process: 4432 Name: conhost.exe
2016-05-11 14:39:45 - Stopping process 4432
2016-05-11 14:39:45 - Send SIGINT 4432
2016-05-11 14:39:45 - SIGINT to 4432 failed - Killing as fallback
2016-05-11 14:39:45 - Stopping process 3608
2016-05-11 14:39:45 - Send SIGINT 3608
2016-05-11 14:39:45 - SIGINT to 3608 failed - Killing as fallback
2016-05-11 14:39:45 - Finished jenkinsslave-D__Jenkins
2016-05-11 14:39:46 - Starting C:\Program Files\Java\jre7\bin\java.exe -Xrs -jar "D:\Jenkins\slave.jar" -jnlpUrl http://ci.infinitecampus.com/computer/build7/slave-agent.jnlp -secret f3e11d126c1c85e9065c7b1d1e8f60b07cac090b63828cb64532bb49da4e0d18
2016-05-11 14:39:46 - Started 2348

phil.johnson@infinitecampus.com (JIRA)

unread,
May 11, 2016, 4:22:05 PM5/11/16
to jenkinsc...@googlegroups.com
Phil Johnson edited a comment on Bug JENKINS-28492
Hello.   I'm getting a similar issue.
*Server Log:*


May 11, 2016 2:39:30 PM hudson.slaves.ChannelPinger$1 onDead
INFO: Ping failed. Terminating the channel build7.
java.util.concurrent.TimeoutException: Ping started at 1462995330113 hasn't completed by 1462995570113
Seems (although certainly not absolute) network-ish ??

* Client Log: *  

2016-05-11 14:39:45 - Stopping jenkinsslave-D__Jenkins
2016-05-11 14:39:45 - ProcessKill 3608
2016-05-11 14:39:45 - Found child process: 4432 Name: conhost.exe
2016-05-11 14:39:45 - Stopping process 4432
2016-05-11 14:39:45 - Send SIGINT 4432
2016-05-11 14:39:45 - SIGINT to 4432 failed - Killing as fallback
2016-05-11 14:39:45 - Stopping process 3608
2016-05-11 14:39:45 - Send SIGINT 3608
2016-05-11 14:39:45 - SIGINT to 3608 failed - Killing as fallback
2016-05-11 14:39:45 - Finished jenkinsslave-D__Jenkins
2016-05-11 14:39:46 - Starting C:\Program Files\Java\jre7\bin\java.exe -Xrs -jar "D:\Jenkins\slave.jar" -jnlpUrl http://ci.infinitecampus.com/computer/build7/slave-agent.jnlp -secret f3e11d126c1c85e9065c7b1d1e8f60b07cac090b63828cb64532bb49da4e0d18
2016-05-11 14:39:46 - Started 2348

phil.johnson@infinitecampus.com (JIRA)

unread,
May 11, 2016, 5:01:02 PM5/11/16
to jenkinsc...@googlegroups.com
Phil Johnson edited a comment on Bug JENKINS-28492
Hello.   I'm getting a similar issue.
*Server Log:*

May 11, 2016 2:39:30 PM hudson.slaves.ChannelPinger$1 onDead
INFO: Ping failed. Terminating the channel build7.
java.util.concurrent.TimeoutException: Ping started at 1462995330113 hasn't completed by 1462995570113
Seems (although certainly not absolute) network-ish ??

*Client Log:* 

2016-05-11 14:39:45 - Stopping jenkinsslave-D__Jenkins
2016-05-11 14:39:45 - ProcessKill 3608
2016-05-11 14:39:45 - Found child process: 4432 Name: conhost.exe
2016-05-11 14:39:45 - Stopping process 4432
2016-05-11 14:39:45 - Send SIGINT 4432
2016-05-11 14:39:45 - SIGINT to 4432 failed - Killing as fallback
2016-05-11 14:39:45 - Stopping process 3608
2016-05-11 14:39:45 - Send SIGINT 3608
2016-05-11 14:39:45 - SIGINT to 3608 failed - Killing as fallback
2016-05-11 14:39:45 - Finished jenkinsslave-D__Jenkins
2016-05-11 14:39:46 - Starting C:\Program Files\Java\jre7\bin\java.exe -Xrs -jar "D:\Jenkins\slave.jar" -jnlpUrl  http://ci.infinitecampus.com/computer/build7/slave-agent.jnlp -secret f3e11d126c1c85e9065c7b1d1e8f60b07cac090b63828cb64532bb49da4e0d18  <server>
2016-05-11 14:39:46 - Started 2348

cheecheeo@gmail.com (JIRA)

unread,
May 16, 2016, 6:49:01 PM5/16/16
to jenkinsc...@googlegroups.com
J C commented on Bug JENKINS-28492

Also seing this issue:

May 16, 2016 10:47:09 PM hudson.TcpSlaveAgentListener$ConnectionHandler run
INFO: Accepted connection #366831 from /10.180.20.162:57952
May 16, 2016 10:47:09 PM jenkins.slaves.JnlpSlaveHandshake error
WARNING: TCP slave agent connection handler #366831 with /10.180.20.162:57952 is aborted: ci-windows4 is already connected to this master. Rejecting this connection.
May 16, 2016 10:47:09 PM hudson.TcpSlaveAgentListener$ConnectionHandler run
INFO: Accepted connection #366832 from /10.180.20.162:57953
May 16, 2016 10:47:09 PM jenkins.slaves.JnlpSlaveHandshake error
WARNING: TCP slave agent connection handler #366832 with /10.180.20.162:57953 is aborted: ci-windows4 is already connected to this master. Rejecting this connection.
May 16, 2016 10:47:09 PM hudson.TcpSlaveAgentListener$ConnectionHandler run
INFO: Accepted connection #366833 from /10.180.20.162:57954
May 16, 2016 10:47:09 PM hudson.TcpSlaveAgentListener$ConnectionHandler run
WARNING: Connection #366833 failed
java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
        at sun.nio.ch.IOUtil.read(IOUtil.java:197)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
        at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:192)
        at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103)
        at java.io.InputStream.read(InputStream.java:101)
        at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:81)
        at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:337)
        at java.io.DataInputStream.readUTF(DataInputStream.java:589)
        at java.io.DataInputStream.readUTF(DataInputStream.java:564)
        at hudson.TcpSlaveAgentListener$ConnectionHandler.run(TcpSlaveAgentListener.java:150)

mark.mann@krogan.co.uk (JIRA)

unread,
May 17, 2016, 1:44:26 PM5/17/16
to jenkinsc...@googlegroups.com

windows 2008R2 master and slaves
master on Jenkins ver. 1.651.1
Java JRE is mixture of 8u60, 8u77, 8u91

I have >200 slaves and started seeing some of my "controller" slaves not wanting to start their jenkins slaves, especially when the slave has been reinstalled (as a refresh)
the sample below is from a fresh slave, on 8u91. try to start the windows service hosting the slave and it stops immediately with the following log trace.

May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main createEngine
INFO: Setting up slave: ComputerA
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener <init>
INFO: Jenkins agent is running in headless mode.
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Locating server among http://10.20.1.181:8080/jenkins/, http://jenkins:8080/jenkins/
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Handshaking
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Connecting to 10.20.1.181:55945
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Trying protocol: JNLP2-connect
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Server didn't understand the protocol: ComputerA is already connected to this master. Rejecting this connection.
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Connecting to 10.20.1.181:55945
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Trying protocol: JNLP-connect
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Server didn't understand the protocol: ComputerA is already connected to this master. Rejecting this connection.
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Connecting to 10.20.1.181:55945
May 17, 2016 5:45:58 PM hudson.remoting.jnlp.Main$CuiListener error
SEVERE: The server rejected the connection: None of the protocols were accepted
java.lang.Exception: The server rejected the connection: None of the protocols were accepted
at hudson.remoting.Engine.onConnectionRejected(Engine.java:297)
at hudson.remoting.Engine.run(Engine.java:268)

i've set the slave to "disconnected" on the master and then restart the service. sometimes it might then stay up, but not for long!!

o.v.nenashev@gmail.com (JIRA)

unread,
Oct 25, 2016, 3:36:01 AM10/25/16
to jenkinsc...@googlegroups.com
Oleg Nenashev assigned an issue to Oleg Nenashev
 
Change By: Oleg Nenashev
Assignee: Oleg Nenashev
This message was sent by Atlassian JIRA (v7.1.7#71011-sha1:2526d7c)
Atlassian logo

o.v.nenashev@gmail.com (JIRA)

unread,
Oct 25, 2016, 3:41:03 AM10/25/16
to jenkinsc...@googlegroups.com
Oleg Nenashev edited a comment on Bug JENKINS-28492
 
Re: The server rejected the connection: *** is already connected to this master. Rejecting this connection.
Added to my analysis queue (no time commitment).
Issue with runaway slaves processes in Windows services should be fixed by JENKINS-39231

o.v.nenashev@gmail.com (JIRA)

unread,
Oct 25, 2016, 3:41:03 AM10/25/16
to jenkinsc...@googlegroups.com

Added to my analysis queue (no time commitment).

Issue with runaway slaves should be fixed by JENKINS-39231

mmitche@microsoft.com (JIRA)

unread,
Nov 15, 2016, 9:41:02 PM11/15/16
to jenkinsc...@googlegroups.com

So I think the "already connected" may be caused by a cycle in the closing logic. Though I don't know why the error keeps propping up. It looks like the channel pinger could cause a channel close to happen. Under the jnlp remoting, we set up a channel with an onClose listener, which itself tries to close the channel under certain circumstances. These listeners are run in the channel termination finally logic, so it's possible that we could try to close while we are already under the close operations.

mmitche@microsoft.com (JIRA)

unread,
Nov 15, 2016, 9:41:03 PM11/15/16
to jenkinsc...@googlegroups.com

hudson.remoting.ChannelClosedException: channel is already closed
at hudson.remoting.Channel.send(Channel.java:578)
at hudson.remoting.Request.callAsync(Request.java:205)
at hudson.remoting.Channel.callAsync(Channel.java:807)
at hudson.node_monitors.AbstractAsyncNodeMonitorDescriptor.monitor(AbstractAsyncNodeMonitorDescriptor.java:75)
at hudson.node_monitors.AbstractNodeMonitorDescriptor$Record.run(AbstractNodeMonitorDescriptor.java:305)
Caused by: java.io.IOException
at hudson.remoting.Channel.close(Channel.java:1163)
at hudson.slaves.ChannelPinger$1.onDead(ChannelPinger.java:123)
at hudson.remoting.PingThread.ping(PingThread.java:126)
at hudson.remoting.PingThread.run(PingThread.java:85)
Caused by: java.util.concurrent.TimeoutException: Ping started at 1479165919577 hasn't completed by 1479166819577
... 2 more

mmitche@microsoft.com (JIRA)

unread,
Nov 21, 2016, 1:22:02 PM11/21/16
to jenkinsc...@googlegroups.com

Some more info.

While I think the "already connected to this master" is a real bug, I think the way that it's triggered might be considered expected. I see this when the number of threads in the system suddenly spikes. This seems to cause some cascading failures (maybe "Unable to allocate new native thread")? In our instance, this might be caused by the Build Failure Analyzer, which can use a lot of threads.

I do know some other things:

1) Raising the java heap size reduces the amount of memory for native threads and potentially seems to reduce the time to repro.
2) Allocating a ton of new threads very fast seems to cause this.

o.v.nenashev@gmail.com (JIRA)

unread,
Nov 28, 2016, 3:43:02 AM11/28/16
to jenkinsc...@googlegroups.com

For runaway processes in WinSW there is an open pull-request: https://github.com/kohsuke/winsw/pull/133
But I agree with Matthew Mitchell that it's is not the only cause.

We also have some cases with channel hanging due to deadlocks, which have been likely fixed by https://github.com/jenkinsci/remoting/pull/100

mmitche@microsoft.com (JIRA)

unread,
Nov 30, 2016, 3:33:03 PM11/30/16
to jenkinsc...@googlegroups.com

I added a bunch more logging to the system to see why the channel would not get cleared out. I've got another couple pieces of info:

  • For me, there seems to be some relation to Job DSL execution. Not exactly sure why.
  • There's definitely something memory related, as we see a big jump in memory usage when this happens, and there are for sure some allocation failures. However, the overall heap usage is actually really low (compared to avialable size), so it might be the GC telling us unable to allocate.
  • When the error happens, I see the following sequence. 1. Timeout failures monitoring for clock difference, disk space, etc. on the node. 2. Ping failure on the node. 3. already connected to this master.

Now, some other things to note. I added logging to the listeners on the channel set up that would close the channel and null out the reference on the Computer object (onClosed). However, for the affected nodes, the onClosed methods are never executed, so the listeners never get run.

Why that is, is the big mystery.

mmitche@microsoft.com (JIRA)

unread,
Nov 30, 2016, 5:08:03 PM11/30/16
to jenkinsc...@googlegroups.com

Also, this Issue looks extremely close to what I am seeing. Perhaps there is a lock on the channel object?

https://issues.jenkins-ci.org/browse/JENKINS-5413

mmitche@microsoft.com (JIRA)

unread,
Nov 30, 2016, 6:29:01 PM11/30/16
to jenkinsc...@googlegroups.com

FYI when this problem occurs the number of threads starts to climb from steady state at ~800-1500 up to 11k. Most of the extra threads look like they are doing nothing (just a single frame on a thread named Thread-NNNNNN).

mariem.baccar@sifast.com (JIRA)

unread,
Dec 5, 2016, 4:46:02 AM12/5/16
to jenkinsc...@googlegroups.com
mariem baccar updated an issue
 
Change By: mariem baccar
Attachment: Slave errors

mariem.baccar@sifast.com (JIRA)

unread,
Dec 5, 2016, 4:52:02 AM12/5/16
to jenkinsc...@googlegroups.com
mariem baccar commented on Bug JENKINS-28492
 
Re: The server rejected the connection: *** is already connected to this master. Rejecting this connection.

You find below some explications for my case which can help you:
-Before installing the plugin "Docker Slave v1.0.5", the slave operates correctly without any problems.
-After installing this plugin, I encountered many problems. One of them is about slave: I always get this message "slave agent is already connected". For more details, you find attached the whole message.
In fact, the problem is related to JENKINS-39078: There is a problem in Docker Slave Plugin 1.0.5 (Fix: https://github.com/jenkinsci/docker-slaves-plugin/commit/451929125fd8ff39c6f84c30476c26cccb912140)
After discovering that this plugin recently installed is the source of all my new problems in Jenkins 2.19.1 LTS, I uninstall it and all my problems are resolved.

mmitche@microsoft.com (JIRA)

unread,
Dec 5, 2016, 1:35:02 PM12/5/16
to jenkinsc...@googlegroups.com

Do you use Job DSL too? I think there might be something there that is related too.

Based on the data seen, I think this may be a deadlock.

o.v.nenashev@gmail.com (JIRA)

unread,
Dec 5, 2016, 1:43:02 PM12/5/16
to jenkinsc...@googlegroups.com

Another known case when the issue happens - JENKINS-30823

o.v.nenashev@gmail.com (JIRA)

unread,
Dec 5, 2016, 1:43:03 PM12/5/16
to jenkinsc...@googlegroups.com
Oleg Nenashev edited a comment on Bug JENKINS-28492
Another *known* case when the issue happens - OutOfMemory exception - JENKINS-30823

mmitche@microsoft.com (JIRA)

unread,
Dec 5, 2016, 1:51:02 PM12/5/16
to jenkinsc...@googlegroups.com

Yep, that correlates with what I've seen too. What is odd about this is that the actual usage doesn't appear that large. A heap dump before the failure doesn't show a heap that is anywhere close to full (3GB usage of 32GB). But I do see lots of "unable to allocate new native thread", etc and the number of threads grows very large from the steady state.

Could this be related to a deadlock of some sort where we start to spawn threads till we die?

o.v.nenashev@gmail.com (JIRA)

unread,
Dec 5, 2016, 2:19:01 PM12/5/16
to jenkinsc...@googlegroups.com

Maybe. I think we firstly need to implement correct handling of Errors and RuntimeExceptions in the core in order to avoid the case when the channel object leaks after the failure. It should help with some cases

mmitche@microsoft.com (JIRA)

unread,
Dec 5, 2016, 2:26:04 PM12/5/16
to jenkinsc...@googlegroups.com

Right, for sure. I think there are a few cases:

1) Cases where plugins/core usae computer.getChannel(). These work fine since if the listeners run properly, the channel is set to null and the code can do the right thing at that point depending on what its function is.
2) Cases where the channel object is held on an object (Ping thread, etc.) but there is error handling. These appear okay (ping thread exits).
3) Cases where the channel object is held on an object but no error handling - These need fixing.

I don't know of any real cases of #3. #2 appears okay. #1 is a problem because the listeners which should null out the channel on the computer object don't actually run. That is why we see the "already connected" issue.

mmitche@microsoft.com (JIRA)

unread,
Dec 6, 2016, 1:32:03 PM12/6/16
to jenkinsc...@googlegroups.com

This also appears to perhaps happen "near" a failure

https://issues.jenkins-ci.org/browse/JENKINS-33358

o.v.nenashev@gmail.com (JIRA)

unread,
Dec 25, 2016, 6:34:01 PM12/25/16
to jenkinsc...@googlegroups.com

Some bits have been addressed in JENKINS-39835
Reply all
Reply to author
Forward
0 new messages