[ https://issues.apache.org/jira/browse/CLOUDSTACK-4204?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Min Chen resolved CLOUDSTACK-4204. ---------------------------------- Resolution: Fixed > [Object_store_refactor] Snapshot created from volume in zone2 is copying to > secondary staging storages in zone1 > --------------------------------------------------------------------------------------------------------------- > > Key: CLOUDSTACK-4204 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4204 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the > default.) > Components: Snapshot, Storage Controller > Affects Versions: 4.2.0 > Environment: Latest build from ACS 4.2 branch. > zones: min of two zones with staging secondary storages > Reporter: Sanjeev N > Assignee: Min Chen > Priority: Critical > Fix For: 4.2.0 > > Attachments: cloud.dmp, cloud.log, management-server.rar > > > Snapshot created from volume in zone2 is copying to secondary staging > storages in zone1 > Steps to Reproduce: > ================= > 1.Bring up CS with two zones > zone1: xen cluster with staging secondary storage with NFS > zone2: vmware cluster with staging secondary storage with NFS > Secondary storage: S3 > 2.Deploy guest vm in zone2 with both root and data disk > 3.Create snapshot on the root/data disk > Result: > ====== > Snapshot creation was successful and got copied to S3 but during the snapshot > creation process copyCommand copies the snapshot from primary to secondary > staging storage. So it copied to secondary staging storage in zone1. > Log snippet: > ========= > Following is the log snippet from SSVM in vmware zone: > 2013-08-09 02:28:24,937 DEBUG [agent.transport.Request] > (Job-Executor-58:job-57 = [ ed3d0135-5cbf-4c2c-86c7-bcf9642e2f39 ]) Seq > 7-983236628: Sending { Cmd , MgmtId: 6615759585382, via: 7, Ver: v1, Flags: > 100011, > [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"6c91e440-6407-413d-abb7-e27c94abc7b5","volume":{"uuid":"120ec744-88f0-4008-a4ba-17a8bbe9ceda","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b845e7d4-562a-3b2d-8e59-b1df565f99e5","id":4,"poolType":"VMFS","host":"VMFS > datastore: > /sanjeev/openFiler","path":"/sanjeev/openFiler","port":0}},"name":"cent53-upload","size":459320832,"path":"c1457d19bf0d4c9bb9e3ef80f916ad93","volumeId":21,"vmName":"i-2-14-VM","accountId":2,"format":"OVA","id":21,"hypervisorType":"VMware"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b845e7d4-562a-3b2d-8e59-b1df565f99e5","id":4,"poolType":"VMFS","host":"VMFS > datastore: > /sanjeev/openFiler","path":"/sanjeev/openFiler","port":0}},"vmName":"i-2-14-VM","name":"v1-s1_cent53-upload_20130809062824","hypervisorType":"VMware","id":2}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/21","volume":{"uuid":"120ec744-88f0-4008-a4ba-17a8bbe9ceda","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b845e7d4-562a-3b2d-8e59-b1df565f99e5","id":4,"poolType":"VMFS","host":"VMFS > datastore: > /sanjeev/openFiler","path":"/sanjeev/openFiler","port":0}},"name":"cent53-upload","size":459320832,"path":"c1457d19bf0d4c9bb9e3ef80f916ad93","volumeId":21,"vmName":"i-2-14-VM","accountId":2,"format":"OVA","id":21,"hypervisorType":"VMware"},"dataStore":{"com.cloud.agent.api.to.S3TO":{"id":6,"uuid":"4f8c91be-94ce-4e44-a05d-f08584f1d56d","endPoint":"10.147.29.56:8080","bucketName":"imagestore","httpsFlag":false,"created":"Aug > 8, 2013 6:25:36 > AM","enableRRS":false}},"vmName":"i-2-14-VM","name":"v1-s1_cent53-upload_20130809062824","hypervisorType":"VMware","id":2}},"cacheTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/21","volume":{"uuid":"120ec744-88f0-4008-a4ba-17a8bbe9ceda","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b845e7d4-562a-3b2d-8e59-b1df565f99e5","id":4,"poolType":"VMFS","host":"VMFS > datastore: > /sanjeev/openFiler","path":"/sanjeev/openFiler","port":0}},"name":"cent53-upload","size":459320832,"path":"c1457d19bf0d4c9bb9e3ef80f916ad93","volumeId":21,"vmName":"i-2-14-VM","accountId":2,"format":"OVA","id":21,"hypervisorType":"VMware"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"ImageCache"}},"vmName":"i-2-14-VM","name":"v1-s1_cent53-upload_20130809062824","hypervisorType":"VMware","id":2}},"executeInSequence":false,"wait":21600}}] > } > 2013-08-09 06:28:24,987 DEBUG [cloud.agent.Agent] > (agentRequest-Handler-5:null) Processing command: > org.apache.cloudstack.storage.command.CopyCommand > 2013-08-09 06:28:25,137 WARN > [storage.resource.VmwareSecondaryStorageResourceHandler] > (agentRequest-Handler-5:null) Context validation failed due to Exception: > java.lang.NullPointerException > Message: null > 2013-08-09 06:28:26,174 WARN [vmware.util.VmwareContext] > (agentRequest-Handler-5:null) Unexpected exception: > javax.xml.ws.soap.SOAPFaultException: The session is not authenticated. > at > com.sun.xml.internal.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:178) > at > com.sun.xml.internal.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:119) > at > com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108) > at > com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78) > at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:107) > at sun.proxy.$Proxy36.logout(Unknown Source) > at > com.cloud.hypervisor.vmware.util.VmwareClient.disconnect(VmwareClient.java:164) > at > com.cloud.hypervisor.vmware.util.VmwareContext.close(VmwareContext.java:599) > at > com.cloud.storage.resource.VmwareSecondaryStorageContextFactory.invalidate(VmwareSecondaryStorageContextFactory.java:71) > at > com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.invalidateServiceContext(VmwareSecondaryStorageResourceHandler.java:226) > at > com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.getServiceContext(VmwareSecondaryStorageResourceHandler.java:209) > at > com.cloud.storage.resource.VmwareStorageProcessor.backupSnapshot(VmwareStorageProcessor.java:1035) > at > com.cloud.storage.resource.VmwareStorageSubsystemCommandHandler.execute(VmwareStorageSubsystemCommandHandler.java:113) > at > com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49) > at > com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:95) > at > com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(PremiumSecondaryStorageResource.java:56) > at com.cloud.agent.Agent.processRequest(Agent.java:525) > at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852) > at com.cloud.utils.nio.Task.run(Task.java:83) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:679) > 2013-08-09 06:28:38,198 DEBUG > [storage.resource.VmwareSecondaryStorageResourceHandler] > (agentRequest-Handler-5:null) Context validation succeeded. Validated via > host: 10.147.40.13, guid: HostSystem:host-3509@10.147.60.13 > 2013-08-09 06:28:38,330 INFO > [storage.resource.VmwareSecondaryStorageResourceHandler] > (agentRequest-Handler-5:null) Setup firewall rule for host: 10.147.40.13 > 2013-08-09 06:28:38,373 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) find VM i-2-14-VM on host > 2013-08-09 06:28:38,373 INFO [vmware.mo.HostMO] > (agentRequest-Handler-5:null) VM i-2-14-VM not found in host cache > 2013-08-09 06:28:38,373 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) load VM cache on host > 2013-08-09 06:28:47,637 DEBUG [storage.resource.VmwareStorageProcessor] > (agentRequest-Handler-5:null) Executing: mkdir -p > /mnt/SecStorage/1f24310b-8f0b-3563-aecc-779179564245/snapshots/2/21/84e927e7-ba89-4430-a8f8-79a2ec438206 > 2013-08-09 06:28:47,671 DEBUG [storage.resource.VmwareStorageProcessor] > (agentRequest-Handler-5:null) Execution is successful. > 2013-08-09 06:28:47,721 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Look for disk device info from volume : > c1457d19bf0d4c9bb9e3ef80f916ad93 > 2013-08-09 06:28:47,721 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Test against disk device, controller key: 200, > unit number: 1 > 2013-08-09 06:28:47,721 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Test against disk backing : [openFiler] > i-2-14-VM/ROOT-14-000001.vmdk > 2013-08-09 06:28:47,725 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Test against disk backing : [openFiler] > i-2-14-VM/ROOT-14.vmdk > 2013-08-09 06:28:47,725 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Test against disk backing : [openFiler] > 9d7d596309e634c8ab7c42aed595543f/9d7d596309e634c8ab7c42aed595543f.vmdk > 2013-08-09 06:28:47,732 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Test against disk device, controller key: 1000, > unit number: 0 > 2013-08-09 06:28:47,732 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Test against disk backing : [openFiler] > i-2-14-VM/c1457d19bf0d4c9bb9e3ef80f916ad93-000001.vmdk > 2013-08-09 06:28:47,733 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Disk backing : [openFiler] > i-2-14-VM/c1457d19bf0d4c9bb9e3ef80f916ad93-000001.vmdk matches ==> scsi0:0 > 2013-08-09 06:28:47,763 INFO [vmware.util.VmwareContext] > (agentRequest-Handler-5:null) Connected, conn: > sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.147.60.13/folder/i-2-14-VM/i-2-14-VM.vmsd?dcPath=sanjeev&dsName=openFiler, > retry: 0 > 2013-08-09 06:28:48,835 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: .encoding = "UTF-8" > 2013-08-09 06:28:48,836 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: snapshot.lastUID = > "1" > 2013-08-09 06:28:48,836 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: snapshot.current = > "1" > 2013-08-09 06:28:48,836 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: snapshot0.uid = "1" > 2013-08-09 06:28:48,843 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: snapshot0.filename > = "i-2-14-VM-Snapshot1.vmsn" > 2013-08-09 06:28:48,843 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.displayName = "6c91e440-6407-413d-abb7-e27c94abc7b5" > 2013-08-09 06:28:48,844 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.description = "Snapshot taken for > v1-s1_cent53-upload_20130809062824" > 2013-08-09 06:28:48,844 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.createTimeHigh = "320381" > 2013-08-09 06:28:48,844 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.createTimeLow = "-230977079" > 2013-08-09 06:28:48,844 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: snapshot0.numDisks > = "2" > 2013-08-09 06:28:48,844 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.disk0.fileName = "ROOT-14.vmdk" > 2013-08-09 06:28:48,844 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.disk0.node = "ide0:1" > 2013-08-09 06:28:48,845 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.disk1.fileName = "c1457d19bf0d4c9bb9e3ef80f916ad93.vmdk" > 2013-08-09 06:28:48,853 INFO [vmware.mo.SnapshotDescriptor] > (agentRequest-Handler-5:null) Parse snapshot file content: > snapshot0.disk1.node = "scsi0:0" > 2013-08-09 06:28:48,853 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Convert snapshot disk file name to datastore > path. c1457d19bf0d4c9bb9e3ef80f916ad93.vmdk->[openFiler] > i-2-14-VM/c1457d19bf0d4c9bb9e3ef80f916ad93.vmdk > 2013-08-09 06:28:48,890 INFO [vmware.mo.HypervisorHostHelper] > (agentRequest-Handler-5:null) Create blank VM. cpuCount: 1, cpuSpeed(MHz): 0, > mem(Mb): 4 > 2013-08-09 06:28:55,376 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending > ping: Seq 7-1164: { Cmd , MgmtId: -1, via: 7, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.PingStorageCommand":{"changes":{},"hostType":"Storage","hostId":7,"wait":0}}] > } > 2013-08-09 06:28:55,419 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null) > Received response: Seq 7-1164: { Ans: , MgmtId: 6615759585382, via: 7, Ver: > v1, Flags: 100010, > [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Storage","hostId":7,"wait":0},"result":true,"wait":0}}] > } > 2013-08-09 06:28:56,496 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) find VM 14559b74c77c4af2b3b67ce26581f870 on host > 2013-08-09 06:28:56,496 INFO [vmware.mo.HostMO] > (agentRequest-Handler-5:null) VM 14559b74c77c4af2b3b67ce26581f870 not found > in host cache > 2013-08-09 06:28:56,496 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) load VM cache on host > 2013-08-09 06:28:56,752 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) find VM 14559b74c77c4af2b3b67ce26581f870 on host > 2013-08-09 06:28:56,752 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) VM 14559b74c77c4af2b3b67ce26581f870 found in > host cache > 2013-08-09 06:29:01,650 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) find VM 14559b74c77c4af2b3b67ce26581f870 on host > 2013-08-09 06:29:01,651 INFO [vmware.mo.HostMO] > (agentRequest-Handler-5:null) VM 14559b74c77c4af2b3b67ce26581f870 not found > in host cache > 2013-08-09 06:29:01,651 DEBUG [vmware.mo.HostMO] > (agentRequest-Handler-5:null) load VM cache on host > 2013-08-09 06:29:01,998 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) volss: copy vmdk and ovf file starts > 1376029741998 > 2013-08-09 06:29:01,999 INFO [vmware.mo.HypervisorHostHelper] > (agentRequest-Handler-5:null) Resolving host name in url through vCenter, > url: https://10.147.40.13/nfc/52f73813-e314-13af-200b-dce199ed38fc/disk-0.vmdk > 2013-08-09 06:29:01,999 INFO [vmware.mo.HypervisorHostHelper] > (agentRequest-Handler-5:null) host name in url is already in IP address, url: > https://10.147.40.13/nfc/52f73813-e314-13af-200b-dce199ed38fc/disk-0.vmdk > 2013-08-09 06:29:02,005 INFO [vmware.mo.VirtualMachineMO] > (agentRequest-Handler-5:null) Download VMDK file for export. url: > https://10.147.40.13/nfc/52f73813-e314-13af-200b-dce199ed38fc/disk-0.vmdk > 2013-08-09 06:29:02,024 INFO [vmware.util.VmwareContext] > (agentRequest-Handler-5:null) Connected, conn: > sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.147.40.13/nfc/52f73813-e314-13af-200b-dce199ed38fc/disk-0.vmdk, > retry: 0 > 2013-08-09 06:30:55,948 DEBUG [vmware.manager.VmwareStorageManagerImpl] > (agentRequest-Handler-5:null) Executing: sudo sync > 2013-08-09 06:30:56,377 DEBUG [vmware.manager.VmwareStorageManagerImpl] > (agentRequest-Handler-5:null) Execution is successful. > 2013-08-09 06:30:56,377 INFO [vmware.manager.VmwareStorageManagerImpl] > (agentRequest-Handler-5:null) Package OVA with commmand: tar -cf > 84e927e7-ba89-4430-a8f8-79a2ec438206.ova > 84e927e7-ba89-4430-a8f8-79a2ec438206.ovf > 84e927e7-ba89-4430-a8f8-79a2ec438206-disk0.vmdk > 2013-08-09 06:30:56,391 DEBUG [vmware.manager.VmwareStorageManagerImpl] > (agentRequest-Handler-5:null) Executing: tar -cf > 84e927e7-ba89-4430-a8f8-79a2ec438206.ova > 84e927e7-ba89-4430-a8f8-79a2ec438206.ovf > 84e927e7-ba89-4430-a8f8-79a2ec438206-disk0.vmdk > 2013-08-09 06:31:51,550 DEBUG [vmware.manager.VmwareStorageManagerImpl] > (agentRequest-Handler-5:null) Execution is successful. > 2013-08-09 06:31:51,754 DEBUG [cloud.utils.S3Utils] > (agentRequest-Handler-5:null) Sending file > 84e927e7-ba89-4430-a8f8-79a2ec438206.ova as S3 object > snapshots/2/21/84e927e7-ba89-4430-a8f8-79a2ec438206.ova in bucket imagestore > 2013-08-09 06:31:51,754 DEBUG [cloud.utils.S3Utils] > (agentRequest-Handler-5:null) Creating S3 client with configuration: > [protocol: http, connectionTimeOut: 50000, maxErrorRetry: 3, socketTimeout: > 50000] > 2013-08-09 06:31:52,246 DEBUG [cloud.utils.S3Utils] > (agentRequest-Handler-5:null) Setting the end point for S3 client > com.amazonaws.services.s3.AmazonS3Client@19ade0a to 10.147.29.56:8080. > 2013-08-09 06:31:55,380 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending > ping: Seq 7-1167: { Cmd , MgmtId: -1, via: 7, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.PingStorageCommand":{"changes":{},"hostType":"Storage","hostId":7,"wait":0}}] > } > 2013-08-09 06:31:55,428 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null) > Received response: Seq 7-1167: { Ans: , MgmtId: 6615759585382, via: 7, Ver: > v1, Flags: 100010, > [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Storage","hostId":7,"wait":0},"result":true,"wait":0}}] > } > 2013-08-09 06:32:55,415 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending > ping: Seq 7-1168: { Cmd , MgmtId: -1, via: 7, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.PingStorageCommand":{"changes":{},"hostType":"Storage","hostId":7,"wait":0}}] > } > 2013-08-09 06:32:55,495 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null) > Received response: Seq 7-1168: { Ans: , MgmtId: 6615759585382, via: 7, Ver: > v1, Flags: 100010, > [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Storage","hostId":7,"wait":0},"result":true,"wait":0}}] > } > 2013-08-09 06:33:05,528 DEBUG [cloud.agent.Agent] > (agentRequest-Handler-5:null) Seq 7-983236628: { Ans: , MgmtId: > 6615759585382, via: 7, Ver: v1, Flags: 10, > [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/21/84e927e7-ba89-4430-a8f8-79a2ec438206.ova","id":0}},"result":true,"wait":0}}] > } > Attaching management server log, cloud.log from SSVM and cloud db. -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira