Deadlock in devman during boot

[Jiri Svoboda]

In one out of a couple of boots the system fails the boot, because a deadlock is detected in devman and the devman task dies.

Boot log:

qemu-system-x86_64 -enable-kvm -drive file=hdisk.img,index=0,media=disk,format=raw -device e1000,netdev=n1 -netdev user,id=n1,hostfwd=udp::8080-:8080,hostfwd=udp::8081-:8081,hostfwd=tcp::8080-:8080,hostfwd=tcp::8081-:8081,hostfwd=tcp::2223-:2223 -usb -device nec-usb-xhci,id=xhci -device usb-tablet -device intel-hda -device hda-duplex -serial stdio -boot d -cdrom image.iso
Program loader at 0xffff80000041d000
RAM disk at 0x0000000000323000 (size 37748736 bytes)
Kernel console ready (press any key to activate)
[init:ns(2)] ns: HelenOS IPC Naming Service
[init:ns(2)] ns: Accepting connections
[init:init(3)] init: HelenOS init
[init:locsrv(4)] loc: HelenOS Location Service
[init:rd(5)] rd: HelenOS RAM disk server
[init:rd(5)] rd: Found RAM disk at 0x0000000000323000, 37748736 bytes
[init:vfs(6)] vfs: HelenOS VFS server
[init:logger(7)] logger: HelenOS Logging Service
[init:ext4fs(8)] ext4fs: HelenOS ext4 file system server
[init:logger(7)] logger: Accepting connections
[init:locsrv(4)] loc: Accepting connections
[init:vfs(6)] vfs: Accepting connections
[init:rd(5)] rd: Accepting connections
[init:ext4fs(8)] ext4fs: Accepting connections
[init:init(3)] init: Root file system mounted on / (ext4fs at bd/initrd)
[init:init(3)] init: Starting /srv/system
[/srv/system(9)] system: HelenOS system server
[/srv/system(9)] system: Starting /srv/fs/tmpfs
[/srv/fs/tmpfs(10)] tmpfs: HelenOS TMPFS file system server
[/srv/fs/tmpfs(10)] tmpfs: Accepting connections
[/srv/system(9)] system: Starting /srv/fs/exfat
[/srv/fs/exfat(11)] exfat: HelenOS exFAT file system server
[/srv/fs/exfat(11)] exfat: Accepting connections
[/srv/system(9)] system: Starting /srv/fs/fat
[/srv/fs/fat(12)] fat: HelenOS FAT file system server
[/srv/fs/fat(12)] fat: Accepting connections
[/srv/system(9)] system: Starting /srv/fs/cdfs
[/srv/fs/cdfs(13)] cdfs: HelenOS cdfs file system server
[/srv/fs/cdfs(13)] cdfs: Accepting connections
[/srv/system(9)] system: Starting /srv/fs/mfs
[/srv/fs/mfs(14)] mfs: HelenOS Minix file system server
[/srv/fs/mfs(14)] mfs: Accepting connections
[/srv/system(9)] system: Starting /srv/klog
[kernel/arch] warn: MADT: Skipping L_APIC_NMI entry (type=4)
[/srv/system(9)] system: Starting /srv/fs/locfs
[kernel/arch] note: 0xffffffff800f5b80: MPS Floating Pointer Structure
[kernel/other] note: Program loader at 0xffff80000041d000
[kernel/other] note: RAM disk at 0x0000000000323000 (size 37748736 bytes)
[/srv/fs/locfs(16)] locfs: HelenOS Device Filesystem
[/srv/fs/locfs(16)] locfs: Accepting connections
[/srv/system(9)] system: Location service file system mounted on /loc (locfs)
[/srv/system(9)] system: Temporary file system mounted on /tmp (tmpfs)
[/srv/system(9)] system: Starting /srv/devman
[/srv/devman(17)] devman: HelenOS Device Manager
[/srv/devman(17)] devman: Accepting connections.
[devman] note: Wait for device tree to stabilize.
[/drv/root/root(18)] root: HelenOS root device driver
[devman] note: The `root' driver was successfully registered as running.
[/drv/pc/pc(20)] pc: HelenOS PC platform driver
[devman] note: The `pc' driver was successfully registered as running.
[/drv/virt/virt(19)] virt: HelenOS virtual devices root driver
[devman] note: The `virt' driver was successfully registered as running.
[virt] note: Registered child device `kfb'
[/drv/pciintel/pciintel(21)] pciintel: HelenOS PCI bus driver (Intel method 1).
[devman] note: The `pciintel' driver was successfully registered as running.
[devman] error: No driver found for device `/hw/sys/00:00.0'.
[/drv/kfb/kfb(22)] kfb: HelenOS kernel framebuffer driver
[devman] note: The `kfb' driver was successfully registered as running.
[pciintel] note: Function 00:01.2 uses irq b.
[devman] note: Function `/virt/kfb/kfb' added to category `display-device'.
[/drv/kfb/kfb(22)] kfb: Accepting connections
[pciintel] note: Function 00:01.3 uses irq 9.
[devman] error: No driver found for device `/hw/sys/00:01.3'.
[devman] error: No driver found for device `/hw/sys/00:02.0'.
[pciintel] note: Function 00:03.0 uses irq b.
[pciintel] note: Function 00:04.0 uses irq b.
[pciintel] note: Function 00:05.0 uses irq a.
[devman] note: Function `/hw/sys/ctl' added to category `pci'.
[/drv/uhci/uhci(25)] uhci: HelenOS UHCI driver.
[/drv/pci-ide/pci-ide(24)] pci-ide: HelenOS PCI IDE device driver
[devman] note: The `pci-ide' driver was successfully registered as running.
[devman] note: The `uhci' driver was successfully registered as running.
[pci-ide] note: sizes: 16
[devman] note: Function `/hw/sys/00:01.2/ctl' added to category `usbhc'.
[pci-ide] note: Bus master IDE regs I/O address: 0xc060
[pci-ide] note: I/O address 0x00000000000001f0/0x00000000000003f4
[pci-ide] note: QEMU HARDDISK: LBA-48 262144 blocks 128 MB.
[/drv/isa/isa(23)] isa: HelenOS ISA bus driver
[devman] note: The `isa' driver was successfully registered as running.
[/drv/e1k/e1k(26)] e1k: HelenOS E1000 network adapter driver
[devman] note: The `e1k' driver was successfully registered as running.
[isa] note: ISA Bridge
[devman] note: Function `/hw/sys/00:03.0/port0' added to category `nic'.
[isa] note: Added mem range (addr=0x20, size=0x2) to function i8259
[devman] note: The `xhci' driver was successfully registered as running.
[isa] note: Added mem range (addr=0xa0, size=0x2) to function i8259
[devman] note: Function `/hw/sys/00:03.0/port0' added to category `pcap'.
[/drv/hdaudio/hdaudio(28)] hdaudio: High Definition Audio driver
[isa] note: Added mem range (addr=0xfec00000, size=0x14) to function apic
[devman] note: The `hdaudio' driver was successfully registered as running.
[devman] note: Function `/hw/sys/00:04.0/ctl' added to category `usbhc'.
[isa] note: Added irq 0x4 to function com1
[isa] note: Added io range (addr=0x3f8, size=0x8) to function com1
[isa] note: Added irq 0x3 to function com2
[isa] note: Added io range (addr=0x2f8, size=0x8) to function com2
[isa] note: Added io range (addr=0x378, size=0x8) to function lpt1
[isa] note: Added irq 0x7 to function lpt1
[isa] note: Added io range (addr=0x278, size=0x8) to function lpt2
[isa] note: Added irq 0x5 to function lpt2
[isa] note: Added irq 0x1 to function i8042
[isa] note: Added irq 0xc to function i8042
[isa] note: Added io range (addr=0x60, size=0x5) to function i8042
[/drv/i8259/i8259(29)] i8259: i8259 Interrupt Controller driver
[isa] note: Added irq 0x5 to function ne2k
[devman] note: The `i8259' driver was successfully registered as running.
[isa] note: Added io range (addr=0x300, size=0x20) to function ne2k
[isa] note: Added io range (addr=0x220, size=0x20) to function sb16
[devman] note: Function `/hw/sys/00:01.0/i8259/a' added to category `irc'.
[isa] note: Added io range (addr=0x330, size=0x2) to function sb16
[isa] note: Added irq 0x5 to function sb16
[isa] note: Added dma 0x1 to function sb16
[isa] note: Added dma 0x5 to function sb16
[isa] note: Added io range (addr=0x70, size=0x2) to function cmos-rtc
[/drv/ns8250/ns8250(31)] ns8250: HelenOS serial port driver
[isa] note: Added io range (addr=0x3f0, size=0x8) to function fdc
[devman] note: The `ns8250' driver was successfully registered as running.
[isa] note: Added irq 0x6 to function fdc
[ns8250] note: Device com1 was assigned irq = 0x4.
[isa] note: Added dma 0x2 to function fdc
[uhci] note: Controlling new `uhci' device `00:01.2'.
[isa] note: Added io range (addr=0x1f0, size=0x8) to function ide1
[isa] note: Added io range (addr=0x3f0, size=0x8) to function ide1
[isa] note: Added io range (addr=0x170, size=0x8) to function ide1
[ns8250] note: Device com1 was assigned I/O address = 0x0x3f8.
[isa] note: Added io range (addr=0x370, size=0x8) to function ide1
[isa] note: Added irq 0xe to function ide1
[isa] note: Added irq 0xf to function ide1
[isa] note: Finished enumerating legacy functions
[devman] note: Function `/hw/sys/00:01.0/com1/a' added to category `serial'.
[/drv/pc-lpt/pc-lpt(32)] pc-lpt: PC parallel port driver
[ns8250] note: Device com1 successfully initialized.
[devman] note: The `pc-lpt' driver was successfully registered as running.
[/drv/apic/apic(30)] apic: APIC driver
[ns8250] note: Device com2 was assigned irq = 0x3.
[devman] note: The `apic' driver was successfully registered as running.
[ns8250] note: Device com2 was assigned I/O address = 0x0x2f8.
[hdaudio] note: HDA version 1.0
[devman] error: No driver found for device `/hw/sys/00:01.0/com2'.
[devman] note: Function `/hw/sys/00:01.0/lpt1/a' added to category `printer-port'.
[xhci] note: Connected state changed on port 1.
[/drv/apic/apic(30)] apic: No APIC found
[xhci] note: Connected state changed on port 2.
[xhci] note: Connected state changed on port 3.
[xhci] note: Connected state changed on port 4.
[hdaudio] note: Output widget 2: rates=0x201fc formats=0x1
[xhci] note: Connected state changed on port 5.
[xhci] note: Connected state changed on port 6.
[xhci] note: Connected state changed on port 7.
[xhci] note: Connected state changed on port 8.
[xhci] note: Controlling new `xhci' device `00:04.0'.
[/drv/i8042/i8042(33)] i8042: HelenOS PS/2 driver.
[devman] note: The `i8042' driver was successfully registered as running.
[i8042] note: Controlling 'i8042' (48).
[/drv/ne2k/ne2k(34)] ne2k: HelenOS NE 2000 network adapter driver
[devman] note: The `ne2k' driver was successfully registered as running.
[devman] error: No driver found for device `/hw/sys/00:01.0/ne2k'.
[/drv/sb16/sb16(35)] sb16: HelenOS SB16 audio driver.
[/drv/cmos-rtc/cmos-rtc(36)] cmos-rtc: HelenOS RTC driver
[devman] note: The `sb16' driver was successfully registered as running.
[/drv/usbhub/usbhub(37)] usbhub: HelenOS USB hub driver.
[devman] note: The `cmos-rtc' driver was successfully registered as running.
[/drv/pc-floppy/pc-floppy(38)] pc-floppy: HelenOS PC floppy disk driver
[devman] note: The `usbhub' driver was successfully registered as running.
[sb16] note: PIO registers at 0x0000000000000220 accessible.
[devman] note: The `pc-floppy' driver was successfully registered as running.
[cmos-rtc] note: Device cmos-rtc was assigned I/O address 0x70
[sb16] error: Invalid DSP reset response: ff.
[pc-floppy] note: DMA channel 2
[usbhub] note: (0x000000000041ead0): Power switching not supported, ports always powered.
[/drv/isa-ide/isa-ide(39)] isa-ide: HelenOS ISA IDE device driver
[/drv/xtkbd/xtkbd(41)] xtkbd: HelenOS XT keyboard driver.
[sb16] error: Failed to initialize SB DSP: [EIO] Input/output error.
[devman] note: The `isa-ide' driver was successfully registered as running.
[sb16] error: Failed to init sb16 driver: [EIO] Input/output error.
[pc-floppy] note: I/O address 0x00000000000003f0
[devman] note: The `xtkbd' driver was successfully registered as running.
[pc-floppy] note: IRQ 6
[usbhub] note: Controlling full-speed hub 'roothub' (0x000000000041ead0: 2 ports).
[devman] note: Function `/hw/sys/00:01.0/cmos-rtc/a' added to category `clock'.
[cmos-rtc] note: Device cmos-rtc successfully initialized
[isa] note: isa_fun_query_legacy_io: ISA bridge - determine legacy IDE availability from PCI bus driver
[/srv/devman(17)] Deadlock detected.
[/srv/devman(17)] 0x0000000000a2cd20: 0x0000000070171943()
[/srv/devman(17)] 0x0000000000a2cd60: 0x000000007017742c()
[/srv/devman(17)] 0x0000000000a2cdd0: 0x0000000070177a62()
[/srv/devman(17)] 0x0000000000a2ce10: 0x0000000000405d3f()
[/srv/devman(17)] 0x0000000000a2cf30: 0x00000000004038e3()
[/srv/devman(17)] 0x0000000000a2cfe0: 0x0000000070163c10()
[/srv/devman(17)] 0x0000000000a2cff0: 0x0000000070176ed6()
[/srv/devman(17)] -- end of stack trace --
[/srv/devman(17)] Fibril 0x0000000000421030 waits for primitive 0x000000000040a810.
[/srv/devman(17)] Primitive 0x000000000040a810 is owned by fibril 0x0000000000421030.
[xtkbd] error: Failed adding function 'kbd' to category 'keyboard'.
[isa-ide] note: I/O address 0x00000000000001f0/0x00000000000003f0
[/drv/xtkbd/xtkbd(41)] Assertion failed (fun->bound == false) in task 41, file "../uspace/lib/drv/generic/driver.c", line 838.
[/drv/xtkbd/xtkbd(41)] 0x0000000000517e00: 0x00000000701718f3()
[/drv/xtkbd/xtkbd(41)] 0x0000000000517e30: 0x000000007016093b()
[/drv/xtkbd/xtkbd(41)] 0x0000000000517e40: 0x0000000000402c92()
[/drv/xtkbd/xtkbd(41)] 0x0000000000517e70: 0x0000000000401d66()
[isa-ide] note: IRQ 14
[pci-ide] note: : CHS 0 cylinders, 0 heads, 0 sectors 0 blocks(NULL)
[pci-ide] error: Failed binding DDF function c0d0: [ENOENT] No such entry
[pci-ide] error: Unable to add device 0.
Task /drv/pci-ide/pci-ide (24) killed due to an exception at program counter 0x00000000004030ac.
cs =0x0000000000000023	rip=0x00000000004030ac	rfl=0x0000000000010246	err=0x0000000000000004
ss =0x000000000000001b
rax=000000000000000000	rbx=0x000000000051e340	rcx=0x000000000051e030	rdx=0x0000000000002000
rsi=0x0000000070183607	rdi=0x0000000070193bd0	rbp=0x000000000051cca0	rsp=0x000000000051cc70
r8 =0x0000000000000040	r9 =000000000000000000	r10=0x0000000000415e40	r11=0x0000000000000216
r12=000000000000000000	r13=0x00000000004157c0	r14=0x000000000051e5c8	r15=000000000000000000
0x000000000051cca0: 0x00000000004030ac()
0x000000000051cce0: 0x00000000004055c5()
0x000000000051ce00: 0x0000000000402942()
0x000000000051cea0: 0x0000000000402dd3()
0x000000000051cf30: 0x0000000000406428()
0x000000000051cfe0: 0x0000000070163c10()
0x000000000051cff0: 0x0000000070176ed6()
Kill message: Page fault: 0000000000000000.
[hdaudio] error: Failed binding function 'pcm'.

[Jiri Svoboda]

Reproduced as of ​b769ca098d928f48269bb338ea242585b13783e8