Plugin doesn't always clean up old nodes in Jenkins, even though the containers are stopped in ECS about amazon-ecs-plugin

[memotype]

Just had it happen again. Here is the docker logs from the container:

[ec2-user@ip-10-0-0-223 ~]$ docker logs 77de4b6c40f3
Warning: JnlpProtocol3 is disabled by default, use JNLP_PROTOCOL_OPTS to alter the behavior
Apr 10, 2019 6:17:43 PM hudson.remoting.jnlp.Main createEngine
INFO: Setting up agent: Jenkins-ECS-269292534c4dc
Apr 10, 2019 6:17:43 PM hudson.remoting.jnlp.Main$CuiListener <init>
INFO: Jenkins agent is running in headless mode.
Apr 10, 2019 6:17:43 PM hudson.remoting.Engine startEngine
INFO: Using Remoting version: 3.28
Apr 10, 2019 6:17:43 PM hudson.remoting.Engine startEngine
WARNING: No Working Directory. Using the legacy JAR Cache location: /home/jenkins/.jenkins/cache/jars
Apr 10, 2019 6:17:43 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Locating server among [http://10.0.0.65:8080]
Apr 10, 2019 6:17:44 PM org.jenkinsci.remoting.engine.JnlpAgentEndpointResolver resolve
INFO: Remoting server accepts the following protocols: [JNLP4-connect, Ping]
Apr 10, 2019 6:17:44 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Agent discovery successful
  Agent address: 10.0.0.65
  Agent port:    50000
  Identity:      8b:02:d4:e9:3b:26:d0:74:15:08:f6:8c:04:35:89:8d
Apr 10, 2019 6:17:44 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Handshaking
Apr 10, 2019 6:17:44 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Connecting to 10.0.0.65:50000
Apr 10, 2019 6:17:44 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Trying protocol: JNLP4-connect
Apr 10, 2019 6:17:44 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Remote identity confirmed: 8b:02:d4:e9:3b:26:d0:74:15:08:f6:8c:04:35:89:8d
Apr 10, 2019 6:17:46 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Connected
Apr 10, 2019 6:17:49 PM hudson.remoting.jnlp.Main$CuiListener status
INFO: Terminated
Apr 10, 2019 6:17:49 PM hudson.remoting.UserRequest perform
WARNING: LinkageError while performing UserRequest:jenkins.slaves.restarter.JnlpSlaveRestarterInstaller$FindEffectiveRestarters@7992d17a
java.lang.NoClassDefFoundError: jenkins/slaves/restarter/JnlpSlaveRestarterInstaller$FindEffectiveRestarters$1
        at jenkins.slaves.restarter.JnlpSlaveRestarterInstaller$FindEffectiveRestarters.call(JnlpSlaveRestarterInstaller.java:87)
        at jenkins.slaves.restarter.JnlpSlaveRestarterInstaller$FindEffectiveRestarters.call(JnlpSlaveRestarterInstaller.java:68)
        at hudson.remoting.UserRequest.perform(UserRequest.java:212)
        at hudson.remoting.UserRequest.perform(UserRequest.java:54)
        at hudson.remoting.Request$2.run(Request.java:369)
        at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:72)
        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 hudson.remoting.Engine$1.lambda$newThread$0(Engine.java:93)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.ClassNotFoundException: jenkins.slaves.restarter.JnlpSlaveRestarterInstaller$FindEffectiveRestarters$1
        at java.net.URLClassLoader.findClass(URLClassLoader.java:382)
        at hudson.remoting.RemoteClassLoader.findClass(RemoteClassLoader.java:171)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        ... 11 more

Apr 10, 2019 6:17:49 PM hudson.remoting.UserRequest perform
WARNING: LinkageError while performing UserRequest:hudson.Launcher$RemoteLauncher$KillTask@63ec4965
java.lang.NoClassDefFoundError: javax/servlet/ServletException
        at hudson.util.ProcessTree.get(ProcessTree.java:413)
        at hudson.Launcher$RemoteLauncher$KillTask.call(Launcher.java:1097)
        at hudson.Launcher$RemoteLauncher$KillTask.call(Launcher.java:1088)
        at hudson.remoting.UserRequest.perform(UserRequest.java:212)
        at hudson.remoting.UserRequest.perform(UserRequest.java:54)
        at hudson.remoting.Request$2.run(Request.java:369)
        at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:72)
        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 hudson.remoting.Engine$1.lambda$newThread$0(Engine.java:93)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.ClassNotFoundException: javax.servlet.ServletException
        at java.net.URLClassLoader.findClass(URLClassLoader.java:382)
        at hudson.remoting.RemoteClassLoader.findClass(RemoteClassLoader.java:171)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        ... 12 more

Apr 10, 2019 6:17:49 PM hudson.remoting.Request$2 run
INFO: Failed to send back a reply to the request hudson.remoting.Request$2@47dbb2fe: hudson.remoting.ChannelClosedException: Channel "hudson.remoting.Channel@29730f69:JNLP4-connect connection to ip-10-0-0-65.ec2.internal/10.0.0.65:50000": channel is already closed
Apr 10, 2019 6:17:49 PM hudson.remoting.Request$2 run
INFO: Failed to send back a reply to the request hudson.remoting.Request$2@b10aaec: hudson.remoting.ChannelClosedException: Channel "hudson.remoting.Channel@29730f69:JNLP4-connect connection to ip-10-0-0-65.ec2.internal/10.0.0.65:50000": channel is already closed

[memotype]

I noticed that on builds that time out waiting for an executor, the task definition is updated with the new image from the template, but the container that's actually launched on the ECS instance is a different image. It's almost as if there is a race condition between updating the task definition in AWS and launching it, where the wrong revision is launched?

[memotype]

Digging through the code a bit, I noticed that after a task is done it's supposed to delete the task definition from ECS (ECSTaskTemplateCallback.finished calls ecsCloud.removeDynamicTemplate, so I assume that's what it means), but in our case the task definition is never deleted from ECS, it just creates new revisions of the task definition every time. I thought this was odd behavior, but now I'm suspecting that it's also unintended behavior. That would explain the race condition where the plugin is trying to create a task definition, but ECS is just creating a new revision, but if there's a slight delay in that, when the plugin kicks off the task definition before ECS has updated it, it'll end up kicking off the old revision with the wrong image and parameters.

[pgarbe]

Hi @memotype, do you use the declarative syntax of the current beta? Which version of the ECS plugin are you using?

[memotype]

We switched to using the kubernetes plugin with EKS and have had much better results. We were using the current plugin from the list in the "manage plugins" page of the UI. And I don't think this had to do with pipelines or declarative syntax. We were seeing this issue with freestyle projects as well. Unfortunately, I can't help much with this issue any more because we're no longer using this plugin.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[rismoney]

Is there any update on this? I am having an issue where Jenkins is not disposing of used agents.

[avadhmr]

Yeah, we have faced the same issue many times and forces us to manually log into instances and clean up dead containers

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[lkolchin]

It's still happening even with the newest version of jenkins/inbound-agent and jenkins master on fargate.
The plugin spins up 2 agents instead of 1 and keeps the other hanging around.

Look at the agent logs to try and figure it out maybe (2 parts of the same log) -
log1.1
log1.2

Instead of 1 agent - plugin is provisioning 2:

Asked to provision 1 agent(s) for: builderagent
Aug 23, 2020 12:55:03 PM INFO com.cloudbees.jenkins.plugins.amazonecs.ECSCloud provision
Will provision ecs-jenkins-dev-cluster-cloud-builderagent-slbd7, for label: builderagent
Aug 23, 2020 12:55:13 PM WARNING org.jenkinsci.remoting.util.AnonymousClassWarnings warn
Attempt to (de-)serialize synthetic class com.cloudbees.jenkins.plugins.amazonecs.ECSService$$Lambda$395/1179679233 in file:/var/jenkins_home/plugins/amazon-ecs/WEB-INF/lib/amazon-ecs.jar; see: https://jenkins.io/redirect/serialization-of-anonymous-classes/
Aug 23, 2020 12:55:13 PM INFO com.cloudbees.jenkins.plugins.amazonecs.ECSService registerTemplate
Match on container definition: false
Aug 23, 2020 12:55:13 PM INFO com.cloudbees.jenkins.plugins.amazonecs.ECSService registerTemplate
Match on volumes: true
Aug 23, 2020 12:55:13 PM INFO com.cloudbees.jenkins.plugins.amazonecs.ECSService registerTemplate
Match on task role: true
Aug 23, 2020 12:55:13 PM INFO com.cloudbees.jenkins.plugins.amazonecs.ECSService registerTemplate
Match on execution role: true
Aug 23, 2020 12:55:13 PM INFO com.cloudbees.jenkins.plugins.amazonecs.ECSService registerTemplate
Match on network mode: true
Aug 23, 2020 12:55:13 PM INFO hudson.slaves.NodeProvisioner lambda$update$6
ecs-jenkins-dev-cluster-cloud-builderagent-slbd7 provisioning successfully completed. We have now 2 computer(s)