The cloudstack log is as follows:
2014-11-20 14:53:10,758 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-3:ctx-c859f450) POST request to https://192.168.1.78:8250/api/HypervResource/org.apache.cloudstack.storage.c ommand.CopyCommand with contents {"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"ht tp://cloudstack.apt-get.eu/systemvm/4.4/systemvm64template-4.4.0-6-hyperv.vh d.bz2","uuid":"12778b5a-7080-11e4-a46b-000c299522c6","id":9,"format":"VHD"," accountId":1,"checksum":"1c0bdb131e3b7ee753d014961fdd6eb0","hvm":false,"disp layText":"SystemVM Template (HyperV)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataSto reTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB" ,"host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin&domain=cloud ","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&domai n=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"nam e":"routing-9","hypervisorType":"Hyperv"}},"destTO":{"org.apache.cloudstack. storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c69b91d7eea6","v olumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryData StoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"S MB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin&domain=cl oud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&do main=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}}," name":"ROOT-2","size":0,"volumeId":2,"vmName":"v-2-VM","accountId":1,"format ":"VHDX","id":2,"deviceId":0,"hypervisorType":"Hyperv"}},"executeInSequence" :false,"options":{},"contextMap":{},"wait":0} 2014-11-20 14:53:10,772 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-3:ctx-c859f450) Sending cmd to https://192.168.1.78:8250/api/HypervResource/org.apache.cloudstack.storage.c ommand.CopyCommand cmd data:{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl ":"http://cloudstack.apt-get.eu/systemvm/4.4/systemvm64template-4.4.0-6-hype rv.vhd.bz2","uuid":"12778b5a-7080-11e4-a46b-000c299522c6","id":9,"format":"V HD","accountId":1,"checksum":"1c0bdb131e3b7ee753d014961fdd6eb0","hvm":false, "displayText":"SystemVM Template (HyperV)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataSto reTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB" ,"host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin&domain=cloud ","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&domai n=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"nam e":"routing-9","hypervisorType":"Hyperv"}},"destTO":{"org.apache.cloudstack. storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c69b91d7eea6","v olumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryData StoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"S MB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin&domain=cl oud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&do main=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}}," name":"ROOT-2","size":0,"volumeId":2,"vmName":"v-2-VM","accountId":1,"format ":"VHDX","id":2,"deviceId":0,"hypervisorType":"Hyperv"}},"executeInSequence" :false,"options":{},"contextMap":{},"wait":0} 2014-11-20 14:53:20,838 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-5:ctx-0427c434) POST response is [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":true,"deta ils":null,"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"dat aStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b48e 8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB","host":"192.168.1. 79","path":"/WINPrimary?user=cloudstackadmin&domain=cloud","port":445,"url": "SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&domain=cloud/?ROLE=Prima ry&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"format":"VHD","name":" ROOT-1","path":"f09879e9-fe76-4c2c-b051-164867c4099a","uuid":"f09879e9-fe76- 4c2c-b051-164867c4099a","size":0,"primaryDataStore":{"host":"192.168.1.79"," uri":"cifs://192.168.1.79/WINPrimary?user=cloudstackadmin&domain=cloud","_ro le":null,"Path":"\\192.168.1.79/WINPrimary","UncPath":"\\192.168.1.79/WINPri mary","User":"cloudstackadmin",,"Domain":"cloud","isLocal":false},"nfsDataSt ore":null,"FullFileName":"\\192.168.1.79\WINPrimary\f09879e9-fe76-4c2c-b051- 164867c4099a.vhd"}},"contextMap":{}}}] 2014-11-20 14:53:20,842 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-3:ctx-c859f450) POST response is [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":true,"deta ils":null,"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"dat aStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b48e 8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB","host":"192.168.1. 79","path":"/WINPrimary?user=cloudstackadmin&domain=cloud","port":445,"url": "SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&domain=cloud/?ROLE=Prima ry&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"format":"VHD","name":" ROOT-2","path":"bab80dd6-16da-4713-979d-c69b91d7eea6","uuid":"bab80dd6-16da- 4713-979d-c69b91d7eea6","size":0,"primaryDataStore":{"host":"192.168.1.79"," uri":"cifs://192.168.1.79/WINPrimary?user=cloudstackadmin&domain=cloud","_ro le":null,"Path":"\\192.168.1.79/WINPrimary","UncPath":"\\192.168.1.79/WINPri mary","User":"cloudstackadmin",,"Domain":"cloud","isLocal":false},"nfsDataSt ore":null,"FullFileName":"\\192.168.1.79\WINPrimary\bab80dd6-16da-4713-979d- c69b91d7eea6.vhd"}},"contextMap":{}}}] 2014-11-20 14:53:20,861 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-5:ctx-0427c434) executeRequest received response [Lcom.cloud.agent.api.Answer;@6addf124 2014-11-20 14:53:20,861 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5:ctx-0427c434) Seq 1-425590164786511882: Response Received: 2014-11-20 14:53:20,863 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-3:ctx-c859f450) executeRequest received response [Lcom.cloud.agent.api.Answer;@65a165fd 2014-11-20 14:53:20,863 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3:ctx-c859f450) Seq 1-425590164786511883: Response Received: 2014-11-20 14:53:20,871 DEBUG [c.c.a.t.Request] (DirectAgent-5:ctx-0427c434) Seq 1-425590164786511882: Processing: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apa che.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-1 64867c4099a","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStore TO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB"," host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin&domain=cloud", "port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&domain= cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"name" :"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c4099a","accountId" :0,"format":"VHD","id":0}},"result":true,"wait":0}}] } 2014-11-20 14:53:20,871 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511882: Received: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } } 2014-11-20 14:53:20,880 DEBUG [c.c.a.t.Request] (DirectAgent-3:ctx-c859f450) Seq 1-425590164786511883: Processing: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apa che.cloudstack.storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c 69b91d7eea6","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStore TO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB"," host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin&domain=cloud", "port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudstackadmin&domain= cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"name" :"ROOT-2","size":0,"path":"bab80dd6-16da-4713-979d-c69b91d7eea6","accountId" :0,"format":"VHD","id":0}},"result":true,"wait":0}}] } 2014-11-20 14:53:20,881 DEBUG [c.c.a.t.Request] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Seq 1-425590164786511883: Received: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } } 2014-11-20 14:53:20,901 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) releasing lock for VMTemplateStoragePool 1 2014-11-20 14:53:20,906 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) releasing lock for VMTemplateStoragePool 1 2014-11-20 14:53:20,906 WARN [c.c.u.d.Merovingian2] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Was unable to find lock for the key template_spool_ref1 and thread id 6728486 2014-11-20 14:53:21,054 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) VmWare hypervisor configured, telling the ssvm to load the PremiumSecondaryStorageResource 2014-11-20 14:53:21,072 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Boot Args for VM[SecondaryStorageVm|s-1-VM]: template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8 2014-11-20 14:53:21,078 DEBUG [c.c.c.ConsoleProxyManagerImpl] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Boot Args for VM[ConsoleProxy|v-2-VM]: template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8 2014-11-20 14:53:21,183 DEBUG [c.c.a.t.Request] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Seq 1-425590164786511884: Sending { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":2,"name":"v-2-VM","type":"C onsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"max Ram":1073741824,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"65ddb27a77d86ad2","params":{}," uuid":"d9fe04b4-2192-43ac-84a6-913916cc27e4","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c69b91 d7eea6","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-2","size":0,"path":"bab80dd6-16da-4713-979d-c69b91d7ee a6","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"VHD","id":2,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"bab80dd6-16da-4713-9 79d-c69b91d7eea6","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.237","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:d4:8e:00:00:1c","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.1.185","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:0 0:a9:fe:01:b9","broadcastType":"LinkLocal","type":"Control","isSecurityGroup Enabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid" :"246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.217","netmask":"255. 255.255.0","gateway":"192.168.1.254","mac":"06:75:be:00:00:08","broadcastTyp e":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtu alSwitch"}]},"hostIp":"192.168.1.78","executeInSequence":false,"wait":0}},{" com.cloud.agent.api.check.CheckSshCommand":{"ip":"192.168.1.217","port":3922 ,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}] } 2014-11-20 14:53:21,199 DEBUG [c.c.a.t.Request] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Seq 1-425590164786511884: Executing: { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":2,"name":"v-2-VM","type":"C onsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"max Ram":1073741824,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"65ddb27a77d86ad2","params":{}," uuid":"d9fe04b4-2192-43ac-84a6-913916cc27e4","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c69b91 d7eea6","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-2","size":0,"path":"bab80dd6-16da-4713-979d-c69b91d7ee a6","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"VHD","id":2,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"bab80dd6-16da-4713-9 79d-c69b91d7eea6","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.237","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:d4:8e:00:00:1c","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.1.185","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:0 0:a9:fe:01:b9","broadcastType":"LinkLocal","type":"Control","isSecurityGroup Enabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid" :"246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.217","netmask":"255. 255.255.0","gateway":"192.168.1.254","mac":"06:75:be:00:00:08","broadcastTyp e":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtu alSwitch"}]},"hostIp":"192.168.1.78","executeInSequence":false,"wait":0}},{" com.cloud.agent.api.check.CheckSshCommand":{"ip":"192.168.1.217","port":3922 ,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}] } 2014-11-20 14:53:21,200 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6:ctx-89f721b0) Seq 1-425590164786511884: Executing request 2014-11-20 14:53:21,224 DEBUG [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) Executing: sudo mount -t cifs //192.168.1.79/SWINSecondary /var/cloudstack/mnt/VM/52237247174.293b50a1 -o uid=cloud,gid=cloud -o user=cloudstackadmin,password=dell_456,domain=cloud 2014-11-20 14:53:21,234 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511885: Sending { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":1,"name":"s-1-VM","type":"S econdaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912 ,"maxRam":536870912,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"6cb55063a5328305","params":{}," uuid":"3c294f1b-c110-4a3f-a23f-73f8fd54bbe8","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-164867 c4099a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c409 9a","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"VHD","id":1,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"f09879e9-fe76-4c2c-b 051-164867c4099a","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.236","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:06:40:00:00:1b","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.2.19","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00 :a9:fe:02:13","broadcastType":"LinkLocal","type":"Control","isSecurityGroupE nabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid": "246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.214","netmask":"255.2 55.255.0","gateway":"192.168.1.254","mac":"06:31:c2:00:00:05","broadcastType ":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtua lSwitch"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"bb6d d0ef-ef4c-47a6-a553-3f4463909e73","ip":"192.168.1.216","netmask":"255.255.25 5.0","gateway":"192.168.1.254","mac":"06:22:28:00:00:07","broadcastType":"Na tive","type":"Storage","isSecurityGroupEnabled":false,"name":"VirtualSwitch" }]},"hostIp":"192.168.1.78","executeInSequence":false,"wait":0}},{"com.cloud .agent.api.check.CheckSshCommand":{"ip":"192.168.1.214","port":3922,"interva l":6,"retries":100,"name":"s-1-VM","wait":0}}] } 2014-11-20 14:53:21,244 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511885: Executing: { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":1,"name":"s-1-VM","type":"S econdaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912 ,"maxRam":536870912,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"6cb55063a5328305","params":{}," uuid":"3c294f1b-c110-4a3f-a23f-73f8fd54bbe8","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-164867 c4099a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c409 9a","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"VHD","id":1,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"f09879e9-fe76-4c2c-b 051-164867c4099a","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.236","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:06:40:00:00:1b","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.2.19","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00 :a9:fe:02:13","broadcastType":"LinkLocal","type":"Control","isSecurityGroupE nabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid": "246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.214","netmask":"255.2 55.255.0","gateway":"192.168.1.254","mac":"06:31:c2:00:00:05","broadcastType ":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtua lSwitch"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"bb6d d0ef-ef4c-47a6-a553-3f4463909e73","ip":"192.168.1.216","netmask":"255.255.25 5.0","gateway":"192.168.1.254","mac":"06:22:28:00:00:07","broadcastType":"Na tive","type":"Storage","isSecurityGroupEnabled":false,"name":"VirtualSwitch" }]},"hostIp":"192.168.1.78","executeInSequence":false,"wait":0}},{"com.cloud .agent.api.check.CheckSshCommand":{"ip":"192.168.1.214","port":3922,"interva l":6,"retries":100,"name":"s-1-VM","wait":0}}] } 2014-11-20 14:53:21,245 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-7:ctx-5843c848) Seq 1-425590164786511885: Executing request 2014-11-20 14:53:21,853 DEBUG [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) Execution is successful. 2014-11-20 14:53:21,856 DEBUG [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) Executing: sudo chmod -R 777 /var/cloudstack/mnt/VM/52237247174.293b50a1 2014-11-20 14:53:21,881 DEBUG [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) Exit value is 1 2014-11-20 14:53:21,882 DEBUG [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) chmod: changing permissions of `/var/cloudstack/mnt/VM/52237247174.293b50a1': Permission denied 2014-11-20 14:53:21,882 WARN [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) Unable to set permissions for /var/cloudstack/mnt/VM/52237247174.293b50a1 due to chmod: changing permissions of `/var/cloudstack/mnt/VM/52237247174.293b50a1': Permission denied 2014-11-20 14:53:21,888 INFO [c.c.h.h.m.HypervManagerImpl] (DirectAgent-6:ctx-89f721b0) Copy System VM patch ISO file to secondary storage. source ISO: /usr/share/cloudstack-common/vms/systemvm.iso, destination: /var/cloudstack/mnt/VM/52237247174.293b50a1/systemvm/systemvm-4.4.1-SNAPSHOT .iso 2014-11-20 14:53:22,831 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-6:ctx-89f721b0) POST request to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StartComman d with contents {"vm":{"id":2,"name":"v-2-VM","type":"ConsoleProxy","cpus":1,"minSpeed":500, "maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os": "Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255. 0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"65ddb27a77d86ad2","params":{}," uuid":"d9fe04b4-2192-43ac-84a6-913916cc27e4","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c69b91 d7eea6","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-2","size":0,"path":"bab80dd6-16da-4713-979d-c69b91d7ee a6","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"VHD","id":2,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"bab80dd6-16da-4713-9 79d-c69b91d7eea6","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.237","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:d4:8e:00:00:1c","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.1.185","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:0 0:a9:fe:01:b9","broadcastType":"LinkLocal","type":"Control","isSecurityGroup Enabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid" :"246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.217","netmask":"255. 255.255.0","gateway":"192.168.1.254","mac":"06:75:be:00:00:08","broadcastTyp e":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtu alSwitch"}]},"hostIp":"192.168.1.78","executeInSequence":false,"secondarySto rage":"cifs://192.168.1.79/SWINSecondary?user=cloudstackadmin&domain=cloud", "contextMap":{},"wait":0} 2014-11-20 14:53:22,833 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-7:ctx-5843c848) POST request to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StartComman d with contents {"vm":{"id":1,"name":"s-1-VM","type":"SecondaryStorageVm","cpus":1,"minSpeed ":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64"," os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"6cb55063a5328305","params":{}," uuid":"3c294f1b-c110-4a3f-a23f-73f8fd54bbe8","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-164867 c4099a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c409 9a","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"VHD","id":1,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"f09879e9-fe76-4c2c-b 051-164867c4099a","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.236","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:06:40:00:00:1b","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.2.19","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00 :a9:fe:02:13","broadcastType":"LinkLocal","type":"Control","isSecurityGroupE nabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid": "246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.214","netmask":"255.2 55.255.0","gateway":"192.168.1.254","mac":"06:31:c2:00:00:05","broadcastType ":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtua lSwitch"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"bb6d d0ef-ef4c-47a6-a553-3f4463909e73","ip":"192.168.1.216","netmask":"255.255.25 5.0","gateway":"192.168.1.254","mac":"06:22:28:00:00:07","broadcastType":"Na tive","type":"Storage","isSecurityGroupEnabled":false,"name":"VirtualSwitch" }]},"hostIp":"192.168.1.78","executeInSequence":false,"secondaryStorage":"ci fs://192.168.1.79/SWINSecondary?user=cloudstackadmin&domain=cloud","contextM ap":{},"wait":0} 2014-11-20 14:53:22,860 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-6:ctx-89f721b0) Sending cmd to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StartComman d cmd data:{"vm":{"id":2,"name":"v-2-VM","type":"ConsoleProxy","cpus":1,"minSpeed" :500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64", "os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false, "enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPa ssword":"65ddb27a77d86ad2","params":{},"uuid":"d9fe04b4-2192-43ac-84a6-91391 6cc27e4","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO" :{"uuid":"bab80dd6-16da-4713-979d-c69b91d7eea6","volumeType":"ROOT","dataSto re":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b48e8cd6 -8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB","host":"192.168.1.79", "path":"/WINPrimary?user=cloudstackadmin&domain=cloud","port":445,"url":"SMB ://192.168.1.79/WINPrimary?user=cloudstackadmin&domain=cloud/?ROLE=Primary&S TOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"name":"ROOT-2","size":0,"p ath":"bab80dd6-16da-4713-979d-c69b91d7eea6","volumeId":2,"vmName":"v-2-VM"," accountId":1,"format":"VHD","id":2,"deviceId":0,"hypervisorType":"Hyperv"}}, "diskSeq":0,"path":"bab80dd6-16da-4713-979d-c69b91d7eea6","type":"ROOT","_de tails":{"managed":"false","storagePort":"445","storageHost":"192.168.1.79"," volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":t rue,"uuid":"88b614de-d611-4e46-94e5-54762d10f1c7","ip":"192.168.1.237","netm ask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:d4:8e:00:00:1c","dn s1":"192.168.1.129","dns2":"8.8.8.8","broadcastType":"Native","type":"Guest" ,"broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true,"name":"Virt ualSwitch"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"fe 7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip":"169.254.1.185","netmask":"255.255. 0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:b9","broadcastType":"Link Local","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"netwo rkRateMbps":-1,"defaultNic":false,"uuid":"246aa3bd-83d6-44ea-98ce-d0ff65b292 49","ip":"192.168.1.217","netmask":"255.255.255.0","gateway":"192.168.1.254" ,"mac":"06:75:be:00:00:08","broadcastType":"Native","type":"Management","isS ecurityGroupEnabled":false,"name":"VirtualSwitch"}]},"hostIp":"192.168.1.78" ,"executeInSequence":false,"secondaryStorage":"cifs://192.168.1.79/SWINSecon dary?user=cloudstackadmin&domain=cloud","contextMap":{},"wait":0} 2014-11-20 14:53:22,867 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-7:ctx-5843c848) Sending cmd to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StartComman d cmd data:{"vm":{"id":1,"name":"s-1-VM","type":"SecondaryStorageVm","cpus":1,"min Speed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_ 64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"6cb55063a5328305","params":{}," uuid":"3c294f1b-c110-4a3f-a23f-73f8fd54bbe8","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-164867 c4099a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c409 9a","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"VHD","id":1,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"f09879e9-fe76-4c2c-b 051-164867c4099a","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.236","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:06:40:00:00:1b","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.2.19","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00 :a9:fe:02:13","broadcastType":"LinkLocal","type":"Control","isSecurityGroupE nabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid": "246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.214","netmask":"255.2 55.255.0","gateway":"192.168.1.254","mac":"06:31:c2:00:00:05","broadcastType ":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtua lSwitch"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"bb6d d0ef-ef4c-47a6-a553-3f4463909e73","ip":"192.168.1.216","netmask":"255.255.25 5.0","gateway":"192.168.1.254","mac":"06:22:28:00:00:07","broadcastType":"Na tive","type":"Storage","isSecurityGroupEnabled":false,"name":"VirtualSwitch" }]},"hostIp":"192.168.1.78","executeInSequence":false,"secondaryStorage":"ci fs://192.168.1.79/SWINSecondary?user=cloudstackadmin&domain=cloud","contextM ap":{},"wait":0} 2014-11-20 14:53:22,914 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-69f3909c) Checking if any host reservation can be released ... 2014-11-20 14:53:22,927 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-69f3909c) Cannot release reservation, Found 2 VMs Running on host 1 2014-11-20 14:53:22,927 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-69f3909c) Done running HostReservationReleaseChecker ... 2014-11-20 14:53:23,022 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-25dcf22e) Found 0 routers to update status. 2014-11-20 14:53:23,024 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-25dcf22e) Found 0 networks to update RvR status. 2014-11-20 14:53:23,063 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Running Capacity Checker ... 2014-11-20 14:53:23,063 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) recalculating system capacity 2014-11-20 14:53:23,063 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Executing cpu/ram capacity update 2014-11-20 14:53:23,073 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-7f67c97e) Found 2 VMs on host 1 2014-11-20 14:53:23,077 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-7f67c97e) Found 0 VM, not running on host 1 2014-11-20 14:53:23,080 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-7f67c97e) No need to calibrate cpu capacity, host:1 usedCpu: 1000 reservedCpu: 0 2014-11-20 14:53:23,080 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-7f67c97e) No need to calibrate memory capacity, host:1 usedMem: 1610612736 reservedMem: 0 2014-11-20 14:53:23,084 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Done executing cpu/ram capacity update 2014-11-20 14:53:23,084 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Executing storage capacity update 2014-11-20 14:53:23,093 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-7f67c97e) Found storage pool WINPrimary of type SMB 2014-11-20 14:53:23,093 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-7f67c97e) Total over provisioned capacity of the pool WINPrimary id: 1 is 149954752512 2014-11-20 14:53:23,093 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-7f67c97e) Successfully set Capacity - 149954752512 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1 2014-11-20 14:53:23,093 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Done executing storage capacity update 2014-11-20 14:53:23,093 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Executing capacity updates for public ip and Vlans 2014-11-20 14:53:23,107 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Done capacity updates for public ip and Vlans 2014-11-20 14:53:23,107 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Executing capacity updates for private ip 2014-11-20 14:53:23,121 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Done executing capacity updates for private ip 2014-11-20 14:53:23,121 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Done recalculating system capacity 2014-11-20 14:53:23,151 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-7f67c97e) Done running Capacity Checker ... 2014-11-20 14:53:25,145 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-7:ctx-5843c848) POST response is [{"com.cloud.agent.api.StartAnswer":{"result":false,"details":"com.cloud.age nt.api.StartCommand fail on exceptionObject reference not set to an instance of an object.","vm":{"id":1,"name":"s-1-VM","type":"SecondaryStorageVm","cpus":1," minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x 86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"6cb55063a5328305","params":{}," uuid":"3c294f1b-c110-4a3f-a23f-73f8fd54bbe8","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-164867 c4099a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c409 9a","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"VHD","id":1,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"f09879e9-fe76-4c2c-b 051-164867c4099a","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.236","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:06:40:00:00:1b","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.2.19","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00 :a9:fe:02:13","broadcastType":"LinkLocal","type":"Control","isSecurityGroupE nabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid": "246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.214","netmask":"255.2 55.255.0","gateway":"192.168.1.254","mac":"06:31:c2:00:00:05","broadcastType ":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtua lSwitch"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"bb6d d0ef-ef4c-47a6-a553-3f4463909e73","ip":"192.168.1.216","netmask":"255.255.25 5.0","gateway":"192.168.1.254","mac":"06:22:28:00:00:07","broadcastType":"Na tive","type":"Storage","isSecurityGroupEnabled":false,"name":"VirtualSwitch" }]},"contextMap":{}}}] 2014-11-20 14:53:25,165 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-7:ctx-5843c848) executeRequest received response [Lcom.cloud.agent.api.Answer;@449814d7 2014-11-20 14:53:25,165 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-7:ctx-5843c848) Seq 1-425590164786511885: Cancelling because one of the answers is false and it is stop on error. 2014-11-20 14:53:25,165 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-7:ctx-5843c848) Seq 1-425590164786511885: Response Received: 2014-11-20 14:53:25,187 DEBUG [c.c.a.t.Request] (DirectAgent-7:ctx-5843c848) Seq 1-425590164786511885: Processing: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":1,"name":"s-1-VM","type":"Se condaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912, "maxRam":536870912,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.130 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.1.236 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.2.19 eth0mask=255.255.0.0 eth1ip=192.168.1.214 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 private.network.device=eth1 eth3ip=192.168.1.216 eth3mask=255.255.255.0 storageip=192.168.1.216 storagenetmask=255.255.255.0 storagegateway=192.168. 1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"6cb55063a5328305","params":{}," uuid":"3c294f1b-c110-4a3f-a23f-73f8fd54bbe8","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"f09879e9-fe76-4c2c-b051-164867 c4099a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-1","size":0,"path":"f09879e9-fe76-4c2c-b051-164867c409 9a","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"VHD","id":1,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"f09879e9-fe76-4c2c-b 051-164867c4099a","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.236","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:06:40:00:00:1b","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.2.19","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00 :a9:fe:02:13","broadcastType":"LinkLocal","type":"Control","isSecurityGroupE nabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid": "246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.214","netmask":"255.2 55.255.0","gateway":"192.168.1.254","mac":"06:31:c2:00:00:05","broadcastType ":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtua lSwitch"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"bb6d d0ef-ef4c-47a6-a553-3f4463909e73","ip":"192.168.1.216","netmask":"255.255.25 5.0","gateway":"192.168.1.254","mac":"06:22:28:00:00:07","broadcastType":"Na tive","type":"Storage","isSecurityGroupEnabled":false,"name":"VirtualSwitch" }]},"result":false,"details":"com.cloud.agent.api.StartCommand fail on exceptionObject reference not set to an instance of an object.","wait":0}}] } 2014-11-20 14:53:25,187 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511885: Received: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, { StartAnswer } } 2014-11-20 14:53:25,191 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Unable to start VM on Host[-1-Routing] due to com.cloud.agent.api.StartCommand fail on exceptionObject reference not set to an instance of an object. 2014-11-20 14:53:25,194 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Cleaning up resources for the vm VM[SecondaryStorageVm|s-1-VM] in Starting state 2014-11-20 14:53:25,201 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511886: Sending { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal se,"checkBeforeCleanup":false,"vmName":"s-1-VM","wait":0}}] } 2014-11-20 14:53:25,201 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511886: Executing: { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal se,"checkBeforeCleanup":false,"vmName":"s-1-VM","wait":0}}] } 2014-11-20 14:53:25,203 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-8:ctx-a8bd9166) Seq 1-425590164786511886: Executing request 2014-11-20 14:53:25,203 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-8:ctx-a8bd9166) POST request to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StopCommand with contents {"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmNam e":"s-1-VM","contextMap":{},"wait":0} 2014-11-20 14:53:25,219 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-8:ctx-a8bd9166) Sending cmd to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StopCommand cmd data:{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false," vmName":"s-1-VM","contextMap":{},"wait":0} 2014-11-20 14:53:25,600 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-6:ctx-89f721b0) POST response is [{"com.cloud.agent.api.StartAnswer":{"result":false,"details":"com.cloud.age nt.api.StartCommand fail on exceptionObject reference not set to an instance of an object.","vm":{"id":2,"name":"v-2-VM","type":"ConsoleProxy","cpus":1,"minSpe ed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_6 4","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false, "enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPa ssword":"65ddb27a77d86ad2","params":{},"uuid":"d9fe04b4-2192-43ac-84a6-91391 6cc27e4","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO" :{"uuid":"bab80dd6-16da-4713-979d-c69b91d7eea6","volumeType":"ROOT","dataSto re":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b48e8cd6 -8ec5-3c34-8a43-020c6daaaea9","id":1,"poolType":"SMB","host":"192.168.1.79", "path":"/WINPrimary?user=cloudstackadmin&domain=cloud","port":445,"url":"SMB ://192.168.1.79/WINPrimary?user=cloudstackadmin&domain=cloud/?ROLE=Primary&S TOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6daaaea9"}},"name":"ROOT-2","size":0,"p ath":"bab80dd6-16da-4713-979d-c69b91d7eea6","volumeId":2,"vmName":"v-2-VM"," accountId":1,"format":"VHD","id":2,"deviceId":0,"hypervisorType":"Hyperv"}}, "diskSeq":0,"path":"bab80dd6-16da-4713-979d-c69b91d7eea6","type":"ROOT","_de tails":{"managed":"false","storagePort":"445","storageHost":"192.168.1.79"," volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":t rue,"uuid":"88b614de-d611-4e46-94e5-54762d10f1c7","ip":"192.168.1.237","netm ask":"255.255.255.0","gateway":"192.168.1.254","mac":"06:d4:8e:00:00:1c","dn s1":"192.168.1.129","dns2":"8.8.8.8","broadcastType":"Native","type":"Guest" ,"broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true,"name":"Virt ualSwitch"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"fe 7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip":"169.254.1.185","netmask":"255.255. 0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:b9","broadcastType":"Link Local","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"netwo rkRateMbps":-1,"defaultNic":false,"uuid":"246aa3bd-83d6-44ea-98ce-d0ff65b292 49","ip":"192.168.1.217","netmask":"255.255.255.0","gateway":"192.168.1.254" ,"mac":"06:75:be:00:00:08","broadcastType":"Native","type":"Management","isS ecurityGroupEnabled":false,"name":"VirtualSwitch"}]},"contextMap":{}}}] 2014-11-20 14:53:25,606 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-6:ctx-89f721b0) executeRequest received response [Lcom.cloud.agent.api.Answer;@6f800ac8 2014-11-20 14:53:25,606 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6:ctx-89f721b0) Seq 1-425590164786511884: Cancelling because one of the answers is false and it is stop on error. 2014-11-20 14:53:25,606 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6:ctx-89f721b0) Seq 1-425590164786511884: Response Received: 2014-11-20 14:53:25,614 DEBUG [c.c.a.t.Request] (DirectAgent-6:ctx-89f721b0) Seq 1-425590164786511884: Processing: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":2,"name":"v-2-VM","type":"Co nsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxR am":1073741824,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.1.130 port=8250 name=v-2-VM zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.237 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.1.185 eth0mask=255.255.0.0 eth1ip=192.168.1.217 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.129 internaldns2=8.8.8.8 dns1=192.168.1.129 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"en ableDynamicallyScaleVm":false,"vncPassword":"65ddb27a77d86ad2","params":{}," uuid":"d9fe04b4-2192-43ac-84a6-913916cc27e4","disks":[{"data":{"org.apache.c loudstack.storage.to.VolumeObjectTO":{"uuid":"bab80dd6-16da-4713-979d-c69b91 d7eea6","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.P rimaryDataStoreTO":{"uuid":"b48e8cd6-8ec5-3c34-8a43-020c6daaaea9","id":1,"po olType":"SMB","host":"192.168.1.79","path":"/WINPrimary?user=cloudstackadmin &domain=cloud","port":445,"url":"SMB://192.168.1.79/WINPrimary?user=cloudsta ckadmin&domain=cloud/?ROLE=Primary&STOREUUID=b48e8cd6-8ec5-3c34-8a43-020c6da aaea9"}},"name":"ROOT-2","size":0,"path":"bab80dd6-16da-4713-979d-c69b91d7ee a6","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"VHD","id":2,"devi ceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"path":"bab80dd6-16da-4713-9 79d-c69b91d7eea6","type":"ROOT","_details":{"managed":"false","storagePort": "445","storageHost":"192.168.1.79","volumeSize":"0"}}],"nics":[{"deviceId":2 ,"networkRateMbps":-1,"defaultNic":true,"uuid":"88b614de-d611-4e46-94e5-5476 2d10f1c7","ip":"192.168.1.237","netmask":"255.255.255.0","gateway":"192.168. 1.254","mac":"06:d4:8e:00:00:1c","dns1":"192.168.1.129","dns2":"8.8.8.8","br oadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSec urityGroupEnabled":true,"name":"VirtualSwitch"},{"deviceId":0,"networkRateMb ps":-1,"defaultNic":false,"uuid":"fe7ff75d-67d7-4728-afc9-6cc6d4f8760b","ip" :"169.254.1.185","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:0 0:a9:fe:01:b9","broadcastType":"LinkLocal","type":"Control","isSecurityGroup Enabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid" :"246aa3bd-83d6-44ea-98ce-d0ff65b29249","ip":"192.168.1.217","netmask":"255. 255.255.0","gateway":"192.168.1.254","mac":"06:75:be:00:00:08","broadcastTyp e":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"Virtu alSwitch"}]},"result":false,"details":"com.cloud.agent.api.StartCommand fail on exceptionObject reference not set to an instance of an object.","wait":0}}] } 2014-11-20 14:53:25,614 DEBUG [c.c.a.t.Request] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Seq 1-425590164786511884: Received: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, { StartAnswer } } 2014-11-20 14:53:25,622 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Unable to start VM on Host[-1-Routing] due to com.cloud.agent.api.StartCommand fail on exceptionObject reference not set to an instance of an object. 2014-11-20 14:53:25,625 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state 2014-11-20 14:53:25,631 DEBUG [c.c.a.t.Request] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Seq 1-425590164786511887: Sending { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal se,"checkBeforeCleanup":false,"vmName":"v-2-VM","wait":0}}] } 2014-11-20 14:53:25,632 DEBUG [c.c.a.t.Request] (Work-Job-Executor-2:ctx-c1208fbd job-2/job-10 ctx-5358fd84) Seq 1-425590164786511887: Executing: { Cmd , MgmtId: 52237247174, via: 1(192.168.1.78), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal se,"checkBeforeCleanup":false,"vmName":"v-2-VM","wait":0}}] } 2014-11-20 14:53:25,632 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1:ctx-704d22cf) Seq 1-425590164786511887: Executing request 2014-11-20 14:53:25,633 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-1:ctx-704d22cf) POST request to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StopCommand with contents {"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmNam e":"v-2-VM","contextMap":{},"wait":0} 2014-11-20 14:53:25,642 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-1:ctx-704d22cf) Sending cmd to https://192.168.1.78:8250/api/HypervResource/com.cloud.agent.api.StopCommand cmd data:{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false," vmName":"v-2-VM","contextMap":{},"wait":0} 2014-11-20 14:53:26,717 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-8:ctx-a8bd9166) POST response is [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":null,"vm":null," contextMap":{}}}] 2014-11-20 14:53:26,718 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-8:ctx-a8bd9166) executeRequest received response [Lcom.cloud.agent.api.Answer;@682fcaba 2014-11-20 14:53:26,719 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-8:ctx-a8bd9166) Seq 1-425590164786511886: Response Received: 2014-11-20 14:53:26,719 DEBUG [c.c.a.t.Request] (DirectAgent-8:ctx-a8bd9166) Seq 1-425590164786511886: Processing: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] } 2014-11-20 14:53:26,719 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Seq 1-425590164786511886: Received: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, { StopAnswer } } 2014-11-20 14:53:26,753 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Asking SecurityGroupProvider to release NicProfile[1-1-f3a53a4e-da5d-4c91-a95d-8cac27008d16-192.168.1.236-vlan://unt agged 2014-11-20 14:53:26,757 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Asking VirtualRouter to release NicProfile[1-1-f3a53a4e-da5d-4c91-a95d-8cac27008d16-192.168.1.236-vlan://unt agged 2014-11-20 14:53:26,762 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Released nic: NicProfile[2-1-null-null-null 2014-11-20 14:53:26,773 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Releasing ip address for reservationId=f3a53a4e-da5d-4c91-a95d-8cac27008d16, instance=3 2014-11-20 14:53:26,774 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Released nic: NicProfile[3-1-null-null-null 2014-11-20 14:53:26,786 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Releasing ip address for reservationId=f3a53a4e-da5d-4c91-a95d-8cac27008d16, instance=5 2014-11-20 14:53:26,786 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Released nic: NicProfile[5-1-null-null-null 2014-11-20 14:53:26,790 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Successfully released network resources for the vm VM[SecondaryStorageVm|s-1-VM] 2014-11-20 14:53:26,790 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-1-VM] in Starting state 2014-11-20 14:53:26,795 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Root volume is ready, need to place VM in volume's cluster 2014-11-20 14:53:26,795 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Vol[1|vm=1|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1 2014-11-20 14:53:26,798 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Deploy avoids pods: null, clusters: null, hosts: [1] 2014-11-20 14:53:26,799 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@6ba6ccb5 2014-11-20 14:53:26,799 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912 2014-11-20 14:53:26,799 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Is ROOT volume READY (pool already allocated)?: Yes 2014-11-20 14:53:26,800 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Searching resources only under specified Cluster: 1 2014-11-20 14:53:26,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Checking resources in Cluster: 1 under Pod: 1 2014-11-20 14:53:26,808 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 2014-11-20 14:53:26,813 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] 2014-11-20 14:53:26,820 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2014-11-20 14:53:26,820 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512 2014-11-20 14:53:26,820 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927 FirstFitRoutingAllocator) Host name: 192.168.1.78, hostId: 1 is in avoid set, skipping this and trying other available hosts 2014-11-20 14:53:26,820 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts 2014-11-20 14:53:26,820 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) No suitable hosts found 2014-11-20 14:53:26,820 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) No suitable hosts found under this Cluster: 1 2014-11-20 14:53:26,823 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Could not find suitable Deployment Destination for this VM under any clusters, returning. 2014-11-20 14:53:26,823 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Searching resources only under specified Cluster: 1 2014-11-20 14:53:26,824 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) The specified cluster is in avoid set, returning. 2014-11-20 14:53:26,827 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Deploy avoids pods: null, clusters: [1], hosts: [1] 2014-11-20 14:53:26,828 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@6ba6ccb5 2014-11-20 14:53:26,828 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912 2014-11-20 14:53:26,828 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Is ROOT volume READY (pool already allocated)?: No 2014-11-20 14:53:26,829 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Searching all possible resources under this Zone: 1 2014-11-20 14:53:26,830 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1 2014-11-20 14:53:26,835 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Removing from the clusterId list these clusters from avoid set: [1] 2014-11-20 14:53:26,836 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) No clusters found after removing disabled clusters and clusters in avoid list, returning. 2014-11-20 14:53:26,856 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1 2014-11-20 14:53:26,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Hosts's actual total CPU: 32000 and CPU after applying overprovisioning: 32000 2014-11-20 14:53:26,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Hosts's actual total RAM: 137357664256 and RAM after applying overprovisioning: 137357664256 2014-11-20 14:53:26,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 32000, total with overprovisioning: 32000; new used: 500,reserved:0; movedfromreserved: false, moveToReserveredfalse 2014-11-20 14:53:26,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) release mem from host: 1, old used: 1610612736,reserved: 0, total: 137357664256; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse 2014-11-20 14:53:26,872 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-1:ctx-704d22cf) POST response is [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":null,"vm":null," contextMap":{}}}] 2014-11-20 14:53:26,873 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-1:ctx-704d22cf) executeRequest received response [Lcom.cloud.agent.api.Answer;@48486fc3 2014-11-20 14:53:26,874 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1:ctx-704d22cf) Seq 1-425590164786511887: Response Received: 2014-11-20 14:53:26,874 DEBUG [c.c.a.t.Request] (DirectAgent-1:ctx-704d22cf) Seq 1-425590164786511887: Processing: { Ans: , MgmtId: 52237247174, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] } 2014-11-20 14:53:26,875 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2014-11-20 14:53:26,875 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11 ctx-ebe86927) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2014-11-20 14:53:26,876 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 1, job origin: 1 2014-11-20 14:53:26,876 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-62db4a9e job-1/job-11) Unable to complete AsyncJobVO {id:11, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB- AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAB AAAAAAAAAAEAAAAAAAAAAXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw cHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52237247174, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Nov 20 14:53:03 CST 2014}, job origin:1 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage rImpl.java:947) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage rImpl.java:5195) 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.jav a:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager Impl.java:5340) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext (AsyncJobManagerImpl.java:503) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo ntextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa ultManagedContext.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(ManagedCont extRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob ManagerImpl.java:460) 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:11 45) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6 15) and The logs in the Hyperv server is as follows: Error HypervResource.HypervResourceController - com.cloud.agent.api.StartCommand fail in exceptionObject reference not set to an instance of an object. System.NullReferenceException: Object reference not set to an instance of an object. At HypervResource.WmiCallsV2.DeployVirtualMachine(object JsonObj, String systemVmIso) At HypervResource.HypervResourceController.StartCommand(Object cmd) khmu -----邮件原件----- 发件人: 穆凯辉 [mailto:k...@landhightech.com] 发送时间: 2014年11月20日 16:06 收件人: dev@cloudstack.apache.org 主题: 答复: hyperv ssvm start failed Hi, We still can not run cloudstack 4.4.1 + hyperv successfully. The Hyperv ssvm still can not start successfully. We run cloudstack 4.4.1 in centos 6.5, not added into ad. A 2012 R2 Hyperv server is used to create hyperv vm with two Ethernet, one for cloudstack management, and an external switch created on the other enternet. This hyperv server have been added to AD. A windows server 2012 is created for the Primary and Secondary storage use SMB protocol, which also has been added into ad. When we start the whole zone. The ssvm can not start successfully. The log of cloudstack is attached in this mail as named "error.log" and The error log in Hyperv Server is only one as shown in "hyperv-server.png". Should the cloudstack manage server be added into AD? Your response is very important for us. Thank you very much. khmu -----邮件原件----- 发件人: 穆凯辉 [mailto:k...@landhightech.com] 发送时间: 2014年11月14日 15:42 收件人: dev@cloudstack.apache.org 主题: 答复: hyperv ssvm start failed Sorry, we encountered some problem to install the windows server 2012 dc R2. So we now try to install Hyperv server 2012 r2. Can windows server 2012 dc be also used for hyperv host with cloudstack 4.4? We will inform you as soon as possible if there is some progress. ------------------------------------------------ -----邮件原件----- 发件人: Rajesh Battala [mailto:rajesh.batt...@citrix.com] 发送时间: 2014年11月14日 15:24 收件人: dev@cloudstack.apache.org 主题: RE: hyperv ssvm start failed Is it working now? -----Original Message----- From: 穆凯辉 [mailto:k...@landhightech.com] Sent: Thursday, November 13, 2014 11:52 AM To: dev@cloudstack.apache.org Subject: 答复: hyperv ssvm start failed Ok. We will change to windows server 2012 hyperv host with English locale set. Thank you very much. ---------------------------------------------------------------------------- ------------------------------- 穆凯辉 苏州蓝海彤翔系统科技有限公司 Suzhou Land High System Tech CO.,Ltd 地址:苏州高新区科灵路78号7号楼2层 手机:13771859356 邮编:215163 ---------------------------------------------------------------------------- ------------------------------- -----邮件原件----- 发件人: Anshul Gangwar [mailto:anshul.gang...@citrix.com] 发送时间: 2014年11月13日 14:00 收件人: dev@cloudstack.apache.org 主题: RE: hyperv ssvm start failed Probably you are facing issue https://issues.apache.org/jira/browse/CLOUDSTACK-7277. -----Original Message----- From: Anshul Gangwar [mailto:anshul.gang...@citrix.com] Sent: Thursday, November 13, 2014 10:52 AM To: dev@cloudstack.apache.org Subject: RE: hyperv ssvm start failed You got me wrong. I have not suggested to change permissions. I have suggested to change the locale to US English(instead of Chinese/Japanese) of account with which the Hyper-V Agent service is running. I suspect that your windows server account is running in different locale other than English. -----Original Message----- From: 穆凯辉 [mailto:k...@landhightech.com] Sent: Thursday, November 13, 2014 6:10 AM To: dev@cloudstack.apache.org Subject: 答复: hyperv ssvm start failed Thanks. We try to run Hyper-v agent by local administrator. But the agent crashed. So we change to use domain administrator to run this agent. We will try to create a new user to run this agent. Thank you very much. ---------------------------------------------------------------------------- ------------------------------- -----邮件原件----- 发件人: Anshul Gangwar [mailto:anshul.gang...@citrix.com] 发送时间: 2014年11月12日 19:39 收件人: dev@cloudstack.apache.org 主题: RE: hyperv ssvm start failed You have to run Hyper-V Agent service with the account which has it locale set to US English. -----Original Message----- From: 穆凯辉 [mailto:k...@landhightech.com] Sent: Wednesday, November 12, 2014 4:56 PM To: dev@cloudstack.apache.org Subject: hyperv ssvm start failed Hi all, We use cloudstack 4.4.0 to manage a windows server 2012 dc hyper-v host. Both of the primary and secondary storage are setup on this windows hyper-v host using SMB protocol. The Virtual Switch in Hyperv is named “VirtualNetork”. when we start the zone, the ssvm is created in hyper-v, but it can not start, and is destroy immediately. The error event in windows is as follows: 2014-11-12 18:55:03,150 [12] INFO HypervResource.HypervResourceController [55c7a1ce-0320-4976-9915-ae6fb44682ba] - { "com.cloud.agent.api.StartAnswer": { "result": false, "details": "com.cloud.agent.api.StartCommand fail on exception未将对象引 用设置到对象的实例。", "vm": { "id": 1, "name": "v-1-VM", "type": "ConsoleProxy", "cpus": 1, "minSpeed": 500, "maxSpeed": 500, "minRam": 1073741824, "maxRam": 1073741824, "arch": "x86_64", "os": "Debian GNU/Linux 5.0 (64-bit)", "bootArgs": " template=domP type=consoleproxy host=192.168.1.137 port=8250 name=v-1-VM zone=1 pod=1 guid=Proxy.1 proxy_vm=1 disable_rp_filter=true eth2ip=192.168.1.33 eth2mask=255.255.255.0 gateway=192.168.1.254 eth0ip=169.254.0.70 eth0mask=255.255.0.0 eth1ip=192.168.1.224 eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.254 internaldns1=192.168.1.92 internaldns2=8.8.8.8 dns1=192.168.1.92 dns2=8.8.8.8", "rebootOnCrash": false, "enableHA": false, "limitCpuUse": false, "enableDynamicallyScaleVm": false, "vncPassword": "861c2ac4e36ed3c3", "params": {}, "uuid": "0c1a15f6-5cc6-4c10-8cf7-46fac26ee215", "disks": [ { "data": { "org.apache.cloudstack.storage.to.VolumeObjectTO": { "uuid": "8b299dfc-2453-4e6a-bd02-b6dcc12fb32a", "volumeType": "ROOT", "dataStore": { "org.apache.cloudstack.storage.to.PrimaryDataStoreTO": { "uuid": "2c739a85-40bf-365f-b448-152f6e10cad0", "id": 2, "poolType": "SMB", "host": "192.168.1.80", "path": "/Primary?user=administrator&domain=vsdevel", "port": 445, "url": "SMB://192.168.1.80/Primary?user=administrator&domain=vsdevel/?ROLE=Primary& STOREUUID=2c739a85-40bf-365f-b448-152f6e10cad0" } }, "name": "ROOT-1", "size": 0, "path": "8b299dfc-2453-4e6a-bd02-b6dcc12fb32a", "volumeId": 1, "vmName": "v-1-VM", "accountId": 1, "format": "VHD", "id": 1, "deviceId": 0, "hypervisorType": "Hyperv" } }, "diskSeq": 0, "path": "8b299dfc-2453-4e6a-bd02-b6dcc12fb32a", "type": "ROOT", "_details": { "managed": "false", "storagePort": "445", "storageHost": "192.168.1.80", "volumeSize": "0" } } ], "nics": [ { "deviceId": 2, "networkRateMbps": -1, "defaultNic": true, "uuid": "e48caaf7-b544-443c-94ee-40055fcf90cc", "ip": "192.168.1.33", "netmask": "255.255.255.0", "gateway": "192.168.1.254", "mac": "06:4b:cc:00:00:87", "dns1": "192.168.1.92", "dns2": "8.8.8.8", "broadcastType": "Native", "type": "Guest", "broadcastUri": "vlan://untagged", "isSecurityGroupEnabled": true, "name": "VirtualNetwork" }, { "deviceId": 0, "networkRateMbps": -1, "defaultNic": false, "uuid": "13bb00ec-b354-4fbf-b3f6-fb0dc29715b4", "ip": "169.254.0.70", "netmask": "255.255.0.0", "gateway": "169.254.0.1", "mac": "0e:00:a9:fe:00:46", "broadcastType": "LinkLocal", "type": "Control", "isSecurityGroupEnabled": false }, { "deviceId": 1, "networkRateMbps": -1, "defaultNic": false, "uuid": "a6d63c0f-72b9-439e-91ce-d158cb37a482", "ip": "192.168.1.224", "netmask": "255.255.255.0", "gateway": "192.168.1.254", "mac": "06:e7:80:00:00:5f", "broadcastType": "Native", "type": "Management", "isSecurityGroupEnabled": false, "name": "VirtualNetwork" } ] }, "contextMap": {} } } We have worked on this problem 3 days, and setup the new zone again and again. But we still can not solve this problem.The Agentshell.exe is build in our development environment. Can anyone encounter this problem. Please help us. Thank you very much. Khmu