Sangeetha Hariharan created CLOUDSTACK-5356: -----------------------------------------------
Summary: Xenserver - Failed to create snapshot when secondary store was made unavaibale for about 1.5 hour leaving behind snapshot in " CreatedOnPrimary" state. The subsequent scheduled snapshot also failed Key: CLOUDSTACK-5356 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5356 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the default.) Components: Management Server Affects Versions: 4.3.0 Environment: Build from 4.3 Reporter: Sangeetha Hariharan Priority: Critical Fix For: 4.3.0 Xenserver - Failed to create snapshot when secondary store was made unavaibale for about 1.5 hour leaving behind snapshot in " CreatedOnPrimary" state. The subsequent scheduled snapshot also failed Set up: Advanced Zone with 2 Xenserver 6.2 hosts: Steps to reproduce the problem: 1. Deploy 5 Vms in each of the hosts with 10 GB ROOT volume size , so we start with 10 Vms. 2. Start concurrent hourly snapshots for ROOT volumes of all the Vms. 3. Shutdown the Secondary storage server when the snapshots are in the progress. 4. Bring the Secondary storage server up after 1and 1/2 hour. We see that the snapshot creation was halted when the Secondary storage server was down. When it was brought up , snapshots creation continued for all the volumes except for 1 volume. Following exception was encountered after about 45 minutes: 2013-12-03 17:53:46,745 DEBUG [c.c.h.x.r.XenServerConnectionPool] (DirectAgent-258:ctx-981656b0) XmlRpcExceptio n for method: PBD.unplug due to Failed to create input stream: Read timed out. Reconnecting...retry=1 2013-12-03 17:53:46,745 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-258:ctx-981656b0) Host 10.223.59.67 O paqueRef:710e7848-b118-cd69-d8c2-d3e8ffad8429: Catch Exception: Failed to create input stream: Read timed out 2013-12-03 17:53:46,745 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-258:ctx-981656b0) Host 10.223.59.67 O paqueRef:710e7848-b118-cd69-d8c2-d3e8ffad8429: Unable to remove SR 2013-12-03 17:53:46,746 WARN [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-258:ctx-981656b0) BackupSnapsh ot Failed due to Task failed! Task record: uuid: 99a9ee1f-645b-8893-5e13-4e16006c57ef nameLabel: Async.VDI.copy nameDescription: allowedOperations: [] currentOperations: {} created: Tue Dec 03 17:11:16 EST 2013 finished: Tue Dec 03 13:25:23 EST 2013 status: failure residentOn: com.xensource.xenapi.Host@72f2fe96 progress: 1.0 type: <none/> result: errorInfo: [SR_BACKEND_FAILURE, non-zero exit, , Traceback (most recent call last): File "/opt/xensource/sm/NFSSR", line 280, in ? SRCommand.run(NFSSR, DRIVER_INFO) File "/opt/xensource/sm/SRCommand.py", line 327, in run ret = cmd.run(sr) File "/opt/xensource/sm/SRCommand.py", line 106, in run return self._run_locked(sr) File "/opt/xensource/sm/SRCommand.py", line 153, in _run_locked return self._run(sr, target) File "/opt/xensource/sm/SRCommand.py", line 197, in _run return target.create(self.params['sr_uuid'], self.vdi_uuid, long(self.params['args'][0])) File "/opt/xensource/sm/FileSR.py", line 487, in create self.sr._update(self.sr.uuid, self.size) File "/opt/xensource/sm/FileSR.py", line 185, in _update self.physical_utilisation = self._getutilisation() File "/opt/xensource/sm/FileSR.py", line 270, in _getutilisation return util.get_fs_utilisation(self.path) File "/opt/xensource/sm/util.py", line 445, in get_fs_utilisation st = ioretry_stat(lambda: os.statvfs(path)) File "/opt/xensource/sm/util.py", line 302, in ioretry_stat stat = f() File "/opt/xensource/sm/util.py", line 445, in <lambda> st = ioretry_stat(lambda: os.statvfs(path)) OSError: [Errno 5] Input/output error: '/var/run/sr-mount/b9dffc14-d14e-aec2-5609-4c8adee168fa' ] otherConfig: {} subtaskOf: com.xensource.xenapi.Task@aaf13f6f subtasks: [] Task failed! Task record: uuid: 99a9ee1f-645b-8893-5e13-4e16006c57ef nameLabel: Async.VDI.copy nameDescription: allowedOperations: [] currentOperations: {} created: Tue Dec 03 17:11:16 EST 2013 finished: Tue Dec 03 13:25:23 EST 2013 status: failure residentOn: com.xensource.xenapi.Host@72f2fe96 progress: 1.0 type: <none/> result: errorInfo: [SR_BACKEND_FAILURE, non-zero exit, , Traceback (most recent call last): File "/opt/xensource/sm/NFSSR", line 280, in ? SRCommand.run(NFSSR, DRIVER_INFO) File "/opt/xensource/sm/SRCommand.py", line 327, in run ret = cmd.run(sr) File "/opt/xensource/sm/SRCommand.py", line 106, in run return self._run_locked(sr) File "/opt/xensource/sm/SRCommand.py", line 153, in _run_locked return self._run(sr, target) File "/opt/xensource/sm/SRCommand.py", line 197, in _run return target.create(self.params['sr_uuid'], self.vdi_uuid, long(self.params['args'][0])) File "/opt/xensource/sm/FileSR.py", line 487, in create self.sr._update(self.sr.uuid, self.size) File "/opt/xensource/sm/FileSR.py", line 185, in _update self.physical_utilisation = self._getutilisation() File "/opt/xensource/sm/FileSR.py", line 270, in _getutilisation return util.get_fs_utilisation(self.path) File "/opt/xensource/sm/util.py", line 445, in get_fs_utilisation st = ioretry_stat(lambda: os.statvfs(path)) File "/opt/xensource/sm/util.py", line 302, in ioretry_stat stat = f() File "/opt/xensource/sm/util.py", line 445, in <lambda> st = ioretry_stat(lambda: os.statvfs(path)) OSError: [Errno 5] Input/output error: '/var/run/sr-mount/b9dffc14-d14e-aec2-5609-4c8adee168fa' ] otherConfig: {} subtaskOf: com.xensource.xenapi.Task@aaf13f6f subtasks: [] at com.cloud.hypervisor.xen.resource.CitrixResourceBase.checkForSuccess(CitrixResourceBase.java:3736) at com.cloud.hypervisor.xen.resource.CitrixResourceBase.cloudVDIcopy(CitrixResourceBase.java:3914) at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.backupSnapshot(XenServerStorageProcessor.java:1268) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:90) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:50) at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:613) at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59) at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216) 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 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$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) 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:722) 2013-12-03 17:53:46,747 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-258:ctx-981656b0) Seq 2-1599668375: Response Received: 2013-12-03 17:53:46,747 DEBUG [c.c.a.t.Request] (DirectAgent-258:ctx-981656b0) Seq 2-1599668375: Processing: { Ans: , MgmtId: 112516401760401, via: 2, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"BackupSnapshot Failed due to Task failed! Task record: uuid: 99a9ee1f-645b-8893-5e13-4e16006c57ef\n nameLabel: Async.VDI.copy\n nameDescription: \n allowedOperations: []\n currentOperations: {}\n created: Tue Dec 03 17:11:16 EST 2013\n finished: Tue Dec 03 13:25:23 EST 2013\n status: failure\n residentOn: com.xensource.xenapi.Host@72f2fe96\n progress: 1.0\n type: <none/>\n result: \n errorInfo: [SR_BACKEND_FAILURE, non-zero exit, , Traceback (most recent call last):\n File \"/opt/xensource/sm/NFSSR\", line 280, in ?\n SRCommand.run(NFSSR, DRIVER_INFO)\n File \"/opt/xensource/sm/SRCommand.py\", line 327, in run\n ret = cmd.run(sr)\n File \"/opt/xensource/sm/SRCommand.py\", line 106, in run\n return self._run_locked(sr)\n File \"/opt/xensource/sm/SRCommand.py\", line 153, in _run_locked\n return self._run(sr, target)\n File \"/opt/xensource/sm/SRCommand.py\", line 197, in _run\n return target.create(self.params['sr_uuid'], self.vdi_uuid, long(self.params['args'][0]))\n File \"/opt/xensource/sm/FileSR.py\", line 487, in create\n self.sr._update(self.sr.uuid, self.size)\n File \"/opt/xensource/sm/FileSR.py\", line 185, in _update\n self.physical_utilisation = self._getutilisation()\n File \"/opt/xensource/sm/FileSR.py\", line 270, in _getutilisation\n return util.get_fs_utilisation(self.path)\n File \"/opt/xensource/sm/util.py\", line 445, in get_fs_utilisation\n st = ioretry_stat(lambda: os.statvfs(path))\n File \"/opt/xensource/sm/util.py\", line 302, in ioretry_stat\n stat = f()\n File \"/opt/xensource/sm/util.py\", line 445, in <lambda>\n st = ioretry_stat(lambda: os.statvfs(path))\nOSError: [Errno 5] Input/output error: '/var/run/sr-mount/b9dffc14-d14e-aec2-5609-4c8adee168fa'\n]\n otherConfig: {}\n subtaskOf: com.xensource.xenapi.Task@aaf13f6f\n subtasks: []\n","wait":0}}] } 2013-12-03 17:53:46,748 DEBUG [c.c.a.t.Request] (Job-Executor-81:ctx-45d54d9d ctx-5b62ab1e) Seq 2-1599668375: Received: { Ans: , MgmtId: 112516401760401, via: 2, Ver: v1, Flags: 10, { CopyCmdAnswer } } 2013-12-03 17:53:46,760 DEBUG [c.c.s.s.SnapshotManagerImpl] (Job-Executor-81:ctx-45d54d9d ctx-5b62ab1e) Failed to create snapshot This failure left behind the snapshot in "CreatedOnPrimary" state. The subsequent hourly snapshot also failed , due to following exception: 2013-12-03 18:10:15,382 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-183:ctx-6020b49b) callHostPlugin failed for cmd : create_secondary_storage_folder with args remoteMountPath: 10.223.57.195:/export/home/secondary, newFolder: snapshots/3 /13, due to There was a failure communicating with the plugin. 2013-12-03 18:10:15,382 WARN [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-183:ctx-6020b49b) BackupSnapshot Failed due to callHostPlugin failed for cmd: create_secondary_storage_folder with args remoteMountPath: 10.223.57.195:/export/ho me/secondary, newFolder: snapshots/3/13, due to There was a failure communicating with the plugin. com.cloud.utils.exception.CloudRuntimeException: callHostPlugin failed for cmd: create_secondary_storage_folder with args remoteMountPath: 10.223.57.195:/export/home/secondary, newFolder: snapshots/3/13, due to There was a failure communicat ing with the plugin. at com.cloud.hypervisor.xen.resource.CitrixResourceBase.callHostPlugin(CitrixResourceBase.java:4340) at com.cloud.hypervisor.xen.resource.CitrixResourceBase.createSecondaryStorageFolder(CitrixResourceBase.java:7847 ) at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.backupSnapshot(XenServerStorageProcessor.java:1259 ) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java: 90) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHan dlerBase.java:50) at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:613) at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59) at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216) 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:10 3) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) 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$201(ScheduledThreadPoolExecutor.ja va:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) 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:722) 2013-12-03 18:10:15,383 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-183:ctx-6020b49b) Seq 1-2071593441: Response Received: 2013-12-03 18:10:15,383 DEBUG [c.c.a.t.Request] (DirectAgent-183:ctx-6020b49b) Seq 1-2071593441: Processing: { Ans: , MgmtId: 112516401760401, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"BackupSnapshot Failed due to callHostPlugin failed for cmd: create_secondary_storage_folder with args remoteMountPath: 10.223.57.195:/export/home/secondary, newFolder: snapshots/3/13, due to There was a failure communicating with the plugin.","wait":0}}] } 2013-12-03 18:10:15,383 DEBUG [c.c.a.t.Request] (Job-Executor-91:ctx-51ac8719 ctx-6eac2069) Seq 1-2071593441: Received: { Ans: , MgmtId: 112516401760401, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } } 2013-12-03 18:10:15,406 DEBUG [c.c.s.s.SnapshotManagerImpl] (Job-Executor-91:ctx-51ac8719 ctx-6eac2069) Failed to create snapshot com.cloud.utils.exception.CloudRuntimeException: BackupSnapshot Failed due to callHostPlugin failed for cmd: create_secondary_storage_folder with args remoteMountPath: 10.223.57.195:/export/home/secondary, newFolder: snapshots/3/13, due to There was a failure communicating with the plugin. at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:275) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:135) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:294) at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:951) at sun.reflect.GeneratedMethodAccessor334.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) 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 $Proxy160.takeSnapshot(Unknown Source) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1342) at com.cloud.storage.VolumeApiServiceImpl.takeSnapshot(VolumeApiServiceImpl.java:1402) at sun.reflect.GeneratedMethodAccessor333.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) 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 $Proxy232.takeSnapshot(Unknown Source) at org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd.execute(CreateSnapshotCmd.java:181) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161) at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109) at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66) 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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:520) 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 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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:722) snapshot entries for volume that encountered this issue: | 13 | 1 | 3 | 1 | 13 | 13 | CreatedOnPrimary | NULL | TestVM-tiny-host-1ps-0-3_ROOT-13_20131203221013 | c7b68a48-d55b-4cef-8c54-85fca5f684ce | 3 | HOURLY | 21474836480 | 2013-12-03 22:10:13 | NULL | NULL | NULL | NULL | NULL | XenServer | 2.2 | NULL | | 23 | 1 | 3 | 1 | 13 | 13 | CreatedOnPrimary | NULL | TestVM-tiny-host-1ps-0-3_ROOT-13_20131203231013 | 667dcdfd-7f47-4ce5-8abb-54cd7df8d9a4 | 3 | HOURLY | 21474836480 | 2013-12-03 23:10:13 | NULL | NULL | NULL | NULL | NULL | XenServer | 2.2 | NULL | | 24 | 1 | 3 | 1 | 13 | 13 | BackingUp | NULL | TestVM-tiny-host-1ps-0-3_ROOT-13_20131204001013 | 5de9e37a-2009-4e56-8fdb-8615ee4fe427 | 3 | HOURLY | 21474836480 | 2013-12-04 00:10:13 | NULL | NULL | NULL | NULL | NULL | XenServer | 2.2 | NULL | +----+----------------+------------+-----------+-----------+------------------+------------------+------+-------------------------------------------------+--------------------------------------+---------------+------------------+-------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+ 4 rows in set (0.00 sec) -- This message was sent by Atlassian JIRA (v6.1#6144)