Re: [Xen-users] Re: tap:qcow causes dom-U to hang in 3.0.3

[Roland Paterson-Jones <roland@rolandpj.com>]

Julian Chesterfield wrote:

>
> There's a bunch of DPRINTFs in the code which send debug output to 
> syslog. You can play with syslog settings to switch on the debug 
> messages and direct them to a log file.
>
Here is another clue from syslog. Below is the full log, but the hang 
seems to accur when the following log messages are triggered (there's a 
bunch of them at the end):

Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869040]

I'm a little frustrated with re-building the blktap user-space tools 
myself. When I do so, I get the following kernel messages:

Nov 13 13:44:08 dom0-0-50-45-5d-6a-bc kernel: blk_tap: invalid user 
buffer -- could not remap it
Nov 13 13:44:08 dom0-0-50-45-5d-6a-bc kernel: blk_tap: Reached Fail_flush
Nov 13 13:44:08 dom0-0-50-45-5d-6a-bc kernel: blk_tap: BLKTAP_INVALID_HANDLE

But I don't get these when I use the (PAE) binary distribution. I'm only 
rebuilding the blktap tools, not the rest, so perhaps my config is not 
right (incompatible with the PAE kernel somehow). If you know off-hand 
what the problem is then I can maybe chase down the offset issue more 
productively.

Regards
Roland

Full debug syslog of qcow creation and dom-U launch using tap:qcow root FS:

Nov 14 11:56:26 dom0-0-50-45-5d-6a-bc qcow-create: Qcow_create: size 
10737418240
Nov 14 11:56:26 dom0-0-50-45-5d-6a-bc qcow-create: Backing file size 
detected: 3123200 sectors(total 1599078400 [1525 MB])
Nov 14 11:56:26 dom0-0-50-45-5d-6a-bc qcow-create: L1 Table offset: 
4096, size 6104
Nov 14 11:56:26 dom0-0-50-45-5d-6a-bc qcow-create: Adjusted filelength 
to 12288 for 4 Kbyte alignment
Nov 14 11:56:26 dom0-0-50-45-5d-6a-bc qcow-create: QCOW file 
successfully created
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Received a poll for a 
new vbd
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: /dev/xen/blktap1 
device already exists
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Received device id 1 
and major 254, sent domid 3 and be_id 2049
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Detected handle: [qcow]
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Process does not exist:
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Launching process, 
CMDLINE [tapdisk /dev/xen/tapctrlwrite1 /dev/xen/tapctrlread1]
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Write_msg called: 
CTLMSG_PID
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc TAPDISK: Tapdisk: Received msg, 
len 8, type 9, UID 13691
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Received CTLMSG_PID_RSP
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL:       PID: [21862]
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Write_msg called: 
CTLMSG_PARAMS, sending [qcow:/mnt/instance_image_store_0/2.qcow, 
/mnt/instance_image_store_0/2.qcow]
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Generated cookie, 13691
Nov 14 11:56:27 dom0-0-50-45-5d-6a-bc TAPDISK: Tapdisk: Received msg, 
len 43, type 1, UID 13691
Nov 14 11:56:28 dom0-0-50-45-5d-6a-bc kernel: tap tap-3-2049: 2 getting info
Nov 14 11:56:28 dom0-0-50-45-5d-6a-bc TAPDISK: Received CTLMSG_PARAMS: 
[/mnt/instance_image_store_0/2.qcow]
Nov 14 11:56:28 dom0-0-50-45-5d-6a-bc TAPDISK: Loaded driver: name 
[tapdisk_qcow], type [4]
Nov 14 11:56:28 dom0-0-50-45-5d-6a-bc TAPDISK: QCOW: Opening 
/mnt/instance_image_store_0/2.qcow
Nov 14 11:56:29 dom0-0-50-45-5d-6a-bc TAPDISK: L1 Table offset detected: 
4096, size 6104 (8192)
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc TAPDISK: Reading backing file data
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc TAPDISK: AIO state initialised
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc TAPDISK: Adding fd_list_entry
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc TAPDISK: Entered cookie 13691
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Received CTLMSG_IMG: 
3123200, 512, 0
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Received a poll for a 
new devmap
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/block: 
add XENBUS_PATH=backend/vbd/3/2050
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/block: 
add XENBUS_PATH=backend/vbd/3/2051
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/blktap: 
add XENBUS_PATH=backend/tap/3/2049
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/vif-aes: 
online XENBUS_PATH=backend/vif/3/0
Nov 14 11:56:30 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Write_msg called: 
CTLMSG_NEWDEV
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/blktap: 
Writing backend/tap/3/2049/hotplug-status connected to xenstore.
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc TAPDISK: Tapdisk: Received msg, 
len 12, type 4, UID 13691
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc TAPDISK: Retrieving state, cookie 
13691.....[OK]
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Received CTLMSG_NEWDEV_RSP
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc BLKTAPCTRL: Exiting map_new_blktapctrl
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/block: 
Writing backend/vbd/3/2051/physical-device fd:4 to xenstore.
Nov 14 11:56:31 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/block: 
Writing backend/vbd/3/2051/hotplug-status connected to xenstore.
Nov 14 11:56:32 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/block: 
Writing backend/vbd/3/2050/physical-device fd:3 to xenstore.
Nov 14 11:56:32 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/block: 
Writing backend/vbd/3/2050/hotplug-status connected to xenstore.
Nov 14 11:56:32 dom0-0-50-45-5d-6a-bc kernel: ADDRCONF(NETDEV_UP): 
vifI93276.0: link is not ready
Nov 14 11:56:33 dom0-0-50-45-5d-6a-bc logger: /etc/xen/scripts/vif-aes: 
Writing backend/vif/3/0/hotplug-status connected to xenstore.
Nov 14 11:56:50 dom0-0-50-45-5d-6a-bc kernel: ADDRCONF(NETDEV_CHANGE): 
vifI93276.0: link becomes ready
Nov 14 11:57:01 dom0-0-50-45-5d-6a-bc kernel: vifI93276.0: no IPv6 
routers present
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869040]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869048]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869056]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869064]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869072]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869080]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869088]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869096]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869104]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869112]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869120]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869128]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869136]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869144]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869152]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869160]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869168]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869176]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869184]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869192]
Nov 14 11:59:47 dom0-0-50-45-5d-6a-bc TAPDISK: AIO_LOCK or 
iocb_free_count (0) failed[869200]