NetBSD Problem Report #50278
From gson@gson.org Sat Sep 26 20:10:53 2015
Return-Path: <gson@gson.org>
Received: from mail.netbsd.org (mail.netbsd.org [149.20.53.66])
(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
(Client CN "mail.netbsd.org", Issuer "Postmaster NetBSD.org" (verified OK))
by mollari.NetBSD.org (Postfix) with ESMTPS id 0B042A654F
for <gnats-bugs@gnats.NetBSD.org>; Sat, 26 Sep 2015 20:10:53 +0000 (UTC)
Message-Id: <20150926201044.8E9D67441E0@guava.gson.org>
Date: Sat, 26 Sep 2015 23:10:44 +0300 (EEST)
From: gson@gson.org (Andreas Gustafsson)
Reply-To: gson@gson.org (Andreas Gustafsson)
To: gnats-bugs@gnats.NetBSD.org
Subject: umidi(4) loses first incoming message after second open
X-Send-Pr-Version: 3.95
>Number: 50278
>Category: kern
>Synopsis: umidi(4) loses first incoming message after second open
>Confidential: no
>Severity: serious
>Priority: medium
>Responsible: kern-bug-people
>State: open
>Class: sw-bug
>Submitter-Id: net
>Arrival-Date: Sat Sep 26 20:15:00 +0000 2015
>Last-Modified: Sat Dec 14 12:50:01 +0000 2019
>Originator: Andreas Gustafsson
>Release: NetBSD-current as of today; also NetBSD 6.1.5
>Organization:
>Environment:
System: NetBSD guiro.gson.org
Architecture: i386
Machine: i386
>Description:
I'm trying to use an external MIDI device via an Edirol UM-1SX USB
MIDI interface and the umidi(4) driver. I'm using the "raw" device,
/dev/rmidi1.
The transmit side seems to work, but I'm having a strange problem with
the receive side. The first time I run my program after booting the
machine or plugging in the USB cable, it works fine. But when I run
the program for a second time, or in other words, after /dev/rmidi1 is
closed and re-opened, the program fails to receive the first MIDI
message transmitted by the external device after the device has been
opened. The second and subsequent messages are received; only the
first message that arrives after the device has been reopened is lost.
>How-To-Repeat:
Connect a USB MIDI interface to a NetBSD machine, and set up a
loopback by connecting a MIDI cable from its output back to its input.
Compile the following test program, which attempts to send a single
MIDI message to itself through the loopback cable and verify that it
is arrives unchanged:
#include <err.h>
#include <fcntl.h>
#include <unistd.h>
#include <stdio.h>
unsigned char data[3] = { 0x90, 0x40, 0x7F };
unsigned char rbuf[3];
int main(int argc, char **argv) {
if (argc < 2)
errx(1, "missing argument");
alarm(5);
int fd = open(argv[1], O_RDWR);
if (fd < 0)
err(1, "open");
ssize_t r = write(fd, data, sizeof data);
if (r < 0)
err(1, "write");
if (r != sizeof data)
errx(1, "short write");
unsigned char *p = rbuf;
unsigned char *end = rbuf + sizeof rbuf;
while (p < end) {
r = read(fd, p, end - p);
printf("read %d bytes\n", (int) r);
if (r < 0)
err(1, "read");
p += r;
}
if (memcmp(data, rbuf, sizeof data) != 0)
errx(1, "mismatch");
printf("pass\n");
return 0;
}
Run the program twice, giving the name of the raw MIDI interface as a
command line argument each time. You will see something like this:
$ ./a.out /dev/rmidi1
read 3 bytes
pass
$ ./a.out /dev/rmidi1
Alarm clock
where the "Alarm clock" indicates that the program timed out trying
to read the looped-back data.
>Fix:
Don't know. In case it helps, here is the dmesg output from
running the above test on a kernel with "options AUDIO_DEBUG"
and mididebug=9:
umidi0 at uhub0 port 2 configuration 1 interface 0
umidi0: EDIROL UM-1, rev 1.10/2.00, addr 2
umidi0: (genuine USB-MIDI)
umidi0: out=1, in=1
midiprobe: type=1 sa=0xdd60ccc4 hw=0xc0d47c60
midi1 at umidi0MIDI attach
: <0 >0 on umidi0
midiopen 0xc5886008
midiwrite: 0xc5886008, unit=1, count=3
midi_fst: s=0xc5886984 data=0x90 state=0
midi_fst: s=0xc5886984 data=0x40 state=12
midi_fst: s=0xc5886984 data=0x7f state=16
midiwrite: uio_resid now 0, props=3
midi_out: 0xc5886008
midiread: 0xc5886008, count=3
midi_fst: s=0xc5886924 data=0x90 state=0
midi_fst: s=0xc5886924 data=0x40 state=12
midi_fst: s=0xc5886924 data=0x7f state=16
midiread: uiomove cc=3
midiclose 0xc5886008
midiopen 0xc5886008
midiwrite: 0xc5886008, unit=1, count=3
midi_fst: s=0xc5886984 data=0x90 state=0
midi_fst: s=0xc5886984 data=0x40 state=12
midi_fst: s=0xc5886984 data=0x7f state=16
midiwrite: uio_resid now 0, props=3
midi_out: 0xc5886008
midiread: 0xc5886008, count=3
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midi_out: 0xc5886008
midiclose 0xc5886008
>Audit-Trail:
From: Andreas Gustafsson <gson@gson.org>
To: gnats-bugs@NetBSD.org
Cc: gson@gson.org (Andreas Gustafsson)
Subject: Re: kern/50278: umidi(4) loses first incoming message after second open
Date: Tue, 26 Nov 2019 21:36:20 +0200
I retested this against multiple USB host controllers using a recent
-current with the OHCI patch from PR 54070 applied. The test still
fails with each of UHCI, OCHI, and EHCI, but it passes with XHCI.
--
Andreas Gustafsson, gson@gson.org
From: Nick Hudson <nick.hudson@gmx.co.uk>
To: gnats-bugs@netbsd.org, kern-bug-people@netbsd.org,
gnats-admin@netbsd.org, netbsd-bugs@netbsd.org,
Andreas Gustafsson <gson@gson.org>
Cc:
Subject: Re: kern/50278: umidi(4) loses first incoming message after second
open
Date: Tue, 26 Nov 2019 20:37:41 +0000
On 26/11/2019 19:40, Andreas Gustafsson wrote:
> The following reply was made to PR kern/50278; it has been noted by GNAT=
S.
>
> From: Andreas Gustafsson <gson@gson.org>
> To: gnats-bugs@NetBSD.org
> Cc: gson@gson.org (Andreas Gustafsson)
> Subject: Re: kern/50278: umidi(4) loses first incoming message after sec=
ond open
> Date: Tue, 26 Nov 2019 21:36:20 +0200
>
> I retested this against multiple USB host controllers using a recent
> -current with the OHCI patch from PR 54070 applied. The test still
> fails with each of UHCI, OCHI, and EHCI, but it passes with XHCI.
Does this suggest a toggle problem? what does your usb protocol analyser
say?
Nick
From: Andreas Gustafsson <gson@gson.org>
To: Nick Hudson <nick.hudson@gmx.co.uk>
Cc: gnats-bugs@netbsd.org
Subject: Re: kern/50278: umidi(4) loses first incoming message after second open
Date: Wed, 27 Nov 2019 09:54:46 +0200
Nick Hudson wrote:
> Does this suggest a toggle problem?
I think so, yes.
> what does your usb protocol analyser say?
I haven't had time to check that yet.
--
Andreas Gustafsson, gson@gson.org
From: Andreas Gustafsson <gson@gson.org>
To: Nick Hudson <nick.hudson@gmx.co.uk>
Cc: gnats-bugs@netbsd.org
Subject: Re: kern/50278: umidi(4) loses first incoming message after second open
Date: Wed, 27 Nov 2019 19:00:39 +0200
Nick Hudson wrote:
> what does your usb protocol analyser say?
I have now analyzed the USB traffic using an OHCI, with my patch from
PR 54070, and with midi.c patched to disable the sending of "MIDI
active sense" to avoid cluttering the logs with unrelated traffic.
When I run the test program for the first time, the analyzer shows a
single 4-byte OUT transaction containing a single DATA0 packet,
followed by a single 4-byte IN transaction containing a single DATA0
packet.
When I run the test program for the second time, the analyzer shows a
single 4-byte OUT transaction containing a single DATA1 packet,
followed by a single 4-byte IN transaction containing a single DATA1
packet.
All the transfers contain the same data, 09 90 40 7F. In other words,
everything looks as expected on the wire. But in the UMIDI_DEBUG
output, the first run of the test program receives input:
[ 241.023669] umidi_open: sc=0xfffff464bd776320
[ 241.023669] umidi out: 45.089117s ep=0xfffff464bd7c94c8 cn=0 len=3 cin=0x9
[ 241.023669] umidi0: umidi packet(out): 09 90 40 7F
[ 241.023669] umidi out transfer: start 0xffff990051ff0a80 end 0xffff990051ff0a84 length 4
[ 241.023669] umidi0: 45.091502s out ep 0xfffff464bd7c94c8 xfer length 4
[ 241.023669] umidi0: input endpoint 0xfffff464bd7c95a8 transfer length 4
[ 241.023669] umidi0: input endpoint 0xfffff464bd7c95a8 cable 0 len 3: 90 40 7F
and the second one does not:
[ 246.176453] umidi_open: sc=0xfffff464bd776320
[ 246.176453] umidi out: 50.248899s ep=0xfffff464bd7c94c8 cn=0 len=3 cin=0x9
[ 246.176453] umidi0: umidi packet(out): 09 90 40 7F
[ 246.176453] umidi out transfer: start 0xffff990051ff0a80 end 0xffff990051ff0a84 length 4
[ 246.186539] umidi0: 50.251081s out ep 0xfffff464bd7c94c8 xfer length 4
The OHCIDEBUG output looks like this (with comments in parenthesis to
correlate the timeline to the test program runs):
(start test program for the first time)
1574871545.089078 ohci_device_bulk_start#6@0: called!
1574871545.089079 ohci_device_bulk_start#6@0: xfer=0xfffff4645591d578 len=64 isread=1 flags=4
1574871545.089079 ohci_device_bulk_start#6@0: endpt=129
1574871545.089081 ohci_reset_std_chain#44@0: called!
1574871545.089082 ohci_reset_std_chain#44@0: start len=64
1574871545.089082 ohci_reset_std_chain#44@0: addr=3 endpt=1 len=64 speed=2
1574871545.089083 ohci_reset_std_chain#44@0: sdataphys=0x45963a40 edataphys=0x45963a7f len=64 curlen=64
1574871545.089085 ohci_device_bulk_start#6@0: xfer 0xfffff4645591d578 data 0xffff99005294fd00 tail 0xffff99005294fe20
1574871545.089085 ohci_device_bulk_start#6@0: ed_flags=0x00400083 td_flags=0xfffffffff0340000 td_cbp=0x45963a40 td_be=0x45963a7f
1574871545.089086 ohci_device_bulk_start#6@0: --- dump start ---
1574871545.089086 ohci_dump_ed#59@0: called!
1574871545.089087 ohci_dump_ed#59@0: ED(0xffff990051275e40) at 0x452a5e40:
1574871545.089088 ohci_dump_ed#59@0: addr=3 endpt=1 maxp=64
1574871545.089088 ohci_dump_ed#59@0: dir=0 speed=0 skip=0 iso=0
1574871545.089089 ohci_dump_ed#59@0: tailp=0x45bdbd00
1574871545.089089 ohci_dump_ed#59@0: headp=0x45bdbd00 nexted=0x452a5e80 halted=0 carry=0
1574871545.089090 ohci_dump_td#312@0: called!
1574871545.089090 ohci_dump_td#312@0: TD(0xffff99005294fd00) at 0x45bdbd00:
1574871545.089091 ohci_dump_td#312@0: round=1 DP=2 DI=1 T=0
1574871545.089091 ohci_dump_td#312@0: EC=0 CC=15
1574871545.089092 ohci_dump_td#312@0: td_cbp=0x45963a40 td_nexttd=0x45bdbe20 td_be=0x45963a7f
1574871545.089092 ohci_dump_td#313@0: called!
1574871545.089093 ohci_dump_td#313@0: TD(0xffff99005294fe20) at 0x45bdbe20:
1574871545.089094 ohci_dump_td#313@0: round=0 DP=0 DI=0 T=0
1574871545.089094 ohci_dump_td#313@0: EC=0 CC=0
1574871545.089095 ohci_dump_td#313@0: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871545.089095 ohci_device_bulk_start#6@0: --- dump end ---
1574871545.089478 ohci_device_bulk_start#7@0: called!
1574871545.089478 ohci_device_bulk_start#7@0: xfer=0xfffff4645591d428 len=4 isread=0 flags=0
1574871545.089479 ohci_device_bulk_start#7@0: endpt=1
1574871545.089480 ohci_reset_std_chain#45@0: called!
1574871545.089480 ohci_reset_std_chain#45@0: start len=4
1574871545.089481 ohci_reset_std_chain#45@0: addr=3 endpt=1 len=4 speed=2
1574871545.089482 ohci_reset_std_chain#45@0: sdataphys=0x45963a80 edataphys=0x45963a83 len=4 curlen=4
1574871545.089483 ohci_device_bulk_start#7@0: xfer 0xfffff4645591d428 data 0xffff99005294ff40 tail 0xffff99005294fd60
1574871545.089483 ohci_device_bulk_start#7@0: ed_flags=0x00400083 td_flags=0xfffffffff0280000 td_cbp=0x45963a80 td_be=0x45963a83
1574871545.089484 ohci_device_bulk_start#7@0: --- dump start ---
1574871545.089484 ohci_dump_ed#60@0: called!
1574871545.089485 ohci_dump_ed#60@0: ED(0xffff990051275e80) at 0x452a5e80:
1574871545.089485 ohci_dump_ed#60@0: addr=3 endpt=1 maxp=64
1574871545.089486 ohci_dump_ed#60@0: dir=0 speed=0 skip=0 iso=0
1574871545.089486 ohci_dump_ed#60@0: tailp=0x45bdbf40
1574871545.089487 ohci_dump_ed#60@0: headp=0x45bdbf40 nexted=0x00000000 halted=0 carry=0
1574871545.089488 ohci_dump_td#314@0: called!
1574871545.089488 ohci_dump_td#314@0: TD(0xffff99005294ff40) at 0x45bdbf40:
1574871545.089489 ohci_dump_td#314@0: round=0 DP=1 DI=1 T=0
1574871545.089489 ohci_dump_td#314@0: EC=0 CC=15
1574871545.089490 ohci_dump_td#314@0: td_cbp=0x45963a80 td_nexttd=0x45bdbd60 td_be=0x45963a83
1574871545.089490 ohci_dump_td#315@0: called!
1574871545.089491 ohci_dump_td#315@0: TD(0xffff99005294fd60) at 0x45bdbd60:
1574871545.089491 ohci_dump_td#315@0: round=0 DP=0 DI=0 T=0
1574871545.089492 ohci_dump_td#315@0: EC=0 CC=0
1574871545.089492 ohci_dump_td#315@0: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871545.089493 ohci_device_bulk_start#7@0: --- dump end ---
1574871545.091468 ohci_intr#60@0: called!
1574871545.091470 ohci_intr1#60@0: called!
1574871545.091472 ohci_intr1#60@0: sc=0xffff990005177000
1574871545.091473 ohci_intr1#60@0: intrs=0x26(0x2) eintrs=0x2(0x5b)
1574871545.091475 ohci_intr1#60@0: sc 0xffff990005177000 blocking intrs 0x2
1574871545.091484 ohci_softintr#53@0: called!
1574871545.091485 ohci_softintr#53@0: add TD 0xffff99005294fd00
1574871545.091486 ohci_softintr#53@0: add TD 0xffff99005294ff40
1574871545.091487 ohci_softintr#53@0: sdone=0xffff99005294ff40 sidone=0
1574871545.091487 ohci_softintr#53@0: --- TD dump start ---
1574871545.091488 ohci_dump_td#316@0: called!
1574871545.091488 ohci_dump_td#316@0: TD(0xffff99005294ff40) at 0x45bdbf40:
1574871545.091489 ohci_dump_td#316@0: round=0 DP=1 DI=1 T=3
1574871545.091489 ohci_dump_td#316@0: EC=0 CC=0
1574871545.091490 ohci_dump_td#316@0: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x45963a83
1574871545.091491 ohci_dump_td#317@0: called!
1574871545.091491 ohci_dump_td#317@0: TD(0xffff99005294fd00) at 0x45bdbd00:
1574871545.091492 ohci_dump_td#317@0: round=1 DP=2 DI=1 T=3
1574871545.091492 ohci_dump_td#317@0: EC=0 CC=0
1574871545.091493 ohci_dump_td#317@0: td_cbp=0x45963a44 td_nexttd=0x45bdbf40 td_be=0x45963a7f
1574871545.091493 ohci_softintr#53@0: --- TD dump end ---
1574871545.091494 ohci_softintr#53@0: std=0xffff99005294ff40 xfer=0xfffff4645591d428 hcpriv=0xffff99005294ff40
1574871545.091497 ohci_softintr#53@0: len=4, flags=0x3
1574871545.091499 ohci_device_bulk_done#6@0: called!
1574871545.091499 ohci_device_bulk_done#6@0: xfer=0xfffff4645591d428, actlen=4
1574871545.091673 ohci_softintr#53@0: std=0xffff99005294fd00 xfer=0xfffff4645591d578 hcpriv=0xffff99005294fd00
1574871545.091675 ohci_softintr#53@0: len=4, flags=0x3
1574871545.091676 ohci_device_bulk_done#7@0: called!
1574871545.091677 ohci_device_bulk_done#7@0: xfer=0xfffff4645591d578, actlen=4
1574871545.091948 ohci_device_bulk_start#8@0: called!
1574871545.091948 ohci_device_bulk_start#8@0: xfer=0xfffff4645591d578 len=64 isread=1 flags=4
1574871545.091949 ohci_device_bulk_start#8@0: endpt=129
1574871545.091950 ohci_reset_std_chain#46@0: called!
1574871545.091950 ohci_reset_std_chain#46@0: start len=64
1574871545.091951 ohci_reset_std_chain#46@0: addr=3 endpt=1 len=64 speed=2
1574871545.091951 ohci_reset_std_chain#46@0: sdataphys=0x45963a40 edataphys=0x45963a7f len=64 curlen=64
1574871545.091952 ohci_device_bulk_start#8@0: xfer 0xfffff4645591d578 data 0xffff99005294fe20 tail 0xffff99005294fd00
1574871545.091953 ohci_device_bulk_start#8@0: ed_flags=0x00400083 td_flags=0xfffffffff0340000 td_cbp=0x45963a40 td_be=0x45963a7f
1574871545.091953 ohci_device_bulk_start#8@0: --- dump start ---
1574871545.091954 ohci_dump_ed#61@0: called!
1574871545.091954 ohci_dump_ed#61@0: ED(0xffff990051275e40) at 0x452a5e40:
1574871545.091955 ohci_dump_ed#61@0: addr=3 endpt=1 maxp=64
1574871545.091955 ohci_dump_ed#61@0: dir=0 speed=0 skip=0 iso=0
1574871545.091956 ohci_dump_ed#61@0: tailp=0x45bdbe20
1574871545.091956 ohci_dump_ed#61@0: headp=0x45bdbe22 nexted=0x452a5e80 halted=0 carry=1
1574871545.091957 ohci_dump_td#318@0: called!
1574871545.091957 ohci_dump_td#318@0: TD(0xffff99005294fe20) at 0x45bdbe20:
1574871545.091958 ohci_dump_td#318@0: round=1 DP=2 DI=1 T=0
1574871545.091958 ohci_dump_td#318@0: EC=0 CC=15
1574871545.091959 ohci_dump_td#318@0: td_cbp=0x45963a40 td_nexttd=0x45bdbd00 td_be=0x45963a7f
1574871545.091959 ohci_dump_td#319@0: called!
1574871545.091960 ohci_dump_td#319@0: TD(0xffff99005294fd00) at 0x45bdbd00:
1574871545.091960 ohci_dump_td#319@0: round=0 DP=0 DI=0 T=0
1574871545.091961 ohci_dump_td#319@0: EC=0 CC=0
1574871545.091961 ohci_dump_td#319@0: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871545.091962 ohci_device_bulk_start#8@0: --- dump end ---
1574871545.091964 ohci_softintr#53@0: --- ITD dump start ---
1574871545.091964 ohci_softintr#53@0: --- ITD dump end ---
1574871545.091965 ohci_softintr#53@0: done
1574871545.092365 ohci_device_bulk_abort#3@0: called!
1574871545.092366 ohci_device_bulk_abort#3@0: xfer=0xfffff4645591d578
1574871545.092366 ohci_abort_xfer#3@0: called!
1574871545.092367 ohci_abort_xfer#3@0: xfer=0xfffff4645591d578 pipe=0xfffff464bd34e408 sed=0xffff990051275e40
1574871545.092371 ohci_abort_xfer#3@0: stop ed=0xffff990051275e40
1574871545.120100 ohci_abort_xfer#3@0: --- dump start ---
1574871545.120100 ohci_abort_xfer#3@0: sed:
1574871545.120101 ohci_dump_ed#62@0: called!
1574871545.120101 ohci_dump_ed#62@0: ED(0xffff990051275e40) at 0x452a5e40:
1574871545.120102 ohci_dump_ed#62@0: addr=3 endpt=1 maxp=64
1574871545.120102 ohci_dump_ed#62@0: dir=0 speed=0 skip=1 iso=0
1574871545.120103 ohci_dump_ed#62@0: tailp=0x45bdbd00
1574871545.120103 ohci_dump_ed#62@0: headp=0x45bdbe22 nexted=0x452a5e80 halted=0 carry=1
1574871545.120104 ohci_dump_td#320@0: called!
1574871545.120105 ohci_dump_td#320@0: TD(0xffff99005294fe20) at 0x45bdbe20:
1574871545.120105 ohci_dump_td#320@0: round=1 DP=2 DI=1 T=0
1574871545.120106 ohci_dump_td#320@0: EC=0 CC=15
1574871545.120106 ohci_dump_td#320@0: td_cbp=0x45963a40 td_nexttd=0x45bdbd00 td_be=0x45963a7f
1574871545.120107 ohci_dump_td#321@0: called!
1574871545.120107 ohci_dump_td#321@0: TD(0xffff99005294fd00) at 0x45bdbd00:
1574871545.120108 ohci_dump_td#321@0: round=0 DP=0 DI=0 T=0
1574871545.120108 ohci_dump_td#321@0: EC=0 CC=0
1574871545.120109 ohci_dump_td#321@0: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871545.120109 ohci_abort_xfer#3@0: --- dump end ---
1574871545.120110 ohci_abort_xfer#3@0: set hd=0x45bdbd00, tl=0x45bdbd00
1574871545.120111 ohci_device_bulk_done#8@0: called!
1574871545.120111 ohci_device_bulk_done#8@0: xfer=0xfffff4645591d578, actlen=0
(test program exits having received a message)
(start test program for the second time)
1574871550.248864 ohci_device_bulk_start#9@1: called!
1574871550.248865 ohci_device_bulk_start#9@1: xfer=0xfffff4645591d578 len=64 isread=1 flags=4
1574871550.248865 ohci_device_bulk_start#9@1: endpt=129
1574871550.248866 ohci_reset_std_chain#47@1: called!
1574871550.248867 ohci_reset_std_chain#47@1: start len=64
1574871550.248868 ohci_reset_std_chain#47@1: addr=3 endpt=1 len=64 speed=2
1574871550.248869 ohci_reset_std_chain#47@1: sdataphys=0x45963a40 edataphys=0x45963a7f len=64 curlen=64
1574871550.248869 ohci_device_bulk_start#9@1: xfer 0xfffff4645591d578 data 0xffff99005294fd00 tail 0xffff99005294fe20
1574871550.248870 ohci_device_bulk_start#9@1: ed_flags=0x00400083 td_flags=0xfffffffff0340000 td_cbp=0x45963a40 td_be=0x45963a7f
1574871550.248871 ohci_device_bulk_start#9@1: --- dump start ---
1574871550.248871 ohci_dump_ed#63@1: called!
1574871550.248872 ohci_dump_ed#63@1: ED(0xffff990051275e40) at 0x452a5e40:
1574871550.248872 ohci_dump_ed#63@1: addr=3 endpt=1 maxp=64
1574871550.248873 ohci_dump_ed#63@1: dir=0 speed=0 skip=0 iso=0
1574871550.248873 ohci_dump_ed#63@1: tailp=0x45bdbd00
1574871550.248874 ohci_dump_ed#63@1: headp=0x45bdbd00 nexted=0x452a5e80 halted=0 carry=0
1574871550.248874 ohci_dump_td#322@1: called!
1574871550.248875 ohci_dump_td#322@1: TD(0xffff99005294fd00) at 0x45bdbd00:
1574871550.248875 ohci_dump_td#322@1: round=1 DP=2 DI=1 T=0
1574871550.248876 ohci_dump_td#322@1: EC=0 CC=15
1574871550.248876 ohci_dump_td#322@1: td_cbp=0x45963a40 td_nexttd=0x45bdbe20 td_be=0x45963a7f
1574871550.248877 ohci_dump_td#323@1: called!
1574871550.248878 ohci_dump_td#323@1: TD(0xffff99005294fe20) at 0x45bdbe20:
1574871550.248878 ohci_dump_td#323@1: round=0 DP=0 DI=0 T=0
1574871550.248879 ohci_dump_td#323@1: EC=0 CC=0
1574871550.248879 ohci_dump_td#323@1: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871550.248880 ohci_device_bulk_start#9@1: --- dump end ---
1574871550.249262 ohci_device_bulk_start#10@1: called!
1574871550.249263 ohci_device_bulk_start#10@1: xfer=0xfffff4645591d428 len=4 isread=0 flags=0
1574871550.249264 ohci_device_bulk_start#10@1: endpt=1
1574871550.249265 ohci_reset_std_chain#48@1: called!
1574871550.249265 ohci_reset_std_chain#48@1: start len=4
1574871550.249266 ohci_reset_std_chain#48@1: addr=3 endpt=1 len=4 speed=2
1574871550.249267 ohci_reset_std_chain#48@1: sdataphys=0x45963a80 edataphys=0x45963a83 len=4 curlen=4
1574871550.249267 ohci_device_bulk_start#10@1: xfer 0xfffff4645591d428 data 0xffff99005294fd60 tail 0xffff99005294ff40
1574871550.249268 ohci_device_bulk_start#10@1: ed_flags=0x00400083 td_flags=0xfffffffff0280000 td_cbp=0x45963a80 td_be=0x45963a83
1574871550.249268 ohci_device_bulk_start#10@1: --- dump start ---
1574871550.249269 ohci_dump_ed#64@1: called!
1574871550.249269 ohci_dump_ed#64@1: ED(0xffff990051275e80) at 0x452a5e80:
1574871550.249270 ohci_dump_ed#64@1: addr=3 endpt=1 maxp=64
1574871550.249271 ohci_dump_ed#64@1: dir=0 speed=0 skip=0 iso=0
1574871550.249271 ohci_dump_ed#64@1: tailp=0x45bdbd60
1574871550.249272 ohci_dump_ed#64@1: headp=0x45bdbd62 nexted=0x00000000 halted=0 carry=1
1574871550.249272 ohci_dump_td#324@1: called!
1574871550.249273 ohci_dump_td#324@1: TD(0xffff99005294fd60) at 0x45bdbd60:
1574871550.249273 ohci_dump_td#324@1: round=0 DP=1 DI=1 T=0
1574871550.249274 ohci_dump_td#324@1: EC=0 CC=15
1574871550.249274 ohci_dump_td#324@1: td_cbp=0x45963a80 td_nexttd=0x45bdbf40 td_be=0x45963a83
1574871550.249275 ohci_dump_td#325@1: called!
1574871550.249275 ohci_dump_td#325@1: TD(0xffff99005294ff40) at 0x45bdbf40:
1574871550.249276 ohci_dump_td#325@1: round=0 DP=0 DI=0 T=0
1574871550.249276 ohci_dump_td#325@1: EC=0 CC=0
1574871550.249277 ohci_dump_td#325@1: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871550.249277 ohci_device_bulk_start#10@1: --- dump end ---
1574871550.251052 ohci_intr#61@0: called!
1574871550.251054 ohci_intr1#61@0: called!
1574871550.251055 ohci_intr1#61@0: sc=0xffff990005177000
1574871550.251056 ohci_intr1#61@0: intrs=0x6(0x2) eintrs=0x2(0x5b)
1574871550.251058 ohci_intr1#61@0: sc 0xffff990005177000 blocking intrs 0x2
1574871550.251066 ohci_softintr#54@0: called!
1574871550.251067 ohci_softintr#54@0: add TD 0xffff99005294fd60
1574871550.251068 ohci_softintr#54@0: sdone=0xffff99005294fd60 sidone=0
1574871550.251069 ohci_softintr#54@0: --- TD dump start ---
1574871550.251069 ohci_dump_td#326@0: called!
1574871550.251070 ohci_dump_td#326@0: TD(0xffff99005294fd60) at 0x45bdbd60:
1574871550.251070 ohci_dump_td#326@0: round=0 DP=1 DI=1 T=2
1574871550.251071 ohci_dump_td#326@0: EC=0 CC=0
1574871550.251072 ohci_dump_td#326@0: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x45963a83
1574871550.251072 ohci_softintr#54@0: --- TD dump end ---
1574871550.251073 ohci_softintr#54@0: std=0xffff99005294fd60 xfer=0xfffff4645591d428 hcpriv=0xffff99005294fd60
1574871550.251076 ohci_softintr#54@0: len=4, flags=0x3
1574871550.251077 ohci_device_bulk_done#9@0: called!
1574871550.251077 ohci_device_bulk_done#9@0: xfer=0xfffff4645591d428, actlen=4
1574871550.251253 ohci_softintr#54@0: --- ITD dump start ---
1574871550.251254 ohci_softintr#54@0: --- ITD dump end ---
1574871550.251255 ohci_softintr#54@0: done
(test program is blocking in read() for 5 seconds until it gets a SIGALRM)
1574871555.273755 ohci_device_bulk_abort#4@1: called!
1574871555.273755 ohci_device_bulk_abort#4@1: xfer=0xfffff4645591d578
1574871555.273756 ohci_abort_xfer#4@1: called!
1574871555.273757 ohci_abort_xfer#4@1: xfer=0xfffff4645591d578 pipe=0xfffff464bd34e408 sed=0xffff990051275e40
1574871555.273762 ohci_abort_xfer#4@1: stop ed=0xffff990051275e40
1574871555.303822 ohci_abort_xfer#4@1: --- dump start ---
1574871555.303822 ohci_abort_xfer#4@1: sed:
1574871555.303823 ohci_dump_ed#65@1: called!
1574871555.303823 ohci_dump_ed#65@1: ED(0xffff990051275e40) at 0x452a5e40:
1574871555.303824 ohci_dump_ed#65@1: addr=3 endpt=1 maxp=64
1574871555.303825 ohci_dump_ed#65@1: dir=0 speed=0 skip=1 iso=0
1574871555.303825 ohci_dump_ed#65@1: tailp=0x45bdbe20
1574871555.303826 ohci_dump_ed#65@1: headp=0x45bdbd00 nexted=0x452a5e80 halted=0 carry=0
1574871555.303826 ohci_dump_td#327@1: called!
1574871555.303827 ohci_dump_td#327@1: TD(0xffff99005294fd00) at 0x45bdbd00:
1574871555.303827 ohci_dump_td#327@1: round=1 DP=2 DI=1 T=2
1574871555.303828 ohci_dump_td#327@1: EC=1 CC=3
1574871555.303828 ohci_dump_td#327@1: td_cbp=0x45963a40 td_nexttd=0x45bdbe20 td_be=0x45963a7f
1574871555.303829 ohci_dump_td#328@1: called!
1574871555.303830 ohci_dump_td#328@1: TD(0xffff99005294fe20) at 0x45bdbe20:
1574871555.303830 ohci_dump_td#328@1: round=0 DP=0 DI=0 T=0
1574871555.303831 ohci_dump_td#328@1: EC=0 CC=0
1574871555.303831 ohci_dump_td#328@1: td_cbp=0x00000000 td_nexttd=0x00000000 td_be=0x00000000
1574871555.303832 ohci_abort_xfer#4@1: --- dump end ---
1574871555.303833 ohci_abort_xfer#4@1: set hd=0x45bdbe20, tl=0x45bdbe20
1574871555.303834 ohci_device_bulk_done#10@1: called!
1574871555.303834 ohci_device_bulk_done#10@1: xfer=0xfffff4645591d578, actlen=0
(test program exits)
I suspect the problem is the "carry=0" at 1574871550.248874.
--
Andreas Gustafsson, gson@gson.org
From: Andreas Gustafsson <gson@gson.org>
To: gnats-bugs@NetBSD.org
Cc: Nick Hudson <nick.hudson@gmx.co.uk>
Subject: Re: kern/50278: umidi(4) loses first incoming message after second open
Date: Thu, 28 Nov 2019 11:34:24 +0200
I have found the cause of the problem in the OHCI case: the toggle
carry gets reset in ohci_abort_xfer() when the MIDI device is closed
as the test program exits for the first time. The following patch
fixes it. It's similar to the patch in PR 54070, but applies to
ohci_abort_xfer() rather than ohci_softintr().
Index: ohci.c
===================================================================
RCS file: /bracket/repo/src/sys/dev/usb/ohci.c,v
retrieving revision 1.290
diff -u -r1.290 ohci.c
--- ohci.c 11 Aug 2019 22:55:03 -0000 1.290
+++ ohci.c 28 Nov 2019 08:57:02 -0000
@@ -2348,7 +2348,9 @@
if (hit) {
DPRINTFN(1, "set hd=0x%08jx, tl=0x%08jx", (int)p->physaddr,
(int)O32TOH(sed->ed.ed_tailp), 0, 0);
- sed->ed.ed_headp = HTOO32(p->physaddr); /* unlink TDs */
+ /* unlink TDs, preserving toggle carry */
+ sed->ed.ed_headp = HTOO32(p->physaddr |
+ (O32TOH(sed->ed.ed_headp) & OHCI_TOGGLECARRY));
usb_syncmem(&sed->dma,
sed->offs + offsetof(ohci_ed_t, ed_headp),
sizeof(sed->ed.ed_headp),
--
Andreas Gustafsson, gson@gson.org
From: "Andreas Gustafsson" <gson@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc:
Subject: PR/50278 CVS commit: src/sys/dev/usb
Date: Fri, 29 Nov 2019 14:15:42 +0000
Module Name: src
Committed By: gson
Date: Fri Nov 29 14:15:42 UTC 2019
Modified Files:
src/sys/dev/usb: ohci.c
Log Message:
Preserve the toggleCarry bit in the Endpoint Descriptor in
ohci_abort_xfer(). Fixes the OHCI part of PR kern/50278.
To generate a diff of this commit:
cvs rdiff -u -r1.291 -r1.292 src/sys/dev/usb/ohci.c
Please note that diffs are not public domain; they are subject to the
copyright notices on the relevant files.
From: "Martin Husemann" <martin@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc:
Subject: PR/50278 CVS commit: [netbsd-9] src/sys/dev/usb
Date: Sat, 14 Dec 2019 12:35:58 +0000
Module Name: src
Committed By: martin
Date: Sat Dec 14 12:35:58 UTC 2019
Modified Files:
src/sys/dev/usb [netbsd-9]: ohci.c
Log Message:
Pull up following revision(s) (requested by gson in ticket #554):
sys/dev/usb/ohci.c: revision 1.292
Preserve the toggleCarry bit in the Endpoint Descriptor in
ohci_abort_xfer(). Fixes the OHCI part of PR kern/50278.
To generate a diff of this commit:
cvs rdiff -u -r1.289.4.2 -r1.289.4.3 src/sys/dev/usb/ohci.c
Please note that diffs are not public domain; they are subject to the
copyright notices on the relevant files.
From: Andreas Gustafsson <gson@gson.org>
To: gnats-bugs@netbsd.org
Cc: Nick Hudson <nick.hudson@gmx.co.uk>
Subject: Re: kern/50278: umidi(4) loses first incoming message after second open
Date: Sat, 14 Dec 2019 14:46:44 +0200
The OHCI fix has now been pulled up to NetBSD-9. The PR should remain
open because UHCI and EHCI are still broken.
--
Andreas Gustafsson, gson@gson.org
(Contact us)
$NetBSD: query-full-pr,v 1.45 2018/12/21 14:23:33 maya Exp $
$NetBSD: gnats_config.sh,v 1.9 2014/08/02 14:16:04 spz Exp $
Copyright © 1994-2017
The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.
Home