George Shuklin
2012-May-23 14:07 UTC
[Pkg-xen-devel] Bug#674161: xcp-xapi: 'the device disappeared from xenstore' message during vbd-plug (vm-start)
Package: xcp-xapi
Version: 1.3.2-6
Severity: normal
Tags: upstream
vbd plug to PV domain cause following error:
The server failed to handle your request, due to an internal error. The given
message may give details useful for debugging the problem.
message: the device disappeared from xenstore (frontend (domid=4 | kind=vbd |
devid=51760); backend (domid=0 | kind=vbd | devid=51760))
(same error occur during normal vm installation/running, but this is too long
way and I cut some edges by creating a 'diskless' VM, wich just boot and
stops inside in initramfs).
Operation log:
(preparation - not related to bug)
# mkdir /boot/guest
# cp /boot/vmlinuz-3.2.0-2-amd64 /boot/initrd.img-3.2.0-2-amd64 /boot/guest/
#(prepare external kernels)
# xe vm-install template=Other\ install\ media new-name-label=raw
8a6f56a7-3511-650e-d14b-4dd2a3d9c75d
# export vm=8a6f56a7-3511-650e-d14b-4dd2a3d9c75d
# xe vm-param-set uuid=$vm HVM-boot-policy= #(disable HVM mode == switch to PV)
# xe vm-param-set uuid=$vm PV-bootloader= #(disable eliloader/pygrub - use
external kernel)
# xe vm-param-set uuid=$vm PV-kernel=/boot/guest/vmlinuz-3.2.0-2-amd64
# xe vm-param-set uuid=$vm PV-ramdisk=/boot/guest/initrd.img-3.2.0-2-amd64
# xe vm-param-set uuid=$vm PV-args="root=/" #(kerel cmdline - to go to
initrd)
# xe vm-start uuid=$vm
(now we got clean vm without network or block devices and we can easily
repeat but conditions)
# xe sr-create type=file name-label=fileSR device-config:location=/mnt
319f3eaa-d1ba-a81d-acb3-493ecbdaab17
#xe vdi-create type=user virtual-size=2GiB name-label=test
sr-uuid=319f3eaa-d1ba-a81d-acb3-493ecbdaab17
8cc62479-e620-4561-a057-2eff0e0b8f8d
here bug part starts:
xe vbd-create vm-uuid=8a6f56a7-3511-650e-d14b-4dd2a3d9c75d
vdi-uuid=8cc62479-e620-4561-a057-2eff0e0b8f8d device=0
716880c9-d6cb-44a8-e5cd-6a68f708c1f9
root at lab-xh3:~# xe vbd-plug uuid=716880c9-d6cb-44a8-e5cd-6a68f708c1f9
The server failed to handle your request, due to an internal error. The given
message may give details useful for debugging the problem.
message: the device disappeared from xenstore (frontend (domid=2 | kind=vbd |
devid=51712); backend (domid=0 | kind=vbd | devid=51712))
Log file content:
[20120523T14:00:23.276Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi||cli] xe
vbd-plug uuid=716880c9-d6cb-44a8-e5cd-6a68f708c1f9 username=root password=null
[20120523T14:00:23.278Z| info|lab-xh3|74 UNIX
/var/lib/xcp/xapi|session.login_with_password D:0661f1729b93|xapi]
Session.create trackid=094bbc269cc3c3ff4fe8b0faadef2ef1 pool=false uname=root
is_local_superuser=true auth_user_sid=
parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120523T14:00:23.278Z|debug|lab-xh3|74 UNIX
/var/lib/xcp/xapi|session.login_with_password D:0661f1729b93|xapi] Attempting to
open /var/lib/xcp/xapi
[20120523T14:00:23.279Z|debug|lab-xh3|75 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid
D:f3e45d1e1222 created by task D:0661f1729b93
[20120523T14:00:23.285Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|audit] VBD.plug: VBD =
'716880c9-d6cb-44a8-e5cd-6a68f708c1f9'
[20120523T14:00:23.289Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|locking_helpers] Acquired lock on VM
OpaqueRef:714e30c2-f627-1df7-db85-f543eccca324 with token 3
[20120523T14:00:23.289Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] vbd_plug: attempting to attach vbd
[20120523T14:00:23.289Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Attempting to dynamically attach VBD to domid 2
[20120523T14:00:23.290Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] VBD device name 0 interpreted as Xen(0, 0) (hvm = false)
[20120523T14:00:23.290Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|sm] SM file sr_content_type
sr=OpaqueRef:90cbfca8-ffca-554a-4809-d85a71dd826c
[20120523T14:00:23.292Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:e2722ffdc310|xapi] Session.create trackid=d1fe239f7a7942262e1e1b0d73c8f9dc
pool=false uname= is_local_superuser=true auth_user_sid=
parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120523T14:00:23.293Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:e2722ffdc310|xapi] Attempting to open /var/lib/xcp/xapi
[20120523T14:00:23.293Z|debug|lab-xh3|76 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid
D:ca1bcfee9e48 created by task D:e2722ffdc310
[20120523T14:00:23.374Z|debug|lab-xh3|77 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config
D:f8b4e61f4b2d created by task R:4b5db3df62d8
[20120523T14:00:23.376Z|debug|lab-xh3|77 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.382Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:e2722ffdc310|xapi] Session.destroy trackid=d1fe239f7a7942262e1e1b0d73c8f9dc
[20120523T14:00:23.383Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|storage_impl] VDI.attach
task:OpaqueRef:4b5db3df-62d8-3ec4-37c5-b813328ea279 dp:vbd/2/0
sr:319f3eaa-d1ba-a81d-acb3-493ecbdaab17 vdi:8cc62479-e620-4561-a057-2eff0e0b8f8d
read_write:true
[20120523T14:00:23.384Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|dummytaskhelper] task VDI.attach D:c50b045b76ac created by task
R:4b5db3df62d8
[20120523T14:00:23.384Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VDI.attach
D:c50b045b76ac|sm] SM file vdi_attach
sr=OpaqueRef:90cbfca8-ffca-554a-4809-d85a71dd826c
vdi=OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e writable=true
[20120523T14:00:23.385Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:b6a28b0b4cd5|xapi] Session.create trackid=86f63a8f7c1a95156bc12aa8873e1d44
pool=false uname= is_local_superuser=true auth_user_sid=
parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120523T14:00:23.386Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:b6a28b0b4cd5|xapi] Attempting to open /var/lib/xcp/xapi
[20120523T14:00:23.387Z|debug|lab-xh3|78 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid
D:2cfe5c31c6b7 created by task D:b6a28b0b4cd5
[20120523T14:00:23.468Z|debug|lab-xh3|79 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config
D:62ab2c48c7f5 created by task D:c50b045b76ac
[20120523T14:00:23.470Z|debug|lab-xh3|79 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.502Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:b6a28b0b4cd5|xapi] Session.destroy trackid=86f63a8f7c1a95156bc12aa8873e1d44
[20120523T14:00:23.503Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|storage_impl] task:OpaqueRef:4b5db3df-62d8-3ec4-37c5-b813328ea279
dp:vbd/2/0 sr:319f3eaa-d1ba-a81d-acb3-493ecbdaab17
vdi:8cc62479-e620-4561-a057-2eff0e0b8f8d superstate:attached RW
[20120523T14:00:23.504Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|storage_impl] VDI.activate
task:OpaqueRef:4b5db3df-62d8-3ec4-37c5-b813328ea279 dp:vbd/2/0
sr:319f3eaa-d1ba-a81d-acb3-493ecbdaab17 vdi:8cc62479-e620-4561-a057-2eff0e0b8f8d
[20120523T14:00:23.504Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|dummytaskhelper] task VDI.activate D:da62a5425fb6 created by task
R:4b5db3df62d8
[20120523T14:00:23.504Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VDI.activate
D:da62a5425fb6|sm] SM file vdi_activate
sr=OpaqueRef:90cbfca8-ffca-554a-4809-d85a71dd826c
vdi=OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e
[20120523T14:00:23.506Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:a249a76eac61|xapi] Session.create trackid=9c511ffe89ca69d435a39ba939dc8083
pool=false uname= is_local_superuser=true auth_user_sid=
parent=trackid=9834f5af41c964e225f24279aefe4e49
[20120523T14:00:23.507Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:a249a76eac61|xapi] Attempting to open /var/lib/xcp/xapi
[20120523T14:00:23.507Z|debug|lab-xh3|80 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:session.get_uuid
D:523810ee01c2 created by task D:a249a76eac61
[20120523T14:00:23.588Z|debug|lab-xh3|81 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_other_config
D:0cd4c9163a9a created by task D:da62a5425fb6
[20120523T14:00:23.590Z|debug|lab-xh3|81 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.600Z|debug|lab-xh3|82 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:f9680d9069ea
created by task D:da62a5425fb6
[20120523T14:00:23.602Z|debug|lab-xh3|82 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.603Z|debug|lab-xh3|83 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:host.get_by_uuid
D:1366191ebd80 created by task D:da62a5425fb6
[20120523T14:00:23.605Z|debug|lab-xh3|83 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.606Z|debug|lab-xh3|84 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config
D:990bce9ac71c created by task D:da62a5425fb6
[20120523T14:00:23.607Z|debug|lab-xh3|84 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.608Z|debug|lab-xh3|85 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.add_to_sm_config
D:ca8a41754135 created by task D:da62a5425fb6
[20120523T14:00:23.609Z| info|lab-xh3|85 UNIX
/var/lib/xcp/xapi|dispatch:VDI.add_to_sm_config D:ca8a41754135|api_effect]
VDI.add_to_sm_config
[20120523T14:00:23.611Z|debug|lab-xh3|85 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.611Z|debug|lab-xh3|86 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_sm_config
D:5743d23d52ab created by task D:da62a5425fb6
[20120523T14:00:23.613Z|debug|lab-xh3|86 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.614Z|debug|lab-xh3|87 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_by_uuid D:fbd52f47c790
created by task D:da62a5425fb6
[20120523T14:00:23.616Z|debug|lab-xh3|87 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.617Z|debug|lab-xh3|88 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VDI.get_SR D:4e937c4a1379
created by task D:da62a5425fb6
[20120523T14:00:23.618Z|debug|lab-xh3|88 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.619Z|debug|lab-xh3|89 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_uuid D:9aaaa895c167
created by task D:da62a5425fb6
[20120523T14:00:23.621Z|debug|lab-xh3|89 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.622Z|debug|lab-xh3|90 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_by_uuid D:4d9c1be2ddba
created by task D:da62a5425fb6
[20120523T14:00:23.624Z|debug|lab-xh3|90 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.624Z|debug|lab-xh3|91 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:SR.get_type D:259559b7ae22
created by task D:da62a5425fb6
[20120523T14:00:23.626Z|debug|lab-xh3|91 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.627Z|debug|lab-xh3|92 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_all_records_where
D:e8b7d1fd933a created by task D:da62a5425fb6
[20120523T14:00:23.629Z|debug|lab-xh3|92 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.630Z|debug|lab-xh3|93 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:SM.get_driver_filename
D:9aace8dccffa created by task D:da62a5425fb6
[20120523T14:00:23.632Z|debug|lab-xh3|93 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.633Z|debug|lab-xh3|94 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:VM.get_all_records_where
D:49f473b24d94 created by task D:da62a5425fb6
[20120523T14:00:23.638Z|debug|lab-xh3|94 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.639Z|debug|lab-xh3|95 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_all_records_where
D:ab689a18ab34 created by task D:da62a5425fb6
[20120523T14:00:23.641Z|debug|lab-xh3|95 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.641Z|debug|lab-xh3|96 UNIX
/var/lib/xcp/xapi||dummytaskhelper] task dispatch:PBD.get_device_config
D:98ed30da69f4 created by task D:da62a5425fb6
[20120523T14:00:23.643Z|debug|lab-xh3|96 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.646Z|debug|lab-xh3|97 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.655Z| info|lab-xh3|98 UNIX
/var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data
D:774a27e7f6a2|api_effect] VDI.remove_from_xenstore_data
[20120523T14:00:23.657Z|debug|lab-xh3|98 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.658Z| info|lab-xh3|99 UNIX
/var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data
D:dfa79cc6aa39|api_effect] VDI.remove_from_xenstore_data
[20120523T14:00:23.660Z|debug|lab-xh3|99 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.661Z| info|lab-xh3|100 UNIX
/var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data
D:55ec2bb8c12a|api_effect] VDI.remove_from_xenstore_data
[20120523T14:00:23.663Z|debug|lab-xh3|100 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.665Z| info|lab-xh3|101 UNIX
/var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data
D:0e6ab4d0e278|api_effect] VDI.remove_from_xenstore_data
[20120523T14:00:23.666Z|debug|lab-xh3|101 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.668Z| info|lab-xh3|102 UNIX
/var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:f3712db91596|api_effect]
VDI.add_to_xenstore_data
[20120523T14:00:23.669Z|debug|lab-xh3|102 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.671Z| info|lab-xh3|103 UNIX
/var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:405254ef3d29|api_effect]
VDI.add_to_xenstore_data
[20120523T14:00:23.672Z|debug|lab-xh3|103 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.674Z| info|lab-xh3|104 UNIX
/var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:9ccdf51d9119|api_effect]
VDI.add_to_xenstore_data
[20120523T14:00:23.676Z|debug|lab-xh3|104 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.677Z| info|lab-xh3|105 UNIX
/var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data
D:a0d04baf4d20|api_effect] VDI.remove_from_xenstore_data
[20120523T14:00:23.679Z|debug|lab-xh3|105 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.681Z| info|lab-xh3|106 UNIX
/var/lib/xcp/xapi|dispatch:VDI.remove_from_xenstore_data
D:809ea44d0919|api_effect] VDI.remove_from_xenstore_data
[20120523T14:00:23.682Z|debug|lab-xh3|106 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.684Z| info|lab-xh3|107 UNIX
/var/lib/xcp/xapi|dispatch:VDI.add_to_xenstore_data D:47e8d83e8ecc|api_effect]
VDI.add_to_xenstore_data
[20120523T14:00:23.685Z|debug|lab-xh3|107 UNIX /var/lib/xcp/xapi||http_critical]
Premature termination of connection!
[20120523T14:00:23.742Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|sm_exec
D:a249a76eac61|xapi] Session.destroy trackid=9c511ffe89ca69d435a39ba939dc8083
[20120523T14:00:23.743Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|storage_impl] task:OpaqueRef:4b5db3df-62d8-3ec4-37c5-b813328ea279
dp:vbd/2/0 sr:319f3eaa-d1ba-a81d-acb3-493ecbdaab17
vdi:8cc62479-e620-4561-a057-2eff0e0b8f8d superstate:activated RW
[20120523T14:00:23.744Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xenops] Device.Vbd.add (device_number=Xen(0, 0) |
params=/dev/sm/backend/319f3eaa-d1ba-a81d-acb3-493ecbdaab17/8cc62479-e620-4561-a057-2eff0e0b8f8d
| phystype=vhd)
[20120523T14:00:23.744Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xenops] adding device B0[/local/domain/0/backend/vbd/2/51712]
F2[/local/domain/2/device/vbd/51712] H[/xapi/2/hotplug/vbd/51712]
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|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
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Converting xenops exception (INTERNAL_ERROR: [
Device_common.Device_backend_vanished(_) ]) into nice API internal error
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at string.ml:150.25-34 -> stringext.ml:108.13-29
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at xapi_xenops_errors.ml:83.10-26 ->
pervasiveext.ml:22.2-9
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at pervasiveext.ml:26.22-25 ->
xapi_vbd.ml:46.3-80 -> pervasiveext.ml:22.2-9
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at pervasiveext.ml:26.22-25 ->
pervasiveext.ml:22.2-9
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|locking_helpers] Released lock on VM
OpaqueRef:714e30c2-f627-1df7-db85-f543eccca324 with token 3
[20120523T14:00:23.745Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at pervasiveext.ml:26.22-25 ->
message_forwarding.ml:233.25-44 -> pervasiveext.ml:22.2-9
[20120523T14:00:23.747Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|backtrace] Raised at pervasiveext.ml:26.22-25 ->
message_forwarding.ml:3238.3-194 -> rbac.ml:229.16-23
[20120523T14:00:23.747Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|backtrace] Raised at rbac.ml:238.10-15 ->
server_helpers.ml:79.11-41
[20120523T14:00:23.747Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|dispatcher] Server_helpers.exec exception_handler: Got exception
INTERNAL_ERROR: [ the device disappeared from xenstore (frontend (domid=2 |
kind=vbd | devid=51712); backend (domid=0 | kind=vbd | devid=51712)) ]
[20120523T14:00:23.747Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|dispatcher] Raised at string.ml:150.25-34 ->
stringext.ml:108.13-29
[20120523T14:00:23.747Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|backtrace] Raised at string.ml:150.25-34 ->
stringext.ml:108.13-29
[20120523T14:00:23.750Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at server_helpers.ml:94.14-15 ->
pervasiveext.ml:22.2-9
[20120523T14:00:23.751Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi|VBD.plug
R:4b5db3df62d8|xapi] Raised at pervasiveext.ml:26.22-25 ->
pervasiveext.ml:22.2-9
[20120523T14:00:23.751Z|debug|lab-xh3|74 UNIX
/var/lib/xcp/xapi|dispatch:VBD.plug D:e3c3ca998d32|xapi] Raised at
pervasiveext.ml:26.22-25 -> pervasiveext.ml:22.2-9
[20120523T14:00:23.751Z|debug|lab-xh3|74 UNIX
/var/lib/xcp/xapi|dispatch:VBD.plug D:e3c3ca998d32|backtrace] Raised at
pervasiveext.ml:26.22-25 -> server_helpers.ml:153.10-106 ->
server.ml:26859.19-167 -> server_helpers.ml:119.4-7
[20120523T14:00:23.751Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi||xapi] Raised at
client.ml:6.37-75 -> client.ml:9878.12-61 -> xapi_cli.ml:112.18-56 ->
pervasiveext.ml:22.2-9
[20120523T14:00:23.753Z| info|lab-xh3|74 UNIX /var/lib/xcp/xapi|session.logout
D:4eb585f43123|xapi] Session.destroy trackid=094bbc269cc3c3ff4fe8b0faadef2ef1
[20120523T14:00:23.754Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi||backtrace]
Raised at pervasiveext.ml:26.22-25 -> xapi_cli.ml:111.2-138 ->
xapi_cli.ml:205.7-44 -> xapi_cli.ml:257.4-23
[20120523T14:00:23.754Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi||cli]
Xapi_cli.exception_handler: Got exception INTERNAL_ERROR: [ the device
disappeared from xenstore (frontend (domid=2 | kind=vbd | devid=51712); backend
(domid=0 | kind=vbd | devid=51712)) ]
[20120523T14:00:23.754Z|debug|lab-xh3|74 UNIX /var/lib/xcp/xapi||cli] Raised at
string.ml:150.25-34 -> stringext.ml:108.13-29
[20120523T14:01:02.079Z|debug|lab-xh3|19|Starting periodic scheduler
D:3f704699c722|backgroundscheduler] Adding function Logrotate to queue,
start=300.000000, type=Periodic(300.000000)
[20120523T14:01:02.079Z|debug|lab-xh3|19|Starting periodic scheduler
D:3f704699c722|backgroundscheduler] Sleeping until next event (119.911749
seconds)
syslog:
May 23 18:00:23 lab-xh3 xapi: [20120523T14:00:23.672Z| info|lab-xh3|103 UNIX
/var/lib/xcp/xapi|VDI.add_to_xenstore_data D:be30c8e0e2cc|audit]
('trackid=9c511ffe89ca69d435a39ba939dc8083' 'LOCAL_SUPERUSER'
'' 'ALLOWED' 'OK' 'API'
'VDI.add_to_xenstore_data' (('self' 'test'
'8cc62479-e620-4561-a057-2eff0e0b8f8d'
'OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e')))
May 23 18:00:23 lab-xh3 xapi: [20120523T14:00:23.675Z| info|lab-xh3|104 UNIX
/var/lib/xcp/xapi|VDI.add_to_xenstore_data D:fb48cb1c478e|audit]
('trackid=9c511ffe89ca69d435a39ba939dc8083' 'LOCAL_SUPERUSER'
'' 'ALLOWED' 'OK' 'API'
'VDI.add_to_xenstore_data' (('self' 'test'
'8cc62479-e620-4561-a057-2eff0e0b8f8d'
'OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e')))
May 23 18:00:23 lab-xh3 xapi: [20120523T14:00:23.679Z| info|lab-xh3|105 UNIX
/var/lib/xcp/xapi|VDI.remove_from_xenstore_data D:d41cb4970a71|audit]
('trackid=9c511ffe89ca69d435a39ba939dc8083' 'LOCAL_SUPERUSER'
'' 'ALLOWED' 'OK' 'API'
'VDI.remove_from_xenstore_data' (('self' 'test'
'8cc62479-e620-4561-a057-2eff0e0b8f8d'
'OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e')))
May 23 18:00:23 lab-xh3 xapi: [20120523T14:00:23.682Z| info|lab-xh3|106 UNIX
/var/lib/xcp/xapi|VDI.remove_from_xenstore_data D:d6afa4349dcc|audit]
('trackid=9c511ffe89ca69d435a39ba939dc8083' 'LOCAL_SUPERUSER'
'' 'ALLOWED' 'OK' 'API'
'VDI.remove_from_xenstore_data' (('self' 'test'
'8cc62479-e620-4561-a057-2eff0e0b8f8d'
'OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e')))
May 23 18:00:23 lab-xh3 xapi: [20120523T14:00:23.685Z| info|lab-xh3|107 UNIX
/var/lib/xcp/xapi|VDI.add_to_xenstore_data D:f03a5d19ee42|audit]
('trackid=9c511ffe89ca69d435a39ba939dc8083' 'LOCAL_SUPERUSER'
'' 'ALLOWED' 'OK' 'API'
'VDI.add_to_xenstore_data' (('self' 'test'
'8cc62479-e620-4561-a057-2eff0e0b8f8d'
'OpaqueRef:cd5aca3f-0e25-b85f-9ba7-866bf783575e')))
May 23 18:00:23 lab-xh3 tapdisk[4245]: tapdisk-control: init, 10 x 4k buffers
May 23 18:00:23 lab-xh3 tapdisk[4245]: I/O queue driver: lio
May 23 18:00:23 lab-xh3 tapdisk[4245]: tapdisk-log: started, level 0
May 23 18:00:23 lab-xh3 tapdisk[4245]: received 'attach' message (uuid =
0)
May 23 18:00:23 lab-xh3 tapdisk[4245]: sending 'attach response' message
(uuid = 0)
May 23 18:00:23 lab-xh3 tapdisk[4245]: received 'open' message (uuid =
0)
May 23 18:00:23 lab-xh3 tapdisk[4245]:
/mnt/8cc62479-e620-4561-a057-2eff0e0b8f8d.vhd version: tap 0x00010003, b: 1024,
a: 0, f: 0, n: 13
May 23 18:00:23 lab-xh3 tapdisk[4245]: opened image
/mnt/8cc62479-e620-4561-a057-2eff0e0b8f8d.vhd (1 users, state: 0x00000001, type:
4, rw)
May 23 18:00:23 lab-xh3 tapdisk[4245]: VBD CHAIN:
May 23 18:00:23 lab-xh3 tapdisk[4245]:
/mnt/8cc62479-e620-4561-a057-2eff0e0b8f8d.vhd: type:vhd(4) storage:ext(2)
May 23 18:00:23 lab-xh3 tapdisk[4245]: bdev: capacity=4194304
sector_size=512/512 flags=0
May 23 18:00:23 lab-xh3 tapdisk[4245]: sending 'open response' message
(uuid = 0)
May 23 18:00:23 lab-xh3 kernel: [ 545.326774] block tda: sector-size: 512/512+0
capacity: 4194304 discard: 0+0 flush: 0x0
May 23 18:00:23 lab-xh3 xapi: [20120523T14:00:23.747Z| info|lab-xh3|74 UNIX
/var/lib/xcp/xapi|VBD.plug R:4b5db3df62d8|audit]
('trackid=094bbc269cc3c3ff4fe8b0faadef2ef1' 'LOCAL_SUPERUSER'
'root' 'ALLOWED' 'ERROR:INTERNAL_ERROR: [ the device
disappeared from xenstore (frontend (domid=2 | kind=vbd | devid=51712); backend
(domid=0 | kind=vbd | devid=51712)) ]' 'API' 'VBD.plug'
(('self' '' '716880c9-d6cb-44a8-e5cd-6a68f708c1f9'
'OpaqueRef:14ac0618-0dd5-d41b-212d-a250221c1e80')))
-- System Information:
Debian Release: wheezy/sid
APT prefers unstable
APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)
Kernel: Linux 3.2.0-2-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Versions of packages xcp-xapi depends on:
ii hwdata 0.233-1
ii libc6 2.13-32
ii libpam0g 1.1.3-7.1
ii libuuid1 2.20.1-5
ii libvhd0 2.0.90-1
ii libxen-4.1 4.1.2-7
ii libxenstore3.0 4.1.2-7
ii lsb-base 4.1+Debian4
ii pciutils 1:3.1.9-3
ii python 2.7.2-10
ii python-xenapi 1.3.2-6
ii stunnel4 [stunnel] 3:4.52-1
ii xcp-eliloader 0.1-4
ii xcp-fe 0.5.2-3+b1
ii xcp-networkd 1.3.2-6
ii xcp-squeezed 1.3.2-6
ii xcp-storage-managers 0.1.1-2
ii xcp-v6d 1.3.2-6
ii xcp-xe 1.3.2-6
ii xen-hypervisor-4.1-amd64 [xen-hypervisor-4.1] 4.1.2-7
ii xen-utils-4.1 4.1.2-7
ii zlib1g 1:1.2.7.dfsg-11
Versions of packages xcp-xapi recommends:
ii cifs-utils 2:5.4-2
ii xcp-guest-templates 0.1-3
ii xcp-vncterm 0.1-2
xcp-xapi suggests no packages.
-- no debconf information
Mike McClurg
2012-May-23 15:28 UTC
[Pkg-xen-devel] Bug#674161: Bug#674161: xcp-xapi: 'the device disappeared from xenstore' message during vbd-plug (vm-start)
Hi George, thanks for testing XCP on Debian! On Wed, May 23, 2012 at 3:07 PM, George Shuklin <george.shuklin at gmail.com> wrote:> Package: xcp-xapi > Version: 1.3.2-6 > Severity: normal > Tags: upstream > > vbd plug to PV domain cause following error: > > The server failed to handle your request, due to an internal error. ?The given message may give details useful for debugging the problem. > message: the device disappeared from xenstore (frontend (domid=4 | kind=vbd | devid=51760); backend (domid=0 | kind=vbd | devid=51760))<snip>> # xe sr-create type=file name-label=fileSR device-config:location=/mnt > 319f3eaa-d1ba-a81d-acb3-493ecbdaab17Here's the problem. The SR type "file" doesn't work the way you'd want it to. It's actually the base class for the ext and NFS backends, and isn't meant to be accessed directly. This class doesn't actually have the create methods required to actually create the appropriate directories necessary for a file-based SR. Could you please try to reproduce this bug with a different backend? NFS would probably be easiest. If the VBD plug happens on a different SR type, then I'll consider this a bug. Mike PS: As an aside, it should be possible to manually create an SR of this type yourself (or so the storage team leads me to believe). If you create a fresh uuid using uuidgen, you can then create a directory called /var/run/sm/<new uuid>, and then call 'xe sr-introduce type=file uuid=<new uuid> name-label=name'. I haven't tried this yet, but I'm about to.
George Shuklin
2012-May-23 15:40 UTC
[Pkg-xen-devel] Bug#674161: Acknowledgement (xcp-xapi: 'the device disappeared from xenstore' message during vbd-plug (vm-start))
Found same problem with vif: xe vif-plug uuid=08e34a92-a973-e61d-1d41-2165a3d51073 The server failed to handle your request, due to an internal error. The given message may give details useful for debugging the problem. message: the device disappeared from xenstore (frontend (domid=5 | kind=vif | devid=0); backend (domid=0 | kind=vif | devid=0))
George Shuklin
2012-May-23 18:10 UTC
[Pkg-xen-devel] Bug#674161: [Xen-API] Bug#674161: xcp-xapi: 'the device disappeared from xenstore' message during vbd-plug (vm-start)
Some more data: Done clean reinstall (now with i386 in dom0), got exactly same error. After some digging around got this (new uuids, same problem): Key logs entries: [20120523T17:50:08.602Z|debug|lab-xh3|249 UNIX /var/lib/xcp/xapi|VM.start R:1c6c2941c565|xenops] Device.Vbd.add (device_number=Xen(0, 0) | params=/dev/sm/backend/357e7a73-ec60-6ae6-fe0d-56ca87d228b2/741cb833-b2c3-4bf7-b724-1295e984f097 | phystype=vhd) [20120523T17:50:08.602Z|debug|lab-xh3|249 UNIX /var/lib/xcp/xapi|VM.start R:1c6c2941c565|xenops] adding device B0[/local/domain/0/backend/vbd/4/51712] F4[/local/domain/4/device/vbd/51712] H[/xapi/4/hotplug/vbd/51712] [20120523T17:50:08.603Z|debug|lab-xh3|249 UNIX /var/lib/xcp/xapi|VM.start R:1c6c2941c565|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 [20120523T17:50:08.603Z|debug|lab-xh3|249 UNIX /var/lib/xcp/xapi|VM.start R:1c6c2941c565|xapi] Converting xenops exception (INTERNAL_ERROR: [ Device_common.Device_backend_vanished(_) ]) into nice API internal error I've checked - when I plug vbd to dom0 it works fine, but I can't do it with other domains.
Debian Bug Tracking System
2012-Jul-05 21:06 UTC
[Pkg-xen-devel] Bug#674161: marked as done (lack of /local/domain/0/vm in xenstore prevents vbd/vif plug)
Your message dated Thu, 05 Jul 2012 21:03:21 +0000 with message-id <E1SmtCr-00064W-Pt at franck.debian.org> and subject line Bug#674161: fixed in xen-api 1.3.2-8 has caused the Debian Bug report #674161, regarding lack of /local/domain/0/vm in xenstore prevents vbd/vif plug to be marked as done. This means that you claim that the problem has been dealt with. If this is not the case it is now your responsibility to reopen the Bug report if necessary, and/or fix the problem forthwith. (NB: If you are a system administrator and have no idea what this message is talking about, this may indicate a serious mail system misconfiguration somewhere. Please contact owner at bugs.debian.org immediately.) -- 674161: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=674161 Debian Bug Tracking System Contact owner at bugs.debian.org with problems -------------- next part -------------- An embedded message was scrubbed... From: George Shuklin <george.shuklin at gmail.com> Subject: xcp-xapi: 'the device disappeared from xenstore' message during vbd-plug (vm-start) Date: Wed, 23 May 2012 18:07:48 +0400 Size: 27671 URL: <http://lists.alioth.debian.org/pipermail/pkg-xen-devel/attachments/20120705/fa02f634/attachment-0002.mht> -------------- next part -------------- An embedded message was scrubbed... From: Thomas Goirand <zigo at debian.org> Subject: Bug#674161: fixed in xen-api 1.3.2-8 Date: Thu, 05 Jul 2012 21:03:21 +0000 Size: 7329 URL: <http://lists.alioth.debian.org/pipermail/pkg-xen-devel/attachments/20120705/fa02f634/attachment-0003.mht>
Possibly Parallel Threads
- Bug#674088: xcp-xapi: vbd-plug to dom0 does not creates /dev/xvd* devices in dom0
- Bug#682979: sample logfile
- xe vdi-create failure ot local SR type=file and type=ext
- Re: [Xen-API] xe vdi-create failure ot local SR type=file and type=ext
- Re: [Xen-API] (solved) xe vdi-create failure ot local SR type=file and type=ext