[CLOUDSTACK-2141] During HA process , dead lock is detected - Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction"

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Cannot Reproduce
• Affects Version/s: 4.2.0
• Fix Version/s: 4.3.0
• Component/s: Management Server
• Security Level: Public (Anyone can view this level - this is the default.)
• Environment: build from master
• Assignee: Koushik Das
• Reporter: Sangeetha Hariharan
• Created: 23/Apr/13 00:04
• Updated: 04/Jan/14 00:11
• Resolved: 11/Dec/13 05:44

Description

During HA process , dead lock is detected - Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction"

Following are the steps that was followed:

Set up - Advanced zone with 3 hosts in a cluster.

One of the host is already shutdown.
Shutdown another Host that has Vms that is ha enabled ( vm in my case "anan-ha1")

As part of performing HA on this Vm , I see couple of exceptions being thrown:

2013-04-22 14:59:05,738 ERROR [cloud.vm.VirtualMachineManagerImpl] (HA-Worker-0:work-52) Failed to start instance VM[User|anan-ha1]
com.cloud.exception.ConcurrentOperationException: Work steps have been changed: ItWork[69587fc9-2bd1-4183-b89c-216ecdf3be5a-Starting-54-Done]
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:770)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:592)
at com.cloud.ha.HighAvailabilityManagerImpl.restart(HighAvailabilityManagerImpl.java:533)
at com.cloud.ha.HighAvailabilityManagerImpl$WorkerThread.run(HighAvailabilityManagerImpl.java:831)
2013-04-22 14:59:05,743 DEBUG [cloud.vm.VirtualMachineManagerImpl] (HA-Worker-0:work-52) Cleaning up resources for the vm VM[User|anan-ha1] in Starting state

........................

2013-04-22 15:00:15,615 WARN [agent.manager.DirectAgentAttache] (DirectAgent-317:null) Seq 8-1217527861: Exception Caught while executing command
com.cloud.utils.exception.CloudRuntimeException: Unable to reset master of slave 10.223.59.3 to 10.223.59.2 due to com.cloud.utils.exception.CloudRuntimeException: Unable to reset master of slave 10.223.59.3 to 10.223.59.2after 30 retry
at com.cloud.hypervisor.xen.resource.XenServerConnectionPool.PoolEmergencyResetMaster(XenServerConnectionPool.java:443)
at com.cloud.hypervisor.xen.resource.XenServerConnectionPool.connect(XenServerConnectionPool.java:661)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getConnection(CitrixResourceBase.java:5583)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2286)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:518)
at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-04-22 15:00:15,616 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-317:null) Seq 8-1217527861: Response Received:
2013-04-22 15:00:15,616 DEBUG [agent.transport.Request] (DirectAgent-317:null) Seq 8-1217527861: Processing: { Ans: , MgmtId: 7508777239729, via: 8, Ver: v1, Flags: 10, [{"Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: Unable to reset master of slave 10.223.59.3 to 10.223.59.2 due to com.cloud.utils.exception.CloudRuntimeException: Unable to reset master of slave 10.223.59.3 to 10.223.59.2after 30 retry","wait":0}}] }
2013-04-22 15:00:15,616 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 8-1217527861: Received: { Ans: , MgmtId: 7508777239729, via: 8, Ver: v1, Flags: 10,

{ Answer }

}
2013-04-22 15:00:15,616 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Details from executing class com.cloud.agent.api.GetVncPortCommand: com.cloud.utils.exception.CloudRuntimeException: Unable to reset master of slave 10.223.59.3 to 10.223.59.2 due to com.cloud.utils.exception.CloudRuntimeException: Unable to reset master of slave 10.223.59.3 to 10.223.59.2after 30 retry
2013-04-22 15:00:15,617 WARN [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Caught:
java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.GetVncPortAnswer
at com.cloud.consoleproxy.AgentHookBase.onConsoleAccessAuthentication(AgentHookBase.java:169)
at com.cloud.consoleproxy.ConsoleProxyListener.processControlCommand(ConsoleProxyListener.java:61)
at com.cloud.agent.manager.AgentManagerImpl.handleControlCommand(AgentManagerImpl.java:348)
at com.cloud.agent.manager.AgentManagerImpl.access$200(AgentManagerImpl.java:145)
at com.cloud.agent.manager.AgentManagerImpl$AgentHandler.processRequest(AgentManagerImpl.java:1286)
at com.cloud.agent.manager.AgentManagerImpl$AgentHandler.doTask(AgentManagerImpl.java:1374)
at com.cloud.agent.manager.ClusteredAgentManagerImpl$ClusteredAgentHandler.doTask(ClusteredAgentManagerImpl.java:659)
at com.cloud.utils.nio.Task.run(Task.java:83)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)

HA on this Vm did succeed eventually.

Attaching management server logs .