Subject: end_request: I/O error, dev sda1, sector 1236704
To: None <port-xen@netbsd.org>
From: pierre-philipp braun <pbraun@nethence.com>
List: port-xen
Date: 06/18/2007 14:02:11
Hi,

I'm having a filesystem issue in Linux DomUs, on several NetBSD/Dom0 
boxes (so it's not related to underlying hardware failures).  It used to 
happen with 3.0.1-4, and it still happens with 3.1, preventing me from 
using Linux domUs on NetBSD dom0.

very much lines like this, a bit while booting, and very much while 
using the system (e.g. doing du -sh),
end_request: I/O error, dev sda1, sector 1236704

This is what happens in the logs,

Jun 18 15:51:54 node2 /netbsd: xbd backend: attach device vnd0d (size 
2099200) for domain 10
Jun 18 15:51:54 node2 /netbsd: xvif10.0: Ethernet address 00:16:3e:56:40:41
Jun 18 15:51:54 node2 /netbsd: xbdback backend/vbd/10/2050: can't ioctl 
device 0xe0b: 6
Jun 18 15:51:55 node2 /netbsd: xbd backend: attach device vnd1d (size 
143360) for domain 10
Jun 18 15:51:55 node2 xenbackendd[504]: Failed to read 
/local/domain/0/backend/console/10/0/script (No such file or directory)
Jun 18 15:51:59 node2 /netbsd: xbd backend 0x801 for domain 10 using 
event channel 48
Jun 18 15:51:59 node2 /netbsd: xbd backend 0x802 for domain 10 using 
event channel 49
Jun 18 15:51:59 node2 /netbsd: xbd backend 0x803 for domain 10 using 
event channel 50
Jun 18 15:53:01 node2 /netbsd: xbd IO domain 10: error 5


And here's /var/log/xen/xend.log,

[2007-06-18 15:51:53 410] DEBUG (XendDomainInfo:78) 
XendDomainInfo.create(['vm', ['name', 'fedora'], ['memory', 256], [
'vcpus', 1], ['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], 
['image', ['linux', ['kernel', '/xendoms/fedora/v
mlinuz'], ['root', '/dev/sda1 ro'], ['args', 'init=/bin/sh']]], 
['device', ['vbd', ['uname', 'file:/xendoms/fedora/fedo
ra.fc6.img'], ['dev', 'sda1'], ['mode', 'w']]], ['device', ['vbd', 
['uname', 'file:/xen/fedora/fedora.swap'], ['dev', '
sda2'], ['mode', 'w']]], ['device', ['vbd', ['uname', 
'file:/xendoms/fedora/modules.ext2'], ['dev', 'sda3'], ['mode', '
w']]], ['device', ['vif', ['bridge', 'bridge0']]]])
[2007-06-18 15:51:53 410] DEBUG (XendDomainInfo:1414) 
XendDomainInfo.constructDomain
[2007-06-18 15:51:53 410] DEBUG (balloon:113) Balloon: 307936 KiB free; 
need 2048; done.
[2007-06-18 15:51:53 410] DEBUG (XendDomain:434) Adding Domain: 10
[2007-06-18 15:51:53 410] DEBUG (XendDomainInfo:1468) 
XendDomainInfo.initDomain: 10 256
[2007-06-18 15:51:53 410] DEBUG (XendDomainInfo:1500) 
_initDomain:shadow_memory=0x0, memory_static_max=0x10000000, memo
ry_static_min=0x0.
[2007-06-18 15:51:53 410] DEBUG (balloon:113) Balloon: 307936 KiB free; 
need 262144; done.
[2007-06-18 15:51:53 410] INFO (image:129) buildDomain os=linux dom=10 
vcpus=1
[2007-06-18 15:51:53 410] DEBUG (image:198) domid          = 10
[2007-06-18 15:51:53 410] DEBUG (image:199) memsize        = 256
[2007-06-18 15:51:53 410] DEBUG (image:200) image          = 
/xendoms/fedora/vmlinuz
[2007-06-18 15:51:53 410] DEBUG (image:201) store_evtchn   = 1
[2007-06-18 15:51:53 410] DEBUG (image:202) console_evtchn = 2
[2007-06-18 15:51:53 410] DEBUG (image:203) cmdline        = 
root=/dev/sda1 ro init=/bin/sh
[2007-06-18 15:51:53 410] DEBUG (image:204) ramdisk        =
[2007-06-18 15:51:53 410] DEBUG (image:205) vcpus          = 1
[2007-06-18 15:51:53 410] DEBUG (image:206) features       =
[2007-06-18 15:51:53 410] INFO (XendDomainInfo:1316) createDevice: vbd : 
{'uuid': 'ceb1e663-c1ca-530b-03de-6ee212290629
', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'sda1', 'uname': 
'file:/xendoms/fedora/fedora.fc6.img', 'mode': '
w'}
[2007-06-18 15:51:53 410] DEBUG (DevController:115) DevController: 
writing {'backend-id': '0', 'virtual-device': '2049'
, 'device-type': 'disk', 'state': '1', 'backend': 
'/local/domain/0/backend/vbd/10/2049'} to /local/domain/10/device/vbd
/2049.
[2007-06-18 15:51:53 410] DEBUG (DevController:117) DevController: 
writing {'domain': 'fedora', 'frontend': '/local/dom
ain/10/device/vbd/2049', 'uuid': 'ceb1e663-c1ca-530b-03de-6ee212290629', 
'dev': 'sda1', 'state': '1', 'params': '/xendo
ms/fedora/fedora.fc6.img', 'mode': 'w', 'online': '1', 'frontend-id': 
'10', 'type': 'file'} to /local/domain/0/backend/
vbd/10/2049.
[2007-06-18 15:51:53 410] INFO (XendDomainInfo:1316) createDevice: vbd : 
{'uuid': '9345d147-f79c-d01c-2490-62b1e62ff0cd
', 'bootable': 0, 'driver': 'paravirtualised', 'dev': 'sda2', 'uname': 
'file:/xen/fedora/fedora.swap', 'mode': 'w'}
[2007-06-18 15:51:53 410] DEBUG (DevController:115) DevController: 
writing {'backend-id': '0', 'virtual-device': '2050'
, 'device-type': 'disk', 'state': '1', 'backend': 
'/local/domain/0/backend/vbd/10/2050'} to /local/domain/10/device/vbd
/2050.
[2007-06-18 15:51:53 410] DEBUG (DevController:117) DevController: 
writing {'domain': 'fedora', 'frontend': '/local/dom
ain/10/device/vbd/2050', 'uuid': '9345d147-f79c-d01c-2490-62b1e62ff0cd', 
'dev': 'sda2', 'state': '1', 'params': '/xen/f
edora/fedora.swap', 'mode': 'w', 'online': '1', 'frontend-id': '10', 
'type': 'file'} to /local/domain/0/backend/vbd/10/
2050.
[2007-06-18 15:51:54 410] INFO (XendDomainInfo:1316) createDevice: vbd : 
{'uuid': '2d4c8cf7-ba2e-5bd6-41ab-428c5b53a484
', 'bootable': 0, 'driver': 'paravirtualised', 'dev': 'sda3', 'uname': 
'file:/xendoms/fedora/modules.ext2', 'mode': 'w'
}
[2007-06-18 15:51:54 410] DEBUG (DevController:115) DevController: 
writing {'backend-id': '0', 'virtual-device': '2051'
, 'device-type': 'disk', 'state': '1', 'backend': 
'/local/domain/0/backend/vbd/10/2051'} to /local/domain/10/device/vbd
/2051.
[2007-06-18 15:51:54 410] DEBUG (DevController:117) DevController: 
writing {'domain': 'fedora', 'frontend': '/local/dom
ain/10/device/vbd/2051', 'uuid': '2d4c8cf7-ba2e-5bd6-41ab-428c5b53a484', 
'dev': 'sda3', 'state': '1', 'params': '/xendo
ms/fedora/modules.ext2', 'mode': 'w', 'online': '1', 'frontend-id': 
'10', 'type': 'file'} to /local/domain/0/backend/vb
d/10/2051.
[2007-06-18 15:51:54 410] INFO (XendDomainInfo:1316) createDevice: vif : 
{'bridge': 'bridge0', 'uuid': '548d7627-2896-5
f9f-3c2b-42056e9813c1'}
[2007-06-18 15:51:54 410] DEBUG (DevController:115) DevController: 
writing {'backend-id': '0', 'mac': '00:16:3e:55:40:4
1', 'handle': '0', 'state': '1', 'backend': 
'/local/domain/0/backend/vif/10/0'} to /local/domain/10/device/vif/0.
[2007-06-18 15:51:54 410] DEBUG (DevController:117) DevController: 
writing {'bridge': 'bridge0', 'domain': 'fedora', 'h
andle': '0', 'uuid': '548d7627-2896-5f9f-3c2b-42056e9813c1', 'script': 
'/usr/pkg/etc/xen/scripts/vif-bridge', 'state':
'1', 'frontend': '/local/domain/10/device/vif/0', 'mac': 
'00:16:3e:55:40:41', 'online': '1', 'frontend-id': '10', 'type
': 'netfront'} to /local/domain/0/backend/vif/10/0.
[2007-06-18 15:51:54 410] DEBUG (XendDomainInfo:1973) Storing VM 
details: {'on_xend_stop': 'ignore', 'shadow_memory': '
0', 'uuid': 'c4bd1970-069e-acb7-0be6-21411bcd5d53', 'on_reboot': 
'restart', 'start_time': '1182174714.57', 'on_poweroff
': 'destroy', 'on_xend_start': 'ignore', 'on_crash': 'restart', 
'xend/restart_count': '0', 'vcpus': '1', 'vcpu_avail':
'1', 'image': "(linux (kernel /xendoms/fedora/vmlinuz) (args 
'root=/dev/sda1 ro init=/bin/sh') (notes (HV_START_LOW 422
7858432) (FEATURES 
'writable_page_tables|writable_descriptor_tables|auto_translated_physmap|pae_pgdir_above_4gb|supervi
sor_mode_kernel') (VIRT_BASE 3221225472) (GUEST_VERSION 2.6) 
(PADDR_OFFSET 3221225472) (GUEST_OS linux) (HYPERCALL_PAGE
  3222278144) (LOADER generic) (SUSPEND_CANCEL 1) (PAE_MODE no) (ENTRY 
3222274048) (XEN_VERSION xen-3.0)))", 'name': 'fe
dora'}
[2007-06-18 15:51:54 410] DEBUG (XendDomainInfo:824) Storing domain 
details: {'console/ring-ref': '76869', 'image/entry
': '3222274048', 'console/port': '2', 'store/ring-ref': '76870', 
'image/loader': 'generic', 'vm': '/vm/c4bd1970-069e-ac
b7-0be6-21411bcd5d53', 
'control/platform-feature-multiprocessor-suspend': '1', 
'image/hv-start-low': '4227858432', 'ima
ge/guest-os': 'linux', 'image/features/writable-descriptor-tables': '1', 
'image/virt-base': '3221225472', 'memory/targe
t': '262144', 'image/guest-version': '2.6', 
'image/features/supervisor-mode-kernel': '1', 'image/pae-mode': 'no', 'cons
ole/limit': '1048576', 'image/paddr-offset': '3221225472', 
'image/hypercall-page': '3222278144', 'image/suspend-cancel'
: '1', 'cpu/0/availability': 'online', 
'image/features/pae-pgdir-above-4gb': '1', 
'image/features/writable-page-tables'
: '1', 'image/features/auto-translated-physmap': '1', 'name': 'fedora', 
'domid': '10', 'image/xen-version': 'xen-3.0',
'store/port': '1'}
[2007-06-18 15:51:54 410] DEBUG (DevController:115) DevController: 
writing {'state': '1', 'backend-id': '0', 'backend':
  '/local/domain/0/backend/console/10/0'} to 
/local/domain/10/device/console/0.
[2007-06-18 15:51:54 410] DEBUG (DevController:117) DevController: 
writing {'domain': 'fedora', 'protocol': 'vt100', 'u
uid': '8ff1743a-af62-9704-b510-4020159f61b5', 'frontend': 
'/local/domain/10/device/console/0', 'state': '1', 'location'
: '2', 'online': '1', 'frontend-id': '10'} to 
/local/domain/0/backend/console/10/0.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices vif.
[2007-06-18 15:51:55 410] DEBUG (DevController:153) Waiting for 0.
[2007-06-18 15:51:55 410] DEBUG (XendDomainInfo:824) Storing domain 
details: {'console/ring-ref': '76869', 'image/entry
': '3222274048', 'console/port': '2', 'store/ring-ref': '76870', 
'image/loader': 'generic', 'vm': '/vm/c4bd1970-069e-ac
b7-0be6-21411bcd5d53', 
'control/platform-feature-multiprocessor-suspend': '1', 
'image/hv-start-low': '4227858432', 'ima
ge/guest-os': 'linux', 'image/features/writable-descriptor-tables': '1', 
'image/virt-base': '3221225472', 'memory/targe
t': '262144', 'image/guest-version': '2.6', 
'image/features/supervisor-mode-kernel': '1', 'image/pae-mode': 'no', 'cons
ole/limit': '1048576', 'image/paddr-offset': '3221225472', 
'image/hypercall-page': '3222278144', 'image/suspend-cancel'
: '1', 'cpu/0/availability': 'online', 
'image/features/pae-pgdir-above-4gb': '1', 
'image/features/writable-page-tables'
: '1', 'image/features/auto-translated-physmap': '1', 'name': 'fedora', 
'domid': '10', 'image/xen-version': 'xen-3.0',
'store/port': '1'}
[2007-06-18 15:51:55 410] DEBUG (XendDomainInfo:908) 
XendDomainInfo.handleShutdownWatch
[2007-06-18 15:51:55 410] DEBUG (DevController:539) 
hotplugStatusCallback /local/domain/0/backend/vif/10/0/hotplug-stat
us.
[2007-06-18 15:51:55 410] DEBUG (DevController:539) 
hotplugStatusCallback /local/domain/0/backend/vif/10/0/hotplug-stat
us.
[2007-06-18 15:51:55 410] DEBUG (DevController:553) hotplugStatusCallback 1.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices usb.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices vbd.
[2007-06-18 15:51:55 410] DEBUG (DevController:153) Waiting for 2049.
[2007-06-18 15:51:55 410] DEBUG (DevController:539) 
hotplugStatusCallback /local/domain/0/backend/vbd/10/2049/hotplug-s
tatus.
[2007-06-18 15:51:55 410] DEBUG (DevController:553) hotplugStatusCallback 1.
[2007-06-18 15:51:55 410] DEBUG (DevController:153) Waiting for 2050.
[2007-06-18 15:51:55 410] DEBUG (DevController:539) 
hotplugStatusCallback /local/domain/0/backend/vbd/10/2050/hotplug-s
tatus.
[2007-06-18 15:51:55 410] DEBUG (DevController:553) hotplugStatusCallback 1.
[2007-06-18 15:51:55 410] DEBUG (DevController:153) Waiting for 2051.
[2007-06-18 15:51:55 410] DEBUG (DevController:539) 
hotplugStatusCallback /local/domain/0/backend/vbd/10/2051/hotplug-s
tatus.
[2007-06-18 15:51:55 410] DEBUG (DevController:553) hotplugStatusCallback 1.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices irq.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices 
vkbd.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices vfb.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices 
console.
[2007-06-18 15:51:55 410] DEBUG (DevController:153) Waiting for 0.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices pci.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices 
ioports.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices tap.
[2007-06-18 15:51:55 410] DEBUG (DevController:148) Waiting for devices 
vtpm.
[2007-06-18 15:51:55 410] INFO (XendDomain:1108) Domain fedora (10) 
unpaused.


Thanks for your help
Pierre-Philipp