From dev-return-110814-archive-asf-public=cust-asf.ponee.io@cloudstack.apache.org Tue Feb 6 16:31:14 2018 Return-Path: X-Original-To: archive-asf-public@eu.ponee.io Delivered-To: archive-asf-public@eu.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by mx-eu-01.ponee.io (Postfix) with ESMTP id 96770180657 for ; Tue, 6 Feb 2018 16:31:14 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 85C2C160C34; Tue, 6 Feb 2018 15:31:14 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 80E93160C3A for ; Tue, 6 Feb 2018 16:31:13 +0100 (CET) Received: (qmail 89630 invoked by uid 500); 6 Feb 2018 15:31:11 -0000 Mailing-List: contact dev-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list dev@cloudstack.apache.org Received: (qmail 89602 invoked by uid 99); 6 Feb 2018 15:31:10 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 06 Feb 2018 15:31:10 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 747DEC0042; Tue, 6 Feb 2018 15:31:10 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.879 X-Spam-Level: * X-Spam-Status: No, score=1.879 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, HTML_MESSAGE=2, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd4-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id 1qlSpDGgFFxt; Tue, 6 Feb 2018 15:31:04 +0000 (UTC) Received: from mail-it0-f42.google.com (mail-it0-f42.google.com [209.85.214.42]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTPS id 7066A5F296; Tue, 6 Feb 2018 15:31:03 +0000 (UTC) Received: by mail-it0-f42.google.com with SMTP id j21-v6so11749823ita.1; Tue, 06 Feb 2018 07:31:03 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to; bh=ErcuMErC3twCmivQhhRfQ8fh8J8QHpFokUq0tG316jA=; b=oxKSv/nH7vttzrr/a4b+7kL76uI3IFvoQoWBbdKLJGZMWPFM/zuq4cW7IDHzOGqNuM RVAi724OiWCyxbaxAhu3vXv9OrTiyi7umPGLSmJXO70bMoCxQ+Lyywv/7cSm+LQK7yjz V4VpaV8HVeeganMy1a+ClCz1xaaSjPfPlkVekeN5WFDYI/5HfvL2Dz6mUxRXmDMh+Zs7 YG/ifjHWrp3bzFEhkPyBilJ4uktt8Pqfd1X+ggfPdVmTKPcmrzfjycqMSlEvhfnKClYZ 0buwnkZVWA3WvbabmDCw0ck3p7aKGfoyBnWoQMLe7SyDKV/lpSYxABa+3R8tEQXrcdHS Vl9A== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to; bh=ErcuMErC3twCmivQhhRfQ8fh8J8QHpFokUq0tG316jA=; b=tE6F+OCeNP/lWBjYdhKj2O2F3GBRra4ew+2R3j7QI4q0jtxJ2w6X7UJrBQPCVAaFgJ uXI67rYodBBi2wgxm4oRbsE99t5of2B3bF+AxDfwOIXtPe+Zy98VAi0DWQGKj9s7Wd/C LKuIkS7cSYcPpkNqyXYxinFEp9Fp3P60s2PJgoO6acWms7x7bDXfwh3kuPnjru0hoghF hzeyuRaCZ72zTJKcTc0GoU9n5ntmy5LJA4UG09CUDqS7OlHXnFnDHlDwC9e7VYHZKKI7 TORtOdtuA7BxQmqPvPYOlD77IUsWOHZ0EB6Y0zzRDDdbwG2wqfsZzmfhu3G/N6u9aKB/ o8kQ== X-Gm-Message-State: APf1xPC2VpdjJctd9leFCg7kRsGusl9XQnKkKH8ovgXmKZv/RFMC4Kpc RlyvGwrjYaa0g+5SfimYhwsvA6Okbfy0O2KNd1KwMA== X-Google-Smtp-Source: AH8x2269purQ0TVbJml2zpiDHhe1L2PfolKsAc34kCxxx2cnR0BvGP2W8NJn5JWC0OnDKvYdHfiZYhR3Td2qPUlMvTM= X-Received: by 10.36.175.15 with SMTP id t15mr3683346ite.106.1517931055528; Tue, 06 Feb 2018 07:30:55 -0800 (PST) MIME-Version: 1.0 Received: by 10.2.180.169 with HTTP; Tue, 6 Feb 2018 07:30:55 -0800 (PST) From: anillakieni Date: Tue, 6 Feb 2018 21:00:55 +0530 Message-ID: Subject: Copy Volume Failed in CloudStack 4.5 (XenServer 6.5) To: users@cloudstack.apache.org, dev@cloudstack.apache.org Content-Type: multipart/alternative; boundary="f403045dcb225bc02905648cddd8" --f403045dcb225bc02905648cddd8 Content-Type: text/plain; charset="UTF-8" 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 , 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. --f403045dcb225bc02905648cddd8--