BEFORE CREATING VM
[20120501T16:25:15.876Z|debug|kronos|19|Starting periodic scheduler D:cfd5315a3287|backgroundscheduler] Sleeping until next event (110.040682 seconds)
[20120501T16:25:15.876Z|debug|kronos|19|Starting periodic scheduler D:cfd5315a3287|backgroundscheduler] Sleeping until next event (110.040532 seconds)
[20120501T16:25:36.052Z|debug|kronos|53 sr_scan|SR scanner D:14d611fa57a4|xapi] Automatically scanning SRs = [ OpaqueRef:9c496088-619a-903a-48bd-6b2e229eeab0 ]
[20120501T16:25:36.053Z|debug|kronos|60||dummytaskhelper] task scan one D:d835638e2ea2 created by task D:14d611fa57a4
[20120501T16:25:36.053Z|debug|kronos|60|scan one D:d835638e2ea2|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:36.053Z|debug|kronos|61 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:a292ec2b937b created by task D:d835638e2ea2
[20120501T16:25:36.055Z| info|kronos|61 UNIX /var/lib/xcp/xapi|session.slave_login D:456aeb97981c|xapi] Session.create trackid=2ee3b899cefa0c5fc2bb1a31913fec25 pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:36.055Z|debug|kronos|61 UNIX /var/lib/xcp/xapi|session.slave_login D:456aeb97981c|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:36.056Z|debug|kronos|62 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:572e0dc76a8c created by task D:456aeb97981c
[20120501T16:25:36.058Z|debug|kronos|60|scan one D:d835638e2ea2|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:36.058Z|debug|kronos|63 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.scan D:c9caea76e455 created by task D:d835638e2ea2
[20120501T16:25:36.061Z| info|kronos|63 UNIX /var/lib/xcp/xapi|dispatch:SR.scan D:c9caea76e455|taskhelper] task SR.scan R:de787b5e7cc4 (uuid:b6fedfbb-1b3c-9c83-d478-1c62e074b220) created (trackid=2ee3b899cefa0c5fc2bb1a31913fec25) by task D:d835638e2ea2
[20120501T16:25:36.061Z|debug|kronos|63 UNIX /var/lib/xcp/xapi|SR.scan R:de787b5e7cc4|xapi] SR.scan: SR = 'ffecdab0-3eb3-0e3d-da2d-4e919ab74420 (NFS ISO library)'
[20120501T16:25:36.061Z|debug|kronos|63 UNIX /var/lib/xcp/xapi|SR.scan R:de787b5e7cc4|xapi] Marking SR for SR.scan (task=OpaqueRef:de787b5e-7cc4-4785-ba82-ed2206dbcaf3)
[20120501T16:25:36.062Z| info|kronos|63 UNIX /var/lib/xcp/xapi|SR.scan R:de787b5e7cc4|storage_impl] SR.scan task:OpaqueRef:de787b5e-7cc4-4785-ba82-ed2206dbcaf3 sr:ffecdab0-3eb3-0e3d-da2d-4e919ab74420
[20120501T16:25:36.063Z|debug|kronos|63 UNIX /var/lib/xcp/xapi|SR.scan R:de787b5e7cc4|dummytaskhelper] task SR.scan D:53bad769b7a8 created by task R:de787b5e7cc4
[20120501T16:25:36.064Z|debug|kronos|63 UNIX /var/lib/xcp/xapi|SR.scan D:53bad769b7a8|sm] SM iso sr_scan sr=OpaqueRef:9c496088-619a-903a-48bd-6b2e229eeab0
[20120501T16:25:36.065Z| info|kronos|63 UNIX /var/lib/xcp/xapi|sm_exec D:0fae6423b51b|xapi] Session.create trackid=23e529dc68230460690d9aefcedeb1de pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:36.066Z|debug|kronos|63 UNIX /var/lib/xcp/xapi|sm_exec D:0fae6423b51b|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:36.066Z|debug|kronos|64 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:c7a570a7662f created by task D:0fae6423b51b
[20120501T16:25:36.145Z|debug|kronos|65 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:6e39c515be37 created by task D:53bad769b7a8
[20120501T16:25:36.147Z|debug|kronos|65 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.165Z|debug|kronos|66 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:8b4cf94df1b1 created by task D:53bad769b7a8
[20120501T16:25:36.167Z|debug|kronos|66 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.168Z|debug|kronos|67 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_all_records_where D:32b575e3722c created by task D:53bad769b7a8
[20120501T16:25:36.176Z|debug|kronos|67 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.179Z|debug|kronos|68 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:d1c1f3f7737c created by task D:53bad769b7a8
[20120501T16:25:36.180Z|debug|kronos|68 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.181Z|debug|kronos|69 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.set_virtual_allocation D:c36cbd56f165 created by task D:53bad769b7a8
[20120501T16:25:36.183Z|debug|kronos|69 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.186Z|debug|kronos|70 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.set_physical_size D:a723c3aee312 created by task D:53bad769b7a8
[20120501T16:25:36.188Z|debug|kronos|70 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.189Z|debug|kronos|71 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.set_physical_utilisation D:5030e3669d67 created by task D:53bad769b7a8
[20120501T16:25:36.192Z|debug|kronos|71 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.192Z|debug|kronos|72 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:b8c3c3754a13 created by task D:53bad769b7a8
[20120501T16:25:36.194Z|debug|kronos|72 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.195Z|debug|kronos|73 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_all_records_where D:045348484581 created by task D:53bad769b7a8
[20120501T16:25:36.203Z|debug|kronos|73 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:36.216Z| info|kronos|63 UNIX /var/lib/xcp/xapi|sm_exec D:0fae6423b51b|xapi] Session.destroy trackid=23e529dc68230460690d9aefcedeb1de
[20120501T16:25:36.218Z|debug|kronos|63 UNIX /var/lib/xcp/xapi|SR.scan R:de787b5e7cc4|xapi] Unmarking SR after SR.scan (task=OpaqueRef:de787b5e-7cc4-4785-ba82-ed2206dbcaf3)
[20120501T16:25:36.223Z|debug|kronos|60|scan one D:d835638e2ea2|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:36.224Z|debug|kronos|74 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:30785eacf83b created by task D:d835638e2ea2
[20120501T16:25:36.225Z| info|kronos|74 UNIX /var/lib/xcp/xapi|session.logout D:a94aba053053|xapi] Session.destroy trackid=2ee3b899cefa0c5fc2bb1a31913fec25
[20120501T16:25:36.226Z|debug|kronos|60|scan one D:d835638e2ea2|xapi] Scan of SR ffecdab0-3eb3-0e3d-da2d-4e919ab74420 complete.
[20120501T16:25:42.049Z|debug|kronos|75 UNIX /var/lib/xcp/xapi||cli] xe template-list name-label=Debian Squeeze 6.0 (32-bit) minimal=true username=root password=null
[20120501T16:25:42.050Z| info|kronos|75 UNIX /var/lib/xcp/xapi|session.login_with_password D:31fe48f0674b|xapi] Session.create trackid=e4f726602bbd9955abe24a18f1092cb1 pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.051Z|debug|kronos|75 UNIX /var/lib/xcp/xapi|session.login_with_password D:31fe48f0674b|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.052Z|debug|kronos|76 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:d94d9b8186fd created by task D:31fe48f0674b
[20120501T16:25:42.106Z| info|kronos|75 UNIX /var/lib/xcp/xapi|session.logout D:adba1903c326|xapi] Session.destroy trackid=e4f726602bbd9955abe24a18f1092cb1
[20120501T16:25:42.107Z| info|kronos|77 UNIX /var/lib/xcp/xapi||cli] xe vm-install template=c735d491-db82-6ed5-681f-b23163988330 new-name-label=debian username=root password=null
[20120501T16:25:42.109Z| info|kronos|77 UNIX /var/lib/xcp/xapi|session.login_with_password D:4fb32a096d85|xapi] Session.create trackid=e8b6410dcffcb434b5a9d237aaf699dd pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.110Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|session.login_with_password D:4fb32a096d85|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.110Z|debug|kronos|78 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:acd2a9b603aa created by task D:4fb32a096d85
[20120501T16:25:42.170Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.clone R:95a0d5aca642|audit] VM.clone: VM = 'c735d491-db82-6ed5-681f-b23163988330 (Debian Squeeze 6.0 (32-bit))'; new_name = 'debian'
[20120501T16:25:42.172Z| warn|kronos|77 UNIX /var/lib/xcp/xapi|VM.clone R:95a0d5aca642|xapi] VM Debian Squeeze 6.0 (32-bit) could run on any of these hosts: [ kronos ]
[20120501T16:25:42.172Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.clone R:95a0d5aca642|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.173Z|debug|kronos|79 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:bb9c90fc7352 created by task R:95a0d5aca642
[20120501T16:25:42.174Z| info|kronos|79 UNIX /var/lib/xcp/xapi|session.slave_login D:7d6966ab1853|xapi] Session.create trackid=714401608914a54f59a3b76753b7bdff pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.175Z|debug|kronos|79 UNIX /var/lib/xcp/xapi|session.slave_login D:7d6966ab1853|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.176Z|debug|kronos|80 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:76a87e8be470 created by task D:7d6966ab1853
[20120501T16:25:42.182Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.clone R:95a0d5aca642|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.183Z|debug|kronos|81 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:c2f7f25a842e created by task R:95a0d5aca642
[20120501T16:25:42.184Z| info|kronos|81 UNIX /var/lib/xcp/xapi|session.slave_login D:188df7a9ed8c|xapi] Session.create trackid=117eacbfc598e610df71696b4fc8797f pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.185Z|debug|kronos|81 UNIX /var/lib/xcp/xapi|session.slave_login D:188df7a9ed8c|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.185Z|debug|kronos|82 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:047d8f2584eb created by task D:188df7a9ed8c
[20120501T16:25:42.187Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.clone R:95a0d5aca642|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.188Z|debug|kronos|83 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:e41530e6874e created by task R:95a0d5aca642
[20120501T16:25:42.189Z| info|kronos|83 UNIX /var/lib/xcp/xapi|session.logout D:832c163c54b7|xapi] Session.destroy trackid=117eacbfc598e610df71696b4fc8797f
[20120501T16:25:42.194Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.clone R:95a0d5aca642|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.195Z|debug|kronos|84 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:831491f0057b created by task R:95a0d5aca642
[20120501T16:25:42.196Z| info|kronos|84 UNIX /var/lib/xcp/xapi|session.logout D:fa4d9fdadb6b|xapi] Session.destroy trackid=714401608914a54f59a3b76753b7bdff
[20120501T16:25:42.203Z| info|kronos|77 UNIX /var/lib/xcp/xapi|dispatch:VM.set_name_description D:f3eafd588545|api_effect] VM.set_name_description
[20120501T16:25:42.206Z| info|kronos|77 UNIX /var/lib/xcp/xapi|dispatch:VM.set_suspend_SR D:3c95daa30ed6|api_effect] VM.set_suspend_SR
[20120501T16:25:42.210Z| info|kronos|77 UNIX /var/lib/xcp/xapi|dispatch:VM.remove_from_other_config D:ace8e84b706f|api_effect] VM.remove_from_other_config
[20120501T16:25:42.213Z| info|kronos|77 UNIX /var/lib/xcp/xapi|dispatch:VM.add_to_other_config D:0be5a215c67c|api_effect] VM.add_to_other_config
[20120501T16:25:42.216Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|audit] VM.provision: VM = '3d08f74a-1329-7fed-6145-5794647d68f9 (debian)'
[20120501T16:25:42.219Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.219Z|debug|kronos|85 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:69806474dea6 created by task R:6c6424b917c8
[20120501T16:25:42.220Z| info|kronos|85 UNIX /var/lib/xcp/xapi|session.slave_login D:557c2eece31f|xapi] Session.create trackid=fcf369b9a5194d80a446602d8afac0ef pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.221Z|debug|kronos|85 UNIX /var/lib/xcp/xapi|session.slave_login D:557c2eece31f|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.222Z|debug|kronos|86 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:19ca53c818a4 created by task D:557c2eece31f
[20120501T16:25:42.224Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.224Z|debug|kronos|87 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_other_config D:30d913ad238a created by task R:6c6424b917c8
[20120501T16:25:42.226Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.227Z|debug|kronos|88 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:c34e7dffe550 created by task R:6c6424b917c8
[20120501T16:25:42.228Z| info|kronos|88 UNIX /var/lib/xcp/xapi|session.logout D:ebfd74565a3f|xapi] Session.destroy trackid=fcf369b9a5194d80a446602d8afac0ef
[20120501T16:25:42.229Z| warn|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] VM debian could run on any of these hosts: [ kronos ]
[20120501T16:25:42.232Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|thread_queue] push(long_running_op, VM.provision VM.provision R:6c6424b917c8): queue = [ VM.provision VM.provision R:6c6424b917c8 ](1)
[20120501T16:25:42.232Z|debug|kronos|89||thread_queue] pop(long_running_op) = VM.provision VM.provision R:6c6424b917c8
[20120501T16:25:42.232Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|locking_helpers] Acquired lock on VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7 with token 2
[20120501T16:25:42.232Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] start: checking to see whether VM needs 'installing'
[20120501T16:25:42.232Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.233Z|debug|kronos|90 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:67f593362af5 created by task R:6c6424b917c8
[20120501T16:25:42.234Z| info|kronos|90 UNIX /var/lib/xcp/xapi|session.slave_login D:03fc6794cbfb|xapi] Session.create trackid=f766424d9ffde54a5edff6596b96a43d pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.252Z|debug|kronos|90 UNIX /var/lib/xcp/xapi|session.slave_login D:03fc6794cbfb|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.253Z|debug|kronos|91 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:b926c775eeb3 created by task D:03fc6794cbfb
[20120501T16:25:42.255Z| info|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] VM.set_is_a_template('false')
[20120501T16:25:42.256Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.257Z|debug|kronos|92 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_other_config D:6f4eefebbace created by task R:6c6424b917c8
[20120501T16:25:42.259Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] install: phase 1/3: creating VBDs and VDIs
[20120501T16:25:42.259Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Performing pre_install actions (ie creating disks)
[20120501T16:25:42.259Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.261Z|debug|kronos|93 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_uuid D:781cb85de24b created by task R:6c6424b917c8
[20120501T16:25:42.262Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.263Z|debug|kronos|94 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_other_config D:7d2a95db28e0 created by task R:6c6424b917c8
[20120501T16:25:42.265Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.265Z|debug|kronos|95 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:51be274e81d5 created by task R:6c6424b917c8
[20120501T16:25:42.267Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Provisioning VDI for new VM
[20120501T16:25:42.267Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.268Z|debug|kronos|96 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.create D:34fb21fb7eb4 created by task R:6c6424b917c8
[20120501T16:25:42.270Z| info|kronos|96 UNIX /var/lib/xcp/xapi|dispatch:VDI.create D:34fb21fb7eb4|taskhelper] task VDI.create R:64601727b1f2 (uuid:a50b520e-3575-28bb-ddad-6ae02001c5b4) created (trackid=f766424d9ffde54a5edff6596b96a43d) by task R:6c6424b917c8
[20120501T16:25:42.270Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create R:64601727b1f2|audit] VDI.create: SR = '96e5db02-c778-5401-b786-5dc9180005e7 (kronossr0)'; name label = ''
[20120501T16:25:42.270Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create R:64601727b1f2|xapi] Marking SR for VDI.create (task=OpaqueRef:64601727-b1f2-3a32-34d9-facc83c66e4d)
[20120501T16:25:42.272Z| info|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create R:64601727b1f2|storage_impl] VDI.create task:OpaqueRef:64601727-b1f2-3a32-34d9-facc83c66e4d sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi_info:{"vdi": "", "name_label": "", "name_description": "Created by template provisioner", "ty": "system", "metadata_of_pool": "", "is_a_snapshot": false, "snapshot_time": "19700101T00:00:00Z", "snapshot_of": "", "read_only": false, "virtual_size": 8589934592, "physical_utilisation": 0} params:vmhint:3d08f74a-1329-7fed-6145-5794647d68f9
[20120501T16:25:42.272Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create R:64601727b1f2|dummytaskhelper] task VDI.create D:0edcfe1f58fa created by task R:64601727b1f2
[20120501T16:25:42.272Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create D:0edcfe1f58fa|sm] SM ext vdi_create sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a sm_config=[vmhint=3d08f74a-1329-7fed-6145-5794647d68f9] type=[system] size=8589934592
[20120501T16:25:42.274Z| info|kronos|96 UNIX /var/lib/xcp/xapi|sm_exec D:7b603c2c41b1|xapi] Session.create trackid=a7bd41987487d8c66350d3c87f4046fa pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.274Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|sm_exec D:7b603c2c41b1|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.275Z|debug|kronos|97 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:6bb16533c3f9 created by task D:7b603c2c41b1
[20120501T16:25:42.361Z|debug|kronos|98 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:a0afce27d4f3 created by task D:0edcfe1f58fa
[20120501T16:25:42.367Z|debug|kronos|98 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.418Z|debug|kronos|99 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.db_introduce D:2209494420a2 created by task D:0edcfe1f58fa
[20120501T16:25:42.420Z| info|kronos|99 UNIX /var/lib/xcp/xapi|dispatch:VDI.db_introduce D:2209494420a2|taskhelper] task VDI.db_introduce R:f30f5b4de534 (uuid:bf748b1e-82a2-c8bf-2f91-5f1572568970) created (trackid=a7bd41987487d8c66350d3c87f4046fa) by task D:0edcfe1f58fa
[20120501T16:25:42.420Z|debug|kronos|99 UNIX /var/lib/xcp/xapi|VDI.db_introduce R:f30f5b4de534|xapi] {pool,db}_introduce uuid=be3aac06-fab9-42d2-a7d7-f72a3603ca23 name_label=
[20120501T16:25:42.421Z|debug|kronos|99 UNIX /var/lib/xcp/xapi|VDI.db_introduce R:f30f5b4de534|xapi] VDI.introduce read_only = false
[20120501T16:25:42.426Z|debug|kronos|99 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.426Z|debug|kronos|100 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_virtual_allocation D:e7b6a0b52c4d created by task D:0edcfe1f58fa
[20120501T16:25:42.428Z|debug|kronos|100 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.429Z|debug|kronos|101 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:45f23d388378 created by task D:0edcfe1f58fa
[20120501T16:25:42.431Z|debug|kronos|101 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.432Z|debug|kronos|102 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.set_virtual_allocation D:9c039ec9d248 created by task D:0edcfe1f58fa
[20120501T16:25:42.434Z|debug|kronos|102 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.435Z|debug|kronos|103 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.set_physical_size D:42bc7e8515e2 created by task D:0edcfe1f58fa
[20120501T16:25:42.437Z|debug|kronos|103 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.438Z|debug|kronos|104 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.set_physical_utilisation D:27530d5906c2 created by task D:0edcfe1f58fa
[20120501T16:25:42.443Z|debug|kronos|104 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.455Z| info|kronos|96 UNIX /var/lib/xcp/xapi|sm_exec D:7b603c2c41b1|xapi] Session.destroy trackid=a7bd41987487d8c66350d3c87f4046fa
[20120501T16:25:42.456Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create R:64601727b1f2|xapi] OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782 snapshot_of <- OpaqueRef:NULL
[20120501T16:25:42.456Z|debug|kronos|96 UNIX /var/lib/xcp/xapi|VDI.create R:64601727b1f2|xapi] Unmarking SR after VDI.create (task=OpaqueRef:64601727-b1f2-3a32-34d9-facc83c66e4d)
[20120501T16:25:42.461Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.462Z|debug|kronos|105 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.create D:16b599e8de49 created by task R:6c6424b917c8
[20120501T16:25:42.464Z| info|kronos|105 UNIX /var/lib/xcp/xapi|dispatch:VBD.create D:16b599e8de49|taskhelper] task VBD.create R:3bbd9c9701eb (uuid:ce3c9dea-77f7-72c0-8330-de31e750c824) created (trackid=f766424d9ffde54a5edff6596b96a43d) by task R:6c6424b917c8
[20120501T16:25:42.464Z|debug|kronos|105 UNIX /var/lib/xcp/xapi|VBD.create R:3bbd9c9701eb|audit] VBD.create: VM = '3d08f74a-1329-7fed-6145-5794647d68f9 (debian)'; VDI = 'be3aac06-fab9-42d2-a7d7-f72a3603ca23'
[20120501T16:25:42.465Z|debug|kronos|105 UNIX /var/lib/xcp/xapi|VBD.create R:3bbd9c9701eb|xapi] VBD.create (device = 0; uuid = e382023a-d185-13b2-c78b-6ba0c7205af2; ref = OpaqueRef:dbec9bfc-c612-7eb9-db53-e249e3c9546f)
[20120501T16:25:42.472Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.472Z|debug|kronos|106 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.get_userdevice D:54e436f7de17 created by task R:6c6424b917c8
[20120501T16:25:42.474Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.475Z|debug|kronos|107 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.set_name_label D:aa864055a78d created by task R:6c6424b917c8
[20120501T16:25:42.477Z| info|kronos|107 UNIX /var/lib/xcp/xapi|dispatch:VDI.set_name_label D:aa864055a78d|taskhelper] task VDI.set_name_label R:9fa060353625 (uuid:c48368be-8e19-3fd7-6ca1-c63ca98c8e42) created (trackid=f766424d9ffde54a5edff6596b96a43d) by task R:6c6424b917c8
[20120501T16:25:42.477Z|debug|kronos|107 UNIX /var/lib/xcp/xapi|VDI.set_name_label R:9fa060353625|audit] VDI.set_name_label: VDI = 'be3aac06-fab9-42d2-a7d7-f72a3603ca23' name-label = '0'
[20120501T16:25:42.478Z|debug|kronos|107 UNIX /var/lib/xcp/xapi|VDI.set_name_label R:9fa060353625|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.479Z|debug|kronos|108 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.update D:69fb4fd69ea7 created by task R:9fa060353625
[20120501T16:25:42.481Z| info|kronos|108 UNIX /var/lib/xcp/xapi|dispatch:VDI.update D:69fb4fd69ea7|taskhelper] task VDI.update R:977ead92d90e (uuid:6444f236-7d88-e8b3-a290-e2ade6ed4e5e) created (trackid=f766424d9ffde54a5edff6596b96a43d) by task R:9fa060353625
[20120501T16:25:42.482Z|debug|kronos|108 UNIX /var/lib/xcp/xapi|VDI.update R:977ead92d90e|xapi] update ref=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782 location=be3aac06-fab9-42d2-a7d7-f72a3603ca23
[20120501T16:25:42.482Z|debug|kronos|108 UNIX /var/lib/xcp/xapi|VDI.update R:977ead92d90e|sm] SM ext vdi_update sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:25:42.484Z| info|kronos|108 UNIX /var/lib/xcp/xapi|sm_exec D:8b92a718df80|xapi] Session.create trackid=01092450e45fadd65ff33bb30340589a pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.485Z|debug|kronos|108 UNIX /var/lib/xcp/xapi|sm_exec D:8b92a718df80|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.485Z|debug|kronos|109 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:fefe8158c36b created by task D:8b92a718df80
[20120501T16:25:42.562Z|debug|kronos|110 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:aef8d512e35b created by task R:977ead92d90e
[20120501T16:25:42.567Z|debug|kronos|110 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.582Z|debug|kronos|111 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:16b177ff0871 created by task R:977ead92d90e
[20120501T16:25:42.585Z|debug|kronos|111 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.585Z|debug|kronos|112 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:da1a7a838e28 created by task R:977ead92d90e
[20120501T16:25:42.587Z|debug|kronos|112 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.588Z|debug|kronos|113 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.set_virtual_size D:bd894eb409ed created by task R:977ead92d90e
[20120501T16:25:42.590Z|debug|kronos|113 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.591Z|debug|kronos|114 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.set_physical_utilisation D:8d785e0aa1e5 created by task R:977ead92d90e
[20120501T16:25:42.593Z|debug|kronos|114 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.594Z|debug|kronos|115 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.set_read_only D:71ddbea684b5 created by task R:977ead92d90e
[20120501T16:25:42.596Z|debug|kronos|115 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.597Z|debug|kronos|116 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:8822cb58d890 created by task R:977ead92d90e
[20120501T16:25:42.603Z|debug|kronos|116 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.613Z| info|kronos|108 UNIX /var/lib/xcp/xapi|sm_exec D:8b92a718df80|xapi] Session.destroy trackid=01092450e45fadd65ff33bb30340589a
[20120501T16:25:42.621Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] install: phase 2/3: running optional script (in domain 0)
[20120501T16:25:42.622Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] install: phase 3/3: removing install information from VM
[20120501T16:25:42.622Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Performing post_install actions (ie removing template information from VM)
[20120501T16:25:42.622Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.623Z|debug|kronos|117 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.remove_from_other_config D:974460439f04 created by task R:6c6424b917c8
[20120501T16:25:42.624Z| info|kronos|117 UNIX /var/lib/xcp/xapi|dispatch:VM.remove_from_other_config D:974460439f04|api_effect] VM.remove_from_other_config
[20120501T16:25:42.625Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.626Z|debug|kronos|118 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.remove_from_other_config D:30dbb89e091e created by task R:6c6424b917c8
[20120501T16:25:42.627Z| info|kronos|118 UNIX /var/lib/xcp/xapi|dispatch:VM.remove_from_other_config D:30dbb89e091e|api_effect] VM.remove_from_other_config
[20120501T16:25:42.629Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] finished install
[20120501T16:25:42.629Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.629Z|debug|kronos|119 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:1f687ee752b2 created by task R:6c6424b917c8
[20120501T16:25:42.631Z| info|kronos|119 UNIX /var/lib/xcp/xapi|session.logout D:86b0d9af6081|xapi] Session.destroy trackid=f766424d9ffde54a5edff6596b96a43d
[20120501T16:25:42.632Z|debug|kronos|77 UNIX /var/lib/xcp/xapi|VM.provision R:6c6424b917c8|locking_helpers] Released lock on VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7 with token 2
[20120501T16:25:42.633Z|debug|kronos|89||thread_queue] long_running_op: completed processing 1 items: queue = [  ](0)
[20120501T16:25:42.643Z| info|kronos|77 UNIX /var/lib/xcp/xapi|session.logout D:c73fe2bfb8c6|xapi] Session.destroy trackid=e8b6410dcffcb434b5a9d237aaf699dd
[20120501T16:25:42.643Z|debug|kronos|120 UNIX /var/lib/xcp/xapi||cli] xe network-list bridge=xenbr0 minimal=true username=root password=null
[20120501T16:25:42.645Z| info|kronos|120 UNIX /var/lib/xcp/xapi|session.login_with_password D:bfaf46b716af|xapi] Session.create trackid=5470fd1bf9bb182c0aa12517ea7fd25b pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.646Z|debug|kronos|120 UNIX /var/lib/xcp/xapi|session.login_with_password D:bfaf46b716af|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.646Z|debug|kronos|121 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:9544aa36778a created by task D:bfaf46b716af
[20120501T16:25:42.652Z| info|kronos|120 UNIX /var/lib/xcp/xapi|session.logout D:3a778f56f425|xapi] Session.destroy trackid=5470fd1bf9bb182c0aa12517ea7fd25b
[20120501T16:25:42.654Z| info|kronos|122 UNIX /var/lib/xcp/xapi||cli] xe vif-create vm-uuid=3d08f74a-1329-7fed-6145-5794647d68f9 network-uuid=6f970ca7-83bb-b7e7-7b4d-e82c85290022 device=0 username=root password=null
[20120501T16:25:42.656Z| info|kronos|122 UNIX /var/lib/xcp/xapi|session.login_with_password D:3388496589f4|xapi] Session.create trackid=62bd424e828e07ca9570b30532aca3f4 pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.657Z|debug|kronos|122 UNIX /var/lib/xcp/xapi|session.login_with_password D:3388496589f4|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.657Z|debug|kronos|123 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:e269169ea097 created by task D:3388496589f4
[20120501T16:25:42.667Z|debug|kronos|122 UNIX /var/lib/xcp/xapi|VIF.create R:47d1c9d6272a|audit] VIF.create: VM = '3d08f74a-1329-7fed-6145-5794647d68f9 (debian)'; network = '6f970ca7-83bb-b7e7-7b4d-e82c85290022'
[20120501T16:25:42.667Z|debug|kronos|122 UNIX /var/lib/xcp/xapi|VIF.create R:47d1c9d6272a|xapi] VIF.create running
[20120501T16:25:42.668Z|debug|kronos|122 UNIX /var/lib/xcp/xapi|VIF.create R:47d1c9d6272a|xapi] Found mac_seed on VM: supplied MAC parameter = ''
[20120501T16:25:42.671Z|debug|kronos|122 UNIX /var/lib/xcp/xapi|VIF.create R:47d1c9d6272a|xapi] VIF ref='OpaqueRef:90ed0e80-14ba-427e-546a-4e5520850e76' created (VM = 'OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7'; MAC address = '9a:eb:37:0a:f1:a8')
[20120501T16:25:42.679Z| info|kronos|122 UNIX /var/lib/xcp/xapi|session.logout D:d84530df8216|xapi] Session.destroy trackid=62bd424e828e07ca9570b30532aca3f4
[20120501T16:25:42.680Z| info|kronos|124 UNIX /var/lib/xcp/xapi||cli] xe vm-param-set uuid=3d08f74a-1329-7fed-6145-5794647d68f9 other-config:install-repository=http://ftp.uk.debian.org/debian username=root password=null
[20120501T16:25:42.682Z| info|kronos|124 UNIX /var/lib/xcp/xapi|session.login_with_password D:af1b299cf4f7|xapi] Session.create trackid=26035c6c60bae68abc6a99010ef1932f pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.682Z|debug|kronos|124 UNIX /var/lib/xcp/xapi|session.login_with_password D:af1b299cf4f7|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.683Z|debug|kronos|125 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:fdc7486ebbae created by task D:af1b299cf4f7
[20120501T16:25:42.690Z| info|kronos|124 UNIX /var/lib/xcp/xapi|dispatch:VM.add_to_other_config D:fe9641b449d6|api_effect] VM.add_to_other_config
[20120501T16:25:42.694Z| info|kronos|124 UNIX /var/lib/xcp/xapi|session.logout D:99c189b993a7|xapi] Session.destroy trackid=26035c6c60bae68abc6a99010ef1932f
[20120501T16:25:42.695Z| info|kronos|126 UNIX /var/lib/xcp/xapi||cli] xe vm-memory-limits-set static-min=256MiB static-max=256MiB dynamic-min=256MiB dynamic-max=256MiB vm=3d08f74a-1329-7fed-6145-5794647d68f9 username=root password=null
[20120501T16:25:42.696Z| info|kronos|126 UNIX /var/lib/xcp/xapi|session.login_with_password D:33814db22a02|xapi] Session.create trackid=3a1af60a38b4c511634ba0b6082cc6c5 pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.697Z|debug|kronos|126 UNIX /var/lib/xcp/xapi|session.login_with_password D:33814db22a02|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.698Z|debug|kronos|127 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:e005138f203c created by task D:33814db22a02
[20120501T16:25:42.704Z|debug|kronos|126 UNIX /var/lib/xcp/xapi|VM.set_memory_limits R:b4668833f1b1|audit] VM.set_memory_limits: self = 3d08f74a-1329-7fed-6145-5794647d68f9 (debian); static_min = 268435456; static_max = 268435456; dynamic_min = 268435456; dynamic_max = 268435456
[20120501T16:25:42.722Z| info|kronos|126 UNIX /var/lib/xcp/xapi|session.logout D:7ddc0a804cd5|xapi] Session.destroy trackid=3a1af60a38b4c511634ba0b6082cc6c5
[20120501T16:25:42.723Z| info|kronos|128 UNIX /var/lib/xcp/xapi||cli] xe vm-start uuid=3d08f74a-1329-7fed-6145-5794647d68f9 username=root password=null
[20120501T16:25:42.725Z| info|kronos|128 UNIX /var/lib/xcp/xapi|session.login_with_password D:ba7fc5b517dd|xapi] Session.create trackid=74ded20eb2d0dfa8f0715f718f6296d7 pool=false uname=root is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.726Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|session.login_with_password D:ba7fc5b517dd|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.726Z|debug|kronos|129 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:2b09f196da87 created by task D:ba7fc5b517dd
[20120501T16:25:42.770Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|audit] VM.start: VM = '3d08f74a-1329-7fed-6145-5794647d68f9 (debian)'
[20120501T16:25:42.775Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] No operations are valid because current-operations = [ OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a -> attach ]
[20120501T16:25:42.777Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Using wlb recommendations for choosing a host has been disabled or wlb is not available. Using original algorithm
[20120501T16:25:42.777Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi_ha_vm_failover] assert_configuration_change_preserves_ha_plan c = configuration_change = { old_vms_leaving = [  ]; new_vms_arriving = [ e72edfaf (kronos) 14990f10 (debian) ]; hosts_to_disable = [  ]; num_failures = no change; new_vms = [  ] }
[20120501T16:25:42.781Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|thread_queue] push(vm_lifecycle_op, VM.start VM.start R:24f1978dd4a3): queue = [ VM.start VM.start R:24f1978dd4a3 ](1)
[20120501T16:25:42.781Z|debug|kronos|130||thread_queue] pop(vm_lifecycle_op) = VM.start VM.start R:24f1978dd4a3
[20120501T16:25:42.781Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|locking_helpers] Acquired lock on VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7 with token 3
[20120501T16:25:42.781Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] start: making sure the VM really is halted
[20120501T16:25:42.781Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] start: checking that VM can run on this host
[20120501T16:25:42.782Z| info|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] The VM's BIOS strings were not yet filled in. The VM is now made BIOS-generic.
[20120501T16:25:42.797Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] start: bringing up domain in the paused state
[20120501T16:25:42.798Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|memory_control] logging into ballooning service
[20120501T16:25:42.798Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Checking pid 5196
[20120501T16:25:42.800Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Written request using id: 7b0a8b99-0dad-c926-aa5b-b56790656ed6
[20120501T16:25:42.800Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/login/7b0a8b99-0dad-c926-aa5b-b56790656ed6 ] with timeout 300.000000 seconds
[20120501T16:25:42.802Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|memory_control] reserve_memory_range min=266240 max=266240
[20120501T16:25:42.802Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Checking pid 5196
[20120501T16:25:42.804Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Written request using id: 280c9e00-93af-5f86-6964-d3f820a5aef1
[20120501T16:25:42.804Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/reserve-memory-range/280c9e00-93af-5f86-6964-d3f820a5aef1 ] with timeout 300.000000 seconds
[20120501T16:25:42.810Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|memory_control] reserve_memory_range actual = 266240
[20120501T16:25:42.810Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|memory_control] reserved_memory = 266240; min = 266240; max = 266240
[20120501T16:25:42.810Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] VM will have 1 hotplugged vcpus out of 1
[20120501T16:25:42.810Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] xen reports max 256 pCPUs
[20120501T16:25:42.811Z| info|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Memory free = 1022236; scrub = 0
[20120501T16:25:42.811Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Regenerating the xenstored tree under: [/local/domain/1]
[20120501T16:25:42.821Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Created domain with id: 1
[20120501T16:25:42.821Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Created domain with domid: 1
[20120501T16:25:42.821Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|memory_control] transfer_reservation_to_domain bcb05064-94af-d031-48be-62b55a2eafa5 -> 1
[20120501T16:25:42.821Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Checking pid 5196
[20120501T16:25:42.823Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Written request using id: c79f2094-05fd-746f-0a99-9e5fcf050629
[20120501T16:25:42.823Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/transfer-reservation-to-domain/c79f2094-05fd-746f-0a99-9e5fcf050629 ] with timeout 300.000000 seconds
[20120501T16:25:42.827Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|memory_control] delete_reservation bcb05064-94af-d031-48be-62b55a2eafa5
[20120501T16:25:42.828Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Checking pid 5196
[20120501T16:25:42.830Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenstore-rpc] Written request using id: d53e08a9-5a80-4fed-37ed-5157497e9f67
[20120501T16:25:42.830Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] watch: watching xenstore paths: [ /squeezed/rpc/response/delete-reservation/d53e08a9-5a80-4fed-37ed-5157497e9f67 ] with timeout 300.000000 seconds
[20120501T16:25:42.837Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Verifying VDI records exist
[20120501T16:25:42.837Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] creating kernel
[20120501T16:25:42.837Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.838Z|debug|kronos|131 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:70ccddf815f8 created by task R:24f1978dd4a3
[20120501T16:25:42.839Z| info|kronos|131 UNIX /var/lib/xcp/xapi|session.slave_login D:55c418c955f8|xapi] Session.create trackid=a4a19bad1103f61e3473c31f87b8c83e pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.840Z|debug|kronos|131 UNIX /var/lib/xcp/xapi|session.slave_login D:55c418c955f8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.841Z|debug|kronos|132 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:718782a2dccc created by task D:55c418c955f8
[20120501T16:25:42.843Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.844Z|debug|kronos|133 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.create D:c0d73cc94b77 created by task R:24f1978dd4a3
[20120501T16:25:42.846Z| info|kronos|133 UNIX /var/lib/xcp/xapi|dispatch:VBD.create D:c0d73cc94b77|taskhelper] task VBD.create R:6e22a7abf816 (uuid:d17febed-2935-c1cb-d824-55561f7ba2b4) created (trackid=a4a19bad1103f61e3473c31f87b8c83e) by task R:24f1978dd4a3
[20120501T16:25:42.846Z|debug|kronos|133 UNIX /var/lib/xcp/xapi|VBD.create R:6e22a7abf816|audit] VBD.create: VM = '27260a46-4e8b-02e8-2d35-e1b3c4479394 (Control domain on host: kronos)'; VDI = 'be3aac06-fab9-42d2-a7d7-f72a3603ca23'
[20120501T16:25:42.847Z|debug|kronos|133 UNIX /var/lib/xcp/xapi|VBD.create R:6e22a7abf816|xapi] VBD.create (device = 0; uuid = 40b54906-0e71-1750-3206-38fdb231934c; ref = OpaqueRef:029bd44e-c526-1d8d-b3cb-31310c448b16)
[20120501T16:25:42.853Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.854Z|debug|kronos|134 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.get_uuid D:6b6ddce980b7 created by task R:24f1978dd4a3
[20120501T16:25:42.855Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.856Z|debug|kronos|135 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_uuid D:fc0718355a75 created by task R:24f1978dd4a3
[20120501T16:25:42.858Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] created VBD (uuid 40b54906-0e71-1750-3206-38fdb231934c); attempting to hotplug to VM (uuid: 27260a46-4e8b-02e8-2d35-e1b3c4479394)
[20120501T16:25:42.858Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.859Z|debug|kronos|136 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.plug D:2392f80ec84d created by task R:24f1978dd4a3
[20120501T16:25:42.861Z| info|kronos|136 UNIX /var/lib/xcp/xapi|dispatch:VBD.plug D:2392f80ec84d|taskhelper] task VBD.plug R:ff69ff1ea507 (uuid:06044645-a3e6-513f-adb2-c4441a5aee67) created (trackid=a4a19bad1103f61e3473c31f87b8c83e) by task R:24f1978dd4a3
[20120501T16:25:42.861Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|audit] VBD.plug: VBD = '40b54906-0e71-1750-3206-38fdb231934c'
[20120501T16:25:42.863Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|locking_helpers] Acquired lock on VM OpaqueRef:f11deee3-93ac-4247-aac0-da3d45d4eef0 with token 4
[20120501T16:25:42.863Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|xapi] vbd_plug: attempting to attach vbd
[20120501T16:25:42.863Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|xapi] Attempting to dynamically attach VBD to domid 0
[20120501T16:25:42.863Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|xapi] VBD device name 0 interpreted as Xen(0, 0) (hvm = false)
[20120501T16:25:42.863Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|xapi] VBD.plug of loopback VBD 'OpaqueRef:029bd44e-c526-1d8d-b3cb-31310c448b16'
[20120501T16:25:42.863Z| info|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|storage_impl] VDI.attach task:OpaqueRef:ff69ff1e-a507-7dbd-24a1-ca3acf2057d8 dp:vbd/0/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 read_write:false
[20120501T16:25:42.864Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|dummytaskhelper] task VDI.attach D:63b6c177b0e1 created by task R:ff69ff1ea507
[20120501T16:25:42.864Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VDI.attach D:63b6c177b0e1|sm] SM ext vdi_attach sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782 writable=false
[20120501T16:25:42.865Z| info|kronos|136 UNIX /var/lib/xcp/xapi|sm_exec D:bfb9b95e3dc9|xapi] Session.create trackid=b0c0201bc0b55b6cfaec101e31488f48 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.866Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|sm_exec D:bfb9b95e3dc9|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.867Z|debug|kronos|137 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:f058f3ea540e created by task D:bfb9b95e3dc9
[20120501T16:25:42.943Z|debug|kronos|138 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:04b1a90963c6 created by task D:63b6c177b0e1
[20120501T16:25:42.947Z|debug|kronos|138 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:42.992Z| info|kronos|136 UNIX /var/lib/xcp/xapi|sm_exec D:bfb9b95e3dc9|xapi] Session.destroy trackid=b0c0201bc0b55b6cfaec101e31488f48
[20120501T16:25:42.993Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|storage_impl] task:OpaqueRef:ff69ff1e-a507-7dbd-24a1-ca3acf2057d8 dp:vbd/0/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:attached  RO
[20120501T16:25:42.993Z| info|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|storage_impl] VDI.activate task:OpaqueRef:ff69ff1e-a507-7dbd-24a1-ca3acf2057d8 dp:vbd/0/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23
[20120501T16:25:42.994Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|dummytaskhelper] task VDI.activate D:dd96696845cb created by task R:ff69ff1ea507
[20120501T16:25:42.994Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VDI.activate D:dd96696845cb|sm] SM ext vdi_activate sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:25:42.996Z| info|kronos|136 UNIX /var/lib/xcp/xapi|sm_exec D:1f45785ca6e1|xapi] Session.create trackid=6e79181bc390940e0c672bb6b059c07d pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:42.996Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|sm_exec D:1f45785ca6e1|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:42.997Z|debug|kronos|139 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:8eb0eb7fbf49 created by task D:1f45785ca6e1
[20120501T16:25:43.073Z|debug|kronos|140 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:ee65da4afc92 created by task D:dd96696845cb
[20120501T16:25:43.079Z|debug|kronos|140 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.120Z|debug|kronos|141 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:9f5f7be0483f created by task D:dd96696845cb
[20120501T16:25:43.122Z|debug|kronos|141 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.123Z|debug|kronos|142 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_by_uuid D:2d316cf07495 created by task D:dd96696845cb
[20120501T16:25:43.125Z|debug|kronos|142 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.125Z|debug|kronos|143 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:0a91d9b222cb created by task D:dd96696845cb
[20120501T16:25:43.127Z|debug|kronos|143 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.128Z|debug|kronos|144 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.add_to_sm_config D:7e2590d5cbdd created by task D:dd96696845cb
[20120501T16:25:43.129Z| info|kronos|144 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_sm_config D:7e2590d5cbdd|api_effect] VDI.add_to_sm_config
[20120501T16:25:43.130Z|debug|kronos|144 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.131Z|debug|kronos|145 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:4e589b3f28ea created by task D:dd96696845cb
[20120501T16:25:43.133Z|debug|kronos|145 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.134Z|debug|kronos|146 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:ddba3a461d07 created by task D:dd96696845cb
[20120501T16:25:43.135Z|debug|kronos|146 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.136Z|debug|kronos|147 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_SR D:3cf3a8005d99 created by task D:dd96696845cb
[20120501T16:25:43.138Z|debug|kronos|147 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.139Z|debug|kronos|148 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_uuid D:487e075fc508 created by task D:dd96696845cb
[20120501T16:25:43.141Z|debug|kronos|148 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.141Z|debug|kronos|149 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:c0b80645aa44 created by task D:dd96696845cb
[20120501T16:25:43.143Z|debug|kronos|149 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.144Z|debug|kronos|150 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_type D:7b0842a55db6 created by task D:dd96696845cb
[20120501T16:25:43.145Z|debug|kronos|150 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.146Z|debug|kronos|151 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_all_records_where D:479abef1d1d7 created by task D:dd96696845cb
[20120501T16:25:43.148Z|debug|kronos|151 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.149Z|debug|kronos|152 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_driver_filename D:65e897f921fd created by task D:dd96696845cb
[20120501T16:25:43.151Z|debug|kronos|152 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.168Z|debug|kronos|153 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_all_records_where D:ca79f19b060b created by task D:dd96696845cb
[20120501T16:25:43.173Z|debug|kronos|153 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.173Z|debug|kronos|154 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_all_records_where D:ed08549fbb8c created by task D:dd96696845cb
[20120501T16:25:43.175Z|debug|kronos|154 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.176Z|debug|kronos|155 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_device_config D:f1c0ae1b9737 created by task D:dd96696845cb
[20120501T16:25:43.178Z|debug|kronos|155 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.183Z|debug|kronos|156 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.191Z| info|kronos|157 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:00970417521d|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:43.193Z|debug|kronos|157 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.195Z| info|kronos|158 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:e6702e6c2e00|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:43.196Z|debug|kronos|158 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.198Z| info|kronos|159 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:4491052e9ba9|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:43.199Z|debug|kronos|159 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.201Z| info|kronos|160 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:fc4473b5f95e|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:43.202Z|debug|kronos|160 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.204Z| info|kronos|161 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:14050908ca59|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:43.205Z|debug|kronos|161 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.207Z| info|kronos|162 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:0a5fe8dd6e39|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:43.209Z|debug|kronos|162 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.210Z| info|kronos|163 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:ed6747dcd610|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:43.212Z|debug|kronos|163 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.213Z| info|kronos|164 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:42db6b361254|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:43.215Z|debug|kronos|164 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.216Z| info|kronos|165 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:c9e4c9abfab1|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:43.218Z|debug|kronos|165 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.219Z| info|kronos|166 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:8779352341e9|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:43.225Z|debug|kronos|166 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.336Z| info|kronos|136 UNIX /var/lib/xcp/xapi|sm_exec D:1f45785ca6e1|xapi] Session.destroy trackid=6e79181bc390940e0c672bb6b059c07d
[20120501T16:25:43.337Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|storage_impl] task:OpaqueRef:ff69ff1e-a507-7dbd-24a1-ca3acf2057d8 dp:vbd/0/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:activated RO
[20120501T16:25:43.339Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|xapi] vbd_plug: successfully hotplugged device
[20120501T16:25:43.339Z|debug|kronos|136 UNIX /var/lib/xcp/xapi|VBD.plug R:ff69ff1ea507|locking_helpers] Released lock on VM OpaqueRef:f11deee3-93ac-4247-aac0-da3d45d4eef0 with token 4
[20120501T16:25:43.345Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|bootloader] Bootloader commandline: /usr/bin/eliloader -q --default_args= --extra_args=-- quiet console=hvc0 --vm=3d08f74a-1329-7fed-6145-5794647d68f9 /dev/sm/backend/96e5db02-c778-5401-b786-5dc9180005e7/be3aac06-fab9-42d2-a7d7-f72a3603ca23

[20120501T16:25:43.440Z| info|kronos|167 UNIX /var/lib/xcp/xapi|session.login_with_password D:9a30b5fe2605|xapi] Session.create trackid=a3522eb6ceb6a954605a8be6d689c383 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:43.441Z|debug|kronos|167 UNIX /var/lib/xcp/xapi|session.login_with_password D:9a30b5fe2605|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:43.441Z|debug|kronos|168 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:8eee15688818 created by task D:9a30b5fe2605
[20120501T16:25:43.444Z|debug|kronos|167 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.446Z|debug|kronos|169 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.449Z|debug|kronos|170 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.451Z|debug|kronos|171 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.453Z|debug|kronos|172 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.456Z|debug|kronos|173 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.459Z|debug|kronos|174 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:43.459Z|debug|kronos|175 UNIX /var/lib/xcp/xapi|dispatch:logout D:122b6db636ae|dispatcher] Unknown rpc "logout"
[20120501T16:25:43.461Z|debug|kronos|175 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.475Z| info|kronos|176 UNIX /var/lib/xcp/xapi|session.login_with_password D:c4855f68ae50|xapi] Session.create trackid=c4c1cf34dfe55363d47b2c8f74659286 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:58.475Z|debug|kronos|176 UNIX /var/lib/xcp/xapi|session.login_with_password D:c4855f68ae50|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.476Z|debug|kronos|177 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:2d388f7daadf created by task D:c4855f68ae50
[20120501T16:25:58.478Z|debug|kronos|176 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.481Z|debug|kronos|178 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.483Z|debug|kronos|179 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.486Z|debug|kronos|180 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.488Z|debug|kronos|181 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.490Z|debug|kronos|182 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.492Z| info|kronos|183 UNIX /var/lib/xcp/xapi|dispatch:VM.set_PV_bootloader D:04c6abaec3c9|api_effect] VM.set_PV_bootloader
[20120501T16:25:58.493Z|debug|kronos|183 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.494Z|debug|kronos|184 UNIX /var/lib/xcp/xapi|dispatch:logout D:89749b133c50|dispatcher] Unknown rpc "logout"
[20120501T16:25:58.495Z|debug|kronos|184 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.496Z| info|kronos|185 UNIX /var/lib/xcp/xapi|session.login_with_password D:2e508f62c923|xapi] Session.create trackid=b2dc92428611b4664bb5980f9a3e6241 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:58.497Z|debug|kronos|185 UNIX /var/lib/xcp/xapi|session.login_with_password D:2e508f62c923|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.498Z|debug|kronos|186 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:d5179ad48c47 created by task D:2e508f62c923
[20120501T16:25:58.500Z|debug|kronos|185 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.502Z|debug|kronos|187 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.505Z|debug|kronos|188 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.507Z|debug|kronos|189 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.509Z|debug|kronos|190 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.512Z|debug|kronos|191 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.513Z| info|kronos|192 UNIX /var/lib/xcp/xapi|dispatch:VM.remove_from_other_config D:53579dd503d6|api_effect] VM.remove_from_other_config
[20120501T16:25:58.515Z|debug|kronos|192 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.516Z| info|kronos|193 UNIX /var/lib/xcp/xapi|dispatch:VM.remove_from_other_config D:285a3c0e5e3a|api_effect] VM.remove_from_other_config
[20120501T16:25:58.519Z|debug|kronos|193 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.519Z|debug|kronos|194 UNIX /var/lib/xcp/xapi|dispatch:logout D:e240b78f70e7|dispatcher] Unknown rpc "logout"
[20120501T16:25:58.526Z|debug|kronos|194 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.527Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.528Z|debug|kronos|195 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.slave_login D:14431b2f88b7 created by task R:24f1978dd4a3
[20120501T16:25:58.529Z| info|kronos|195 UNIX /var/lib/xcp/xapi|session.slave_login D:72091828176b|xapi] Session.create trackid=57bbf1941de3ba49e4394bf54b1a825c pool=true uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:58.530Z|debug|kronos|195 UNIX /var/lib/xcp/xapi|session.slave_login D:72091828176b|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.530Z|debug|kronos|196 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:82121019d5ce created by task D:72091828176b
[20120501T16:25:58.533Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.533Z|debug|kronos|197 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.unplug D:a258768af891 created by task R:24f1978dd4a3
[20120501T16:25:58.535Z| info|kronos|197 UNIX /var/lib/xcp/xapi|dispatch:VBD.unplug D:a258768af891|taskhelper] task VBD.unplug R:c6409e743833 (uuid:6d84af15-ed85-4c71-4c39-34b2d4547f11) created (trackid=57bbf1941de3ba49e4394bf54b1a825c) by task R:24f1978dd4a3
[20120501T16:25:58.536Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|audit] VBD.unplug: VBD = '40b54906-0e71-1750-3206-38fdb231934c'
[20120501T16:25:58.537Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|locking_helpers] Acquired lock on VM OpaqueRef:f11deee3-93ac-4247-aac0-da3d45d4eef0 with token 5
[20120501T16:25:58.538Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|xapi] VBD.unplug of loopback VBD 'OpaqueRef:029bd44e-c526-1d8d-b3cb-31310c448b16'
[20120501T16:25:58.538Z| info|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|storage_impl] DP.destroy task:OpaqueRef:c6409e74-3833-9298-4491-d3bbb4532a86 dp:vbd/0/0 allow_leak:false
[20120501T16:25:58.538Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|dummytaskhelper] task VDI.deactivate D:48e992d3a827 created by task R:c6409e743833
[20120501T16:25:58.538Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VDI.deactivate D:48e992d3a827|sm] SM ext vdi_deactivate sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:25:58.540Z| info|kronos|197 UNIX /var/lib/xcp/xapi|sm_exec D:1bdeb658205a|xapi] Session.create trackid=23d638b8bf332aac2b884ab744f8daec pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:58.540Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|sm_exec D:1bdeb658205a|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.541Z|debug|kronos|198 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:83a07d90a219 created by task D:1bdeb658205a
[20120501T16:25:58.617Z|debug|kronos|199 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:811a07e3bbd8 created by task D:48e992d3a827
[20120501T16:25:58.623Z|debug|kronos|199 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.630Z|debug|kronos|200 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:3b8c25c3395e created by task D:48e992d3a827
[20120501T16:25:58.633Z|debug|kronos|200 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.633Z|debug|kronos|201 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:38c8da804c04 created by task D:48e992d3a827
[20120501T16:25:58.637Z|debug|kronos|201 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.672Z|debug|kronos|202 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:09d2ec4536b0 created by task D:48e992d3a827
[20120501T16:25:58.674Z|debug|kronos|202 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.675Z|debug|kronos|203 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_SR D:b7ec112f4f6f created by task D:48e992d3a827
[20120501T16:25:58.676Z|debug|kronos|203 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.677Z|debug|kronos|204 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_uuid D:a1965a50f401 created by task D:48e992d3a827
[20120501T16:25:58.679Z|debug|kronos|204 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.680Z|debug|kronos|205 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:d4500ab8db05 created by task D:48e992d3a827
[20120501T16:25:58.682Z|debug|kronos|205 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.682Z|debug|kronos|206 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_type D:6c154da7e886 created by task D:48e992d3a827
[20120501T16:25:58.684Z|debug|kronos|206 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.685Z|debug|kronos|207 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_all_records_where D:d1955cab1d92 created by task D:48e992d3a827
[20120501T16:25:58.688Z|debug|kronos|207 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.688Z|debug|kronos|208 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_driver_filename D:bc68a125c2f5 created by task D:48e992d3a827
[20120501T16:25:58.691Z|debug|kronos|208 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.692Z|debug|kronos|209 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_all_records_where D:49469e0b26c8 created by task D:48e992d3a827
[20120501T16:25:58.696Z|debug|kronos|209 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.697Z|debug|kronos|210 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_all_records_where D:00918ef533f2 created by task D:48e992d3a827
[20120501T16:25:58.699Z|debug|kronos|210 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.700Z|debug|kronos|211 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_device_config D:31ef363d41da created by task D:48e992d3a827
[20120501T16:25:58.702Z|debug|kronos|211 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.707Z|debug|kronos|212 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.714Z|debug|kronos|213 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:9932ea54dae6 created by task D:48e992d3a827
[20120501T16:25:58.716Z|debug|kronos|213 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.717Z|debug|kronos|214 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_by_uuid D:d78bd742e200 created by task D:48e992d3a827
[20120501T16:25:58.719Z|debug|kronos|214 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.719Z|debug|kronos|215 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:ba1639253de2 created by task D:48e992d3a827
[20120501T16:25:58.721Z|debug|kronos|215 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.722Z|debug|kronos|216 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.remove_from_sm_config D:c5de78324ec8 created by task D:48e992d3a827
[20120501T16:25:58.723Z| info|kronos|216 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_sm_config D:c5de78324ec8|api_effect] VDI.remove_from_sm_config
[20120501T16:25:58.731Z|debug|kronos|216 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.739Z| info|kronos|197 UNIX /var/lib/xcp/xapi|sm_exec D:1bdeb658205a|xapi] Session.destroy trackid=23d638b8bf332aac2b884ab744f8daec
[20120501T16:25:58.740Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|storage_impl] task:OpaqueRef:c6409e74-3833-9298-4491-d3bbb4532a86 dp:vbd/0/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:attached  RO
[20120501T16:25:58.741Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|dummytaskhelper] task VDI.detach D:4d72e92c67e4 created by task R:c6409e743833
[20120501T16:25:58.741Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VDI.detach D:4d72e92c67e4|sm] SM ext vdi_detach sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:25:58.743Z| info|kronos|197 UNIX /var/lib/xcp/xapi|sm_exec D:28afd2cc5a13|xapi] Session.create trackid=ba7ac5b597fafc3b375e82146407a062 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:58.743Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|sm_exec D:28afd2cc5a13|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.744Z|debug|kronos|217 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:acdd93ce9117 created by task D:28afd2cc5a13
[20120501T16:25:58.820Z|debug|kronos|218 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:61af4f38728e created by task D:4d72e92c67e4
[20120501T16:25:58.826Z|debug|kronos|218 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:58.846Z| info|kronos|197 UNIX /var/lib/xcp/xapi|sm_exec D:28afd2cc5a13|xapi] Session.destroy trackid=ba7ac5b597fafc3b375e82146407a062
[20120501T16:25:58.847Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|storage_impl] task:OpaqueRef:c6409e74-3833-9298-4491-d3bbb4532a86 dp:vbd/0/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:detached
[20120501T16:25:58.849Z|debug|kronos|197 UNIX /var/lib/xcp/xapi|VBD.unplug R:c6409e743833|locking_helpers] Released lock on VM OpaqueRef:f11deee3-93ac-4247-aac0-da3d45d4eef0 with token 5
[20120501T16:25:58.855Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.856Z|debug|kronos|219 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VBD.destroy D:6fba81a824c1 created by task R:24f1978dd4a3
[20120501T16:25:58.858Z| info|kronos|219 UNIX /var/lib/xcp/xapi|dispatch:VBD.destroy D:6fba81a824c1|taskhelper] task VBD.destroy R:ddfd106df2bc (uuid:c4a5a5ee-ba9b-ce38-8fd8-e48a6eae0655) created (trackid=57bbf1941de3ba49e4394bf54b1a825c) by task R:24f1978dd4a3
[20120501T16:25:58.858Z|debug|kronos|219 UNIX /var/lib/xcp/xapi|VBD.destroy R:ddfd106df2bc|audit] VBD.destroy: VBD = '40b54906-0e71-1750-3206-38fdb231934c'
[20120501T16:25:58.858Z|debug|kronos|219 UNIX /var/lib/xcp/xapi|VBD.destroy R:ddfd106df2bc|xapi] VBD.destroy (uuid = 40b54906-0e71-1750-3206-38fdb231934c; ref = OpaqueRef:029bd44e-c526-1d8d-b3cb-31310c448b16)
[20120501T16:25:58.863Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.864Z|debug|kronos|220 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:2071edfacdb2 created by task R:24f1978dd4a3
[20120501T16:25:58.865Z| info|kronos|220 UNIX /var/lib/xcp/xapi|session.logout D:6fb07f2fef55|xapi] Session.destroy trackid=57bbf1941de3ba49e4394bf54b1a825c
[20120501T16:25:58.867Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:58.867Z|debug|kronos|221 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.logout D:e6e59641b690 created by task R:24f1978dd4a3
[20120501T16:25:58.869Z| info|kronos|221 UNIX /var/lib/xcp/xapi|session.logout D:1b54dbfee674|xapi] Session.destroy trackid=a4a19bad1103f61e3473c31f87b8c83e
[20120501T16:25:58.870Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] build linux "/var/run/xend/boot/vmlinuz-G72MJ4" "-- quiet console=hvc0  " vcpus:1 mem_max:262144 mem_target:262144
[20120501T16:25:58.870Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] build_pre domid=1; max=256 MiB; shadow=3 MiB; required=260 MiB
[20120501T16:25:58.870Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenguesthelper] connect: args = [ -mode linux_build -domid 1 -mem_max_mib 256 -mem_start_mib 256 -image /var/run/xend/boot/vmlinuz-G72MJ4 -ramdisk /var/run/xend/boot/ramdisk-492z0b -cmdline -- quiet console=hvc0   -features  -flags 0 -store_port 1 -console_port 2 -fork true ]
[20120501T16:25:59.415Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Read [254310 254309 ]
[20120501T16:25:59.423Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] creating VCPU devices and attaching to domain
[20120501T16:25:59.426Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] creating VBD devices and attaching to domain
[20120501T16:25:59.426Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] VBD device name 0 interpreted as Xen(0, 0) (hvm = false)
[20120501T16:25:59.427Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|sm] SM ext sr_content_type sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a
[20120501T16:25:59.428Z|debug|kronos|52 xal_listen||event] VM (domid: 1) device_event = ChangeUncooperative false
[20120501T16:25:59.428Z|debug|kronos|52 xal_listen|VM (domid: 1) device_event = ChangeUncooperative false D:0d0882968fac|event] VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7 is now cooperative
[20120501T16:25:59.429Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:99fc38324ce8|xapi] Session.create trackid=aed769f3a3677c89c2b26985197c69be pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:59.429Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:99fc38324ce8|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:59.430Z|debug|kronos|222 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:89d2e3e31c9e created by task D:99fc38324ce8
[20120501T16:25:59.506Z|debug|kronos|223 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:e037ee4cf859 created by task R:24f1978dd4a3
[20120501T16:25:59.511Z|debug|kronos|223 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.517Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:99fc38324ce8|xapi] Session.destroy trackid=aed769f3a3677c89c2b26985197c69be
[20120501T16:25:59.518Z| info|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] VDI.attach task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 read_write:true
[20120501T16:25:59.519Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|dummytaskhelper] task VDI.attach D:1952ff5f8dd2 created by task R:24f1978dd4a3
[20120501T16:25:59.519Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VDI.attach D:1952ff5f8dd2|sm] SM ext vdi_attach sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782 writable=true
[20120501T16:25:59.520Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:4659beb6c1dd|xapi] Session.create trackid=3639839b15526146e7911e369a88d013 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:59.521Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:4659beb6c1dd|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:59.522Z|debug|kronos|224 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:89ad43f2c668 created by task D:4659beb6c1dd
[20120501T16:25:59.598Z|debug|kronos|225 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:8fcaeb6d070c created by task D:1952ff5f8dd2
[20120501T16:25:59.603Z|debug|kronos|225 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.623Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:4659beb6c1dd|xapi] Session.destroy trackid=3639839b15526146e7911e369a88d013
[20120501T16:25:59.624Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:attached  RW
[20120501T16:25:59.625Z| info|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] VDI.activate task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23
[20120501T16:25:59.625Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|dummytaskhelper] task VDI.activate D:952bb0092b04 created by task R:24f1978dd4a3
[20120501T16:25:59.625Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VDI.activate D:952bb0092b04|sm] SM ext vdi_activate sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:25:59.627Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:2f69d18a0a18|xapi] Session.create trackid=cdbb97c4c2023fd2e1793635a92812fa pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:59.627Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:2f69d18a0a18|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:59.628Z|debug|kronos|226 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:9b3788955302 created by task D:2f69d18a0a18
[20120501T16:25:59.704Z|debug|kronos|227 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:39a89252c8cb created by task D:952bb0092b04
[20120501T16:25:59.707Z|debug|kronos|227 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.717Z|debug|kronos|228 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:f4e7e82db89a created by task D:952bb0092b04
[20120501T16:25:59.719Z|debug|kronos|228 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.720Z|debug|kronos|229 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_by_uuid D:49972ba4347f created by task D:952bb0092b04
[20120501T16:25:59.722Z|debug|kronos|229 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.722Z|debug|kronos|230 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:e2c67f9bd003 created by task D:952bb0092b04
[20120501T16:25:59.724Z|debug|kronos|230 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.725Z|debug|kronos|231 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.add_to_sm_config D:efc5eb13cd3f created by task D:952bb0092b04
[20120501T16:25:59.726Z| info|kronos|231 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_sm_config D:efc5eb13cd3f|api_effect] VDI.add_to_sm_config
[20120501T16:25:59.727Z|debug|kronos|231 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.728Z|debug|kronos|232 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:75313cede67f created by task D:952bb0092b04
[20120501T16:25:59.730Z|debug|kronos|232 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.731Z|debug|kronos|233 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:c6387e8f6ce8 created by task D:952bb0092b04
[20120501T16:25:59.733Z|debug|kronos|233 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.734Z|debug|kronos|234 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_SR D:03c46795ae01 created by task D:952bb0092b04
[20120501T16:25:59.735Z|debug|kronos|234 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.736Z|debug|kronos|235 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_uuid D:b9ee90bf1f96 created by task D:952bb0092b04
[20120501T16:25:59.738Z|debug|kronos|235 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.739Z|debug|kronos|236 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:d03d097aa18b created by task D:952bb0092b04
[20120501T16:25:59.740Z|debug|kronos|236 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.741Z|debug|kronos|237 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_type D:bb3f44d15524 created by task D:952bb0092b04
[20120501T16:25:59.743Z|debug|kronos|237 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.743Z|debug|kronos|238 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_all_records_where D:a5cb057d69ce created by task D:952bb0092b04
[20120501T16:25:59.746Z|debug|kronos|238 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.746Z|debug|kronos|239 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_driver_filename D:042871e495c5 created by task D:952bb0092b04
[20120501T16:25:59.749Z|debug|kronos|239 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.749Z|debug|kronos|240 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_all_records_where D:f9b40fb7df87 created by task D:952bb0092b04
[20120501T16:25:59.754Z|debug|kronos|240 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.755Z|debug|kronos|241 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_all_records_where D:6e2117e71d28 created by task D:952bb0092b04
[20120501T16:25:59.757Z|debug|kronos|241 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.758Z|debug|kronos|242 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_device_config D:9454feda2bb5 created by task D:952bb0092b04
[20120501T16:25:59.760Z|debug|kronos|242 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.766Z|debug|kronos|243 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.773Z| info|kronos|244 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:1574b343b270|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:59.775Z|debug|kronos|244 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.776Z| info|kronos|245 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:ed66dfbc505b|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:59.778Z|debug|kronos|245 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.780Z| info|kronos|246 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:037a2da2c45b|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:59.781Z|debug|kronos|246 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.783Z| info|kronos|247 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:6e6a0c44fde5|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:59.784Z|debug|kronos|247 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.786Z| info|kronos|248 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:01f166f894d4|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:59.788Z|debug|kronos|248 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.789Z| info|kronos|249 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:1b54483a4e13|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:59.790Z|debug|kronos|249 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.792Z| info|kronos|250 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data D:1a8aa39b3083|api_effect] VDI.remove_from_xenstore_data
[20120501T16:25:59.793Z|debug|kronos|250 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.795Z| info|kronos|251 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:4e90fc0df013|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:59.796Z|debug|kronos|251 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.798Z| info|kronos|252 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:fdba3114a07f|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:59.799Z|debug|kronos|252 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.801Z| info|kronos|253 UNIX /var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:9687229d44fd|api_effect] VDI.add_to_xenstore_data
[20120501T16:25:59.806Z|debug|kronos|253 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:25:59.877Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:2f69d18a0a18|xapi] Session.destroy trackid=cdbb97c4c2023fd2e1793635a92812fa
[20120501T16:25:59.878Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:activated RW
[20120501T16:25:59.878Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Device.Vbd.add (device_number=Xen(0, 0) | params=/dev/sm/backend/96e5db02-c778-5401-b786-5dc9180005e7/be3aac06-fab9-42d2-a7d7-f72a3603ca23 | phystype=vhd)
[20120501T16:25:59.879Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] adding device  B0[/local/domain/0/backend/vbd/1/51712]  F1[/local/domain/1/device/vbd/51712]  H[/xapi/1/hotplug/vbd/51712]
[20120501T16:25:59.879Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|backtrace] Raised at device.ml:65.10-42 -> xst.ml:52.18-23 -> xst.ml:55.9-12 -> device.ml:497.1-60 -> vbdops.ml:102.37-229 -> storage_access.ml:516.14-317 -> xapi_xenops_errors.ml:79.4-8
[20120501T16:25:59.879Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Converting xenops exception (INTERNAL_ERROR: [ Device_common.Device_backend_vanished(_) ]) into nice API internal error
[20120501T16:25:59.879Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at string.ml:150.25-34 -> stringext.ml:108.13-29
[20120501T16:25:59.879Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|backtrace] Raised at xapi_xenops_errors.ml:83.10-26 -> list.ml:69.12-15 -> vmops.ml:1081.8-116
[20120501T16:25:59.879Z|error|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Vmops.start_paused caught: INTERNAL_ERROR: [ the device disappeared from xenstore (frontend (domid=1 | kind=vbd | devid=51712); backend (domid=0 | kind=vbd | devid=51712)) ]
[20120501T16:25:59.879Z| info|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Memory F 756856 KiB S 0 KiB T 2046 MiB
[20120501T16:25:59.880Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Domain.destroy: all known devices = [  ]
[20120501T16:25:59.880Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Domain.destroy calling Xenctrl.domain_destroy (domid 1)
[20120501T16:25:59.952Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Domain.destroy: rm /local/domain/1
[20120501T16:25:59.952Z|debug|kronos|52 xal_listen||event] VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain
[20120501T16:25:59.953Z|debug|kronos|52 xal_listen|VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain D:63d0eac040e5|event] adding Resync.vm to work queue
[20120501T16:25:59.953Z|debug|kronos|52 xal_listen|VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain D:63d0eac040e5|locking_helpers] push(per-VM queue, VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain); queue = [ VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain ](1)
[20120501T16:25:59.955Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Domain.destroy: deleting backend paths
[20120501T16:25:59.955Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Xenctrl.domain_getinfo 1 threw: 11: Resource temporarily unavailable -- assuming domain nolonger exists
[20120501T16:25:59.955Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xenops] Xenctrl.domain_getinfo 1 threw: 11: Resource temporarily unavailable -- assuming domain nolonger exists
[20120501T16:25:59.955Z| info|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] DP.destroy task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 allow_leak:false
[20120501T16:25:59.956Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|dummytaskhelper] task VDI.deactivate D:83b87962f87a created by task R:24f1978dd4a3
[20120501T16:25:59.956Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VDI.deactivate D:83b87962f87a|sm] SM ext vdi_deactivate sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:25:59.957Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:9367cbccebe0|xapi] Session.create trackid=3ee82e47f0e279d839964c61802a27a7 pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:25:59.958Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:9367cbccebe0|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:25:59.959Z|debug|kronos|254 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:763e42267bb2 created by task D:9367cbccebe0
[20120501T16:26:00.035Z|debug|kronos|255 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:2871ef251207 created by task D:83b87962f87a
[20120501T16:26:00.039Z|debug|kronos|255 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.048Z|debug|kronos|256 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:ec23e32137d7 created by task D:83b87962f87a
[20120501T16:26:00.050Z|debug|kronos|256 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.051Z|debug|kronos|257 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:f2173d626ea5 created by task D:83b87962f87a
[20120501T16:26:00.055Z|debug|kronos|257 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.090Z|debug|kronos|258 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:a38205ec7642 created by task D:83b87962f87a
[20120501T16:26:00.093Z|debug|kronos|258 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.093Z|debug|kronos|259 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_SR D:84e423f2921c created by task D:83b87962f87a
[20120501T16:26:00.095Z|debug|kronos|259 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.096Z|debug|kronos|260 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_uuid D:23a2f1abecb4 created by task D:83b87962f87a
[20120501T16:26:00.098Z|debug|kronos|260 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.098Z|debug|kronos|261 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:6f4188ac0e0d created by task D:83b87962f87a
[20120501T16:26:00.100Z|debug|kronos|261 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.101Z|debug|kronos|262 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_type D:8c8017a50a91 created by task D:83b87962f87a
[20120501T16:26:00.103Z|debug|kronos|262 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.103Z|debug|kronos|263 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_all_records_where D:7aba6040a0db created by task D:83b87962f87a
[20120501T16:26:00.106Z|debug|kronos|263 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.106Z|debug|kronos|264 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_driver_filename D:5ae386f3e0b0 created by task D:83b87962f87a
[20120501T16:26:00.109Z|debug|kronos|264 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.110Z|debug|kronos|265 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_all_records_where D:f3ac6ee77080 created by task D:83b87962f87a
[20120501T16:26:00.115Z|debug|kronos|265 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.115Z|debug|kronos|266 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_all_records_where D:9b471effa422 created by task D:83b87962f87a
[20120501T16:26:00.117Z|debug|kronos|266 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.118Z|debug|kronos|267 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_device_config D:7ecb31a1b3ef created by task D:83b87962f87a
[20120501T16:26:00.120Z|debug|kronos|267 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.126Z|debug|kronos|268 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.132Z|debug|kronos|269 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:7191a07bc444 created by task D:83b87962f87a
[20120501T16:26:00.135Z|debug|kronos|269 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.135Z|debug|kronos|270 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_by_uuid D:0928f2b6a09b created by task D:83b87962f87a
[20120501T16:26:00.137Z|debug|kronos|270 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.138Z|debug|kronos|271 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config D:e89bbd282766 created by task D:83b87962f87a
[20120501T16:26:00.140Z|debug|kronos|271 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.141Z|debug|kronos|272 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.remove_from_sm_config D:9350c43283b7 created by task D:83b87962f87a
[20120501T16:26:00.141Z| info|kronos|272 UNIX /var/lib/xcp/xapi|dispatch:VDI.remove_from_sm_config D:9350c43283b7|api_effect] VDI.remove_from_sm_config
[20120501T16:26:00.151Z|debug|kronos|272 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.157Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:9367cbccebe0|xapi] Session.destroy trackid=3ee82e47f0e279d839964c61802a27a7
[20120501T16:26:00.158Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:attached  RW
[20120501T16:26:00.159Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|dummytaskhelper] task VDI.detach D:be7efd8bbfea created by task R:24f1978dd4a3
[20120501T16:26:00.159Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VDI.detach D:be7efd8bbfea|sm] SM ext vdi_detach sr=OpaqueRef:fc230534-ac95-5b19-3a68-4866f3a53e7a vdi=OpaqueRef:b1f01c7c-ca11-0fb8-8938-1a8aa6892782
[20120501T16:26:00.160Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:9bfcfb1221ca|xapi] Session.create trackid=7e720d6907e43b94278405d0e07924bc pool=false uname= is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120501T16:26:00.161Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:9bfcfb1221ca|xapi] Attempting to open /var/lib/xcp/xapi
[20120501T16:26:00.162Z|debug|kronos|273 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid D:dae14be55d6c created by task D:9bfcfb1221ca
[20120501T16:26:00.238Z|debug|kronos|274 UNIX /var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config D:f8e8c207072b created by task D:be7efd8bbfea
[20120501T16:26:00.244Z|debug|kronos|274 UNIX /var/lib/xcp/xapi||http_critical] Premature termination of connection!
[20120501T16:26:00.263Z| info|kronos|128 UNIX /var/lib/xcp/xapi|sm_exec D:9bfcfb1221ca|xapi] Session.destroy trackid=7e720d6907e43b94278405d0e07924bc
[20120501T16:26:00.264Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|storage_impl] task:OpaqueRef:24f1978d-d4a3-cb74-7ddd-4ed9df7cad7a dp:vbd/1/0 sr:96e5db02-c778-5401-b786-5dc9180005e7 vdi:be3aac06-fab9-42d2-a7d7-f72a3603ca23 superstate:detached
[20120501T16:26:00.270Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at vmops.ml:1141.10-47 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.270Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> xenctrl.ml:114.13-17 -> xenctrl.ml:114.56-59 -> xapi_vm.ml:234.6-120 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.270Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|locking_helpers] pop(per-VM queue) = VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain
[20120501T16:26:00.271Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7: processing VM domid:1 uuid:3d08f74a-1329-7fed-6145-5794647d68f9 @releaseDomain D:9fd85146eaee|event] VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7 (debian) resident_on other host OpaqueRef:NULL (kronos): taking no action
[20120501T16:26:00.271Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.271Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|locking_helpers] Released lock on VM OpaqueRef:14990f10-39c8-35f1-75cb-fe37c1d9d0e7 with token 3
[20120501T16:26:00.271Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.271Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> message_forwarding.ml:233.25-44 -> message_forwarding.ml:880.15-67 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.271Z|debug|kronos|130||thread_queue] vm_lifecycle_op: completed processing 1 items: queue = [  ](0)
[20120501T16:26:00.273Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.274Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.276Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|xapi] Raised at pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20120501T16:26:00.277Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|backtrace] Raised at pervasiveext.ml:26.22-25 -> message_forwarding.ml:1147.4-1023 -> rbac.ml:229.16-23
[20120501T16:26:00.278Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|backtrace] Raised at rbac.ml:238.10-15 -> server_helpers.ml:79.11-41
[20120501T16:26:00.278Z|debug|kronos|128 UNIX /var/lib/xcp/xapi|VM.start R:24f1978dd4a3|dispatcher] Server_helpers.exec exception_handler: Got exception INTERNAL_ERROR: [ the device disappeared from xenstore (frontend (domid=1 | kind=vbd | devid=51712); backend (domid=0 | kind=vbd | devid=51712)) ]