[
https://issues.apache.org/jira/browse/CLOUDSTACK-5342?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13846043#comment-13846043
]
Girish Shilamkar commented on CLOUDSTACK-5342:
----------------------------------------------
ceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd, cmdInfo:
{"response":"json","sessionkey":"D+cRXhCkN+eHk9chCpFpEVBD47E\u003d","virtualmachineid":"bcddd332-9c2d-4319-b421-097e72f10167","cmdEventType":"NIC.CREATE","ctxUserId":"2","httpmethod":"GET","_":"1386158703567","ctxAccountId":"2","networkid":"a05731b2-b132-4087-b250-5a159fb811bf","ctxStartEventId":"379"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 6851580133501, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-12-04 22:56:10,915 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-b672bd0f
ctx-23a1ba4b) ===END=== 10.252.192.19 -- GET
command=addNicToVirtualMachine&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&virtualmachineid=bcddd332-9c2d-4319-b421-097e72f10167&networkid=a05731b2-b132-4087-b250-5a159fb811bf&_=1386158703567
2013-12-04 22:56:10,919 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-17:ctx-ebfd064f) Add job-96 into job monitoring
2013-12-04 22:56:10,919 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-17:ctx-ebfd064f) Executing AsyncJobVO {id:96, userId: 2,
accountId: 2, instanceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd, cmdInfo:
{"response":"json","sessionkey":"D+cRXhCkN+eHk9chCpFpEVBD47E\u003d","virtualmachineid":"bcddd332-9c2d-4319-b421-097e72f10167","cmdEventType":"NIC.CREATE","ctxUserId":"2","httpmethod":"GET","_":"1386158703567","ctxAccountId":"2","networkid":"a05731b2-b132-4087-b250-5a159fb811bf","ctxStartEventId":"379"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 6851580133501, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-12-04 22:56:10,944 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Adding vm VM[User|testVM1] to
network Ntwk[205|Guest|8]; requested nic profile NicProfile[0-0-null-null-null
2013-12-04 22:56:10,957 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Allocating nic for vm
VM[User|testVM1] in network Ntwk[205|Guest|8] with requested profile
NicProfile[0-0-null-null-null
2013-12-04 22:56:11,002 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Service SecurityGroup is not
supported in the network id=205
2013-12-04 22:56:11,005 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Nic is allocated successfully for
vm VM[User|testVM1] in network Ntwk[205|Guest|8]
2013-12-04 22:56:11,006 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Network id=205 is already
implemented
2013-12-04 22:56:11,025 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Service SecurityGroup is not
supported in the network id=205
2013-12-04 22:56:11,030 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null)
Seq 1-493553024: Processing: { Ans: , MgmtId: 6851580133501, via: 1, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.CheckRouterAnswer":{"state":"BACKUP","isBumped":false,"result":true,"details":"Status:
BACKUP&Bumped: NO","wait":0}}] }
2013-12-04 22:56:11,031 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-2:ctx-147da5be) Seq 1-493553024: Received: {
Ans: , MgmtId: 6851580133501, via: 1, Ver: v1, Flags: 10, { CheckRouterAnswer }
}
2013-12-04 22:56:11,031 DEBUG [c.c.a.m.AgentManagerImpl]
(RedundantRouterStatusMonitor-2:ctx-147da5be) Details from executing class
com.cloud.agent.api.CheckRouterCommand: Status: BACKUP&Bumped: NO
2013-12-04 22:56:11,050 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Changing active number of nics for
network id=205 on 1
2013-12-04 22:56:11,063 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Asking VirtualRouter to prepare for
Nic[42-5-null-10.1.1.137]
2013-12-04 22:56:11,081 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Lock is acquired for network id 205
as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(null)-Cluster(null)-Host(1)-Storage()]
2013-12-04 22:56:11,085 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Lock is released for network id 205
as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(null)-Cluster(null)-Host(1)-Storage()]
2013-12-04 22:56:11,098 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Service SecurityGroup is not
supported in the network id=205
2013-12-04 22:56:11,119 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Service SecurityGroup is not
supported in the network id=205
2013-12-04 22:56:11,128 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Applying dhcp entry in network
Ntwk[205|Guest|8]
2013-12-04 22:56:11,160 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-ebfd064f
ctx-23a1ba4b) Seq 1-493553025: Sending { Cmd , MgmtId: 6851580133501, via:
1(Rack1Pod1Host31), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:21:b4:00:04","vmIpAddress":"10.1.1.137","vmName":"testVM1","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:21:b4:00:04","isDefault":false,"executeInSequence":false,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-8-VM","router.ip":"169.254.0.210"},"wait":0}}]
}
2013-12-04 22:56:11,312 DEBUG [c.c.a.t.Request] (AgentManager-Handler-3:null)
Seq 1-493553025: Processing: { Ans: , MgmtId: 6851580133501, via: 1, Ver: v1,
Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2013-12-04 22:56:11,313 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-ebfd064f
ctx-23a1ba4b) Seq 1-493553025: Received: { Ans: , MgmtId: 6851580133501, via:
1, Ver: v1, Flags: 10, { Answer } }
2013-12-04 22:56:11,326 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Service SecurityGroup is not
supported in the network id=205
2013-12-04 22:56:11,338 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Applying userdata and password
entry in network Ntwk[205|Guest|8]
2013-12-04 22:56:11,361 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-ebfd064f
ctx-23a1ba4b) Seq 1-493553026: Sending { Cmd , MgmtId: 6851580133501, via:
1(Rack1Pod1Host31), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.137","vmName":"testVM1","executeInSequence":false,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.0.210","router.name":"r-8-VM"},"wait":0}}]
}
2013-12-04 22:56:11,469 DEBUG [c.c.a.t.Request] (AgentManager-Handler-2:null)
Seq 1-493553026: Processing: { Ans: , MgmtId: 6851580133501, via: 1, Ver: v1,
Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2013-12-04 22:56:11,469 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-ebfd064f
ctx-23a1ba4b) Seq 1-493553026: Received: { Ans: , MgmtId: 6851580133501, via:
1, Ver: v1, Flags: 10, { Answer } }
2013-12-04 22:56:11,472 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Service SecurityGroup is not
supported in the network id=205
2013-12-04 22:56:11,472 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Nic is prepared successfully for vm
VM[User|testVM1] in network Ntwk[205|Guest|8]
2013-12-04 22:56:11,481 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Plugging nic for vm
VM[User|testVM1] in network Ntwk[205|Guest|8]
2013-12-04 22:56:11,489 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-ebfd064f
ctx-23a1ba4b) Seq 1-493553027: Sending { Cmd , MgmtId: 6851580133501, via:
1(Rack1Pod1Host31), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.PlugNicCommand":{"nic":{"deviceId":2,"networkRateMbps":200,"defaultNic":false,"uuid":"a831db68-514a-4489-85d6-f550bc09cff3","ip":"10.1.1.137","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:21:b4:00:04","dns1":"10.140.50.6","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://967","isolationUri":"vlan://967","isSecurityGroupEnabled":false},"instanceName":"i-5-5-VM","vmType":"User","wait":0}}]
}
2013-12-04 22:56:11,703 DEBUG [c.c.a.t.Request] (AgentManager-Handler-4:null)
Seq 1-493553027: Processing: { Ans: , MgmtId: 6851580133501, via: 1, Ver: v1,
Flags: 110,
[{"com.cloud.agent.api.PlugNicAnswer":{"result":true,"details":"success","wait":0}}]
}
2013-12-04 22:56:11,703 DEBUG [c.c.a.m.AgentAttache]
(AgentManager-Handler-4:null) Seq 1-493553027: No more commands found
2013-12-04 22:56:11,703 DEBUG [c.c.a.t.Request] (Job-Executor-17:ctx-ebfd064f
ctx-23a1ba4b) Seq 1-493553027: Received: { Ans: , MgmtId: 6851580133501, via:
1, Ver: v1, Flags: 110, { PlugNicAnswer } }
2013-12-04 22:56:11,704 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Nic is plugged successfully for vm
VM[User|testVM1] in network Ntwk[205|Guest|8]. Vm is a part of network now
2013-12-04 22:56:11,713 DEBUG [c.c.v.UserVmManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Successful addition of
Ntwk[205|Guest|8] from VM[User|testVM1]
2013-12-04 22:56:11,738 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-17:ctx-ebfd064f ctx-23a1ba4b) Complete async job-96, jobStatus:
SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"bcddd332-9c2d-4319-b421-097e72f10167","name":"testVM1","displayname":"testVM1","account":"test","domainid":"7f9219f5-e458-4e76-9454-0901f67b165c","domain":"test","created":"2013-12-03T20:50:34+0530","state":"Running","haenable":false,"zoneid":"5d183080-7858-4adf-92ff-ea6933c9be27","zonename":"z","hostid":"4484f869-a428-482e-990a-f3a908dfbb85","hostname":"Rack1Pod1Host31","guestosid":"112","securitygroup":[],"nic":[{"id":"19ea92f9-9b79-4092-8bd8-b51c2ed6c5b6","networkid":"1a4c3dc6-f0e0-40bf-a005-9b9d85b7696d","networkname":"testNet1","netmask":"255.255.255.0","gateway":"10.1.1.1","ipaddress":"10.1.1.123","isolationuri":"vlan://963","broadcasturi":"vlan://963","traffictype":"Guest","type":"Isolated","isdefault":true,"macaddress":"02:00:70:31:00:01"},{"id":"58f02263-c5e8-4aed-bdf3-de862b8f4ffa","networkid":"eb30c55a-0ed2-494f-90a3-8710f7020ffc","networkname":"shared","netmask":"255.255.255.0","gateway":"10.0.1.1","ipaddress":"10.0.1.5","isolationuri":"vlan://971","broadcasturi":"vlan://971","traffictype":"Guest","type":"Shared","isdefault":false,"macaddress":"06:d0:7c:00:00:2a"},{"id":"a831db68-514a-4489-85d6-f550bc09cff3","networkid":"a05731b2-b132-4087-b250-5a159fb811bf","networkname":"testNet2","netmask":"255.255.255.0","gateway":"10.1.1.1","ipaddress":"10.1.1.137","isolationuri":"vlan://967","broadcasturi":"vlan://967","traffictype":"Guest","type":"Isolated","isdefault":false,"macaddress":"02:00:21:b4:00:04"}],"hypervisor":"KVM","publicipid":"24a1e6cf-0e9e-411f-87d2-7ccef2d805fd","publicip":"10.147.47.10","instancename":"i-5-5-VM","tags":[],"affinitygroup":[],"displayvm":true,"isdynamicallyscalable":false}
2013-12-04 22:56:11,749 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-17:ctx-ebfd064f) Done executing
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd for job-96
2013-12-04 22:56:11,756 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-17:ctx-ebfd064f) Remove job-96 from job monitoring
2013-12-04 22:56:12,223 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-6:null) SeqA 5-1455: Processing Seq 5-1455: { Cmd ,
MgmtId: -1, via: 5, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":3,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-12-04 22:56:12,231 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-6:null) SeqA 5-1455: Sending Seq 5-1455: { Ans: ,
MgmtId: 6851580133501, via: 5, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-04 22:56:14,030 DEBUG [c.c.a.ApiServlet]
(catalina-exec-22:ctx-552b3750) ===START=== 10.252.192.19 -- GET
command=queryAsyncJobResult&jobId=38b00d5e-8098-4c47-84c6-2e02d2e7f9a6&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158706971
2013-12-04 22:56:14,065 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-552b3750
ctx-ea60769c) ===END=== 10.252.192.19 -- GET
command=queryAsyncJobResult&jobId=38b00d5e-8098-4c47-84c6-2e02d2e7f9a6&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158706971
2013-12-04 22:56:14,242 DEBUG [c.c.a.ApiServlet]
(catalina-exec-23:ctx-222552b8) ===START=== 10.252.192.19 -- GET
command=listVirtualMachines&details=nics&id=bcddd332-9c2d-4319-b421-097e72f10167&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158707088
2013-12-04 22:56:14,280 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-222552b8
ctx-80a4c6ac) ===END=== 10.252.192.19 -- GET
command=listVirtualMachines&details=nics&id=bcddd332-9c2d-4319-b421-097e72f10167&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158707088
2013-12-04 22:56:15,416 DEBUG [c.c.s.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-46e7aafb) Zone 1 is ready to launch secondary storage VM
2013-12-04 22:56:15,488 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-e8adcbc5) Zone 1 is ready to launch console proxy
2013-12-04 22:56:15,864 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-ec5d9af1) Resetting hosts suitable for reconnect
2013-12-04 22:56:15,867 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-ec5d9af1) Completed resetting hosts suitable for reconnect
2013-12-04 22:56:15,867 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-ec5d9af1) Acquiring hosts for clusters already owned by this
management server
2013-12-04 22:56:15,868 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-ec5d9af1) Completed acquiring hosts for clusters already owned by
this management server
2013-12-04 22:56:15,868 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-ec5d9af1) Acquiring hosts for clusters not owned by any management
server
2013-12-04 22:56:15,869 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-ec5d9af1) Completed acquiring hosts for clusters not owned by any
management server
2013-12-04 22:56:17,618 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-7:null) Ping from 1
2013-12-04 22:56:19,577 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-84495902)
===START=== 10.252.192.19 -- GET
command=listVirtualMachines&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&listAll=true&page=1&pagesize=20&_=1386158712452
2013-12-04 22:56:19,639 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-84495902
ctx-90cea5c6) ===END=== 10.252.192.19 -- GET
command=listVirtualMachines&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&listAll=true&page=1&pagesize=20&_=1386158712452
2013-12-04 22:56:21,807 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-ec4d90cd) StorageCollector is running...
2013-12-04 22:56:21,870 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-ec4d90cd)
Seq 6-51249334: Received: { Ans: , MgmtId: 6851580133501, via: 6, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-12-04 22:56:22,028 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-ec4d90cd)
Seq 1-493553028: Received: { Ans: , MgmtId: 6851580133501, via: 1, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-12-04 22:56:22,223 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 5-1456: Processing Seq 5-1456: { Cmd ,
MgmtId: -1, via: 5, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":3,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-12-04 22:56:22,233 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 5-1456: Sending Seq 5-1456: { Ans: ,
MgmtId: 6851580133501, via: 5, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-04 22:56:23,435 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-6c5a1b10)
===START=== 10.252.192.19 -- GET
command=listZones&id=5d183080-7858-4adf-92ff-ea6933c9be27&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158716319
2013-12-04 22:56:23,455 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-6c5a1b10
ctx-ac33212f) ===END=== 10.252.192.19 -- GET
command=listZones&id=5d183080-7858-4adf-92ff-ea6933c9be27&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158716319
2013-12-04 22:56:23,533 DEBUG [c.c.a.ApiServlet]
(catalina-exec-20:ctx-75b46641) ===START=== 10.252.192.19 -- GET
command=listVirtualMachines&id=bcddd332-9c2d-4319-b421-097e72f10167&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158716465
2013-12-04 22:56:23,572 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-75b46641
ctx-a0909f12) ===END=== 10.252.192.19 -- GET
command=listVirtualMachines&id=bcddd332-9c2d-4319-b421-097e72f10167&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158716465
2013-12-04 22:56:23,743 DEBUG [c.c.a.ApiServlet]
(catalina-exec-25:ctx-06d86725) ===START=== 10.252.192.19 -- GET
command=listOsTypes&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158716584
2013-12-04 22:56:23,784 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-4d19ee9c)
===START=== 10.252.192.19 -- GET
command=listTags&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&resourceId=bcddd332-9c2d-4319-b421-097e72f10167&resourceType=UserVm&listAll=true&_=1386158716625
2013-12-04 22:56:23,797 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-4d19ee9c
ctx-ff0bed68) ===END=== 10.252.192.19 -- GET
command=listTags&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&resourceId=bcddd332-9c2d-4319-b421-097e72f10167&resourceType=UserVm&listAll=true&_=1386158716625
2013-12-04 22:56:24,159 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-06d86725
ctx-ec136a31) ===END=== 10.252.192.19 -- GET
command=listOsTypes&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158716584
2013-12-04 22:56:25,674 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-fa8ed547)
===START=== 10.252.192.19 -- GET
command=listVirtualMachines&details=nics&id=bcddd332-9c2d-4319-b421-097e72f10167&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158718580
2013-12-04 22:56:25,714 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-fa8ed547
ctx-f055ad3b) ===END=== 10.252.192.19 -- GET
command=listVirtualMachines&details=nics&id=bcddd332-9c2d-4319-b421-097e72f10167&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158718580
2013-12-04 22:56:32,225 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 5-1457: Processing Seq 5-1457: { Cmd ,
MgmtId: -1, via: 5, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":3,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-12-04 22:56:32,262 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 5-1457: Sending Seq 5-1457: { Ans: ,
MgmtId: 6851580133501, via: 5, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-04 22:56:32,732 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-10:null) Ping from 6
2013-12-04 22:56:33,497 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-29081485)
===START=== 10.252.192.19 -- GET
command=listNetworks&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&zoneid=5d183080-7858-4adf-92ff-ea6933c9be27&account=test&domainid=7f9219f5-e458-4e76-9454-0901f67b165c&_=1386158726427
2013-12-04 22:56:33,514 DEBUG [c.c.u.AccountManagerImpl]
(catalina-exec-5:ctx-29081485 ctx-1539c154) Access granted to Acct[2-admin] to
Domain:2/test/ by AffinityGroupAccessChecker
2013-12-04 22:56:33,782 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-29081485
ctx-1539c154) ===END=== 10.252.192.19 -- GET
command=listNetworks&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&zoneid=5d183080-7858-4adf-92ff-ea6933c9be27&account=test&domainid=7f9219f5-e458-4e76-9454-0901f67b165c&_=1386158726427
2013-12-04 22:56:35,116 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-3fd1ad18)
===START=== 10.252.192.19 -- GET
command=addNicToVirtualMachine&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&virtualmachineid=bcddd332-9c2d-4319-b421-097e72f10167&networkid=a05731b2-b132-4087-b250-5a159fb811bf&_=1386158727976
2013-12-04 22:56:35,142 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-9:ctx-3fd1ad18 ctx-978c03e0) submit async job-97, details:
AsyncJobVO {id:97, userId: 2, accountId: 2, instanceType: None, instanceId:
null, cmd: org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd, cmdInfo:
{"response":"json","sessionkey":"D+cRXhCkN+eHk9chCpFpEVBD47E\u003d","virtualmachineid":"bcddd332-9c2d-4319-b421-097e72f10167","cmdEventType":"NIC.CREATE","ctxUserId":"2","httpmethod":"GET","_":"1386158727976","ctxAccountId":"2","networkid":"a05731b2-b132-4087-b250-5a159fb811bf","ctxStartEventId":"380"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 6851580133501, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-12-04 22:56:35,143 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-3fd1ad18
ctx-978c03e0) ===END=== 10.252.192.19 -- GET
command=addNicToVirtualMachine&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&virtualmachineid=bcddd332-9c2d-4319-b421-097e72f10167&networkid=a05731b2-b132-4087-b250-5a159fb811bf&_=1386158727976
2013-12-04 22:56:35,145 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-18:ctx-dda264e1) Add job-97 into job monitoring
2013-12-04 22:56:35,145 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-18:ctx-dda264e1) Executing AsyncJobVO {id:97, userId: 2,
accountId: 2, instanceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd, cmdInfo:
{"response":"json","sessionkey":"D+cRXhCkN+eHk9chCpFpEVBD47E\u003d","virtualmachineid":"bcddd332-9c2d-4319-b421-097e72f10167","cmdEventType":"NIC.CREATE","ctxUserId":"2","httpmethod":"GET","_":"1386158727976","ctxAccountId":"2","networkid":"a05731b2-b132-4087-b250-5a159fb811bf","ctxStartEventId":"380"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 6851580133501, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-12-04 22:56:35,157 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-18:ctx-dda264e1) Unexpected exception while executing
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd
com.cloud.utils.exception.CloudRuntimeException: A NIC already exists for
VM:i-5-5-VM in network: a05731b2-b132-4087-b250-5a159fb811bf
at
com.cloud.vm.UserVmManagerImpl.addNicToVirtualMachine(UserVmManagerImpl.java:994)
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:616)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at $Proxy169.addNicToVirtualMachine(Unknown Source)
at
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd.execute(AddNicToVMCmd.java:110)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at
com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at
com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:520)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-12-04 22:56:35,159 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-18:ctx-dda264e1) Complete async job-97, jobStatus: FAILED,
resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"A
NIC already exists for VM:i-5-5-VM in network:
a05731b2-b132-4087-b250-5a159fb811bf"}
2013-12-04 22:56:35,180 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-18:ctx-dda264e1) Done executing
org.apache.cloudstack.api.command.user.vm.AddNicToVMCmd for job-97
2013-12-04 22:56:35,185 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-18:ctx-dda264e1) Remove job-97 from job monitoring
2013-12-04 22:56:38,216 DEBUG [c.c.a.ApiServlet]
(catalina-exec-10:ctx-b63ec78f) ===START=== 10.252.192.19 -- GET
command=queryAsyncJobResult&jobId=0274872d-e249-44cd-943a-e5d7bbd5e88e&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158731156
2013-12-04 22:56:38,289 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-b63ec78f
ctx-42c9d601) ===END=== 10.252.192.19 -- GET
command=queryAsyncJobResult&jobId=0274872d-e249-44cd-943a-e5d7bbd5e88e&response=json&sessionkey=D%2BcRXhCkN%2BeHk9chCpFpEVBD47E%3D&_=1386158731156
2013-12-04 22:56:40,742 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-b031c6a4) Found 5 routers to update status.
2013-12-04 22:56:40,745 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-b031c6a4) Found 1 networks to update RvR status.
2013-12-04 22:56:40,766 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-9:ctx-c1db7120) Seq 1-493553029: Sending { Cmd ,
MgmtId: 6851580133501, via: 1(Rack1Pod1Host31), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckRouterCommand":{"accessDetails":{"router.ip":"169.254.3.139","router.name":"r-12-VM"},"wait":30}}]
}
2013-12-04 22:56:40,867 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null)
Seq 1-493553029: Processing: { Ans: , MgmtId: 6851580133501, via: 1, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.CheckRouterAnswer":{"state":"MASTER","isBumped":false,"result":true,"details":"Status:
MASTER&Bumped: NO","wait":0}}] }
2013-12-04 22:56:40,867 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-9:ctx-c1db7120) Seq 1-493553029: Received: {
Ans: , MgmtId: 6851580133501, via: 1, Ver: v1, Flags: 10, { CheckRouterAnswer }
}
2013-12-04 22:56:40,867 DEBUG [c.c.a.m.AgentManagerImpl]
(RedundantRouterStatusMonitor-9:ctx-c1db7120) Details from executing class
com.cloud.agent.api.CheckRouterCommand: Status: MASTER&Bumped: NO
2013-12-04 22:56:40,888 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-9:ctx-c1db7120) Seq 1-493553030: Sending { Cmd ,
MgmtId: 6851580133501, via: 1(Rack1Pod1Host31), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckRouterCommand":{"accessDetails":{"router.ip":"169.254.1.193","router.name":"r-13-VM"},"wait":30}}]
}
2013-12-04 22:56:41,026 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:null)
Seq 1-493553030: Processing: { Ans: , MgmtId: 6851580133501, via: 1
> Add NIC to virtual machine fails in KVM
> ---------------------------------------
>
> Key: CLOUDSTACK-5342
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5342
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Network Controller
> Affects Versions: 4.3.0
> Environment: KVM advanced
> Reporter: Gaurav Aradhye
> Assignee: Gaurav Aradhye
> Priority: Blocker
> Fix For: 4.3.0
>
>
> Add network to VM test cases fail in KVM with following error.
> Execute cmd: asyncquery failed, due to: {errorcode : 530, errortext :
> u'Unable to add NIC to VM[User|VM-e9350ee5-bf2e-418c-91d6-1535dcb4d488]'}
> The same test cases execute successfully on XenServer. As per the feature
> specification (see
> https://cwiki.apache.org/confluence/display/CLOUDSTACK/Add+Remove+Networks+to+VMs),
> "Add network to VM" feature should be supported on KVM too.
--
This message was sent by Atlassian JIRA
(v6.1.4#6159)
