Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-54187

EC2 Plugin deadlock leaving Jenkins unresponsive

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Critical
    • Resolution: Unresolved
    • Component/s: ec2-plugin
    • Labels:
      None
    • Environment:
    • Similar Issues:

      Description

      We recently upgraded our Jenkins instance to the latest LTS (2.138.2) and started noticing some irregularities with the EC2 plugin, namely:

      • A lot more build nodes were created than before, for the same amount of incoming items in the build queue
      • This caused an increased amount of AWS API calls, namely StopInstances event. Possibly related to the previous point.

      This led us to try out the latest snapshot, 1.41-SNAPSHOT build on revision d4bdd6b83a7102330fd97ffbbd067edc34e47f97. A few hours later, our Jenkins instance had a deadlock problem that is described in the log I'm attaching.

      Notice how the Gerrit plugin stops processing events after the EC2 plugin deadlock, this ultimately left our Jenkins unresponsive.

      One important bit of information might be that we're using the Stop/Disconnect on Idle Timeout plugin option.

      We're happy to provide more information if needed.

        Attachments

        1. all-jenkins.log
          26 kB
        2. jenkins.log
          10 kB
        3. jenkins.txt
          6 kB

          Issue Links

            Activity

            Hide
            jsquyres Jeff Squyres added a comment -

            +1 – we are hitting this issue, too. We had to disable all of the EC2 testing in the Open MPI project (github.com/open-mpi/ompi), which has unfortunately killed a good portion of our CI testing.

            Show
            jsquyres Jeff Squyres added a comment - +1 – we are hitting this issue, too. We had to disable all of the EC2 testing in the Open MPI project (github.com/open-mpi/ompi), which has unfortunately killed a good portion of our CI testing.
            Hide
            callum_p Callum Pember added a comment - - edited

            +1. This has been an ongoing issue for us for over a month. Attached a log from today.

            Once this happens, Jenkins becomes unresponsive to most actions.

            jenkins.txt

             

            Dec 12, 2018 11:08:04 PM INFO hudson.plugins.ec2.EC2Cloud provision
            SlaveTemplate{ami='ami-xx', labels='lapis-prod'}. Attempting to provision slave needed by excess workload of 1 units
            Dec 12, 2018 11:08:04 PM INFO hudson.plugins.ec2.SlaveTemplate logProvisionInfo
            SlaveTemplate{ami='ami-xx', labels='lapis-prod'}. Considering launching
            Dec 12, 2018 11:08:05 PM INFO hudson.plugins.ec2.SlaveTemplate logProvisionInfo
            SlaveTemplate{ami='ami-xx', labels='lapis-prod'}. Setting Instance Initiated Shutdown Behavior : ShutdownBehavior.Terminate
            Dec 12, 2018 11:08:05 PM INFO hudson.plugins.ec2.SlaveTemplate logProvisionInfo
            SlaveTemplate{ami='ami-xxx', labels='lapis-prod'}. Looking for existing instances with describe-instance: {Filters: [{Name: image-id,Values: [ami-xxx]}, {Name: instance-type,Values: [m3.2xlarge]}, {Name: key-name,Values: [jenkins-slave]}, {Name: availability-zone,Values: [ap-southeast-2b]}, {Name: subnet-id,Values: [subnet-xx]}, {Name: instance.group-id,Values: [sg-xx]}, {Name: tag:jenkins_server_url,Values: [https://jenkins.xx.xx.xx/]}, {Name: tag:Name,Values: [jenkins-lapis-worker]}, {Name: tag:jenkins_slave_type,Values: [demand_lapis-prod]}],InstanceIds: [],}
            Dec 12, 2018 11:08:33 PM WARNING jenkins.metrics.api.Metrics$HealthChecker execute
            Some health checks are reporting as unhealthy: [thread-deadlock : [jenkins.util.Timer [#3] locked on hudson.plugins.ec2.AmazonEC2Cloud@76b6b03d (owned by jenkins.util.Timer [#4]):
            	 at hudson.plugins.ec2.EC2Cloud.connect(EC2Cloud.java:748)
            	 at hudson.plugins.ec2.CloudHelper.getInstance(CloudHelper.java:47)
            	 at hudson.plugins.ec2.CloudHelper.getInstanceWithRetry(CloudHelper.java:25)
            	 at hudson.plugins.ec2.EC2Computer.getState(EC2Computer.java:127)
            	 at hudson.plugins.ec2.EC2RetentionStrategy.internalCheck(EC2RetentionStrategy.java:112)
            	 at hudson.plugins.ec2.EC2RetentionStrategy.check(EC2RetentionStrategy.java:90)
            	 at hudson.plugins.ec2.EC2RetentionStrategy.check(EC2RetentionStrategy.java:48)
            	 at hudson.slaves.ComputerRetentionWork$1.run(ComputerRetentionWork.java:72)
            	 at hudson.model.Queue._withLock(Queue.java:1381)
            	 at hudson.model.Queue.withLock(Queue.java:1258)
            	 at hudson.slaves.ComputerRetentionWork.doRun(ComputerRetentionWork.java:63)
            	 at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:72)
            	 at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58)
            	 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
            	 at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
            	 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
            	 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
            	 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)
            , jenkins.util.Timer [#4] locked on java.util.concurrent.locks.ReentrantLock$NonfairSync@486c87f (owned by jenkins.util.Timer [#3]):
            	 at sun.misc.Unsafe.park(Native Method)
            	 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
            	 at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
            	 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
            	 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
            	 at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
            	 at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
            	 at hudson.model.Queue._withLock(Queue.java:1438)
            	 at hudson.model.Queue.withLock(Queue.java:1301)
            	 at jenkins.model.Nodes.updateNode(Nodes.java:193)
            	 at jenkins.model.Jenkins.updateNode(Jenkins.java:2097)
            	 at hudson.model.Node.save(Node.java:140)
            	 at hudson.util.PersistedList.onModified(PersistedList.java:173)
            	 at hudson.util.PersistedList.replaceBy(PersistedList.java:85)
            	 at hudson.model.Slave.<init>(Slave.java:199)
            	 at hudson.plugins.ec2.EC2AbstractSlave.<init>(EC2AbstractSlave.java:138)
            	 at hudson.plugins.ec2.EC2OndemandSlave.<init>(EC2OndemandSlave.java:49)
            	 at hudson.plugins.ec2.EC2OndemandSlave.<init>(EC2OndemandSlave.java:42)
            	 at hudson.plugins.ec2.SlaveTemplate.newOndemandSlave(SlaveTemplate.java:963)
            	 at hudson.plugins.ec2.SlaveTemplate.toSlaves(SlaveTemplate.java:660)
            	 at hudson.plugins.ec2.SlaveTemplate.provisionOndemand(SlaveTemplate.java:632)
            	 at hudson.plugins.ec2.SlaveTemplate.provision(SlaveTemplate.java:463)
            	 at hudson.plugins.ec2.EC2Cloud.getNewOrExistingAvailableSlave(EC2Cloud.java:587)
            	 at hudson.plugins.ec2.EC2Cloud.provision(EC2Cloud.java:602)
            	 at hudson.slaves.NodeProvisioner$StandardStrategyImpl.apply(NodeProvisioner.java:715)
            	 at hudson.slaves.NodeProvisioner.update(NodeProvisioner.java:320)
            	 at hudson.slaves.NodeProvisioner.access$000(NodeProvisioner.java:61)
            	 at hudson.slaves.NodeProvisioner$NodeProvisionerInvoker.doRun(NodeProvisioner.java:809)
            	 at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:72)
            	 at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58)
            	 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
            	 at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
            	 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
            	 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
            	 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)
            ]]
            
            
            Show
            callum_p Callum Pember added a comment - - edited +1. This has been an ongoing issue for us for over a month. Attached a log from today. Once this happens, Jenkins becomes unresponsive to most actions. jenkins.txt   Dec 12, 2018 11:08:04 PM INFO hudson.plugins.ec2.EC2Cloud provision SlaveTemplate{ami= 'ami-xx' , labels= 'lapis-prod' }. Attempting to provision slave needed by excess workload of 1 units Dec 12, 2018 11:08:04 PM INFO hudson.plugins.ec2.SlaveTemplate logProvisionInfo SlaveTemplate{ami= 'ami-xx' , labels= 'lapis-prod' }. Considering launching Dec 12, 2018 11:08:05 PM INFO hudson.plugins.ec2.SlaveTemplate logProvisionInfo SlaveTemplate{ami= 'ami-xx' , labels= 'lapis-prod' }. Setting Instance Initiated Shutdown Behavior : ShutdownBehavior.Terminate Dec 12, 2018 11:08:05 PM INFO hudson.plugins.ec2.SlaveTemplate logProvisionInfo SlaveTemplate{ami= 'ami-xxx' , labels= 'lapis-prod' }. Looking for existing instances with describe-instance: {Filters: [{Name: image-id,Values: [ami-xxx]}, {Name: instance-type,Values: [m3.2xlarge]}, {Name: key-name,Values: [jenkins-slave]}, {Name: availability-zone,Values: [ap-southeast-2b]}, {Name: subnet-id,Values: [subnet-xx]}, {Name: instance.group-id,Values: [sg-xx]}, {Name: tag:jenkins_server_url,Values: [https: //jenkins.xx.xx.xx/]}, {Name: tag:Name,Values: [jenkins-lapis-worker]}, {Name: tag:jenkins_slave_type,Values: [demand_lapis-prod]}],InstanceIds: [],} Dec 12, 2018 11:08:33 PM WARNING jenkins.metrics.api.Metrics$HealthChecker execute Some health checks are reporting as unhealthy: [thread-deadlock : [jenkins.util.Timer [#3] locked on hudson.plugins.ec2.AmazonEC2Cloud@76b6b03d (owned by jenkins.util.Timer [#4]): at hudson.plugins.ec2.EC2Cloud.connect(EC2Cloud.java:748) at hudson.plugins.ec2.CloudHelper.getInstance(CloudHelper.java:47) at hudson.plugins.ec2.CloudHelper.getInstanceWithRetry(CloudHelper.java:25) at hudson.plugins.ec2.EC2Computer.getState(EC2Computer.java:127) at hudson.plugins.ec2.EC2RetentionStrategy.internalCheck(EC2RetentionStrategy.java:112) at hudson.plugins.ec2.EC2RetentionStrategy.check(EC2RetentionStrategy.java:90) at hudson.plugins.ec2.EC2RetentionStrategy.check(EC2RetentionStrategy.java:48) at hudson.slaves.ComputerRetentionWork$1.run(ComputerRetentionWork.java:72) at hudson.model.Queue._withLock(Queue.java:1381) at hudson.model.Queue.withLock(Queue.java:1258) at hudson.slaves.ComputerRetentionWork.doRun(ComputerRetentionWork.java:63) at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:72) at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) 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) , jenkins.util.Timer [#4] locked on java.util.concurrent.locks.ReentrantLock$NonfairSync@486c87f (owned by jenkins.util.Timer [#3]): at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) at hudson.model.Queue._withLock(Queue.java:1438) at hudson.model.Queue.withLock(Queue.java:1301) at jenkins.model.Nodes.updateNode(Nodes.java:193) at jenkins.model.Jenkins.updateNode(Jenkins.java:2097) at hudson.model.Node.save(Node.java:140) at hudson.util.PersistedList.onModified(PersistedList.java:173) at hudson.util.PersistedList.replaceBy(PersistedList.java:85) at hudson.model.Slave.<init>(Slave.java:199) at hudson.plugins.ec2.EC2AbstractSlave.<init>(EC2AbstractSlave.java:138) at hudson.plugins.ec2.EC2OndemandSlave.<init>(EC2OndemandSlave.java:49) at hudson.plugins.ec2.EC2OndemandSlave.<init>(EC2OndemandSlave.java:42) at hudson.plugins.ec2.SlaveTemplate.newOndemandSlave(SlaveTemplate.java:963) at hudson.plugins.ec2.SlaveTemplate.toSlaves(SlaveTemplate.java:660) at hudson.plugins.ec2.SlaveTemplate.provisionOndemand(SlaveTemplate.java:632) at hudson.plugins.ec2.SlaveTemplate.provision(SlaveTemplate.java:463) at hudson.plugins.ec2.EC2Cloud.getNewOrExistingAvailableSlave(EC2Cloud.java:587) at hudson.plugins.ec2.EC2Cloud.provision(EC2Cloud.java:602) at hudson.slaves.NodeProvisioner$StandardStrategyImpl.apply(NodeProvisioner.java:715) at hudson.slaves.NodeProvisioner.update(NodeProvisioner.java:320) at hudson.slaves.NodeProvisioner.access$000(NodeProvisioner.java:61) at hudson.slaves.NodeProvisioner$NodeProvisionerInvoker.doRun(NodeProvisioner.java:809) at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:72) at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) 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) ]]
            Hide
            sverhoef Stefan Verhoeff added a comment -

            Same issue again after accidentally upgrading to ec2-1.41 and Jenkins LTS 2.150.1.

             

            Looks like this bug is a duplicate, linking: JENKINS-53858

             

            Fix for JENKINS-53858 has been announced for 1.42 on the wiki: https://wiki.jenkins.io/display/JENKINS/Amazon+EC2+Plugin#AmazonEC2Plugin-Version1.42(NotReleaseyet,2018)

            Show
            sverhoef Stefan Verhoeff added a comment - Same issue again after accidentally upgrading to ec2-1.41 and Jenkins LTS 2.150.1.   Looks like this bug is a duplicate, linking: JENKINS-53858   Fix for JENKINS-53858 has been announced for 1.42 on the wiki:  https://wiki.jenkins.io/display/JENKINS/Amazon+EC2+Plugin#AmazonEC2Plugin-Version1.42(NotReleaseyet,2018)
            Hide
            eric_knecht Eric Knecht added a comment -

            We have encountered this issue as well. An ETA on the 1.42 release would be highly appreciated.

            Show
            eric_knecht Eric Knecht added a comment - We have encountered this issue as well. An ETA on the 1.42 release would be highly appreciated.
            Hide
            mikepoulson Mike Poulson added a comment -

            I have confirmed the RC version of 1.42 fixed things. I couldn’t wait.

            Show
            mikepoulson Mike Poulson added a comment - I have confirmed the RC version of 1.42 fixed things. I couldn’t wait.

              People

              • Assignee:
                thoulen FABRIZIO MANFREDI
                Reporter:
                ruenzuo Renzo Crisóstomo
              • Votes:
                6 Vote for this issue
                Watchers:
                18 Start watching this issue

                Dates

                • Created:
                  Updated: