SQLIntegrityConstraintViolationException: Duplicate entry 's-190-VM-PremiumSecondaryStorageResource' for key 'guid'

[borisstoyanov]

ISSUE TYPE

• Bug Report

COMPONENT NAME

Host Outage and SSVM

CLOUDSTACK VERSION

4.15

CONFIGURATION

VMware

OS / ENVIRONMENT

NA

SUMMARY

When a host goes down a system vm that is being on it is marked as stopped, then when the host is up again the agent on the SSVM tries to connect back, but there's already a new SSVM.

STEPS TO REPRODUCE

Host1 disconnected (where s-190-VM resides on and s-190-VM still running)

s-190-VM marked as stopped due to host unavailability and tried starting s-190-VM on another host

Cloudstack could not start the VM (tried using the existing vmx file but failed since s-190-VM is running and there is lock on vmx file)

After several retries, CloudStack deployed another SSVM on different host

Resaon for the error  “SQLIntegrityConstraintViolationException: Duplicate entry 's-190-VM-PremiumSecondaryStorageResource' for key 'guid'“ is because the agent running inside s-190-VM trying to contact management server and trying to register itself in CloudStack but failing with “Entity already exists“ error since there is already entry for s-190-VM

2020-09-24 13:53:26,076 DEBUG [c.c.u.d.T.Transaction] (AgentConnectTaskPool-19:ctx-a24fabc2) (logid:814e24e0) Rolling back the transaction: Time = 1 Name =  AgentConnectTaskPool-19; called by -TransactionLegacy.rollback:888-TransactionLegacy.removeUpTo:831-TransactionLegacy.close:655-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:95-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:212-$Proxy78.persist:-1-ResourceManagerImpl.createHostVO:1938-ResourceManagerImpl.createHostVOForConnectedAgent:2264-GeneratedMethodAccessor173.invoke:-1
2020-09-24 13:53:26,077 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-19:ctx-a24fabc2) (logid:814e24e0) Failed to handle host connection:
javax.persistence.EntityExistsException: Entity already exists
	at com.cloud.utils.db.GenericDaoBase.handleEntityExistsException(GenericDaoBase.java:869)
	at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1466)
	at com.cloud.host.dao.HostDaoImpl.persist(HostDaoImpl.java:868)
	at com.cloud.host.dao.HostDaoImpl.persist(HostDaoImpl.java:74)
	at jdk.internal.reflect.GeneratedMethodAccessor152.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:34)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
	at com.sun.proxy.$Proxy78.persist(Unknown Source)
	at com.cloud.resource.ResourceManagerImpl.createHostVO(ResourceManagerImpl.java:1938)
	at com.cloud.resource.ResourceManagerImpl.createHostVOForConnectedAgent(ResourceManagerImpl.java:2264)
	at jdk.internal.reflect.GeneratedMethodAccessor173.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
	at com.sun.proxy.$Proxy187.createHostVOForConnectedAgent(Unknown Source)
	at com.cloud.agent.manager.AgentManagerImpl.handleConnectedAgent(AgentManagerImpl.java:1097)
	at com.cloud.agent.manager.AgentManagerImpl$HandleAgentConnectTask.runInContext(AgentManagerImpl.java:1194)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.sql.SQLIntegrityConstraintViolationException: Duplicate entry 's-190-VM-PremiumSecondaryStorageResource' for key 'guid'
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:117)
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
	... 44 more
2020-09-24 13:53:26,078 WARN  [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-19:ctx-a24fabc2) (logid:814e24e0) Unable to create attache for agent: Seq 0-0:  { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 101, [{"com.cloud.agent.api.StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-190-VM-PremiumSecondaryStorageResource","name":"s-190-VM","id":"0","version":"4.15.0.0-SNAPSHOT","iqn":"NoIqn","publicIpAddress":"10.1.38.182","publicNetmask":"255.255.224.0","publicMacAddress":"1e:00:c7:00:00:02","privateIpAddress":"10.10.9.222","privateMacAddress":"1e:00:5c:00:00:16","privateNetmask":"255.255.0.0","storageIpAddress":"10.10.9.222","storageNetmask":"255.255.0.0","storageMacAddress":"1e:00:5c:00:00:16","resourceName":"PremiumSecondaryStorageResource","msHostList":"10.10.4.251@static","wait":"0"}}] }
2020-09-24 13:53:26,181 WARN  [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-19:null) (logid:) Throwing away a request because it came through as the first command on a connect: Seq 0--1:  { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 111, [{"com.cloud.agent.api.ShutdownCommand":{"reason":"sig.kill","wait":"0"}}] }

[DaanHoogland]

sounds like serious but verymuch an edge case.
I would expect

1. a ssvm to be removed by the system if it isn't functional
2. a new ssvm to be created with a new id
3. an extra ssvm not to be a problem in a running system.

have you relyably reproduced this @borisstoyanov?
and can you confirm this is a new issue in current master/4.15?

[DaanHoogland]

sounds like could be related to #3784 will test this scenario in the same env (probably just the same test with a longer timeout.

[DaanHoogland]

@borisstoyanov i ran this test but no new ssvm was automatically started and as I registered a template while the host was down, as soon as it came up the ssvm was functional again and the template got installed.
Can you add details or close , please?

[Spaceman1984]

I tried powering off the host from ESXI and shutting down the host within VSphere, I was not able to reproduce the behavior.

[yadvr]

Closing on the remark that it was not reproducible, let's reopen revisit if it happens with more recent 4.15/master codebase. cc @borisstoyanov