I've been randomly hitting this with my master testing, and I'm unsure if it's something strange in my test environment, or if somebody has been working on the async job handler and there's some sort of race condition. I saw it first when trying to destroy a vm, then during a test run with volume detach.
2014-02-10 02:29:10,865 WARN [jobs.impl.AsyncJobManagerImpl] (Job-Executor-92:Job-159 ctx-7198b697) Unable to schedule async job for command com.cloud.storage.VmWorkDetachVolume, unexpected exception. javax.persistence.EntityExistsException: Entity already exists: at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1398) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$1.doInTransaction(AsyncJobManagerImpl.java:193) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$1.doInTransaction(AsyncJobManagerImpl.java:189) at com.cloud.utils.db.Transaction$2.doInTransaction(Transaction.java:49) at com.cloud.utils.db.Transaction.execute(Transaction.java:37) at com.cloud.utils.db.Transaction.execute(Transaction.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:189) at com.cloud.storage.VolumeApiServiceImpl$4.doInTransaction(VolumeApiServiceImpl.java:2215) at com.cloud.storage.VolumeApiServiceImpl$4.doInTransaction(VolumeApiServiceImpl.java:2191) at com.cloud.utils.db.Transaction$2.doInTransaction(Transaction.java:49) at com.cloud.utils.db.Transaction.execute(Transaction.java:37) at com.cloud.utils.db.Transaction.execute(Transaction.java:46) at com.cloud.storage.VolumeApiServiceImpl.detachVolumeFromVmThroughJobQueue(VolumeApiServiceImpl.java:2191) at com.cloud.storage.VolumeApiServiceImpl.detachVolumeFromVM(VolumeApiServiceImpl.java:1349) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy179.detachVolumeFromVM(Unknown Source) at org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd.execute(DetachVolumeCmd.java:138) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:168) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:100) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:488) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:445) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '160' for key 'PRIMARY' at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:526) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.Util.getInstance(Util.java:386) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1040) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2333) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2318) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1363) ... 43 more 2014-02-10 02:29:10,867 WARN [utils.db.Merovingian2] (Job-Executor-92:Job-159 ctx-7198b697) Was unable to find lock for the key vm_instance87 and thread id 1476855290 2014-02-10 02:29:10,871 ERROR [cloud.api.ApiAsyncJobDispatcher] (Job-Executor-92:Job-159) Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd com.cloud.utils.exception.CloudRuntimeException: Unable to schedule async job for command com.cloud.storage.VmWorkDetachVolume, unexpected exception. at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:203) at com.cloud.storage.VolumeApiServiceImpl$4.doInTransaction(VolumeApiServiceImpl.java:2215) at com.cloud.storage.VolumeApiServiceImpl$4.doInTransaction(VolumeApiServiceImpl.java:2191) at com.cloud.utils.db.Transaction$2.doInTransaction(Transaction.java:49) at com.cloud.utils.db.Transaction.execute(Transaction.java:37) at com.cloud.utils.db.Transaction.execute(Transaction.java:46) at com.cloud.storage.VolumeApiServiceImpl.detachVolumeFromVmThroughJobQueue(VolumeApiServiceImpl.java:2191) at com.cloud.storage.VolumeApiServiceImpl.detachVolumeFromVM(VolumeApiServiceImpl.java:1349) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy179.detachVolumeFromVM(Unknown Source) at org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd.execute(DetachVolumeCmd.java:138) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:168) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:100) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:488) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:445) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744)
