Race between usbhc_release_address() and usbhc_read/write()

[Jakub Jermář]

With the attached patch (some debugging changes to the uspace memory allocator, mainly needed for altered timing) mainline,2531 will reproducibly hit the assert in endpoint_destroy():

        assert(!instance->active);

Using a debugger, instance->active can be observed to be true (1) (i.e. not corrupted).

Steps to reproduce:

• check out mainline,2531
• apply the attached patch
• configure HelenOS to the default ia32 build with the following changes:
  • Disable "Dynamic linking support" (CONFIG_RTLD)
  • Enable "Support for NS16550 controller (kernel console)" (CONFIG_NS16550_KCON)
• download the batch script from #389
• start HelenOS:

$ ./batch | (qemu-system-x86_64 --enable-kvm -cdrom image.iso -usb -monitor stdio -serial file:serial.log -m 1024M)

• wait for HelenOS to fully start up, but make sure not to press enter at the (qemu) prompt yet
• in bdsh, set max log level for uhci:

/ # logset uhci 5

• switch to kconsole by pressing eg. Break
• now go to the QEMU monitor ((qemu) prompt) and press enter, the bug should reproduce shortly (uhci will crash), the console output should be captured in serial.log

This is a sample console output as captured by me:

Program loader at 0xc0400000
RAM disk at 0x002d1000 (size 29360128 bytes)
Kernel console ready (press any key to activate)
ns: HelenOS IPC Naming Service
ns: Accepting connections
init: HelenOS init
loc: HelenOS Location Service
rd: HelenOS RAM disk server
rd: Found RAM disk at 0x002d1000, 29360128 bytes
vfs: HelenOS VFS server
logger: HelenOS Logging Service
ext4fs: HelenOS ext4 file system server
loc: Accepting connections
vfs: Accepting connections
logger: Accepting connections
rd: Accepting connections
ext4fs: Accepting connections
init: Root filesystem mounted on / (ext4fs at bd/initrd)
init: Starting /srv/tmpfs
tmpfs: HelenOS TMPFS file system server
tmpfs: Accepting connections
init: Starting /srv/klog
[kernel/arch] warn: MADT: Skipping L_APIC_NMI entry (type=4)
init: Starting /srv/locfs
[kernel/arch] note: 0x800f6bd0: MPS Floating Pointer Structure
[kernel/other] note: Program loader at 0xc0400000
[kernel/other] note: RAM disk at 0x002d1000 (size 29360128 bytes)
locfs: HelenOS Device Filesystem
locfs: Accepting connections
init: Starting /srv/taskmon
taskmon: Task Monitoring Service
init: Location service filesystem mounted on /loc (locfs)
init: Temporary filesystem mounted on /tmp (tmpfs)
init: Starting /srv/devman
devman: HelenOS Device Manager
devman: Accepting connections.
root: HelenOS root device driver
init: Starting /srv/apic
[devman] note: The `root' driver was successfully registered as running.
apic: HelenOS APIC driver
apic: No APIC found
init: Server /srv/apic failed to start (exit code -1)
virt: HelenOS virtual devices root driver
[devman] note: The `virt' driver was successfully registered as running.
pc: HelenOS PC platform driver
[devman] note: The `pc' driver was successfully registered as running.
[virt] note: Registered child device `kfb'
kfb: HelenOS kernel framebuffer driver
pciintel: HelenOS PCI bus driver (Intel method 1).
[devman] note: The `kfb' driver was successfully registered as running.
[devman] note: The `pciintel' driver was successfully registered as running.
[devman] note: Function `/virt/kfb/vsl0' added to category `visualizer'.
kfb: Accepting connections
[devman] error: No driver found for device `/hw/pci0/00:00.0'.
[devman] error: No driver found for device `/hw/pci0/00:01.1'.
[pciintel] note: Function 00:01.2 uses irq b.
[pciintel] note: Function 00:01.3 uses irq 9.
[devman] error: No driver found for device `/hw/pci0/00:01.3'.
[devman] error: No driver found for device `/hw/pci0/00:02.0'.
[pciintel] note: Function 00:03.0 uses irq b.
init: Starting /srv/i8259
isa: HelenOS ISA bus driver
[devman] note: The `isa' driver was successfully registered as running.
[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
uhci: HelenOS UHCI driver.
[isa] note: Added io range (addr=0x2f8, size=0x8) to function com2
[devman] note: The `uhci' driver was successfully registered as running.
i8259: HelenOS i8259 driver
i8259: Accepting connections
init: Unable to stat /srv/icp-ic
[isa] note: Added irq 0x1 to function i8042
init: Unable to stat /srv/obio
init: Unable to stat /srv/cuda_adb
[isa] note: Added irq 0xc to function i8042
init: Unable to stat /srv/s3c24xx_uart
[isa] note: Added io range (addr=0x60, size=0x5) to function i8042
init: Unable to stat /srv/s3c24xx_ts
e1k: HelenOS E1000 network adapter driver
init: Starting /srv/vbd
[isa] note: Added irq 0x5 to function ne2k
[devman] note: The `e1k' 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/pci0/00:01.2/uhci_hc' added to category `usbhc'.
[isa] note: Added io range (addr=0x330, size=0x2) to function sb16
[uhci] note: Controlling new UHCI device '00:01.2'.
[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
[isa] note: Added io range (addr=0x1f0, size=0x8) to function ata-c1
[devman] note: Function `/hw/pci0/00:03.0/port0' added to category `nic'.
[isa] note: Added io range (addr=0x3f0, size=0x8) to function ata-c1
[isa] note: Added io range (addr=0x170, size=0x8) to function ata-c2
[isa] note: Added io range (addr=0x370, size=0x8) to function ata-c2
[isa] note: Added io range (addr=0x1e8, size=0x8) to function ata-c3
[isa] note: Added io range (addr=0x3e8, size=0x8) to function ata-c3
[isa] note: Added io range (addr=0x168, size=0x8) to function ata-c4
[isa] note: Added io range (addr=0x368, size=0x8) to function ata-c4
[isa] note: Finished enumerating legacy functions
ns8250: HelenOS serial port driver
[devman] note: The `ns8250' driver was successfully registered as running.
[ns8250] note: Device com1 was assigned irq = 0x4.
[ns8250] note: Device com1 was assigned I/O address = 0x3f8.
[devman] note: Function `/hw/pci0/00:01.0/com1/a' added to category `serial'.
vbd: Virtual Block Device service
[ns8250] note: Device com1 successfully initialized.
vbd: Accepting connections.
[ns8250] note: Device com2 was assigned irq = 0x3.
init: Starting /srv/volsrv
[ns8250] note: Device com2 was assigned I/O address = 0x2f8.
i8042: HelenOS PS/2 driver.
ne2k: HelenOS NE 2000 network adapter driver
[devman] note: The `ne2k' driver was successfully registered as running.
[devman] note: The `i8042' driver was successfully registered as running.
cmos-rtc: HelenOS RTC driver
uhcirh: HelenOS UHCI root hub driver.
sb16: HelenOS SB16 audio driver.
[devman] note: The `cmos-rtc' driver was successfully registered as running.
ata_bd: HelenOS ATA(PI) device driver
[devman] note: The `uhcirh' driver was successfully registered as running.
[devman] note: The `sb16' driver was successfully registered as running.
[devman] note: The `ata_bd' driver was successfully registered as running.
[cmos-rtc] note: Device cmos-rtc was assigned I/O address 0x70
[ata_bd] note: I/O address 0x000001f0/0x000003f0
[i8042] note: Controlling 'i8042' (33).
[sb16] note: PIO registers at 0x00000220 accessible.
[ata_bd] note: Identify drive 0...
[uhcirh] note: Controlling root hub 'uhci_rh' (38).
[devman] note: Function `/hw/pci0/00:01.0/cmos-rtc/a' added to category `clock'.
[sb16] error: Invalid DSP reset response: ff.
[cmos-rtc] note: Device cmos-rtc successfully initialized
[sb16] error: Failed to initialize SB DSP: Unkown error code -266.
volsrv: Volume service
[sb16] error: Failed to init sb16 driver: Unkown error code -266.
volsrv: Accepting connections.
init: Starting /srv/loopip
xtkbd: HelenOS XT keyboard driver.
[devman] note: The `xtkbd' driver was successfully registered as running.
loopip: HelenOS loopback IP link provider
ps2mouse: HelenOS ps/2 mouse driver.
loopip: Accepting connections.
[devman] note: The `ps2mouse' driver was successfully registered as running.
init: Starting /srv/ethip
[devman] note: Function `/hw/pci0/00:01.0/i8042/ps2a/kbd' added to category `keyboard'.
[xtkbd] note: Controlling 'ps2a' (54).
[devman] note: Function `/hw/pci0/00:01.0/i8042/ps2b/mouse' added to category `mouse'.
[ps2mouse] note: Enabled IntelliMouse extensions
[ps2mouse] note: Enabled 4th and 5th button.
[ps2mouse] note: Controlling 'ps2b' (56).
ethip: HelenOS IP over Ethernet service
ethip: Accepting connections.
init: Starting /srv/inetsrv
inetsrv: HelenOS Internet Protocol service
inetsrv: Accepting connections.
init: Starting /srv/tcp
tcp: TCP (Transmission Control Protocol) network module
tcp: Accepting connections.
init: Starting /srv/udp
udp: UDP (User Datagram Protocol) service
udp: Accepting connections.
init: Starting /srv/dnsrsrv
dnsres: DNS Resolution Service
dnsres: Accepting connections.
init: Starting /srv/dhcp
dhcp: DHCP Service
dhcp: Accepting connections.
init: Starting /srv/nconfsrv
nconfsrv: HelenOS Network configuration service
[nconfsrv] note: Found IP link '36'
[nconfsrv] note: Configure link net/loopback
[nconfsrv] note: Found IP link '39'
[nconfsrv] note: Configure link net/eth1
nconfsrv: Accepting connections.
[ata_bd] note: Not found.
init: Starting /srv/clipboard
[inetsrv] note: inet_iplink_recv: link_id=39
[ata_bd] note: Identify drive 1...
[inetsrv] note: inet_ev_recv: iplink=39
[dhcp] note: dhcp_recv_msg()
[dhcp] note: dhcp_recv_msg() - call recv_cb
[inetsrv] note: inet_iplink_recv: link_id=39
[inetsrv] note: inet_ev_recv: iplink=39
[dhcp] note: dhcp_recv_msg()
[dhcp] note: dhcp_recv_msg() - call recv_cb
clipboard: HelenOS clipboard service
clipboard: Accepting connections
[dhcp] note: net/eth1: Successfully configured.
init: Starting /srv/remcons
remcons: HelenOS Remote console service
init: Starting /srv/input
input: HelenOS input service
input: Connected keyboard device 'devices/\hw\pci0\00:01.0\i8042\ps2a\kbd'
input: Connected mouse device 'devices/\hw\pci0\00:01.0\i8042\ps2b\mouse'
input: Accepting connections
init: Starting /srv/output
output: HelenOS output service
output: Accepting connections
init: Starting /srv/hound
hound: HelenOS sound service
[hound] note: Running with service id 50
init: Starting /srv/compositor
compositor: HelenOS Compositor server
compositor: Accepting connections
init: Spawning /app/barber comp:0/winreg
[ata_bd] note: Not found.
[ata_bd] warn: No disks detected.
[ata_bd] error: Failed initializing ATA controller.
[ata_bd] note: I/O address 0x00000170/0x00000370
[ata_bd] note: Identify drive 0...
[ata_bd] note: QEMU DVD-ROM: PACKET 16671 blocks 8 MB.
[ata_bd] note: Identify drive 1...
init: Spawning /app/vlaunch comp:0/winreg
init: Spawning /app/vterm comp:0/winreg
init: Starting /srv/console
console: HelenOS Console service
console: Accepting connections
init: Spawning /app/getterm term/vc0 /loc --msg --wait -- /app/bdsh
init: Spawning /app/getterm term/vc1 /loc --wait -- /app/bdsh
init: Spawning /app/getterm term/vc2 /loc --wait -- /app/bdsh
[ata_bd] note: Not found.
[devman] note: Function `/hw/pci0/00:01.0/ata-c2/d0' added to category `disk'.
[vbd] note: Found disk '63'
[ata_bd] note: I/O address 0x000001e8/0x000003e8
[ata_bd] note: Identify drive 0...
[vbd] note: Recognized disk label. Adding partitions.
[volsrv] note: Found partition '64'
init: Spawning /app/getterm term/vc3 /loc --wait -- /app/bdsh
[volsrv] note: Added partition 64
init: Spawning /app/getterm term/vc4 /loc --wait -- /app/bdsh
init: Spawning /app/getterm term/vc5 /loc --wait -- /app/bdsh
[ata_bd] note: Not found.
[ata_bd] note: Identify drive 1...
[ata_bd] note: Not found.
[ata_bd] warn: No disks detected.
[ata_bd] error: Failed initializing ATA controller.
[ata_bd] note: I/O address 0x00000168/0x00000368
[ata_bd] note: Identify drive 0...
[ata_bd] note: Not found.
[ata_bd] note: Identify drive 1...
[ata_bd] note: Not found.
[ata_bd] warn: No disks detected.
[ata_bd] error: Failed initializing ATA controller.
kconsole> ??[uhci] debug: Address request: speed: full, address: 0, strict: NO.
[uhci] debug: Address request: speed: full, address: 0, strict: YES.
[uhci] debug: Register endpoint 0:0 control-both full 8B 0ms.
[uhci] debug2: READ 0:0 8(8).
[uhci] debug2: Batch 0x002a1030 [0:0 full ctrl-both 8B/8] memory structures ready.
[uhci] debug2: Created TD(0x002a5080): 9F35094:18800000:E0002D:9F350B8(0x002a50b8).
[uhci] debug2: TD(0x002a5080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 80 06 00 01  00 00 08 00
[uhci] debug2: Created TD(0x002a5090): 9F350A4:38800000:E80069:9F350C0(0x002a50c0).
[uhci] debug2: TD(0x002a5090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x002a50a0): 5:18800000:FFE800E1:0(0x00000000).
[uhci] debug2: TD(0x002a50a0) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 19800000.
[uhci] debug2: Batch 0x002a1030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x002a1030 [0:0 full ctrl-both 8B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x002a1030 [0:0 full ctrl-both 8B/8] checking 3 transfer(s) for completion.
[uhci] debug2: Batch 0x002a1030 removing from queue CONTROL FULL.
[uhci] debug2: Batch 0x002a1030 [0:0 full ctrl-both 8B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] debug2: Batch 0x002a1030 [0:0 full ctrl-both 8B/8] finishing.
[uhci] debug2: Batch 0x002a1030 [0:0 full ctrl-both 8B/8] disposing.
[uhci] debug2: WRITE 0:0 0(8).
[uhci] debug2: Batch 0x0004c030 [0:0 full ctrl-both 0B/8] memory structures ready.
[uhci] debug2: Created TD(0x00050080): A072094:18800000:E0002D:A0720A8(0x000500a8).
[uhci] debug2: TD(0x00050080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 00 05 01 00  00 00 00 00
[uhci] debug2: Created TD(0x00050090): 5:38800000:FFE80069:0(0x00000000).
[uhci] debug2: TD(0x00050090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 39800000.
[uhci] debug2: Batch 0x0004c030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x0004c030 [0:0 full ctrl-both 0B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x0004c030 [0:0 full ctrl-both 0B/8] checking 2 transfer(s) for completion.
[uhci] debug2: Batch 0x0004c030 removing from queue CONTROL FULL.
[uhci] debug2: Batch 0x0004c030 [0:0 full ctrl-both 0B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] debug2: Batch 0x0004c030 [0:0 full ctrl-both 0B/8] finishing.
[uhci] debug2: Batch 0x0004c030 [0:0 full ctrl-both 0B/8] disposing.
[uhci] debug: Unregister endpoint 0:0 both.
[uhci] debug: Address release 0.
[uhci] debug: Register endpoint 1:0 control-both full 8B 0ms.
[uhci] debug2: READ 1:0 18(8).
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] memory structures ready.
[uhci] debug2: Created TD(0x0029f080): A003094:18800000:E0012D:A0030D8(0x0029f0d8).
[uhci] debug2: TD(0x0029f080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 80 06 00 01  00 00 12 00
[uhci] debug2: Created TD(0x0029f090): A0030A4:38800000:E80169:A0030E0(0x0029f0e0).
[uhci] debug2: TD(0x0029f090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0a0): A0030B4:38800000:E00169:A0030E8(0x0029f0e8).
[uhci] debug2: TD(0x0029f0a0) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0b0): A0030C4:38800000:280169:A0030F0(0x0029f0f0).
[uhci] debug2: TD(0x0029f0b0) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0c0): 5:18800000:FFE801E1:0(0x00000000).
[uhci] debug2: TD(0x0029f0c0) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 19800000.
[uhci] debug2: Batch 0x0029b030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] checking 5 transfer(s) for completion.
[uhci] debug2: Batch 0x0029b030 removing from queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] finishing.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] disposing.
[uhci] debug: Address bind 1-61.
[uhcirh] note: Port (0x00170030 - 0): New device, address 1 (handle 61).
usbmid: USB multi interface device driver.
[devman] note: The `usbmid' driver was successfully registered as running.
[devman] error: IPC forwarding failed - no device or function with handle 62 was found.
[uhci] debug: Address release 1.
[usbmid] error: USB device `usb01_a1' init failed (device parameters retrieval): Not enough memory.
[uhci] warn: Endpoint 1:0 both was left behind, removing.
[uhcirh] note: Port (0x00170030 - 0): Removed attached device.
[uhci] debug: Address request: speed: full, address: 0, strict: NO.
[uhci] debug: Address request: speed: full, address: 0, strict: YES.
[uhci] debug: Register endpoint 0:0 control-both full 8B 0ms.
[uhci] debug2: READ 0:0 8(8).
[uhci] debug2: Batch 0x0029b030 [0:0 full ctrl-both 8B/8] memory structures ready.
[uhci] debug2: Created TD(0x0029f080): A553094:18800000:E0002D:A5530B8(0x0029f0b8).
[uhci] debug2: TD(0x0029f080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 80 06 00 01  00 00 08 00
[uhci] debug2: Created TD(0x0029f090): A5530A4:38800000:E80069:A5530C0(0x0029f0c0).
[uhci] debug2: TD(0x0029f090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0a0): 5:18800000:FFE800E1:0(0x00000000).
[uhci] debug2: TD(0x0029f0a0) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 19800000.
[uhci] debug2: Batch 0x0029b030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [0:0 full ctrl-both 8B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [0:0 full ctrl-both 8B/8] checking 3 transfer(s) for completion.
[uhci] debug2: Batch 0x0029b030 removing from queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [0:0 full ctrl-both 8B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] debug2: Batch 0x0029b030 [0:0 full ctrl-both 8B/8] finishing.
[uhci] debug2: Batch 0x0029b030 [0:0 full ctrl-both 8B/8] disposing.
[uhci] debug2: WRITE 0:0 0(8).
[uhci] debug2: Batch 0x00297030 [0:0 full ctrl-both 0B/8] memory structures ready.
[uhci] debug2: Created TD(0x0029b080): A67A094:18800000:E0002D:A67A0A8(0x0029b0a8).
[uhci] debug2: TD(0x0029b080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 00 05 01 00  00 00 00 00
[uhci] debug2: Created TD(0x0029b090): 5:38800000:FFE80069:0(0x00000000).
[uhci] debug2: TD(0x0029b090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 39800000.
[uhci] debug2: Batch 0x00297030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x00297030 [0:0 full ctrl-both 0B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x00297030 [0:0 full ctrl-both 0B/8] checking 2 transfer(s) for completion.
[uhci] debug2: Batch 0x00297030 removing from queue CONTROL FULL.
[uhci] debug2: Batch 0x00297030 [0:0 full ctrl-both 0B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] debug2: Batch 0x00297030 [0:0 full ctrl-both 0B/8] finishing.
[uhci] debug2: Batch 0x00297030 [0:0 full ctrl-both 0B/8] disposing.
[uhci] debug: Unregister endpoint 0:0 both.
[uhci] debug: Address release 0.
[uhci] debug: Register endpoint 1:0 control-both full 8B 0ms.
[uhci] debug2: READ 1:0 18(8).
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] memory structures ready.
[uhci] debug2: Created TD(0x0029f080): A662094:18800000:E0012D:A6620D8(0x0029f0d8).
[uhci] debug2: TD(0x0029f080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 80 06 00 01  00 00 12 00
[uhci] debug2: Created TD(0x0029f090): A6620A4:38800000:E80169:A6620E0(0x0029f0e0).
[uhci] debug2: TD(0x0029f090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0a0): A6620B4:38800000:E00169:A6620E8(0x0029f0e8).
[uhci] debug2: TD(0x0029f0a0) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0b0): A6620C4:38800000:280169:A6620F0(0x0029f0f0).
[uhci] debug2: TD(0x0029f0b0) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0c0): 5:18800000:FFE801E1:0(0x00000000).
[uhci] debug2: TD(0x0029f0c0) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 19800000.
[uhci] debug2: Batch 0x0029b030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] checking 5 transfer(s) for completion.
[uhci] debug2: Batch 0x0029b030 removing from queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] finishing.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] disposing.
[uhci] debug: Address bind 1-63.
[uhcirh] note: Port (0x0017006c - 1): New device, address 1 (handle 63).
[uhci] debug2: READ 1:0 18(8).
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] memory structures ready.
[uhci] debug2: Created TD(0x0029f080): A752094:18800000:E0012D:A7520D8(0x0029f0d8).
[uhci] debug2: TD(0x0029f080) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: SETUP BUFFER: 80 06 00 01  00 00 12 00
[uhci] debug2: Created TD(0x0029f090): A7520A4:38800000:E80169:A7520E0(0x0029f0e0).
[uhci] debug2: TD(0x0029f090) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0a0): A7520B4:38800000:E00169:A7520E8(0x0029f0e8).
[uhci] debug2: TD(0x0029f0a0) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0b0): A7520C4:38800000:280169:A7520F0(0x0029f0f0).
[uhci] debug2: TD(0x0029f0b0) status(0x38800000): SPD, 3, ACTIVE, 1.
[uhci] debug2: Created TD(0x0029f0c0): 5:18800000:FFE801E1:0(0x00000000).
[uhci] debug2: TD(0x0029f0c0) status(0x18800000): 3, ACTIVE, 1.
[uhci] debug2: Control last TD status: 19800000.
[uhci] debug2: Batch 0x0029b030 adding to queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] scheduled in queue CONTROL FULL.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] checking 5 transfer(s) for completion.
[uhci] debug: Batch 0x0029b030 found error TD(0->0x0029f080):40000.
[uhci] debug2: TD(0x0029f080) status(0x40000): 0, CRC/TIMEOUT, 1.
[uhci] debug2: Batch 0x0029b030 removing from queue CONTROL FULL.
[uhci] debug: Address release 1.
[uhci] debug2: Batch 0x0029b030 [1:0 full ctrl-both 18B/8] removed (FIRST) from CONTROL FULL, next: 6e01032.
[uhci] warn: Endpoint 1:0 both was left behind, removing.
Assertion failed (!instance->active) in file "src/endpoint.c", line 82.
Assertion failed (!instance->active) in file "src/endpoint.c", line 82.
0x003bbe18: 0x000285fe()
0x003bbe28: 0x000286ae()
0x003bbe48: 0x00004ba6()
0x003bbe88: 0x00006a4b()
0x003bbec8: 0x0000548e()
0x003bbef8: 0x0000f40c()
0x003bbf78: 0x00007bdf()
0x003bbf98: 0x00007c1b()
0x003bbfc8: 0x000200e3()
0x003bbff8: 0x00016835()
-- end of stack trace --
Task uhci (21) killed due to an exception at program counter 0x00010c8c.
cs =0x0000001b	eip=0x00010c8c	efl=0x00010202	err=0x00000006
ds =0x00000023	es =0x00000023	fs =0x00000023	gs =0x00000030
ss =0x00000023
eax=0x00000123	ebx=0x00295030	ecx=0x0002fea4	edx=0x0002fea4
esi=0x002b8f98	edi=0x002a80a4	ebp=0x003bbe18	esp=0x003bbe10
0x003bbe18: 0x00010c8c()
0x003bbe28: 0x000286b3()
0x003bbe48: 0x00004ba6()
0x003bbe88: 0x00006a4b()
0x003bbec8: 0x0000548e()
0x003bbef8: 0x0000f40c()
0x003bbf78: 0x00007bdf()
0x003bbf98: 0x00007c1b()
0x003bbfc8: 0x000200e3()
0x003bbff8: 0x00016835()
Kill message: Page fault: 0x00000123.
taskmon: Task 21 fault in thread 0x840c6830.
taskmon: Executing /app/taskdump -t 21
Task Dump Utility
Dumping task 'uhci' (task ID 21).
failed opening file
failed opening file
Loaded symbol table from /drv/uhci/uhci

Threads:
 [1] hash: 0x840c6830
Thread 0x840c6830: PC = 0x00010c8c (abort+11). FP = 0x003bbe18
  0x003bbe18: 0x00010c8c (abort+11)
  0x003bbe28: 0x000286b3 (link_initialize+0)
  0x003bbe48: 0x00004ba6 (endpoint_destroy+62)
  0x003bbe88: 0x00006a4b (usb_endpoint_manager_remove_address+236)
  0x003bbec8: 0x0000548e (release_address+158)
  0x003bbef8: 0x0000f40c (remote_usbhc_release_address+69)
  0x003bbf78: 0x00007bdf (driver_connection_gen+761)
  0x003bbf98: 0x00007c1b (driver_connection_client+22)
  0x003bbfc8: 0x000200e3 (connection_fibril+229)
  0x003bbff8: 0x00016835 (fibril_main+35)

Address space areas:
 [1] flags: R-XC base: 0x00001000 size: 184320
 [2] flags: RW-C base: 0x0002e000 size: 12288
 [3] flags: RW-C base: 0x00032000 size: 4096
 [4] flags: RW-C base: 0x00034000 size: 4096
 [5] flags: RW-C base: 0x00036000 size: 4096
 [6] flags: RW-C base: 0x00038000 size: 4096
 [7] flags: RW-C base: 0x0003a000 size: 4096
 [8] flags: RW-C base: 0x0003c000 size: 4096
 [9] flags: RW-C base: 0x0003e000 size: 4096
 [10] flags: RW-C base: 0x00040000 size: 4096
 [11] flags: RW-C base: 0x00042000 size: 4096
 [12] flags: RW-C base: 0x00044000 size: 4096
 [13] flags: RW-C base: 0x00046000 size: 4096
 [14] flags: RW-C base: 0x00048000 size: 4096
 [15] flags: RW-C base: 0x0004a000 size: 4096
 [16] flags: RW-C base: 0x0004c000 size: 4096
 [17] flags: RW-C base: 0x0004e000 size: 4096
 [18] flags: RW-C base: 0x00050000 size: 4096
 [19] flags: RW-C base: 0x00052000 size: 8192
 [20] flags: RW-C base: 0x00055000 size: 4096
 [21] flags: RW-C base: 0x00057000 size: 4096
 [22] flags: RW-C base: 0x00059000 size: 4096
 [23] flags: RW-C base: 0x0005b000 size: 4096
 [24] flags: RW-C base: 0x0005d000 size: 4096
 [25] flags: RW-C base: 0x0005f000 size: 4096
 [26] flags: RW-C base: 0x00061000 size: 4096
 [27] flags: RW-C base: 0x00063000 size: 4096
 [28] flags: RW-C base: 0x00065000 size: 4096
 [29] flags: RW-C base: 0x00067000 size: 4096
 [30] flags: RW-C base: 0x00069000 size: 4096
 [31] flags: RW-C base: 0x0006b000 size: 1048576
 [32] flags: RW-C base: 0x0016c000 size: 4096
 [33] flags: RW-C base: 0x0016e000 size: 4096
 [34] flags: RW-C base: 0x00170000 size: 4096
 [35] flags: RW-C base: 0x00172000 size: 4096
 [36] flags: RW-C base: 0x00174000 size: 4096
 [37] flags: RW-C base: 0x00176000 size: 4096
 [38] flags: RW-C base: 0x00178000 size: 4096
 [39] flags: RW-C base: 0x0017a000 size: 4096
 [40] flags: RW-C base: 0x0017c000 size: 4096
 [41] flags: RW-C base: 0x0017e000 size: 4096
 [42] flags: RW-- base: 0x00180000 size: 4096
 [43] flags: RW-C base: 0x00182000 size: 4096
 [44] flags: RW-C base: 0x00184000 size: 4096
 [45] flags: RW-C base: 0x00186000 size: 4096
 [46] flags: RW-C base: 0x00188000 size: 4096
 [47] flags: RW-C base: 0x0018a000 size: 4096
 [48] flags: RW-C base: 0x0018c000 size: 4096
 [49] flags: R--C base: 0x0018e000 size: 4096
 [50] flags: RW-C base: 0x00190000 size: 4096
 [51] flags: RW-C base: 0x00192000 size: 1048576
 [52] flags: RW-C base: 0x00293000 size: 4096
 [53] flags: RW-C base: 0x00295000 size: 4096
 [54] flags: RW-C base: 0x00297000 size: 4096
 [55] flags: RW-C base: 0x00299000 size: 4096
 [56] flags: RW-C base: 0x0029b000 size: 4096
 [57] flags: RW-C base: 0x0029d000 size: 4096
 [58] flags: RW-C base: 0x0029f000 size: 4096
 [59] flags: RW-C base: 0x002a1000 size: 8192
 [60] flags: RW-C base: 0x002a8000 size: 4096
 [61] flags: RW-C base: 0x002aa000 size: 4096
 [62] flags: RW-C base: 0x002ac000 size: 4096
 [63] flags: RW-C base: 0x002ae000 size: 4096
 [64] flags: RW-C base: 0x002b0000 size: 4096
 [65] flags: RW-C base: 0x002b2000 size: 4096
 [66] flags: RW-C base: 0x002b4000 size: 4096
 [67] flags: RW-C base: 0x002b6000 size: 4096
 [68] flags: RW-C base: 0x002b8000 size: 4096
 [69] flags: RW-C base: 0x002ba000 size: 4096
 [70] flags: RW-C base: 0x002bc000 size: 1048576
 [71] flags: RW-C base: 0x003bd000 size: 4096
 [72] flags: R-XC base: 0x70001000 size: 102400
 [73] flags: RW-C base: 0x7001a000 size: 8192
 [74] flags: RW-C base: 0x7001d000 size: 4096
 [75] flags: RW-C base: 0x7001f000 size: 4096
 [76] flags: RW-C base: 0x70021000 size: 4096
 [77] flags: RW-C base: 0x70023000 size: 4096
 [78] flags: RW-C base: 0x70025000 size: 4096
 [79] flags: RW-C base: 0x70027000 size: 4096
 [80] flags: RW-C base: 0x70029000 size: 4096
 [81] flags: RW-C base: 0x7002b000 size: 4096
 [82] flags: RW-C base: 0x7002d000 size: 4096
 [83] flags: RW-C base: 0x7002f000 size: 4096
 [84] flags: RW-C base: 0x70031000 size: 4096
 [85] flags: RW-C base: 0x70033000 size: 4096
 [86] flags: RW-C base: 0x70035000 size: 4096
 [87] flags: RW-C base: 0x70037000 size: 4096
 [88] flags: RW-C base: 0x70039000 size: 4096
 [89] flags: RW-C base: 0x7003b000 size: 4096
 [90] flags: RW-C base: 0x7003d000 size: 1048576
 [91] flags: RW-C base: 0x7013e000 size: 4096
 [92] flags: RW-C base: 0x70140000 size: 4096
 [93] flags: RW-C base: 0x70142000 size: 4096
 [94] flags: RW-C base: 0x70144000 size: 4096
 [95] flags: RW-C base: 0x70146000 size: 4096
 [96] flags: RW-C base: 0x70148000 size: 4096
 [97] flags: RW-C base: 0x7014a000 size: 4096
 [98] flags: RW-C base: 0x7ff00000 size: 1048576

Fibril 0x00069030:
  0x0016af08: 0x00016aa0 (fibril_switch+225)
  0x0016af48: 0x00020afb (async_get_call_timeout+272)
  0x0016af98: 0x00007843 (driver_connection_devman+36)
  0x0016afc8: 0x000200e3 (connection_fibril+229)
  0x0016aff8: 0x00016835 (fibril_main+35)
Fibril 0x002ae030:
  0x002b2cb8: 0x00016aa0 (fibril_switch+225)
  0x002b2d08: 0x00017191 (fibril_mutex_lock+135)
  0x002b2d38: 0x000227a9 (async_exchange_begin+646)
  0x002b2d68: 0x0001a534 (logger_message+17)
  0x002b2d98: 0x0001a894 (log_msgv+137)
  0x002b2dc8: 0x0001a805 (log_msg+30)
  0x002b2e38: 0x00006d92 (usb_transfer_batch_finish_error+171)
  0x002b2e58: 0x00003591 (usb_transfer_batch_finish+60)
  0x002b2e78: 0x00003a1b (uhci_transfer_batch_finish_dispose+94)
  0x002b2eb8: 0x0000150d (hc_interrupt+223)
  0x002b2ee8: 0x00002fed (irq_handler+112)
  0x002b2f18: 0x000207d5 (process_notification+157)
  0x002b2f58: 0x00020dd4 (handle_call+81)
  0x002b2fb8: 0x0002115b (async_manager_worker+372)
  0x002b2fc8: 0x00021184 (async_manager_fibril+27)
  0x002b2ff8: 0x00016835 (fibril_main+35)
Fibril 0x00050030:
  0x00291eb8: 0x00016aa0 (fibril_switch+225)
  0x00291ef8: 0x00020afb (async_get_call_timeout+272)
  0x00291f78: 0x00007a16 (driver_connection_gen+304)
  0x00291f98: 0x00007c1b (driver_connection_client+22)
  0x00291fc8: 0x000200e3 (connection_fibril+229)
  0x00291ff8: 0x00016835 (fibril_main+35)
Fibril 0x002b6030:
  0x002b8f58: 0x00016aa0 (fibril_switch+225)
  0x002b8fb8: 0x00020ff8 (async_manager_worker+17)
  0x002b8fc8: 0x00021184 (async_manager_fibril+27)
  0x002b8ff8: 0x00016835 (fibril_main+35)
Fibril 0x002ba030:
  0x003bbd48: 0x00016aa0 (fibril_switch+225)
  0x00016f7e: 0x0002fea4 (async_futex+0)
[uhcirh] error: Port (0x00170030 - 0): Failed to connect to HC Not enough memory.
[usbmid] error: USB device `usb02_a1' init failed (descriptor retrieval): Answerbox closed connection.
[uhcirh] error: Port (0x0017006c - 1): Failed to unregister address of removed device: Answerbox closed connection.
[uhcirh] error: Port (0x00170030 - 0): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x00170030 - 0): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x00170030 - 0): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x00170030 - 0): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x00170030 - 0): Failed to connect to HC Not enough memory.
[uhcirh] fatal: Maximum number of failures reached, bailing out.
[uhcirh] error: Port (0x0017006c - 1): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x0017006c - 1): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x0017006c - 1): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x0017006c - 1): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x0017006c - 1): Failed to connect to HC Not enough memory.
[uhcirh] error: Port (0x0017006c - 1): Failed to connect to HC Not enough memory.
[uhcirh] fatal: Maximum number of failures reached, bailing out.

The log shows us two interesting fibrils:

1. The fibril which hit the assert. By inspecting the sources, I think the fibril must have been created as a consequence of usbhc_release_address() being run in libdrv and sending IPC_M_USBHC_RELEASE_ADDRESS over IPC to uhci.

  0x003bbe48: 0x00004ba6 (endpoint_destroy+62)
  0x003bbe88: 0x00006a4b (usb_endpoint_manager_remove_address+236)
  0x003bbec8: 0x0000548e (release_address+158)
  0x003bbef8: 0x0000f40c (remote_usbhc_release_address+69)
  0x003bbf78: 0x00007bdf (driver_connection_gen+761)
  0x003bbf98: 0x00007c1b (driver_connection_client+22)
  0x003bbfc8: 0x000200e3 (connection_fibril+229)
  0x003bbff8: 0x00016835 (fibril_main+35)

2. A fibril which seems to be executing the interrupt-half of what is essentially libdrv's usbhc_read() or usbhc_write() resulting in a IPC_M_USBHC_READ/WRITE request to uhci:

  0x002b2cb8: 0x00016aa0 (fibril_switch+225)
  0x002b2d08: 0x00017191 (fibril_mutex_lock+135)
  0x002b2d38: 0x000227a9 (async_exchange_begin+646)
  0x002b2d68: 0x0001a534 (logger_message+17)
  0x002b2d98: 0x0001a894 (log_msgv+137)
  0x002b2dc8: 0x0001a805 (log_msg+30)
  0x002b2e38: 0x00006d92 (usb_transfer_batch_finish_error+171)
  0x002b2e58: 0x00003591 (usb_transfer_batch_finish+60)
  0x002b2e78: 0x00003a1b (uhci_transfer_batch_finish_dispose+94)
  0x002b2eb8: 0x0000150d (hc_interrupt+223)
  0x002b2ee8: 0x00002fed (irq_handler+112)
  0x002b2f18: 0x000207d5 (process_notification+157)
  0x002b2f58: 0x00020dd4 (handle_call+81)
  0x002b2fb8: 0x0002115b (async_manager_worker+372)
  0x002b2fc8: 0x00021184 (async_manager_fibril+27)
  0x002b2ff8: 0x00016835 (fibril_main+35)

It seems that somehow usbhc_release_address() is attempted when the ep is being actively used for a transfer.

[Jakub Jermář]

Here is an IRC conversation including a proposed fix:

<jermar> jvesely, #668 with my updated observations and debug2 console debug output for uhci
<jvesely> jermar, thanks, it's as I suspected
<jvesely> the plan was to change endpoints and usb transfers to reference counted, but I think the time is better spent integrating the USB branch rather than fixing the old usb implementation
<jermar> jvesely, by all means, any estimates?
<jermar> jvesely, I assume the USB branch will suffer from the same problem, won't it?
<jvesely> it probably will, although device discovery was moved to hcd/usbd, so some accidental locking might prevent it

[Jakub Jermář]

Fixed in mainline,2542.