Christian Gmeiner, MSc
2012/10/11 Christian Gmeiner christian.gmeiner@gmail.com:
2012/10/11 Kevin O'Connor kevin@koconnor.net:
On Tue, Oct 09, 2012 at 02:31:05PM +0200, Christian Gmeiner wrote:
2012/10/9 Kevin O'Connor kevin@koconnor.net:
On Mon, Oct 08, 2012 at 02:14:03PM +0200, Christian Gmeiner wrote:
HI all
I am running into some usb problems with coreboot & seabios:
Can you set the debug level to 8 and post the whole log? Also, for timeout issues, having timestamps (via tools/readserial.py tool) sometimes helps.
Attached
Hrmm, I guess you've disabled threads in your config?
yep...
From your log, I see:
[14:23:00.5] ehci_send_bulk qh=0x000ef680 dir=0 data=0x00006d55 size=31^M [14:23:00.5] ehci_send_bulk qh=0x000ef700 dir=128 data=0x00006e3c size=36^M [14:23:00.5] ehci_send_bulk qh=0x000ef700 dir=128 data=0x00006d8f size=13^M [14:23:05.5] WARNING - Timeout at ehci_wait_td:542!^M [14:23:05.5] ehci pipe=0x000ef700 cur=00000000 tok=00000000 next=6b80 td=0x00006b80 +status=d0d80^M [14:23:05.5] USB transmission failed^M [14:23:05.5] Unable to configure USB MSC drive.^M
This looks like the transfer is stalling in the cdb_get_inquiry() call as part of scsi_init_drive(). The drive is identified okay and at least some transfers look okay, so it doesn't appear to be a controller issue.
I've been told some USB sticks are very picky about init order, but I'm surprised to see that this is occuring for you on a variety of USB sticks.
It's possible to verify that a stall has occurred - print out tds[i].token for all tds in ehci_send_bulk() on the error path.
Does this device still have problems if you soft-reset after a failed boot?
Here are the results with some more debug:
Cold Reboot
|0f7a5000| pmm_malloc zone=0x0f7afe87 handle=ffffffff size=192 align=40 ret=0x0f7a7bc0 (detail=0x0f7a7d70) |0f7a5000| ehci_control: td at phys(f7a7bc0): status: 80 : token 80e80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c00): status: 0 : token d00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c40): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef700 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef680 (detail=0x0f7a7d10) |0f7a5000| ehci_control 0x0f7a7cd0 (dir=128 cmd=8 data=1) |0f7a5000| pmm_malloc zone=0x0f7afe87 handle=ffffffff size=192 align=40 ret=0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| ehci_control: td at phys(f7a7bc0): status: 80 : token 80e80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c00): status: 0 : token d00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c40): status: 0 : token 1c00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| pmm_malloc zone=0x0f7afe83 handle=ffffffff size=48 align=10 ret=0x000fdae0 (detail=0x0f7a7ce0) |0f7a5000| usb_cmd_data id=0x000fdae0 write=0 count=1 bs=36 buf=0x0f7a5f3c |0f7a5000| cbw to device |0f7a5000| ehci_send_bulk qh=0x000ef680 dir=0 data=0x0f7a5e65 size=31 |0f7a5000| before setup: td at phys(f7a5c80): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| ehci_send_bulk: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| Data-In from the device to the host - 36 bytes |0f7a5000| ehci_send_bulk qh=0x000ef700 dir=128 data=0x0f7a5f3c size=36 |0f7a5000| before setup: td at phys(f7a5c80): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| ehci_send_bulk: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0
Warm Reboot
0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef700 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef680 (detail=0x0f7a7d10) |0f7a5000| ehci_control 0x0f7a7cd0 (dir=128 cmd=8 data=1) |0f7a5000| pmm_malloc zone=0x0f7afe87 handle=ffffffff size=192 align=40 ret=0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| ehci_control: td at phys(f7a7bc0): status: 80 : token 80e80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c00): status: 0 : token d00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c40): status: 0 : token 1c00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| pmm_malloc zone=0x0f7afe83 handle=ffffffff size=48 align=10 ret=0x000fdae0 (detail=0x0f7a7ce0) |0f7a5000| usb_cmd_data id=0x000fdae0 write=0 count=1 bs=36 buf=0x0f7a5f3c |0f7a5000| cbw to device |0f7a5000| ehci_send_bulk qh=0x000ef680 dir=0 data=0x0f7a5e65 size=31 |0f7a5000| before setup: td at phys(f7a5c80): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| ehci_send_bulk: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0
This is the used patch:
diff --git a/src/usb-ehci.c b/src/usb-ehci.c index 2676615..92a9c60 100644 --- a/src/usb-ehci.c +++ b/src/usb-ehci.c @@ -178,6 +178,14 @@ check_ehci_ports(struct usb_ehci_s *cntl)
- Setup
****************************************************************/
+static void dump_td(struct ehci_qtd *td, const char *func) +{
- u32 addr = (u32)td;
- dprintf(1, "%s: td at phys(%x): status: %x : token %x\n", func,
addr, td->token & QTD_STS_MASK, td->token);
- dprintf(1, "- cerr: %x, total_len: %x\n", (td->token &
QTD_CERR_MASK) >> QTD_CERR_SHIFT,
(td->token & QTD_LENGTH_MASK) >> QTD_LENGTH_SHIFT);
+}
// Wait for next USB async frame to start - for ensuring safe memory release. static void ehci_waittick(struct usb_ehci_s *cntl) @@ -535,6 +543,9 @@ ehci_wait_td(struct ehci_pipe *pipe, struct ehci_qtd *td, int timeout) status = td->token; if (!(status & QTD_STS_ACTIVE)) break;
dump_td(td, __func__);
if (check_tsc(end)) { u32 cur = GET_LOWFLAT(pipe->qh.current); u32 tok = GET_LOWFLAT(pipe->qh.token);
@@ -633,6 +644,7 @@ ehci_control(struct usb_pipe *p, int dir, const void *cmd, int cmdsize int i, ret=0; for (i=0; i<3; i++) { struct ehci_qtd *td = &tds[i];
dump_td(td, __func__); ret = ehci_wait_td(pipe, td, 500); if (ret) break;
@@ -665,18 +677,25 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize) struct ehci_qtd *td = &tds[tdpos++ % STACKQTDS]; int ret = ehci_wait_td(pipe, td, 5000); if (ret)
{
dump_td(td, "ehci_send_bulk ERROR2"); return -1;
} struct ehci_qtd *nexttd_fl = MAKE_FLATPTR(GET_SEG(SS) , &tds[tdpos % STACKQTDS]);
dump_td(td, "before setup");
int transfer = fillTDbuffer(td, maxpacket, data, datasize); td->qtd_next = (transfer==datasize ? EHCI_PTR_TERM : (u32)nexttd_fl); td->alt_next = EHCI_PTR_TERM; barrier();
td->token = (ehci_explen(transfer) | QTD_STS_ACTIVE
td->token = (/*ehci_explen(transfer) | */QTD_STS_ACTIVE | (dir ? QTD_PID_IN : QTD_PID_OUT) | ehci_maxerr(3));
dump_td(td, __func__);
data += transfer; datasize -= transfer;
}
@@ -685,7 +704,10 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize) struct ehci_qtd *td = &tds[tdpos++ % STACKQTDS]; int ret = ehci_wait_td(pipe, td, 5000); if (ret)
{
dump_td(td, "ehci_send_bulk ERROR2"); return -1;
}
}
return 0;
greets
Here is the log of filo using libpayload
[16:40:24.5] FILO version 0.6.0 (christian@chgm-pc) Thu Oct 11 16:12:26 CEST 2012 [16:40:24.5] 00:0f.5 2095:1022.5 EHCI controller [16:40:24.7] highspeed device [16:40:24.7] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:24.8] - cerr: 3, total_len: 0
[16:40:24.8] wait_for_tds done: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:24.8] - cerr: 3, total_len: 0
[16:40:24.8] moving from 148260 to 1482a0 [16:40:24.8] wait_for_tds: td at phys(1f6b22a0): status: 0 token: 100
[16:40:24.8] - cerr: 0, total_len: 0
[16:40:24.8] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:24.8] - cerr: 3, total_len: 0
[16:40:24.8] wait_for_tds done: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:24.9] - cerr: 3, total_len: 0
[16:40:24.9] moving from 148260 to 1482a0 [16:40:24.9] wait_for_tds: td at phys(1f6b22a0): status: 0 token: d00
[16:40:25.0] - cerr: 3, total_len: 0
[16:40:25.0] wait_for_tds done: td at phys(1f6b22a0): status: 0 token: d00
[16:40:25.0] - cerr: 3, total_len: 0
[16:40:25.1] moving from 1482a0 to 1482e0 [16:40:25.1] wait_for_tds: td at phys(1f6b22e0): status: 0 token: 1000
[16:40:25.2] - cerr: 0, total_len: 0
[16:40:25.2] maxPacketSize0: 40 [16:40:25.2] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:25.2] - cerr: 3, total_len: 0
[16:40:25.3] wait_for_tds done: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:25.3] - cerr: 3, total_len: 0
[16:40:25.4] moving from 148260 to 1482a0 [16:40:25.4] wait_for_tds: td at phys(1f6b22a0): status: 0 token: d00
[16:40:25.5] - cerr: 3, total_len: 0
[16:40:25.5] wait_for_tds done: td at phys(1f6b22a0): status: 0 token: d00
[16:40:25.5] - cerr: 3, total_len: 0
[16:40:25.6] moving from 1482a0 to 1482e0 [16:40:25.6] wait_for_tds: td at phys(1f6b22e0): status: 0 token: 1000
[16:40:25.7] - cerr: 0, total_len: 0
[16:40:25.7] * found device (0x1370:0x3252, USB 2.0) [16:40:25.7] device has 1 configurations [16:40:25.7] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:25.8] - cerr: 3, total_len: 0
[16:40:25.8] wait_for_tds done: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:25.9] - cerr: 3, total_len: 0
[16:40:25.9] moving from 148260 to 1482a0 [16:40:26.0] wait_for_tds: td at phys(1f6b22a0): status: 0 token: d00
[16:40:26.0] - cerr: 3, total_len: 0
[16:40:26.0] wait_for_tds done: td at phys(1f6b22a0): status: 0 token: d00
[16:40:26.1] - cerr: 3, total_len: 0
[16:40:26.1] moving from 1482a0 to 1482e0 [16:40:26.1] wait_for_tds: td at phys(1f6b22e0): status: 0 token: 1000
[16:40:26.2] - cerr: 0, total_len: 0
[16:40:26.2] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:26.3] - cerr: 3, total_len: 0
[16:40:26.3] wait_for_tds done: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:26.4] - cerr: 3, total_len: 0
[16:40:26.4] moving from 148260 to 1482a0 [16:40:26.4] wait_for_tds: td at phys(1f6b22a0): status: 0 token: d00
[16:40:26.5] - cerr: 3, total_len: 0
[16:40:26.5] wait_for_tds done: td at phys(1f6b22a0): status: 0 token: d00
[16:40:26.6] - cerr: 3, total_len: 0
[16:40:26.6] moving from 1482a0 to 1482e0 [16:40:26.7] wait_for_tds: td at phys(1f6b22e0): status: 0 token: 1000
[16:40:26.7] - cerr: 0, total_len: 0
[16:40:26.7] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:26.8] - cerr: 3, total_len: 0
[16:40:26.8] wait_for_tds done: td at phys(1f6b2260): status: 0 token: 80000e00
[16:40:26.8] - cerr: 3, total_len: 0
[16:40:26.9] moving from 148260 to 1482a0 [16:40:26.9] wait_for_tds: td at phys(1f6b22a0): status: 0 token: 100
[16:40:27.0] - cerr: 0, total_len: 0
[16:40:27.0] device has 1 interfaces [16:40:27.0] #0 has 2 endpoints, interface 8:6, protocol 50 [16:40:27.0] #1: Endpoint 1 (in), max packet size 200, type bulk [16:40:27.1] #2: Endpoint 2 (out), max packet size 200, type bulk [16:40:27.1] , class: MSC [16:40:27.1] Waiting for device to become ready...ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:27.2] - cerr: 0, total_len: 0
[16:40:27.2] wait_for_tds: td at phys(1f6b2260): status: 1 token: 80000001
[16:40:27.3] - cerr: 0, total_len: 0
[16:40:27.3] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:27.3] - cerr: 0, total_len: 0
[16:40:27.4] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000100
[16:40:27.4] - cerr: 0, total_len: 0
[16:40:27.5] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:27.5] - cerr: 0, total_len: 0
[16:40:27.5] wait_for_tds: td at phys(1f6b2260): status: 1 token: 1
[16:40:27.6] - cerr: 0, total_len: 0
[16:40:27.6] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:27.7] - cerr: 0, total_len: 0
[16:40:27.7] wait_for_tds: td at phys(1f6b2260): status: 0 token: 100
[16:40:27.7] - cerr: 0, total_len: 0
[16:40:27.8] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:27.8] - cerr: 0, total_len: 0
[16:40:27.9] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000100
[16:40:27.9] - cerr: 0, total_len: 0
[16:40:28.1] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:28.1] - cerr: 0, total_len: 0
[16:40:28.2] wait_for_tds: td at phys(1f6b2260): status: 1 token: 80000001
[16:40:28.2] - cerr: 0, total_len: 0
[16:40:28.2] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:28.3] - cerr: 0, total_len: 0
[16:40:28.3] wait_for_tds: td at phys(1f6b2260): status: 0 token: 100
[16:40:28.3] - cerr: 0, total_len: 0
[16:40:28.4] ok. [16:40:28.4] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:28.4] - cerr: 0, total_len: 0
[16:40:28.5] wait_for_tds: td at phys(1f6b2260): status: 1 token: 1
[16:40:28.5] - cerr: 0, total_len: 0
[16:40:28.6] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:28.6] - cerr: 0, total_len: 0
[16:40:28.6] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000100
[16:40:28.7] - cerr: 0, total_len: 0
[16:40:28.7] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:28.8] - cerr: 0, total_len: 0
[16:40:28.8] wait_for_tds: td at phys(1f6b2260): status: 1 token: 80000001
[16:40:28.9] - cerr: 0, total_len: 0
[16:40:28.9] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:28.9] - cerr: 0, total_len: 0
[16:40:29.0] wait_for_tds: td at phys(1f6b2260): status: 0 token: 100
[16:40:29.0] - cerr: 0, total_len: 0
[16:40:29.1] ehci_bulk: setup: td at phys(148260): status: 0 token: 0
[16:40:29.1] - cerr: 0, total_len: 0
[16:40:29.2] wait_for_tds: td at phys(1f6b2260): status: 0 token: 80000100
[16:40:29.2] - cerr: 0, total_len: 0
[16:40:29.2] 15663104 512-byte sectors (8019 MB) [16:40:29.3] 00:0f.4 2094:1022.4 OHCI controller [16:40:29.3] OHCI Version 1.0 [16:40:29.4] ERROR: No such CMOS option (boot_devices) [16:40:29.4] menu: hda3:/boot/filo/menu.lst
--- Christian Gmeiner, MSc