Hi All,
I'm facing issue when copying larger size volumes. i.e., Secondary Storage
to Primary Storage (I mean attaching DATA volume to VM), after certain time
around 37670 seconds.
Version of:
- CloudStack is 4.5.0
- XenServer 6.5.0
- MySQL 5.1.73
The error and log is provided below, Could someone please assist me here
which steps i have to take to fix this issue. Also, can we have a chance to
update the failed status to success through database tables because i have
to upload the whole disk again to secondary storage and then later attach
it to VM, which is consuming more time. My environment has very slow
network transfers (I have only 1 Gig switch). Please let me know if we can
tweak the DB to update the status of the disk or do we have any settings to
be changed to accept more time (wait time) for updating the status.
"
2018-02-06 03:20:42,385 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-31:ctx-c1c78a5a job-106186/job-106187 ctx-ea1ef3e6)
(logid:c59b2359) Seq 38-367887794560851961: Received: { Ans: , MgmtId:
47019105324719, via: 38, Ver: v1, Flags: 110, { CopyCmdAnswer } }
2018-02-06 03:20:42,389 DEBUG [o.a.c.s.v.VolumeObject]
(Work-Job-Executor-31:ctx-c1c78a5a job-106186/job-106187 ctx-ea1ef3e6)
(logid:c59b2359) *Failed to update state*
*com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@54bd3a25: SELECT volume_store_ref.id
<http://volume_store_ref.id>, volume_store_ref.store_id,
volume_store_ref.volume_id, volume_store_ref.zone_id,
volume_store_ref.created, volume_store_ref.last_updated,
volume_store_ref.download_pct, volume_store_ref.size,
volume_store_ref.physical_size, volume_store_ref.download_state,
volume_store_ref.checksum, volume_store_ref.local_path,
volume_store_ref.error_str, volume_store_ref.job_id,
volume_store_ref.install_path, volume_store_ref.url,
volume_store_ref.download_url, volume_store_ref.download_url_created,
volume_store_ref.destroyed, volume_store_ref.update_count,
volume_store_ref.updated, volume_store_ref.state, volume_store_ref.ref_cnt
FROM volume_store_ref WHERE volume_store_ref.store_id = 1 AND
volume_store_ref.volume_id = 1178 AND volume_store_ref.destroyed = 0
ORDER BY RAND() LIMIT 1*
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:425)
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:361)
at
com.cloud.utils.db.GenericDaoBase.findOneIncludingRemovedBy(GenericDaoBase.java:889)
at
com.cloud.utils.db.GenericDaoBase.findOneBy(GenericDaoBase.java:900)
at
org.apache.cloudstack.storage.image.db.VolumeDataStoreDaoImpl.findByStoreVolume(VolumeDataStoreDaoImpl.java:209)
at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source)
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
com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:34)
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.$Proxy173.findByStoreVolume(Unknown Source)
at
org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.findObject(ObjectInDataStoreManagerImpl.java:353)
at
org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.findObject(ObjectInDataStoreManagerImpl.java:338)
at
org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.update(ObjectInDataStoreManagerImpl.java:289)
at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:294)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolumeFromImageToPrimaryCallback(VolumeServiceImpl.java:901)
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.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:25)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:126)
at
org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:463)
at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:68)
at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:73)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolumeFromImageToPrimary(VolumeServiceImpl.java:870)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:968)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.copyVolumeFromSecToPrimary(VolumeOrchestrator.java:430)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.copyVolume(VolumeOrchestrator.java:764)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeOnPrimaryStorage(VolumeOrchestrator.java:784)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:1211)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:2732)
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
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:2771)
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.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.$Proxy186.handleVmWorkJob(Unknown Source)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:547)
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:498)
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.CommunicationsException: The
last packet successfully received from the server was 37,706,960
milliseconds ago. The last packet sent successfully to the server was
37,706,961 milliseconds ago. is longer than the server configured value of
'wait_timeout'. You should consider either expiring and/or testing
connection validity before use in your application, increasing the server
configured values for client timeouts, or using the Connector/J connection
property 'autoReconnect=true' to avoid this problem.*
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.SQLError.createCommunicationsException(SQLError.java:1116)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3352)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1971)
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.executeQuery(PreparedStatement.java:2283)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:419)
... 68 more
Caused by: java.net.SocketException: Broken pipe
... 82 more
2018-02-06 03:20:42,390 DEBUG [c.c.a.m.AgentAttache]
(DirectAgent-212:ctx-418e3b03) (logid:c59b2359) Seq 38-367887794560855816:
Sending now. is current sequence.
2018-02-06 03:20:42,391 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-31:ctx-c1c78a5a job-106186/job-106187 ctx-ea1ef3e6)
(logid:c59b2359) copy volume failed:
com.cloud.utils.exception.CloudRuntimeException: Failed to update
state:com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@54bd3a25: SELECT volume_store_ref.id,
volume_store_ref.store_id, volume_store_ref.volume_id,
volume_store_ref.zone_id, volume_store_ref.created,
volume_store_ref.last_updated, volume_store_ref.download_pct,
volume_store_ref.size, volume_store_ref.physical_size,
volume_store_ref.download_state, volume_store_ref.checksum,
volume_store_ref.local_path, volume_store_ref.error_str,
volume_store_ref.job_id, volume_store_ref.install_path,
volume_store_ref.url, volume_store_ref.download_url,
volume_store_ref.download_url_created, volume_store_ref.destroyed,
volume_store_ref.update_count, volume_store_ref.updated,
volume_store_ref.state, volume_store_ref.ref_cnt FROM volume_store_ref
WHERE volume_store_ref.store_id = 1 AND volume_store_ref.volume_id = 1178
AND volume_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
2018-02-06 03:20:42,391 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-31:ctx-c1c78a5a job-106186/job-106187 ctx-ea1ef3e6)
(logid:c59b2359) Invocation exception, caused by:
com.cloud.utils.exception.CloudRuntimeException: copy volume failed:
com.cloud.utils.exception.CloudRuntimeException: Failed to update
state:com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@54bd3a25: SELECT volume_store_ref.id,
volume_store_ref.store_id, volume_store_ref.volume_id,
volume_store_ref.zone_id, volume_store_ref.created,
volume_store_ref.last_updated, volume_store_ref.download_pct,
volume_store_ref.size, volume_store_ref.physical_size,
volume_store_ref.download_state, volume_store_ref.checksum,
volume_store_ref.local_path, volume_store_ref.error_str,
volume_store_ref.job_id, volume_store_ref.install_path,
volume_store_ref.url, volume_store_ref.download_url,
volume_store_ref.download_url_created, volume_store_ref.destroyed,
volume_store_ref.update_count, volume_store_ref.updated,
volume_store_ref.state, volume_store_ref.ref_cnt FROM volume_store_ref
WHERE volume_store_ref.store_id = 1 AND volume_store_ref.volume_id = 1178
AND volume_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
2018-02-06 03:20:42,392 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-31:ctx-c1c78a5a job-106186/job-106187 ctx-ea1ef3e6)
(logid:c59b2359) Rethrow exception
com.cloud.utils.exception.CloudRuntimeException: copy volume failed:
com.cloud.utils.exception.CloudRuntimeException: Failed to update
state:com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@54bd3a25: SELECT volume_store_ref.id,
volume_store_ref.store_id, volume_store_ref.volume_id,
volume_store_ref.zone_id, volume_store_ref.created,
volume_store_ref.last_updated, volume_store_ref.download_pct,
volume_store_ref.size, volume_store_ref.physical_size,
volume_store_ref.download_state, volume_store_ref.checksum,
volume_store_ref.local_path, volume_store_ref.error_str,
volume_store_ref.job_id, volume_store_ref.install_path,
volume_store_ref.url, volume_store_ref.download_url,
volume_store_ref.download_url_created, volume_store_ref.destroyed,
volume_store_ref.update_count, volume_store_ref.updated,
volume_store_ref.state, volume_store_ref.ref_cnt FROM volume_store_ref
WHERE volume_store_ref.store_id = 1 AND volume_store_ref.volume_id = 1178
AND volume_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
2018-02-06 03:20:42,392 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-31:ctx-c1c78a5a job-106186/job-106187) (logid:c59b2359)
Done with run of VM work job: com.cloud.vm.VmWorkAttachVolume for VM 877,
job origin: 106186
"
If you require more info please let me know to provide it. Looking forward
for the help. Much appreciation.
Thanks,
Anil.
