[
https://issues.apache.org/jira/browse/CLOUDSTACK-4624?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13797695#comment-13797695
]
Paul Angus commented on CLOUDSTACK-4624:
----------------------------------------
Hi Jayapal
/var/log/SMLog below...
Oct 17 08:41:02 hdkvm02c SM: [9226] lock: acquired
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:41:02 hdkvm02c SM: [9226] sr_scan {'sr_uuid':
'5609c1c0-03e4-8b58-1bf1-533f1ade34a1', 'subtask_of':
'DummyRef:|84d09d98-57d4-2c63-b97c-cf1da9c5f87a|SR.scan', 'args': [],
'host_ref': 'OpaqueRef:99e28465-5100-6b59-e9d7-ea48b5cdde49', 'session_ref':
'OpaqueRef:75f0e554-b926-847e-5730-ccd7591c08b1', 'device_config': {'device':
'/dev/md0', 'SRmaster': 'true'}, 'command': 'sr_scan', 'sr_ref':
'OpaqueRef:3155b7a0-1a0a-6dea-42d3-db95d84dbd82'}
Oct 17 08:41:02 hdkvm02c SM: [9226] ['/usr/bin/vhd-util', 'scan', '-f', '-c',
'-m', '/var/run/sr-mount/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/*.vhd']
Oct 17 08:41:02 hdkvm02c SM: [9226] pread SUCCESS
Oct 17 08:41:02 hdkvm02c SM: [9226] ['ls',
'/var/run/sr-mount/5609c1c0-03e4-8b58-1bf1-533f1ade34a1', '-1', '--color=never']
Oct 17 08:41:02 hdkvm02c SM: [9226] pread SUCCESS
Oct 17 08:41:02 hdkvm02c SM: [9226] lock: tried lock
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/running, acquired: True
(exists: True)
Oct 17 08:41:02 hdkvm02c SM: [9226] lock: released
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/running
Oct 17 08:41:02 hdkvm02c SM: [9226] Kicking GC
Oct 17 08:41:02 hdkvm02c SMGC: [9226] === SR
5609c1c0-03e4-8b58-1bf1-533f1ade34a1: gc ===
Oct 17 08:41:02 hdkvm02c SMGC: [9230] Will finish as PID [9231]
Oct 17 08:41:02 hdkvm02c SMGC: [9226] New PID [9230]
Oct 17 08:41:02 hdkvm02c SM: [9226] lock: closed
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/running
Oct 17 08:41:02 hdkvm02c SM: [9226] lock: released
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:41:02 hdkvm02c SM: [9226] lock: closed
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:41:03 hdkvm02c SMGC: [9231] Found 0 cache files
Oct 17 08:41:03 hdkvm02c SM: [9231] lock: tried lock
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr, acquired: True (exists:
True)
Oct 17 08:41:03 hdkvm02c SM: [9231] ['/usr/bin/vhd-util', 'scan', '-f', '-c',
'-m', '/var/run/sr-mount/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/*.vhd']
Oct 17 08:41:03 hdkvm02c SM: [9231] pread SUCCESS
Oct 17 08:41:03 hdkvm02c SMGC: [9231] SR 5609
('5609c1c0-03e4-8b58-1bf1-533f1ade34a1') (0 VDIs in 0 VHD trees): no changes
Oct 17 08:41:03 hdkvm02c SM: [9231] lock: released
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:41:03 hdkvm02c SMGC: [9231] No work, exiting
Oct 17 08:41:03 hdkvm02c SMGC: [9231] In cleanup
Oct 17 08:41:03 hdkvm02c SMGC: [9231] SR 5609
('5609c1c0-03e4-8b58-1bf1-533f1ade34a1') (0 VDIs in 0 VHD trees): no changes
Oct 17 08:41:08 hdkvm02c SM: [9365] #### VMOPS enter gethostvmstats ####
Oct 17 08:41:08 hdkvm02c SM: [9365] #### VMOPS exit gethostvmstats ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS enter get_rule_logs_for_vms ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS enter
network_rules_for_rebooted_vm ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS enter check_domid_changed ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS exit check_domid_changed ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS exit
network_rules_for_rebooted_vm ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS enter
network_rules_for_rebooted_vm ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS enter check_domid_changed ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS exit check_domid_changed ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS exit
network_rules_for_rebooted_vm ####
Oct 17 08:41:16 hdkvm02c SM: [9486] #### VMOPS exit get_rule_logs_for_vms ####
Oct 17 08:41:29 hdkvm02c SM: [11083] lock: acquired
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:29 hdkvm02c SM: [11083] ['/usr/sbin/td-util', 'query', 'vhd',
'-vpf',
'/var/run/sr-mount/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839.vhd']
Oct 17 08:41:29 hdkvm02c SM: [11083] pread SUCCESS
Oct 17 08:41:29 hdkvm02c SM: [11083] vdi_attach {'sr_uuid':
'081b1189-0b81-d55c-b230-b914ce8a9030', 'subtask_of':
'DummyRef:|684284be-93d1-5813-083b-98d6632b3a54|VDI.attach', 'vdi_ref':
'OpaqueRef:524343bd-1a86-ac9a-b9e9-9bba88bb66a3', 'vdi_on_boot': 'persist',
'args': ['true'], 'vdi_location': 'f5e5ffae-0c95-4db8-a3d1-c17c8879f839',
'host_ref': 'OpaqueRef:99e28465-5100-6b59-e9d7-ea48b5cdde49', 'session_ref':
'OpaqueRef:c5a97db8-6732-5bcd-4bad-6cf083d8a6be', 'device_config': {'SRmaster':
'false', 'serverpath': '/vol/test_p2_c1_pri2/RootQtree', 'server':
'10.28.231.2'}, 'command': 'vdi_attach', 'vdi_allow_caching': 'false',
'sr_ref': 'OpaqueRef:e0b08b24-46c2-f945-36b3-f9feadb3aa93', 'vdi_uuid':
'f5e5ffae-0c95-4db8-a3d1-c17c8879f839'}
Oct 17 08:41:29 hdkvm02c SM: [11083] lock: creating lock file
/var/lock/sm/f5e5ffae-0c95-4db8-a3d1-c17c8879f839/vdi
Oct 17 08:41:30 hdkvm02c SM: [11083] result: {'params':
'/dev/sm/backend/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839',
'xenstore_data': {'scsi/0x12/0x80': 'AIAAEmY1ZTVmZmFlLTBjOTUtNGQgIA==',
'scsi/0x12/0x83':
'AIMAMQIBAC1YRU5TUkMgIGY1ZTVmZmFlLTBjOTUtNGRiOC1hM2QxLWMxN2M4ODc5ZjgzOSA=',
'vdi-uuid': 'f5e5ffae-0c95-4db8-a3d1-c17c8879f839', 'mem-pool':
'081b1189-0b81-d55c-b230-b914ce8a9030'}}
Oct 17 08:41:30 hdkvm02c SM: [11083] lock: closed
/var/lock/sm/f5e5ffae-0c95-4db8-a3d1-c17c8879f839/vdi
Oct 17 08:41:30 hdkvm02c SM: [11083] lock: released
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:30 hdkvm02c SM: [11083] lock: closed
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:30 hdkvm02c SM: [11129] lock: acquired
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:30 hdkvm02c SM: [11129] ['/usr/sbin/td-util', 'query', 'vhd',
'-vpf',
'/var/run/sr-mount/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839.vhd']
Oct 17 08:41:30 hdkvm02c SM: [11129] pread SUCCESS
Oct 17 08:41:30 hdkvm02c SM: [11129] lock: released
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:30 hdkvm02c SM: [11129] vdi_activate {'sr_uuid':
'081b1189-0b81-d55c-b230-b914ce8a9030', 'subtask_of':
'DummyRef:|1abd5da6-67a4-5b4f-9def-5c970d3d693b|VDI.activate', 'vdi_ref':
'OpaqueRef:524343bd-1a86-ac9a-b9e9-9bba88bb66a3', 'vdi_on_boot': 'persist',
'args': ['true'], 'vdi_location': 'f5e5ffae-0c95-4db8-a3d1-c17c8879f839',
'host_ref': 'OpaqueRef:99e28465-5100-6b59-e9d7-ea48b5cdde49', 'session_ref':
'OpaqueRef:fd703659-88b2-fb31-8001-188308426227', 'device_config': {'SRmaster':
'false', 'serverpath': '/vol/test_p2_c1_pri2/RootQtree', 'server':
'10.28.231.2'}, 'command': 'vdi_activate', 'vdi_allow_caching': 'false',
'sr_ref': 'OpaqueRef:e0b08b24-46c2-f945-36b3-f9feadb3aa93', 'vdi_uuid':
'f5e5ffae-0c95-4db8-a3d1-c17c8879f839'}
Oct 17 08:41:30 hdkvm02c SM: [11129] blktap2.activate
Oct 17 08:41:30 hdkvm02c SM: [11129] lock: acquired
/var/lock/sm/f5e5ffae-0c95-4db8-a3d1-c17c8879f839/vdi
Oct 17 08:41:30 hdkvm02c SM: [11129] Adding tag to:
f5e5ffae-0c95-4db8-a3d1-c17c8879f839
Oct 17 08:41:30 hdkvm02c SM: [11129] Activate lock succeeded
Oct 17 08:41:31 hdkvm02c SM: [11129] ['/usr/sbin/td-util', 'query', 'vhd',
'-vpf',
'/var/run/sr-mount/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839.vhd']
Oct 17 08:41:31 hdkvm02c SM: [11129] pread SUCCESS
Oct 17 08:41:31 hdkvm02c SM: [11129]
PhyLink(/dev/sm/phy/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839)
->
/var/run/sr-mount/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839.vhd
Oct 17 08:41:31 hdkvm02c SM: [11129] ['/usr/sbin/tap-ctl', 'allocate']
Oct 17 08:41:31 hdkvm02c SM: [11129] = 0
Oct 17 08:41:31 hdkvm02c SM: [11129] ['/usr/sbin/tap-ctl', 'spawn']
Oct 17 08:41:31 hdkvm02c SM: [11129] = 0
Oct 17 08:41:31 hdkvm02c SM: [11129] ['/usr/sbin/tap-ctl', 'attach', '-p',
'11282', '-m', '2']
Oct 17 08:41:31 hdkvm02c SM: [11129] = 0
Oct 17 08:41:31 hdkvm02c SM: [11129] ['/usr/sbin/tap-ctl', 'open', '-p',
'11282', '-m', '2', '-a',
'vhd:/var/run/sr-mount/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839.vhd']
Oct 17 08:41:31 hdkvm02c SM: [11129] = 0
Oct 17 08:41:31 hdkvm02c SM: [11129] tap.activate: Launched
Tapdisk(vhd:/var/run/sr-mount/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839.vhd,
pid=11282, minor=2, state=R)
Oct 17 08:41:31 hdkvm02c SM: [11129]
DeviceNode(/dev/sm/backend/081b1189-0b81-d55c-b230-b914ce8a9030/f5e5ffae-0c95-4db8-a3d1-c17c8879f839)
-> /dev/xen/blktap-2/tapdev2
Oct 17 08:41:31 hdkvm02c SM: [11129] lock: released
/var/lock/sm/f5e5ffae-0c95-4db8-a3d1-c17c8879f839/vdi
Oct 17 08:41:31 hdkvm02c SM: [11129] lock: closed
/var/lock/sm/f5e5ffae-0c95-4db8-a3d1-c17c8879f839/vdi
Oct 17 08:41:31 hdkvm02c SM: [11129] lock: closed
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:31 hdkvm02c SM: [11129] lock: closed
/var/lock/sm/081b1189-0b81-d55c-b230-b914ce8a9030/sr
Oct 17 08:41:33 hdkvm02c SM: [11442] #### VMOPS enter gethostvmstats ####
Oct 17 08:41:33 hdkvm02c SM: [11442] #### VMOPS exit gethostvmstats ####
Oct 17 08:41:36 hdkvm02c SM: [11509] #### VMOPS enter network_rules ####
Oct 17 08:41:36 hdkvm02c SM: [11509] ['ifconfig', 'tap13.0']
Oct 17 08:41:36 hdkvm02c SM: [11509] FAILED in util.pread: (rc 1) stdout: '',
stderr: 'tap13.0: error fetching interface information: Device not found
Oct 17 08:41:36 hdkvm02c SM: [11509] '
Oct 17 08:41:36 hdkvm02c SM: [11509] #### VMOPS enter check_rule_log_for_vm
####
Oct 17 08:41:36 hdkvm02c SM: [11509] Failed to find logfile
/var/run/cloud/i-2-60-VM.log
Oct 17 08:41:36 hdkvm02c SM: [11509] #### VMOPS exit check_rule_log_for_vm ####
Oct 17 08:41:36 hdkvm02c SM: [11509] Change detected in vmId or vmIp or domId,
resetting default rules
Oct 17 08:41:36 hdkvm02c SM: [11509] #### VMOPS enter default_network_rules
####
Oct 17 08:41:36 hdkvm02c SM: [11509] Failed to network rule !
Oct 17 08:41:36 hdkvm02c SM: [11509] #### VMOPS exit network_rules ####
Oct 17 08:42:09 hdkvm02c SM: [13304] lock: acquired
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:42:09 hdkvm02c SM: [13304] sr_scan {'sr_uuid':
'5609c1c0-03e4-8b58-1bf1-533f1ade34a1', 'subtask_of':
'DummyRef:|5ac8798c-f340-d0e6-ee9b-9e3c37a94d4b|SR.scan', 'args': [],
'host_ref': 'OpaqueRef:99e28465-5100-6b59-e9d7-ea48b5cdde49', 'session_ref':
'OpaqueRef:2d91c259-8f5d-86b3-327a-3f906d5c5f0b', 'device_config': {'device':
'/dev/md0', 'SRmaster': 'true'}, 'command': 'sr_scan', 'sr_ref':
'OpaqueRef:3155b7a0-1a0a-6dea-42d3-db95d84dbd82'}
Oct 17 08:42:09 hdkvm02c SM: [13304] ['/usr/bin/vhd-util', 'scan', '-f', '-c',
'-m', '/var/run/sr-mount/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/*.vhd']
Oct 17 08:42:10 hdkvm02c SM: [13304] pread SUCCESS
Oct 17 08:42:10 hdkvm02c SM: [13304] ['ls',
'/var/run/sr-mount/5609c1c0-03e4-8b58-1bf1-533f1ade34a1', '-1', '--color=never']
Oct 17 08:42:10 hdkvm02c SM: [13304] pread SUCCESS
Oct 17 08:42:10 hdkvm02c SM: [13304] lock: tried lock
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/running, acquired: True
(exists: True)
Oct 17 08:42:10 hdkvm02c SM: [13304] lock: released
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/running
Oct 17 08:42:10 hdkvm02c SM: [13304] Kicking GC
Oct 17 08:42:10 hdkvm02c SMGC: [13304] === SR
5609c1c0-03e4-8b58-1bf1-533f1ade34a1: gc ===
Oct 17 08:42:10 hdkvm02c SMGC: [13308] Will finish as PID [13309]
Oct 17 08:42:10 hdkvm02c SMGC: [13304] New PID [13308]
Oct 17 08:42:10 hdkvm02c SM: [13304] lock: closed
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/running
Oct 17 08:42:10 hdkvm02c SM: [13304] lock: released
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:42:10 hdkvm02c SM: [13304] lock: closed
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:42:10 hdkvm02c SMGC: [13309] Found 0 cache files
Oct 17 08:42:10 hdkvm02c SM: [13309] lock: tried lock
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr, acquired: True (exists:
True)
Oct 17 08:42:10 hdkvm02c SM: [13309] ['/usr/bin/vhd-util', 'scan', '-f', '-c',
'-m', '/var/run/sr-mount/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/*.vhd']
Oct 17 08:42:10 hdkvm02c SM: [13309] pread SUCCESS
Oct 17 08:42:10 hdkvm02c SMGC: [13309] SR 5609
('5609c1c0-03e4-8b58-1bf1-533f1ade34a1') (0 VDIs in 0 VHD trees): no changes
Oct 17 08:42:10 hdkvm02c SM: [13309] lock: released
/var/lock/sm/5609c1c0-03e4-8b58-1bf1-533f1ade34a1/sr
Oct 17 08:42:10 hdkvm02c SMGC: [13309] No work, exiting
Oct 17 08:42:10 hdkvm02c SMGC: [13309] In cleanup
Oct 17 08:42:10 hdkvm02c SMGC: [13309] SR 5609
('5609c1c0-03e4-8b58-1bf1-533f1ade34a1') (0 VDIs in 0 VHD trees): no changes
Oct 17 08:42:10 hdkvm02c SM: [13402] #### VMOPS enter gethostvmstats ####
Oct 17 08:42:11 hdkvm02c SM: [13402] #### VMOPS exit gethostvmstats ####
regards,
Paul
> VM Migration fails in 'Security Group Enabled Advanced Zone' with
> CloudRuntimeException: callHostPlugin failed for cmd: network_rules
> -------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-4624
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4624
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: XenServer
> Affects Versions: 4.2.0, Future
> Environment: CloudStack 4.2.0 with XenServer 6.1 or 6.2
> Reporter: Paul Angus
> Assignee: Jayapal Reddy
> Priority: Critical
> Fix For: 4.2.1
>
>
> VM Migration fails in a 'Security Group Enabled Advanced Zone' with
> CloudRuntimeException: callHostPlugin failed for cmd: network_rules
> 013-09-06 14:18:07,711 DEBUG [network.security.SecurityGroupManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Security
> Group Mgr v2: scheduling ruleset updates for 1 vms (unique=1), current queue
> size=0
> 2013-09-06 14:18:07,715 DEBUG [network.security.SecurityGroupManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Security
> Group Mgr v2: done scheduling ruleset updates for 1 vms: num new jobs=1 num
> rows insert or updated=1 time taken=4
> 2013-09-06 14:18:07,715 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) VM state
> transitted from :Migrating to Running with event: OperationSucceededvm's
> original host id: 7 new host id: 8 host id before state transition: 8
> 2013-09-06 14:18:07,721 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-244:null) Ping from 5
> 2013-09-06 14:18:07,728 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Hosts's
> actual total CPU: 63840 and CPU after applying overprovisioning: 127680
> 2013-09-06 14:18:07,729 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Hosts's
> actual total RAM: 267404820480 and RAM after applying overprovisioning:
> 267404820480
> 2013-09-06 14:18:07,729 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) release
> cpu from host: 7, old used: 1000,reserved: 0, actual total: 63840, total with
> overprovisioning: 127680; new used: 0,reserved:0; movedfromreserved:
> false,moveToReserveredfalse
> 2013-09-06 14:18:07,729 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) release
> mem from host: 7, old used: 1073741824,reserved: 0, total: 267404820480; new
> used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-09-06 14:18:07,731 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
> ===START=== 10.67.9.233 -- GET
> command=queryAsyncJobResult&jobId=16e9e8e3-460e-4a72-a455-d65b01f3b360&response=json&sessionkey=hLoqoRm93LQk67lSOtoBQZludFg%3D&_=1378473487668
> 2013-09-06 14:18:07,738 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Seq
> 8-576979043: Sending { Cmd , MgmtId: 345052351047, via: 8, Ver: v1, Flags:
> 100011,
> [{"com.cloud.agent.api.CheckVirtualMachineCommand":{"vmName":"i-2-11-VM","wait":20}}]
> }
> 2013-09-06 14:18:07,738 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Seq
> 8-576979043: Executing: { Cmd , MgmtId: 345052351047, via: 8, Ver: v1,
> Flags: 100011,
> [{"com.cloud.agent.api.CheckVirtualMachineCommand":{"vmName":"i-2-11-VM","wait":20}}]
> }
> 2013-09-06 14:18:07,739 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-436:null) Seq 8-576979043: Executing request
> 2013-09-06 14:18:07,747 DEBUG [network.security.SecurityGroupManagerImpl]
> (SecGrp-Worker-41:null) SecurityGroupManager v2: sending ruleset update for
> vm i-2-11-VM:ingress num rules=4:egress num rules=0 num cidrs=6
> sig=8ccd7a72119d5c8180377d3cd847c10f
> 2013-09-06 14:18:07,750 DEBUG [agent.transport.Request]
> (SecGrp-Worker-41:null) Seq 8-576979044: Sending { Cmd , MgmtId:
> 345052351047, via: 8, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"10.79.129.49","vmName":"i-2-11-VM","guestMac":"06:b5:fa:00:07:25","signature":"8ccd7a72119d5c8180377d3cd847c10f","seqNum":11,"vmId":11,"msId":345052351047,"ingressRuleSet":[{"proto":"icmp","startPort":-1,"endPort":-1},{"proto":"tcp","startPort":1,"endPort":65535},{"proto":"tcp","startPort":22,"endPort":22},{"proto":"udp","startPort":1,"endPort":65535}],"egressRuleSet":[],"wait":0}}]
> }
> 2013-09-06 14:18:07,750 DEBUG [agent.transport.Request]
> (SecGrp-Worker-41:null) Seq 8-576979044: Executing: { Cmd , MgmtId:
> 345052351047, via: 8, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"10.79.129.49","vmName":"i-2-11-VM","guestMac":"06:b5:fa:00:07:25","signature":"8ccd7a72119d5c8180377d3cd847c10f","seqNum":11,"vmId":11,"msId":345052351047,"ingressRuleSet":[{"proto":"icmp","startPort":-1,"endPort":-1},{"proto":"tcp","startPort":1,"endPort":65535},{"proto":"tcp","startPort":22,"endPort":22},{"proto":"udp","startPort":1,"endPort":65535}],"egressRuleSet":[],"wait":0}}]
> }
> 2013-09-06 14:18:07,750 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-406:null) Seq 8-576979044: Executing request
> 2013-09-06 14:18:07,765 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
> ===END=== 10.67.9.233 -- GET
> command=queryAsyncJobResult&jobId=16e9e8e3-460e-4a72-a455-d65b01f3b360&response=json&sessionkey=hLoqoRm93LQk67lSOtoBQZludFg%3D&_=1378473487668
> 2013-09-06 14:18:07,773 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-9:null) SeqA 14-366: Processing Seq 14-366: { Cmd ,
> MgmtId: -1, via: 14, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":4,"_loadInfo":"{\n
> \"connections\": [\n {\n \"id\": 2,\n \"clientInfo\": \"\",\n
> \"host\": \"10.79.149.198\",\n \"port\": -1,\n \"tag\":
> \"d40c2f3a-7677-4e8f-abb4-ee40ca6e4ff9\",\n \"createTime\":
> 1378472362519,\n \"lastUsedTime\": 1378473485748\n },\n {\n
> \"id\": 1,\n \"clientInfo\": \"\",\n \"host\": \"10.79.149.196\",\n
> \"port\": -1,\n \"tag\":
> \"e4a541da-d89c-45f2-afe4-cd8899b85a81\",\n \"createTime\":
> 1378472139707,\n \"lastUsedTime\": 1378473486795\n }\n
> ]\n}","wait":0}}] }
> 2013-09-06 14:18:07,779 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-9:null) SeqA 14-366: Sending Seq 14-366: { Ans: ,
> MgmtId: 345052351047, via: 14, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-09-06 14:18:07,868 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-457:null) Ping from 4
> 2013-09-06 14:18:07,900 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-436:null) 3. The VM i-2-11-VM is in Running state
> 2013-09-06 14:18:07,900 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-436:null) Seq 8-576979043: Response Received:
> 2013-09-06 14:18:07,901 DEBUG [agent.transport.Request]
> (DirectAgent-436:null) Seq 8-576979043: Processing: { Ans: , MgmtId:
> 345052351047, via: 8, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.CheckVirtualMachineAnswer":{"state":"Running","result":true,"wait":0}}]
> }
> 2013-09-06 14:18:07,901 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Seq
> 8-576979043: Received: { Ans: , MgmtId: 345052351047, via: 8, Ver: v1,
> Flags: 10, { CheckVirtualMachineAnswer } }
> 2013-09-06 14:18:07,942 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Complete
> async job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ], jobStatus: 1,
> resultCode: 0, result:
> org.apache.cloudstack.api.response.UserVmResponse@18546902
> 2013-09-06 14:18:07,947 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-16:job-64 = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]) Done
> executing org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd for job-64
> = [ 16e9e8e3-460e-4a72-a455-d65b01f3b360 ]
> 2013-09-06 14:18:07,979 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-292:null) Ping from 3
> 2013-09-06 14:18:08,272 WARN [xen.resource.CitrixResourceBase]
> (DirectAgent-406:null) callHostPlugin failed for cmd: network_rules with args
> seqno: 11, vmIP: 10.79.129.49, deflated: true, secIps: 0:, vmID: 11, vmMAC:
> 06:b5:fa:00:07:25, vmName: i-2-11-VM, rules:
> eJzztMpMzi2w0jUEIQM9MNQ30PFzjQhR8LQqSS6wMrQyMzU1NrUyNNAzt9QzNLLUMzHXNzbSQeJbgvhIWoyMQMgQZpwFTK40hUTjAHzDJCY=,
> signature: 8ccd7a72119d5c8180377d3cd847c10f, due to There was a failure
> communicating with the plugin.
> 2013-09-06 14:18:08,273 WARN [agent.manager.DirectAgentAttache]
> (DirectAgent-406:null) Seq 8-576979044: Exception Caught while executing
> command
> com.cloud.utils.exception.CloudRuntimeException: callHostPlugin failed for
> cmd: network_rules with args seqno: 11, vmIP: 10.79.129.49, deflated: true,
> secIps: 0:, vmID: 11, vmMAC: 06:b5:fa:00:07:25, vmName: i-2-11-VM, rules:
> eJzztMpMzi2w0jUEIQM9MNQ30PFzjQhR8LQqSS6wMrQyMzU1NrUyNNAzt9QzNLLUMzHXNzbSQeJbgvhIWoyMQMgQZpwFTK40hUTjAHzDJCY=,
> signature: 8ccd7a72119d5c8180377d3cd847c10f, due to There was a failure
> communicating with the plugin.
> at
> com.cloud.hypervisor.xen.resource.CitrixResourceBase.callHostPlugin(CitrixResourceBase.java:4188)
> at
> com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:5776)
> at
> com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:561)
> at
> com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
> at
> com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:104)
> at
> com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:679)
--
This message was sent by Atlassian JIRA
(v6.1#6144)
