Opened 8 years ago

Closed 8 years ago

#668 closed defect (fixed)

Race between usbhc_release_address() and usbhc_read/write()

Reported by: Jakub Jermář Owned by:
Priority: major Milestone: 0.7.0
Component: helenos/drv/uhci Version: mainline
Keywords: Cc:
Blocker for: Depends on:
See also: #389

Description (last modified by 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)
  1. 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.

Attachments (1)

allocator.patch (5.5 KB ) - added by Jakub Jermář 8 years ago.

Download all attachments as: .zip

Change History (4)

by Jakub Jermář, 8 years ago

Attachment: allocator.patch added

comment:1 by Jakub Jermář, 8 years ago

Description: modified (diff)

comment:2 by Jakub Jermář, 8 years ago

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

comment:3 by Jakub Jermář, 8 years ago

Resolution: fixed
Status: newclosed

Fixed in mainline,2542.

Note: See TracTickets for help on using tickets.