[20110901T13:27:57.001Z|debug|xen-blade13|15509 inet-RPC|Connection to VM console R:c080c73b3a98|console] VM OpaqueRef:14265b6a-41a3-c860-dde6-f3fe107fabba console port: None
[20110901T13:28:01.664Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|dispatcher] spawning a new thread to handle the current task (trackid=24562c1f4c6e50267611dc66fda0ed77)
[20110901T13:28:01.664Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|audit] VM.start: VM = '7ef51a1e-2a0a-5ef4-50f6-618cbb251543 (Win2008-64bit-R2 (1))'
[20110901T13:28:01.683Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] No operations are valid because current-operations = [ OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 -> attach ]
[20110901T13:28:01.688Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Using wlb recommendations for choosing a host has been disabled or wlb is not available. Using original algorithm
[20110901T13:28:01.690Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi_ha_vm_failover] assert_configuration_change_preserves_ha_plan c = configuration_change = { old_vms_leaving = [  ]; new_vms_arriving = [ 8372e737 (xen-blade13) 8f56e611 (Win2008-64bit-R2 (1)) ]; hosts_to_disable = [  ]; num_failures = no change; new_vms = [  ] }
[20110901T13:28:01.702Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|thread_queue] push(vm_lifecycle_op, VM.start Async.VM.start R:3fae217e8466): queue = [ VM.start Async.VM.start R:3fae217e8466 ](1)
[20110901T13:28:01.702Z|debug|xen-blade13|614||thread_queue] pop(vm_lifecycle_op) = VM.start Async.VM.start R:3fae217e8466
[20110901T13:28:01.702Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|locking_helpers] Acquired lock on VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f with token 63
[20110901T13:28:01.702Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] start: making sure the VM really is halted
[20110901T13:28:01.702Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] start: checking that VM can run on this host
[20110901T13:28:01.704Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] start: bringing up domain in the paused state
[20110901T13:28:01.707Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|memory_control] reserve_memory_range min=1067008 max=1591296
[20110901T13:28:01.707Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenstore-rpc] Checking pid 1958
[20110901T13:28:01.713Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenstore-rpc] Written request using id: e3005f23-bc9c-7a1c-1952-76c52499d004
[20110901T13:28:01.729Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/reserve-memory-range/e3005f23-bc9c-7a1c-1952-76c52499d004 ] with timeout 1200.000000 seconds
[20110901T13:28:01.803Z| info|xen-blade13|15518 inet-RPC|dispatch:task.add_to_other_config D:94a59072ee2d|api_effect] task.add_to_other_config
[20110901T13:28:01.935Z| info|xen-blade13|15522 inet-RPC|dispatch:task.add_to_other_config D:d73b18d26f20|api_effect] task.add_to_other_config
[20110901T13:28:02.040Z|debug|xen-blade13|15526 inet-RPC|Connection to VM console R:e262e28bf8d0|console] VM OpaqueRef:14265b6a-41a3-c860-dde6-f3fe107fabba console port: None
[20110901T13:28:02.920Z|debug|xen-blade13|140 sr_scan|SR scanner D:4f84a3fa01a7|xapi] Automatically scanning SRs = [ OpaqueRef:6979cc64-f22e-0dcc-8eff-4a26aea40a0f ]
[20110901T13:28:02.921Z|debug|xen-blade13|15533||dummytaskhelper] task scan one D:8bd33f2fbf14 created by task D:4f84a3fa01a7
[20110901T13:28:02.921Z|debug|xen-blade13|15533|scan one D:8bd33f2fbf14|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:02.923Z|debug|xen-blade13|15534 unix-RPC||dummytaskhelper] task dispatch:session.slave_login D:3e302de29f67 created by task D:8bd33f2fbf14
[20110901T13:28:02.927Z| info|xen-blade13|15534 unix-RPC|session.slave_login D:56773ed71a8a|xapi] Session.create trackid=49c9d9ca62b2e30feb8a89d4674ac1f0 pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:02.929Z|debug|xen-blade13|15534 unix-RPC|session.slave_login D:56773ed71a8a|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:02.932Z|debug|xen-blade13|15535 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:51e553924ed8 created by task D:56773ed71a8a
[20110901T13:28:02.937Z|debug|xen-blade13|15533|scan one D:8bd33f2fbf14|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:02.939Z|debug|xen-blade13|15536 unix-RPC||dummytaskhelper] task dispatch:SR.scan D:5c42658ecabc created by task D:8bd33f2fbf14
[20110901T13:28:02.946Z| info|xen-blade13|15536 unix-RPC|dispatch:SR.scan D:5c42658ecabc|taskhelper] task SR.scan R:05f0dcb934ea (uuid:31dfb66d-887d-ad02-1f48-619d006f554b) created (trackid=49c9d9ca62b2e30feb8a89d4674ac1f0) by task D:8bd33f2fbf14
[20110901T13:28:02.947Z|debug|xen-blade13|15536 unix-RPC|SR.scan R:05f0dcb934ea|xapi] SR.scan: SR = 'd3320530-2ed1-8212-3297-467473afca02 (CIFS ISO library)'
[20110901T13:28:02.949Z|debug|xen-blade13|15536 unix-RPC|SR.scan R:05f0dcb934ea|xapi] Marking SR for SR.scan (task=OpaqueRef:05f0dcb9-34ea-1ab2-43b2-8b5b78e1dd95)
[20110901T13:28:02.953Z|debug|xen-blade13|15536 unix-RPC|SR.scan R:05f0dcb934ea|sm] SM iso sr_scan sr=OpaqueRef:6979cc64-f22e-0dcc-8eff-4a26aea40a0f
[20110901T13:28:02.958Z| info|xen-blade13|15536 unix-RPC|sm_exec D:1758997b1597|xapi] Session.create trackid=9006df2b2c732d2de18bd55a53e7dc22 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:02.959Z|debug|xen-blade13|15536 unix-RPC|sm_exec D:1758997b1597|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:02.962Z|debug|xen-blade13|15538 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:0d7504b1a7c0 created by task D:1758997b1597
[20110901T13:28:03.083Z|debug|xen-blade13|15541 unix-RPC||dummytaskhelper] task dispatch:host.get_other_config D:8b57416ff262 created by task R:05f0dcb934ea
[20110901T13:28:03.111Z|debug|xen-blade13|15542 unix-RPC||dummytaskhelper] task dispatch:SR.get_by_uuid D:3304364852d1 created by task R:05f0dcb934ea
[20110901T13:28:03.119Z|debug|xen-blade13|15543 unix-RPC||dummytaskhelper] task dispatch:VDI.get_all_records_where D:1d2d6d73e747 created by task R:05f0dcb934ea
[20110901T13:28:03.130Z|debug|xen-blade13|15544 unix-RPC||dummytaskhelper] task dispatch:SR.get_by_uuid D:6ffa2c745fb7 created by task R:05f0dcb934ea
[20110901T13:28:03.139Z|debug|xen-blade13|15545 unix-RPC||dummytaskhelper] task dispatch:SR.set_virtual_allocation D:ab03d6d51719 created by task R:05f0dcb934ea
[20110901T13:28:03.149Z|debug|xen-blade13|15546 unix-RPC||dummytaskhelper] task dispatch:SR.set_physical_size D:de8322a942a4 created by task R:05f0dcb934ea
[20110901T13:28:03.159Z|debug|xen-blade13|15548 unix-RPC||dummytaskhelper] task dispatch:SR.set_physical_utilisation D:97f36f02207f created by task R:05f0dcb934ea
[20110901T13:28:03.169Z|debug|xen-blade13|15550 unix-RPC||dummytaskhelper] task dispatch:SR.get_by_uuid D:9acc69a55583 created by task R:05f0dcb934ea
[20110901T13:28:03.176Z|debug|xen-blade13|15551 unix-RPC||dummytaskhelper] task dispatch:VDI.get_all_records_where D:2e9d548a4511 created by task R:05f0dcb934ea
[20110901T13:28:03.199Z| info|xen-blade13|15536 unix-RPC|sm_exec D:1758997b1597|xapi] Session.destroy trackid=9006df2b2c732d2de18bd55a53e7dc22
[20110901T13:28:03.203Z|debug|xen-blade13|15536 unix-RPC|SR.scan R:05f0dcb934ea|xapi] Unmarking SR after SR.scan (task=OpaqueRef:05f0dcb9-34ea-1ab2-43b2-8b5b78e1dd95)
[20110901T13:28:03.217Z|debug|xen-blade13|15533|scan one D:8bd33f2fbf14|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:03.219Z|debug|xen-blade13|15553 unix-RPC||dummytaskhelper] task dispatch:session.logout D:6bd47cc1316d created by task D:8bd33f2fbf14
[20110901T13:28:03.223Z| info|xen-blade13|15553 unix-RPC|session.logout D:6241576bf4d3|xapi] Session.destroy trackid=49c9d9ca62b2e30feb8a89d4674ac1f0
[20110901T13:28:03.226Z|debug|xen-blade13|15533|scan one D:8bd33f2fbf14|xapi] Scan of SR d3320530-2ed1-8212-3297-467473afca02 complete.
[20110901T13:28:03.740Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|memory_control] reserve_memory_range actual = 1216180
[20110901T13:28:03.740Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|memory_control] reserved_memory = 1216180; min = 1067008; max = 1591296
[20110901T13:28:03.740Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] VM will have 4 hotplugged vcpus out of 4
[20110901T13:28:03.740Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] xen reports max 256 pCPUs
[20110901T13:28:03.740Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Memory free = 1225396; scrub = 0
[20110901T13:28:03.741Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Regenerating the xenstored tree under: [/local/domain/14]
[20110901T13:28:03.780Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Created domain with id: 14
[20110901T13:28:03.780Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Created domain with domid: 14
[20110901T13:28:03.780Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|memory_control] transfer_reservation_to_domain f6cd929b-dc30-33f8-0ccc-d8e39f9f89a9 -> 14
[20110901T13:28:03.780Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenstore-rpc] Checking pid 1958
[20110901T13:28:03.786Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenstore-rpc] Written request using id: 26f701af-200e-aa6d-dbd0-dce22262ec1a
[20110901T13:28:03.786Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/transfer-reservation-to-domain/26f701af-200e-aa6d-dbd0-dce22262ec1a ] with timeout 1200.000000 seconds
[20110901T13:28:03.797Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|memory_control] delete_reservation f6cd929b-dc30-33f8-0ccc-d8e39f9f89a9
[20110901T13:28:03.798Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenstore-rpc] Checking pid 1958
[20110901T13:28:03.804Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenstore-rpc] Written request using id: 145b9430-b458-54dd-cbeb-0d32390353b0
[20110901T13:28:03.804Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/delete-reservation/145b9430-b458-54dd-cbeb-0d32390353b0 ] with timeout 1200.000000 seconds
[20110901T13:28:03.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Verifying VDI records exist
[20110901T13:28:03.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] creating kernel
[20110901T13:28:03.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] build hvm "/usr/lib/xen-4.1/boot/hvmloader" vcpus:4 mem_max:1572864 mem_target:1197748 timeoffset:3600
[20110901T13:28:03.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] build_pre domid=14; max=1537 MiB; shadow=16 MiB; required=1188 MiB
[20110901T13:28:03.838Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenguesthelper] connect: args = [ -mode hvm_build -domid 14 -store_port 5 -console_port 6 -image /usr/lib/xen-4.1/boot/hvmloader -mem_max_mib 1532 -mem_start_mib 1166 -fork true ]
[20110901T13:28:03.869Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenguesthelper] xc: info: VIRTUAL MEMORY ARRANGEMENT:\n  Loader:        0000000000100000->000000000017c2d0\n  TOTAL:         0000000000000000->000000005fc00000\n  ENTRY ADDRESS: 00000000001015a0\n
[20110901T13:28:04.314Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenguesthelper] xc: 
[20110901T13:28:04.314Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenguesthelper] info: 
[20110901T13:28:04.314Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenguesthelper] PHYSICAL MEMORY ALLOCATION:\n  4KB PAGES: 0x0000000000000200\n  2MB PAGES: 0x00000000000002fd\n  1GB PAGES: 0x0000000000000000
[20110901T13:28:04.315Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenguesthelper] \n
[20110901T13:28:04.323Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Read [1044476 1044479]
[20110901T13:28:04.336Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] actual shadow value is 16 MiB [multiplier = 1.00]; requested value was 16 MiB [multiplier = 1.00]
[20110901T13:28:04.342Z|debug|xen-blade13|139 xal_listen||event] VM (domid: -1) device_event = change rtc {7ef51a1e-2a0a-5ef4-50f6-618cbb251543,3600}
[20110901T13:28:04.345Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] creating VCPU devices and attaching to domain
[20110901T13:28:04.353Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] creating VBD devices and attaching to domain
[20110901T13:28:04.353Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] VBD device name 3 interpreted as Ide(3, 0) (hvm = true)
[20110901T13:28:04.355Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Vbd.add (device_number=Ide(3, 0) | physpath= | phystype=file)
[20110901T13:28:04.356Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] adding device  B0[/local/domain/0/backend/vbd/14/5696]  F14[/local/domain/14/device/vbd/5696]  H[/xapi/14/hotplug/vbd/5696]
[20110901T13:28:04.376Z|debug|xen-blade13|139 xal_listen||event] VM (domid: 14) device_event = ChangeUncooperative false
[20110901T13:28:04.378Z|debug|xen-blade13|139 xal_listen|VM (domid: 14) device_event = ChangeUncooperative false D:d0223ebb50b9|event] VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f is now cooperative
[20110901T13:28:04.384Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] VBD device name 0 interpreted as Ide(0, 0) (hvm = true)
[20110901T13:28:04.385Z|debug|xen-blade13|139 xal_listen||event] VM (domid: 14) device_event = device eject {5696}
[20110901T13:28:04.386Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] VDI.attach task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b read_write:true
[20110901T13:28:04.388Z|debug|xen-blade13|139 xal_listen|VM (domid: 14) device_event = device eject {5696} D:5548e6a5b9a4|event] Adding Vbdops.eject_vbd to queue
[20110901T13:28:04.388Z|debug|xen-blade13|139 xal_listen|VM (domid: 14) device_event = device eject {5696} D:5548e6a5b9a4|locking_helpers] push(per-VM queue, DevEject(5696) domid 14); queue = [ DevEject(5696) domid 14 ](1)
[20110901T13:28:04.388Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|dummytaskhelper] task VDI.attach D:cf55b8ac8207 created by task R:3fae217e8466
[20110901T13:28:04.388Z|debug|xen-blade13|15516|VDI.attach D:cf55b8ac8207|sm] SM ocfs vdi_attach sr=OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi=OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b writable=true
[20110901T13:28:04.394Z| info|xen-blade13|15516|sm_exec D:d285de7d3aa4|xapi] Session.create trackid=df31534c822fee1cec827cf61c9f62da pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:04.396Z|debug|xen-blade13|15516|sm_exec D:d285de7d3aa4|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:04.400Z|debug|xen-blade13|15564 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:f9761ba62e01 created by task D:d285de7d3aa4
[20110901T13:28:04.522Z|debug|xen-blade13|15567 unix-RPC||dummytaskhelper] task dispatch:host.get_other_config D:caf2ce18bcf4 created by task D:cf55b8ac8207
[20110901T13:28:04.590Z| info|xen-blade13|15516|sm_exec D:d285de7d3aa4|xapi] Session.destroy trackid=df31534c822fee1cec827cf61c9f62da
[20110901T13:28:04.592Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b superstate:attached  RW
[20110901T13:28:04.594Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] VDI.activate task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b
[20110901T13:28:04.596Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|dummytaskhelper] task VDI.activate D:e1bd05723beb created by task R:3fae217e8466
[20110901T13:28:04.596Z|debug|xen-blade13|15516|VDI.activate D:e1bd05723beb|sm] SM ocfs vdi_activate sr=OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi=OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b
[20110901T13:28:04.601Z| info|xen-blade13|15516|sm_exec D:3dbdb199a000|xapi] Session.create trackid=d905d1f68156cec1cf714aeb4745b4d5 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:04.602Z|debug|xen-blade13|15516|sm_exec D:3dbdb199a000|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:04.605Z|debug|xen-blade13|15568 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:d7bac5e99f67 created by task D:3dbdb199a000
[20110901T13:28:04.716Z|debug|xen-blade13|15570 unix-RPC||dummytaskhelper] task dispatch:host.get_other_config D:2a79a311b4a3 created by task D:e1bd05723beb
[20110901T13:28:04.766Z|debug|xen-blade13|15571 unix-RPC||dummytaskhelper] task dispatch:VDI.get_by_uuid D:a086e0c1c25b created by task D:e1bd05723beb
[20110901T13:28:04.774Z|debug|xen-blade13|15572 unix-RPC||dummytaskhelper] task dispatch:host.get_by_uuid D:9581b5641448 created by task D:e1bd05723beb
[20110901T13:28:04.783Z|debug|xen-blade13|15573 unix-RPC||dummytaskhelper] task dispatch:VDI.get_sm_config D:1aedcadec49c created by task D:e1bd05723beb
[20110901T13:28:04.791Z|debug|xen-blade13|15574 unix-RPC||dummytaskhelper] task dispatch:VDI.add_to_sm_config D:e3270651a724 created by task D:e1bd05723beb
[20110901T13:28:04.794Z| info|xen-blade13|15574 unix-RPC|dispatch:VDI.add_to_sm_config D:e3270651a724|api_effect] VDI.add_to_sm_config
[20110901T13:28:04.803Z|debug|xen-blade13|15575 unix-RPC||dummytaskhelper] task dispatch:VDI.get_sm_config D:6ae3d41ce591 created by task D:e1bd05723beb
[20110901T13:28:04.811Z|debug|xen-blade13|15576 unix-RPC||dummytaskhelper] task dispatch:VDI.get_by_uuid D:f4c674e16639 created by task D:e1bd05723beb
[20110901T13:28:04.819Z|debug|xen-blade13|15578 unix-RPC||dummytaskhelper] task dispatch:VDI.get_SR D:494ad9c80571 created by task D:e1bd05723beb
[20110901T13:28:04.827Z|debug|xen-blade13|15579 unix-RPC||dummytaskhelper] task dispatch:SR.get_uuid D:44433dbc3c2f created by task D:e1bd05723beb
[20110901T13:28:04.835Z|debug|xen-blade13|15580 unix-RPC||dummytaskhelper] task dispatch:SR.get_by_uuid D:07b829fd650a created by task D:e1bd05723beb
[20110901T13:28:04.843Z|debug|xen-blade13|15581 unix-RPC||dummytaskhelper] task dispatch:SR.get_type D:be96c4b74679 created by task D:e1bd05723beb
[20110901T13:28:04.851Z|debug|xen-blade13|15582 unix-RPC||dummytaskhelper] task dispatch:SM.get_all_records_where D:d00501e8a837 created by task D:e1bd05723beb
[20110901T13:28:04.861Z|debug|xen-blade13|15583 unix-RPC||dummytaskhelper] task dispatch:SM.get_driver_filename D:72f0cd036f46 created by task D:e1bd05723beb
[20110901T13:28:04.870Z|debug|xen-blade13|15585 unix-RPC||dummytaskhelper] task dispatch:VM.get_all_records_where D:5ef2eedfd088 created by task D:e1bd05723beb
[20110901T13:28:04.882Z|debug|xen-blade13|15586 unix-RPC||dummytaskhelper] task dispatch:PBD.get_all_records_where D:cc67e3f3842b created by task D:e1bd05723beb
[20110901T13:28:04.891Z|debug|xen-blade13|15587 unix-RPC||dummytaskhelper] task dispatch:PBD.get_device_config D:e45e4ce32bea created by task D:e1bd05723beb
[20110901T13:28:04.930Z| info|xen-blade13|15590 unix-RPC|dispatch:VDI.remove_from_xenstore_data D:7f61abac3c7c|api_effect] VDI.remove_from_xenstore_data
[20110901T13:28:04.941Z| info|xen-blade13|15591 unix-RPC|dispatch:VDI.remove_from_xenstore_data D:393c70cb2740|api_effect] VDI.remove_from_xenstore_data
[20110901T13:28:04.954Z| info|xen-blade13|15592 unix-RPC|dispatch:VDI.add_to_xenstore_data D:f40c7bcddb81|api_effect] VDI.add_to_xenstore_data
[20110901T13:28:04.966Z| info|xen-blade13|15594 unix-RPC|dispatch:VDI.remove_from_xenstore_data D:b74024cc81b8|api_effect] VDI.remove_from_xenstore_data
[20110901T13:28:04.975Z| info|xen-blade13|15595 unix-RPC|dispatch:VDI.remove_from_xenstore_data D:aea665e0dc16|api_effect] VDI.remove_from_xenstore_data
[20110901T13:28:04.985Z| info|xen-blade13|15596 unix-RPC|dispatch:VDI.remove_from_xenstore_data D:98b770efd47e|api_effect] VDI.remove_from_xenstore_data
[20110901T13:28:04.994Z| info|xen-blade13|15597 unix-RPC|dispatch:VDI.remove_from_xenstore_data D:e4f8d33c1040|api_effect] VDI.remove_from_xenstore_data
[20110901T13:28:05.009Z| info|xen-blade13|15598 unix-RPC|dispatch:VDI.add_to_xenstore_data D:f945d37506d1|api_effect] VDI.add_to_xenstore_data
[20110901T13:28:05.018Z| info|xen-blade13|15599 unix-RPC|dispatch:VDI.add_to_xenstore_data D:55f640262311|api_effect] VDI.add_to_xenstore_data
[20110901T13:28:05.028Z| info|xen-blade13|15602 unix-RPC|dispatch:VDI.add_to_xenstore_data D:d6e60be8c4af|api_effect] VDI.add_to_xenstore_data
[20110901T13:28:05.176Z| info|xen-blade13|15516|sm_exec D:3dbdb199a000|xapi] Session.destroy trackid=d905d1f68156cec1cf714aeb4745b4d5
[20110901T13:28:05.179Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b superstate:activated RW
[20110901T13:28:05.181Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Vbd.add (device_number=Ide(0, 0) | physpath=/dev/sm/backend/caa409d1-cda8-3a72-429f-0498e378f70d/afd0c61f-c961-4297-ac3f-35c94ca381e0 | phystype=vhd)
[20110901T13:28:05.181Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] adding device  B0[/local/domain/0/backend/vbd/14/768]  F14[/local/domain/14/device/vbd/768]  H[/xapi/14/hotplug/vbd/768]
[20110901T13:28:05.215Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] set_currently_attached to true for VBD uuid 622f6d9e-93e2-8acd-783d-6bddd7ae4064
[20110901T13:28:05.217Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] creating VIF devices and attaching to domain
[20110901T13:28:05.218Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] register_vif vif=OpaqueRef:a8d05b17-c34e-7f79-6124-84629dfd278c network=OpaqueRef:27c534be-d88d-16d9-67d5-d574df631fe1
[20110901T13:28:05.218Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Trying to attach PIF: 6b25f096-04c3-06b5-e3b0-eaa8c2ab5648
[20110901T13:28:05.241Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Vif.add domid=14 devid=0 mac=3a:97:29:2f:c0:aa carrier=true rate=none other_config=[] extra_private_keys=[ref=OpaqueRef:a8d05b17-c34e-7f79-6124-84629dfd278c; vif-uuid=ea160a73-36a6-cfdc-dcf9-3083653d917b; network-uuid=65c59465-b20d-f640-01bd-c78e83ae7b72]
[20110901T13:28:05.241Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] adding device  B0[/local/domain/0/backend/vif/14/0]  F14[/local/domain/14/device/vif/0]  H[/xapi/14/hotplug/vif/0]
[20110901T13:28:05.269Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] could not update MTU field on VIF ea160a73-36a6-cfdc-dcf9-3083653d917b
[20110901T13:28:05.273Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] adjusting CPU number against startup-number
[20110901T13:28:05.282Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] creating device emulator
[20110901T13:28:05.282Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Dm.start domid=14
[20110901T13:28:05.293Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] qemu-dm: should be running in the background (stdout redirected to syslog)
[20110901T13:28:05.293Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] qemu-dm: pid = 13405. Waiting for /local/domain/0/device-model/14/state
[20110901T13:28:05.293Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/device-model/14/state ] with timeout 5.000000 seconds
[20110901T13:28:05.545Z|debug|xen-blade13|139 xal_listen||event] VM (domid: 14) device_event = HotplugChanged on 0 {""->online}
[20110901T13:28:05.547Z|debug|xen-blade13|139 xal_listen|VM (domid: 14) device_event = HotplugChanged on 0 {""->online} D:0171622a87c3|event] Adding Resync.vif to queue
[20110901T13:28:05.548Z|debug|xen-blade13|139 xal_listen|VM (domid: 14) device_event = HotplugChanged on 0 {""->online} D:0171622a87c3|locking_helpers] push(per-VM queue, HotplugChanged(vif, 0) domid: 14); queue = [ DevEject(5696) domid 14; HotplugChanged(vif, 0) domid: 14 ](2)
[20110901T13:28:06.314Z|debug|xen-blade13|24 monitor|performance monitor D:9d380de3ee5c|monitor_rrds] Creating fresh RRD for VM uuid=7ef51a1e-2a0a-5ef4-50f6-618cbb251543
[20110901T13:28:07.062Z|debug|xen-blade13|15619 inet-RPC|Connection to VM console R:39beb709a811|console] VM OpaqueRef:14265b6a-41a3-c860-dde6-f3fe107fabba console port: None
[20110901T13:28:10.298Z|error|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: timeout while watching xenstore after 5.000000 seconds
[20110901T13:28:10.299Z|error|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] qemu-dm: unexpected exit with code: 1
[20110901T13:28:10.299Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|backtrace] Raised at 
[20110901T13:28:10.299Z|error|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Vmops.start_paused caught: INTERNAL_ERROR: [ Device.Ioemu_failed("qemu-dm exitted unexpectedly") ]
[20110901T13:28:10.299Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Memory F 14604 KiB S 0 KiB T 32758 MiB
[20110901T13:28:10.301Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Domain.destroy: all known devices = [ frontend (domid=14 | kind=vbd | devid=5696); backend (domid=0 | kind=vbd | devid=5696); frontend (domid=14 | kind=vbd | devid=768); backend (domid=0 | kind=vbd | devid=768); frontend (domid=14 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0) ]
[20110901T13:28:10.301Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Domain.destroy calling Xc.domain_destroy (domid 14)
[20110901T13:28:10.665Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] qemu-dm: stopping qemu-dm with SIGTERM (domid = 14)
[20110901T13:28:10.666Z|debug|xen-blade13|139 xal_listen||event] VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain
[20110901T13:28:10.668Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] removing core files from /var/xen/qemu: ignoring exception Unix.Unix_error(20, "rmdir", "/var/xen/qemu/13405")
[20110901T13:28:10.668Z|debug|xen-blade13|139 xal_listen|VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain D:f4d07097d50d|event] adding Resync.vm to work queue
[20110901T13:28:10.668Z|debug|xen-blade13|139 xal_listen|VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain D:f4d07097d50d|locking_helpers] push(per-VM queue, VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain); queue = [ DevEject(5696) domid 14; HotplugChanged(vif, 0) domid: 14; VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain ](3)
[20110901T13:28:10.668Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown_request frontend (domid=14 | kind=vbd | devid=5696); backend (domid=0 | kind=vbd | devid=5696)
[20110901T13:28:10.668Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-write /local/domain/0/backend/vbd/14/5696/online = 0
[20110901T13:28:10.669Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown about to blow away frontend
[20110901T13:28:10.669Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/device/vbd/5696
[20110901T13:28:10.672Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/backend/vbd/14/5696/hotplug-status ] with timeout 1200.000000 seconds
[20110901T13:28:10.924Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown about to blow away backend and error paths
[20110901T13:28:10.924Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.rm_device_state frontend (domid=14 | kind=vbd | devid=5696); backend (domid=0 | kind=vbd | devid=5696)
[20110901T13:28:10.924Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/device/vbd/5696
[20110901T13:28:10.925Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/0/backend/vbd/14/5696
[20110901T13:28:10.926Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/0/error/backend/vbd/14
[20110901T13:28:10.926Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/error/device/vbd/5696
[20110901T13:28:10.927Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown_request frontend (domid=14 | kind=vbd | devid=768); backend (domid=0 | kind=vbd | devid=768)
[20110901T13:28:10.927Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-write /local/domain/0/backend/vbd/14/768/online = 0
[20110901T13:28:10.927Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown about to blow away frontend
[20110901T13:28:10.929Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/device/vbd/768
[20110901T13:28:10.931Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/backend/vbd/14/768/hotplug-status ] with timeout 1200.000000 seconds
[20110901T13:28:10.934Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown about to blow away backend and error paths
[20110901T13:28:10.934Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.rm_device_state frontend (domid=14 | kind=vbd | devid=768); backend (domid=0 | kind=vbd | devid=768)
[20110901T13:28:10.934Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/device/vbd/768
[20110901T13:28:10.936Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/0/backend/vbd/14/768
[20110901T13:28:10.942Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/0/error/backend/vbd/14
[20110901T13:28:10.942Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/error/device/vbd/768
[20110901T13:28:10.942Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown_request frontend (domid=14 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0)
[20110901T13:28:10.943Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-write /local/domain/0/backend/vif/14/0/online = 0
[20110901T13:28:10.943Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown about to blow away frontend
[20110901T13:28:10.944Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/device/vif/0
[20110901T13:28:10.946Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/backend/vif/14/0/hotplug-status ] with timeout 1200.000000 seconds
[20110901T13:28:10.948Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.Generic.hard_shutdown about to blow away backend and error paths
[20110901T13:28:10.948Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Device.rm_device_state frontend (domid=14 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0)
[20110901T13:28:10.948Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/device/vif/0
[20110901T13:28:10.949Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/0/backend/vif/14/0
[20110901T13:28:10.953Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/0/error/backend/vif/14
[20110901T13:28:10.953Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] xenstore-rm /local/domain/14/error/device/vif/0
[20110901T13:28:10.954Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Hotplug.release: frontend (domid=14 | kind=vbd | devid=5696); backend (domid=0 | kind=vbd | devid=5696)
[20110901T13:28:10.954Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Hotplug.wait_for_unplug: frontend (domid=14 | kind=vbd | devid=5696); backend (domid=0 | kind=vbd | devid=5696)
[20110901T13:28:10.954Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/backend/vbd/14/5696/hotplug-status ] with timeout 1200.000000 seconds
[20110901T13:28:10.955Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Synchronised ok with hotplug script: frontend (domid=14 | kind=vbd | devid=5696); backend (domid=0 | kind=vbd | devid=5696)
[20110901T13:28:10.956Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Hotplug.release: frontend (domid=14 | kind=vbd | devid=768); backend (domid=0 | kind=vbd | devid=768)
[20110901T13:28:10.956Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Hotplug.wait_for_unplug: frontend (domid=14 | kind=vbd | devid=768); backend (domid=0 | kind=vbd | devid=768)
[20110901T13:28:10.956Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/backend/vbd/14/768/hotplug-status ] with timeout 1200.000000 seconds
[20110901T13:28:10.957Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Synchronised ok with hotplug script: frontend (domid=14 | kind=vbd | devid=768); backend (domid=0 | kind=vbd | devid=768)
[20110901T13:28:10.958Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Hotplug.release: frontend (domid=14 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0)
[20110901T13:28:10.958Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Hotplug.wait_for_unplug: frontend (domid=14 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0)
[20110901T13:28:10.958Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] watch: watching xenstore paths: [ /local/domain/0/backend/vif/14/0/hotplug-status ] with timeout 1200.000000 seconds
[20110901T13:28:10.959Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Synchronised ok with hotplug script: frontend (domid=14 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0)
[20110901T13:28:10.959Z| warn|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] Warning, deleting unexpected 'vif' entry from /xapi/14/hotplug/vif/0
[20110901T13:28:10.960Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|hotplug] xenstore-rm /xapi/14/hotplug/vif/0/online
[20110901T13:28:10.964Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Domain.destroy: rm /local/domain/14
[20110901T13:28:10.980Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Domain.destroy: deleting backend paths
[20110901T13:28:10.988Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Xc.domain_getinfo 14 threw: 2: No such file or directory -- assuming domain nolonger exists
[20110901T13:28:10.988Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xenops] Xc.domain_getinfo 14 threw: 2: No such file or directory -- assuming domain nolonger exists
[20110901T13:28:10.988Z| info|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] DP.destroy task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda allow_leak:false
[20110901T13:28:10.988Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:821e82be-1cf5-95d3-4cc0-8ae919af9919 vdi:OpaqueRef:1746b5ca-7ddc-a32a-d932-5508378a0ebf superstate:activated RO
[20110901T13:28:10.993Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|dummytaskhelper] task VDI.deactivate D:a3bb09716ac9 created by task R:3fae217e8466
[20110901T13:28:10.993Z|debug|xen-blade13|15516|VDI.deactivate D:a3bb09716ac9|sm] SM ocfs vdi_deactivate sr=OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi=OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b
[20110901T13:28:10.998Z| info|xen-blade13|15516|sm_exec D:c14a83cdfa0a|xapi] Session.create trackid=8877c2426d9a941fe6e5c0457f20d557 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:11.000Z|debug|xen-blade13|15516|sm_exec D:c14a83cdfa0a|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:11.002Z|debug|xen-blade13|15634 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:868fa9538556 created by task D:c14a83cdfa0a
[20110901T13:28:11.118Z|debug|xen-blade13|15635 unix-RPC||dummytaskhelper] task dispatch:host.get_other_config D:6f496e2cc058 created by task D:a3bb09716ac9
[20110901T13:28:11.156Z|debug|xen-blade13|15636 unix-RPC||dummytaskhelper] task dispatch:VDI.get_by_uuid D:df2906f2ab7a created by task D:a3bb09716ac9
[20110901T13:28:11.164Z|debug|xen-blade13|15637 unix-RPC||dummytaskhelper] task dispatch:VDI.get_sm_config D:aaa2b88f1c13 created by task D:a3bb09716ac9
[20110901T13:28:11.323Z|debug|xen-blade13|24 monitor|performance monitor D:9d380de3ee5c|monitor_rrds] Sending back RRD for VM uuid=7ef51a1e-2a0a-5ef4-50f6-618cbb251543
[20110901T13:28:11.323Z|debug|xen-blade13|24 monitor|performance monitor D:9d380de3ee5c|monitor_rrds] Archiving RRD for object uuid=7ef51a1e-2a0a-5ef4-50f6-618cbb251543 to local disk
[20110901T13:28:11.328Z|debug|xen-blade13|24 monitor|performance monitor D:9d380de3ee5c|monitor_rrds] No local storage: not persisting RRDs
[20110901T13:28:11.361Z| info|xen-blade13|15639 unix-RPC|session.login_with_password D:5827e68ecb9c|xapi] Session.create trackid=79f7a8681170559e393fc74e0854b4d5 pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:11.363Z|debug|xen-blade13|15639 unix-RPC|session.login_with_password D:5827e68ecb9c|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:11.366Z|debug|xen-blade13|15640 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:fe83b7919590 created by task D:5827e68ecb9c
[20110901T13:28:11.416Z| info|xen-blade13|15648 unix-RPC|dispatch:VDI.remove_from_sm_config D:105e91d35341|api_effect] VDI.remove_from_sm_config
[20110901T13:28:11.426Z| info|xen-blade13|15649 unix-RPC|dispatch:VDI.remove_from_sm_config D:d401f83a5994|api_effect] VDI.remove_from_sm_config
[20110901T13:28:11.439Z| info|xen-blade13|15650 unix-RPC|session.logout D:b067ebbc455b|xapi] Session.destroy trackid=79f7a8681170559e393fc74e0854b4d5
[20110901T13:28:11.445Z|debug|xen-blade13|15652 unix-RPC||dummytaskhelper] task dispatch:VDI.get_by_uuid D:500d9e53a71c created by task D:a3bb09716ac9
[20110901T13:28:11.454Z|debug|xen-blade13|15653 unix-RPC||dummytaskhelper] task dispatch:VDI.get_SR D:6e44c794ef60 created by task D:a3bb09716ac9
[20110901T13:28:11.462Z|debug|xen-blade13|15654 unix-RPC||dummytaskhelper] task dispatch:SR.get_uuid D:6e34d1b49bcb created by task D:a3bb09716ac9
[20110901T13:28:11.470Z|debug|xen-blade13|15655 unix-RPC||dummytaskhelper] task dispatch:SR.get_by_uuid D:8f76ef342375 created by task D:a3bb09716ac9
[20110901T13:28:11.478Z|debug|xen-blade13|15656 unix-RPC||dummytaskhelper] task dispatch:SR.get_type D:db1845a7f139 created by task D:a3bb09716ac9
[20110901T13:28:11.488Z|debug|xen-blade13|15657 unix-RPC||dummytaskhelper] task dispatch:SM.get_all_records_where D:a22538b9290e created by task D:a3bb09716ac9
[20110901T13:28:11.497Z|debug|xen-blade13|15659 unix-RPC||dummytaskhelper] task dispatch:SM.get_driver_filename D:e62c5c64f38c created by task D:a3bb09716ac9
[20110901T13:28:11.507Z|debug|xen-blade13|15660 unix-RPC||dummytaskhelper] task dispatch:VM.get_all_records_where D:0987ca3b4145 created by task D:a3bb09716ac9
[20110901T13:28:11.519Z|debug|xen-blade13|15661 unix-RPC||dummytaskhelper] task dispatch:PBD.get_all_records_where D:c63de088c845 created by task D:a3bb09716ac9
[20110901T13:28:11.527Z|debug|xen-blade13|15663 unix-RPC||dummytaskhelper] task dispatch:PBD.get_device_config D:e06d2fa696bc created by task D:a3bb09716ac9
[20110901T13:28:11.566Z|debug|xen-blade13|15665 unix-RPC||dummytaskhelper] task dispatch:VDI.get_by_uuid D:207e1115f672 created by task D:a3bb09716ac9
[20110901T13:28:11.574Z|debug|xen-blade13|15666 unix-RPC||dummytaskhelper] task dispatch:host.get_by_uuid D:62558fe7038e created by task D:a3bb09716ac9
[20110901T13:28:11.583Z|debug|xen-blade13|15667 unix-RPC||dummytaskhelper] task dispatch:VDI.get_sm_config D:150b09eaee04 created by task D:a3bb09716ac9
[20110901T13:28:11.593Z|debug|xen-blade13|15668 unix-RPC||dummytaskhelper] task dispatch:VDI.remove_from_sm_config D:65d47c862f84 created by task D:a3bb09716ac9
[20110901T13:28:11.596Z| info|xen-blade13|15668 unix-RPC|dispatch:VDI.remove_from_sm_config D:65d47c862f84|api_effect] VDI.remove_from_sm_config
[20110901T13:28:11.620Z| info|xen-blade13|15516|sm_exec D:c14a83cdfa0a|xapi] Session.destroy trackid=8877c2426d9a941fe6e5c0457f20d557
[20110901T13:28:11.623Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b superstate:attached  RW
[20110901T13:28:11.626Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|dummytaskhelper] task VDI.detach D:692c37a50ef0 created by task R:3fae217e8466
[20110901T13:28:11.626Z|debug|xen-blade13|15516|VDI.detach D:692c37a50ef0|sm] SM ocfs vdi_detach sr=OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi=OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b
[20110901T13:28:11.631Z| info|xen-blade13|15516|sm_exec D:4515f56bf779|xapi] Session.create trackid=15fdaf4154c108620f6cfacd6bbabf7a pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20110901T13:28:11.633Z|debug|xen-blade13|15516|sm_exec D:4515f56bf779|xapi] Attempting to open /var/xapi/xapi
[20110901T13:28:11.637Z|debug|xen-blade13|15670 unix-RPC||dummytaskhelper] task dispatch:session.get_uuid D:b49c5cdb84ed created by task D:4515f56bf779
[20110901T13:28:11.750Z|debug|xen-blade13|15673 unix-RPC||dummytaskhelper] task dispatch:host.get_other_config D:af3aefeb08bc created by task D:692c37a50ef0
[20110901T13:28:11.796Z| info|xen-blade13|15516|sm_exec D:4515f56bf779|xapi] Session.destroy trackid=15fdaf4154c108620f6cfacd6bbabf7a
[20110901T13:28:11.799Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:0ce5e273-94d0-f71a-f238-5cf6b0a0733b superstate:detached
[20110901T13:28:11.802Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:e46a18c2-df9a-69cd-9db9-5d7e929829f5 superstate:activated RW
[20110901T13:28:11.806Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|storage_impl] task:OpaqueRef:3fae217e-8466-c5c9-1e07-0a6f6e4bb209 dp:vbd/14/hda sr:OpaqueRef:661661b4-611d-3757-3e20-a6487e7ef75d vdi:OpaqueRef:d0c6ea5b-7a51-a85e-ceb9-8beb852127e7 superstate:activated RW
[20110901T13:28:11.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.835Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|locking_helpers] pop(per-VM queue) = DevEject(5696) domid 14
[20110901T13:28:11.837Z|debug|xen-blade13|15516|VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f: processing DevEject(5696) domid 14 D:e41272a2d20a|event] VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f (Win2008-64bit-R2 (1)) resident_on other host OpaqueRef:NULL (xen-blade13): taking no action
[20110901T13:28:11.838Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|locking_helpers] pop(per-VM queue) = HotplugChanged(vif, 0) domid: 14
[20110901T13:28:11.840Z|debug|xen-blade13|15516|VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f: processing HotplugChanged(vif, 0) domid: 14 D:c8cbc0d6c6f7|event] VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f (Win2008-64bit-R2 (1)) resident_on other host OpaqueRef:NULL (xen-blade13): taking no action
[20110901T13:28:11.840Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|locking_helpers] pop(per-VM queue) = VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain
[20110901T13:28:11.842Z|debug|xen-blade13|15516|VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f: processing VM domid:14 uuid:7ef51a1e-2a0a-5ef4-50f6-618cbb251543 @releaseDomain D:fa3ddf40f736|event] VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f (Win2008-64bit-R2 (1)) resident_on other host OpaqueRef:NULL (xen-blade13): taking no action
[20110901T13:28:11.842Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.843Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|locking_helpers] Released lock on VM OpaqueRef:8f56e611-ea23-b4f3-4e8e-ebc4f513312f with token 63
[20110901T13:28:11.843Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.844Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.844Z|debug|xen-blade13|614||thread_queue] vm_lifecycle_op: completed processing 1 items: queue = [  ](0)
[20110901T13:28:11.851Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.855Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.878Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.884Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|backtrace] Raised at 
[20110901T13:28:11.885Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|backtrace] Raised at 
[20110901T13:28:11.885Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|dispatcher] Server_helpers.exec exception_handler: Got exception INTERNAL_ERROR: [ device model failed to initialise: qemu-dm exitted unexpectedly ]
[20110901T13:28:11.885Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|dispatcher] Raised at 
[20110901T13:28:11.886Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|backtrace] Raised at 
[20110901T13:28:11.894Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.895Z|debug|xen-blade13|15516|Async.VM.start R:3fae217e8466|xapi] Raised at 
[20110901T13:28:11.895Z|debug|xen-blade13|15516||xapi] Raised at 
[20110901T13:28:11.895Z|debug|xen-blade13|15516||xapi] Raised at 
[20110901T13:28:12.105Z|debug|xen-blade13|15681 inet-RPC|Connection to VM console R:20ba1f554192|console] VM OpaqueRef:14265b6a-41a3-c860-dde6-f3fe107fabba console port: None
[20110901T13:28:17.127Z|debug|xen-blade13|15697 inet-RPC|Connection to VM console R:e7656898af86|console] VM OpaqueRef:14265b6a-41a3-c860-dde6-f3fe107fabba console port: None