Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 097CBF683 for ; Sun, 7 Apr 2013 09:43:18 +0000 (UTC) Received: (qmail 69392 invoked by uid 500); 7 Apr 2013 09:43:17 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 69359 invoked by uid 500); 7 Apr 2013 09:43:17 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 69320 invoked by uid 500); 7 Apr 2013 09:43:16 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 69312 invoked by uid 99); 7 Apr 2013 09:43:16 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 07 Apr 2013 09:43:16 +0000 Date: Sun, 7 Apr 2013 09:43:15 +0000 (UTC) From: "ASF subversion and git services (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (CLOUDSTACK-1946) VMSnapshot Limitations Violation: VM's memory snapshots are not automatically getting discarded if VM's service offering is upgraded. MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-1946?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId= =3D13624852#comment-13624852 ]=20 ASF subversion and git services commented on CLOUDSTACK-1946: ------------------------------------------------------------- Commit a85b498afd224fbc34e52b032ee4ba05f141f2a0 in branch refs/heads/master= from [~mice] [ https://git-wip-us.apache.org/repos/asf?p=3Dcloudstack.git;h=3Da85b498 ] 1) fix CLOUDSTACK-1946 2) remove redundant VMSnapshotVO.java =20 > VMSnapshot Limitations Violation: VM's memory snapshots are not automatic= ally getting discarded if VM's service offering is upgraded. > -------------------------------------------------------------------------= ------------------------------------------------------------ > > Key: CLOUDSTACK-1946 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-194= 6 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: Management Server > Affects Versions: 4.2.0 > Reporter: Chandan Purushothama > Assignee: Mice Xia > Fix For: 4.2.0 > > > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > Steps to Reproduce: > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > 1. Create a "DiskAndMemorySnapshot" type VM snapshot for a VM - M1.=20 > 2. Create a "Disk" type VM snapshot for the same VM -D1. > 3. Upgrade the Service offering for this VM. > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > Observations: > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > [root@asfmgmt ~]# grep -i "job-84" /var/log/cloudstack/management/managem= ent-server.log > 2013-04-04 15:10:08,820 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina= -exec-3:null) submit async job-84, details: AsyncJobVO {id:84, userId: 4, a= ccountId: 4, sessionKey: null, instanceType: null, instanceId: 11, cmd: org= .apache.cloudstack.api.command.user.vm.StartVMCmd, cmdOriginator: null, cmd= Info: {"response":"json","id":"fdcad7b3-f7c7-437f-af1d-6a5598996e50","sessi= onkey":"tS2YZXdWvuaD21qQKrpELMkXwvA\u003d","ctxUserId":"4","_":"13651134118= 36","ctxAccountId":"4","ctxStartEventId":"368"}, cmdVersion: 0, callbackTyp= e: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, re= sult: null, initMsid: 7200344900649, completeMsid: null, lastUpdated: null,= lastPolled: null, created: null} > 2013-04-04 15:10:08,824 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-26:job-84) Executing org.apache.cloudstack.api.command.user.vm.StartVM= Cmd for job-84 > 2013-04-04 15:10:08,840 DEBUG [cloud.user.AccountManagerImpl] (Job-Execut= or-26:job-84) Access to VM[User|atoms-VM-1] granted to Acct[4-atoms] by Dom= ainChecker_EnhancerByCloudStack_64286415 > 2013-04-04 15:10:08,851 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:08,854 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:08,862 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) DeploymentPlanner allocation algorithm: random > 2013-04-04 15:10:08,862 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Trying to allocate a host and storage pools from dc:1, pod:1,c= luster:1, requested cpu: 500, requested ram: 536870912 > 2013-04-04 15:10:08,862 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Is ROOT volume READY (pool already allocated)?: Yes > 2013-04-04 15:10:08,862 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) This VM has last host_id specified, trying to choose the same = host: 1 > 2013-04-04 15:10:08,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Checking if host: 1 has enough capacity for requested CP= U: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0 > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Hosts's actual total CPU: 4520 and CPU after applying ov= erprovisioning: 4520 > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) We need to allocate to the last host again, so checking = if there is enough reserved capacity > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Reserved CPU: 500 , Requested CPU: 500 > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Reserved RAM: 536870912 , Requested RAM: 536870912 > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Host has enough CPU and RAM available > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) STATS: Can alloc CPU from host: 1, used: 2100, reserved:= 500, actual total: 4520, total with overprovisioning: 4520; requested cpu:= 500,alloc_from_last_host?:true ,considerReservedCapacity?: true > 2013-04-04 15:10:08,868 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) STATS: Can alloc MEM from host: 1, used: 1744830464, res= erved: 536870912, total: 17169530880; requested mem: 536870912,alloc_from_l= ast_host?:true ,considerReservedCapacity?: true > 2013-04-04 15:10:08,868 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) The last host of this VM is UP and has enough capacity > 2013-04-04 15:10:08,868 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Now checking for suitable pools under zone: 1, pod: 1, cluster= : 1 > 2013-04-04 15:10:08,870 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Checking suitable pools for volume (Id, Type): (11,ROOT) > 2013-04-04 15:10:08,870 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Volume has pool already allocated, checking if pool can be reu= sed, poolId: 1 > 2013-04-04 15:10:08,871 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Planner need not allocate a pool for this volume since its REA= DY > 2013-04-04 15:10:08,871 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Trying to find a potenial host and associated storage pools fr= om the suitable host/pool lists for this VM > 2013-04-04 15:10:08,871 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Checking if host: 1 can access any suitable storage pool for v= olume: ROOT > 2013-04-04 15:10:08,872 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Host: 1 can access pool: 1 > 2013-04-04 15:10:08,872 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Found a potential host id: 1 name: 10.223.58.2 and associated = storage pools for this VM > 2013-04-04 15:10:08,873 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluste= r(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cl= uster(1)-Host(1)-Storage()] > 2013-04-04 15:10:08,886 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) VM state transitted from :Stopped to Starting with event= : StartRequestedvm's original host id: 1 new host id: null host id before s= tate transition: null > 2013-04-04 15:10:08,886 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) Successfully transitioned to start state for VM[User|ato= ms-VM-1] reservation id =3D 27dd2766-1951-440c-98a4-65773b2c16d6 > 2013-04-04 15:10:08,891 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) Trying to deploy VM, vm has dcId: 1 and podId: 1 > 2013-04-04 15:10:08,892 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) advanceStart: DeploymentPlan is provided, using dcId:1, = podId: 1, clusterId: 1, hostId: 1, poolId: null > 2013-04-04 15:10:08,892 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) Deploy avoids pods: null, clusters: null, hosts: null > 2013-04-04 15:10:08,894 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) Root volume is ready, need to place VM in volume's clust= er > 2013-04-04 15:10:08,894 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) DeploymentPlanner allocation algorithm: random > 2013-04-04 15:10:08,894 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Trying to allocate a host and storage pools from dc:1, pod:1,c= luster:1, requested cpu: 500, requested ram: 536870912 > 2013-04-04 15:10:08,894 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Is ROOT volume READY (pool already allocated)?: Yes > 2013-04-04 15:10:08,894 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) DeploymentPlan has host_id specified, making no checks on this= host, looks like admin test: 1 > 2013-04-04 15:10:08,895 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Looking for suitable pools for this host under zone: 1, pod: 1= , cluster: 1 > 2013-04-04 15:10:08,896 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Checking suitable pools for volume (Id, Type): (11,ROOT) > 2013-04-04 15:10:08,897 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Volume has pool already allocated, checking if pool can be reu= sed, poolId: 1 > 2013-04-04 15:10:08,898 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Planner need not allocate a pool for this volume since its REA= DY > 2013-04-04 15:10:08,898 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Trying to find a potenial host and associated storage pools fr= om the suitable host/pool lists for this VM > 2013-04-04 15:10:08,898 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Checking if host: 1 can access any suitable storage pool for v= olume: ROOT > 2013-04-04 15:10:08,899 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Host: 1 can access pool: 1 > 2013-04-04 15:10:08,899 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Found a potential host id: 1 name: 10.223.58.2 and associated = storage pools for this VM > 2013-04-04 15:10:08,900 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-26:job-84) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluste= r(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cl= uster(1)-Host(1)-Storage()] > 2013-04-04 15:10:08,900 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) Deployment found - P0=3DVM[User|atoms-VM-1], P0=3DDest[= Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] := Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()] > 2013-04-04 15:10:08,909 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) VM state transitted from :Starting to Starting with even= t: OperationRetryvm's original host id: 1 new host id: 1 host id before sta= te transition: null > 2013-04-04 15:10:08,910 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) VM starting again on the last host it was stopped on > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Hosts's actual total CPU: 4520 and CPU after applying ov= erprovisioning: 4520 > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) We are allocating VM, increasing the used capacity of th= is host:1 > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Current Used CPU: 2100 , Free CPU:1920 ,Requested CPU: 5= 00 > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Current Used RAM: 1744830464 , Free RAM:14887829504 ,Req= uested RAM: 536870912 > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) We are allocating VM to the last host again, so adjustin= g the reserved capacity if it is not less than required > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Reserved CPU: 500 , Requested CPU: 500 > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) Reserved RAM: 536870912 , Requested RAM: 536870912 > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) CPU STATS after allocation: for host: 1, old used: 2100,= old reserved: 500, actual total: 4520, total with overprovisioning: 4520; = new used:2600, reserved:0; requested cpu:500,alloc_from_last:true > 2013-04-04 15:10:08,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) RAM STATS after allocation: for host: 1, old used: 17448= 30464, old reserved: 536870912, total: 17169530880; new used: 2281701376, r= eserved: 0; requested mem: 536870912,alloc_from_last:true > 2013-04-04 15:10:08,921 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) VM is being created in podId: 1 > 2013-04-04 15:10:08,923 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Lock is acquired for network id 205 as a part of network i= mplement > 2013-04-04 15:10:08,923 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Network id=3D205 is already implemented > 2013-04-04 15:10:08,924 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Lock is released for network id 205 as a part of network i= mplement > 2013-04-04 15:10:08,935 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:08,939 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Changing active number of nics for network id=3D205 on 1 > 2013-04-04 15:10:08,943 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking JuniperSRX to prepare for Nic[22-11-27dd2766-1951-4= 40c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:08,946 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking Netscaler to prepare for Nic[22-11-27dd2766-1951-44= 0c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:08,949 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking F5BigIP to prepare for Nic[22-11-27dd2766-1951-440c= -98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:08,951 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking CiscoNexus1000vVSM to prepare for Nic[22-11-27dd276= 6-1951-440c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:08,951 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking BigSwitchVnsElement to prepare for Nic[22-11-27dd27= 66-1951-440c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:08,951 DEBUG [network.element.BigSwitchVnsElement] (Job-= Executor-26:job-84) Checking if BigSwitchVnsElement can handle service Conn= ectivity on network TestNetwork-atoms-1 > 2013-04-04 15:10:08,954 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking VirtualRouter to prepare for Nic[22-11-27dd2766-195= 1-440c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:08,977 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-26:job-84) Lock is acquired for network id 205 as a = part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storag= e(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Stor= age()] > 2013-04-04 15:10:08,980 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-26:job-84) Lock is released for network id 205 as a = part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storag= e(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Stor= age()] > 2013-04-04 15:10:08,985 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:08,988 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-26:job-84) Applying dhcp entry in network Ntwk[205|G= uest|8] > 2013-04-04 15:10:09,001 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227770: Sending { Cmd , MgmtId: 7200344900649, via: 1, V= er: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"02:00:6c:00:0= 0:04","vmIpAddress":"10.1.1.149","vmName":"atoms-VM-1","defaultRouter":"10.= 1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:6c:00:00:04","isDe= fault":true,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.typ= e":"Advanced","router.name":"r-7-VMSNAP","router.ip":"10.223.58.4"},"wait":= 0}}] } > 2013-04-04 15:10:09,001 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227770: Executing: { Cmd , MgmtId: 7200344900649, via: 1= , Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"02:00:6c:0= 0:00:04","vmIpAddress":"10.1.1.149","vmName":"atoms-VM-1","defaultRouter":"= 10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:6c:00:00:04","i= sDefault":true,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.= type":"Advanced","router.name":"r-7-VMSNAP","router.ip":"10.223.58.4"},"wai= t":0}}] } > 2013-04-04 15:10:12,495 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227770: Received: { Ans: , MgmtId: 7200344900649, via: 1= , Ver: v1, Flags: 110, { Answer } } > 2013-04-04 15:10:12,504 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:12,507 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-26:job-84) Applying userdata and password entry in n= etwork Ntwk[205|Guest|8] > 2013-04-04 15:10:12,521 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227771: Sending { Cmd , MgmtId: 7200344900649, via: 1, V= er: v1, Flags: 100111, [{"routing.SavePasswordCommand":{"password":"fnirq_c= nffjbeq","vmIpAddress":"10.1.1.149","vmName":"atoms-VM-1","accessDetails":{= "router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"10= .223.58.4","router.name":"r-7-VMSNAP"},"wait":0}},{"routing.VmDataCommand":= {"vmIpAddress":"10.1.1.149","vmName":"atoms-VM-1","accessDetails":{"router.= guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"10.223.58.= 4","router.name":"r-7-VMSNAP"},"wait":0}}] } > 2013-04-04 15:10:12,522 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227771: Executing: { Cmd , MgmtId: 7200344900649, via: 1= , Ver: v1, Flags: 100111, [{"routing.SavePasswordCommand":{"password":"fnir= q_cnffjbeq","vmIpAddress":"10.1.1.149","vmName":"atoms-VM-1","accessDetails= ":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":= "10.223.58.4","router.name":"r-7-VMSNAP"},"wait":0}},{"routing.VmDataComman= d":{"vmIpAddress":"10.1.1.149","vmName":"atoms-VM-1","accessDetails":{"rout= er.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"10.223.= 58.4","router.name":"r-7-VMSNAP"},"wait":0}}] } > 2013-04-04 15:10:16,772 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227771: Received: { Ans: , MgmtId: 7200344900649, via: 1= , Ver: v1, Flags: 110, { Answer, Answer } } > 2013-04-04 15:10:16,772 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking Ovs to prepare for Nic[22-11-27dd2766-1951-440c-98a= 4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:16,772 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking SecurityGroupProvider to prepare for Nic[22-11-27dd= 2766-1951-440c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:16,775 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-26:job-84) Asking VpcVirtualRouter to prepare for Nic[22-11-27dd2766-= 1951-440c-98a4-65773b2c16d6-10.1.1.149] > 2013-04-04 15:10:16,778 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:16,779 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Exec= utor-26:job-84) Checking if we need to prepare 1 volumes for VM[User|atoms-= VM-1] > 2013-04-04 15:10:16,779 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Exec= utor-26:job-84) No need to recreate the volume: Vol[11|vm=3D11|ROOT], since= it already has a pool assigned: 1, adding disk to VM > 2013-04-04 15:10:16,793 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227772: Sending { Cmd , MgmtId: 7200344900649, via: 1, V= er: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":11,"name":"i-4-11-VMSNA= P","bootloader":"HVM","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,= "minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"CentOS 5.3 (64-= bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":fa= lse,"vncPassword":"cebf388dfffe758","params":{"rootDiskController":"ide","n= icAdapter":"E1000"},"uuid":"fdcad7b3-f7c7-437f-af1d-6a5598996e50","disks":[= {"id":11,"name":"ROOT-11","mountPoint":"/export/home/chandan/asf4-131-170/p= rimary","path":"ROOT-11-11-000004","size":2147483648,"type":"ROOT","storage= PoolType":"NetworkFilesystem","storagePoolUuid":"f42a60c2-0940-305b-bb14-23= d8b40f42bc","deviceId":0},{"id":11,"name":"CentOS 5.3(64-bit) no GUI (vSphe= re)","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{= "deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"5f4fd59f-df59-= 41bb-bfd9-de15c8a89e6a","ip":"10.1.1.149","netmask":"255.255.255.0","gatewa= y":"10.1.1.1","mac":"02:00:6c:00:00:04","dns1":"8.8.8.8","dns2":"8.8.4.4","= broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2241","isolatio= nUri":"vlan://2241","isSecurityGroupEnabled":false}]},"hostIp":"10.223.58.2= ","wait":0}}] } > 2013-04-04 15:10:16,794 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227772: Executing: { Cmd , MgmtId: 7200344900649, via: 1= , Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":11,"name":"i-4-11-VM= SNAP","bootloader":"HVM","type":"User","cpus":1,"minSpeed":500,"maxSpeed":5= 00,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"CentOS 5.3 (= 64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse"= :false,"vncPassword":"cebf388dfffe758","params":{"rootDiskController":"ide"= ,"nicAdapter":"E1000"},"uuid":"fdcad7b3-f7c7-437f-af1d-6a5598996e50","disks= ":[{"id":11,"name":"ROOT-11","mountPoint":"/export/home/chandan/asf4-131-17= 0/primary","path":"ROOT-11-11-000004","size":2147483648,"type":"ROOT","stor= agePoolType":"NetworkFilesystem","storagePoolUuid":"f42a60c2-0940-305b-bb14= -23d8b40f42bc","deviceId":0},{"id":11,"name":"CentOS 5.3(64-bit) no GUI (vS= phere)","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics"= :[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"5f4fd59f-df= 59-41bb-bfd9-de15c8a89e6a","ip":"10.1.1.149","netmask":"255.255.255.0","gat= eway":"10.1.1.1","mac":"02:00:6c:00:00:04","dns1":"8.8.8.8","dns2":"8.8.4.4= ","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2241","isola= tionUri":"vlan://2241","isSecurityGroupEnabled":false}]},"hostIp":"10.223.5= 8.2","wait":0}}] } > 2013-04-04 15:10:26,218 DEBUG [agent.transport.Request] (Job-Executor-26:= job-84) Seq 1-1397227772: Received: { Ans: , MgmtId: 7200344900649, via: 1= , Ver: v1, Flags: 110, { StartAnswer } } > 2013-04-04 15:10:26,259 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:26,262 DEBUG [cloud.network.NetworkModelImpl] (Job-Execu= tor-26:job-84) Service SecurityGroup is not supported in the network id=3D2= 05 > 2013-04-04 15:10:26,267 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-26:job-84) VM state transitted from :Starting to Running with event= : OperationSucceededvm's original host id: 1 new host id: 1 host id before = state transition: 1 > 2013-04-04 15:10:26,267 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-26:job-84) Start completed for VM VM[User|atoms-VM-1] > 2013-04-04 15:10:26,277 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-26:job-84) Complete async job-84, jobStatus: 1, resultCode: 0, result:= org.apache.cloudstack.api.response.UserVmResponse@619936d > 2013-04-04 15:10:26,371 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-26:job-84) Done executing org.apache.cloudstack.api.command.user.vm.St= artVMCmd for job-84 > 2013-04-04 15:10:26,809 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina= -exec-14:null) Async job-84 completed > [root@asfmgmt ~]# > mysql> select id,name,display_name,vm_id,account_id,vm_snapshot_type,stat= e,parent,current,update_count,updated,created,removed from vm_snapshots whe= re vm_id=3D11; > +----+---------------------------------+-----------------------+-------+-= -----------+------------------+-------+--------+---------+--------------+--= -------------------+---------------------+---------+ > | id | name | display_name | vm_id | = account_id | vm_snapshot_type | state | parent | current | update_count | u= pdated | created | removed | > +----+---------------------------------+-----------------------+-------+-= -----------+------------------+-------+--------+---------+--------------+--= -------------------+---------------------+---------+ > | 1 | i-4-11-VMSNAP_VS_20130402235913 | vmsnap-atm-vm-1-1 | 11 | = 4 | Disk | Ready | NULL | 0 | 4 | 2= 013-04-03 00:02:55 | 2013-04-02 23:59:13 | NULL | > | 4 | i-4-11-VMSNAP_VS_20130403205843 | vmsnap-run-atm-vm-1-2 | 11 | = 4 | Disk | Ready | 1 | 1 | 6 | 2= 013-04-03 23:17:41 | 2013-04-03 20:58:43 | NULL | > | 5 | i-4-11-VMSNAP_VS_20130403210837 | vmsnap-run-atm-vm-1-3 | 11 | = 4 | DiskAndMemory | Ready | 4 | 0 | 6 | 2= 013-04-03 22:28:43 | 2013-04-03 21:08:37 | NULL | > +----+---------------------------------+-----------------------+-------+-= -----------+------------------+-------+--------+---------+--------------+--= -------------------+---------------------+---------+ > 3 rows in set (0.00 sec) -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrato= rs For more information on JIRA, see: http://www.atlassian.com/software/jira