Sanjeev N created CLOUDSTACK-4204:
-------------------------------------
Summary: [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
Priority: Critical
Fix For: 4.2.0
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:[email protected]
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
