Hi Oliver,
finally got device which stops responding after while on my table...
On Mon, Jun 13, 2016 at 11:02:19AM +0200, Oliver Neukum wrote:
> On Mon, 2016-06-13 at 00:37 +0200, Ladislav Michl wrote:
> > On Sun, Jun 12, 2016 at 11:03:45PM +0200, Ladislav Michl wrote:
> > > Once ttyACM0 starts behave strangely, read() returns only what's in buffer before
> > > ttyACM0 was opened and then hangs infinitely. As this bug is hard to trigger, has
> > > anyone clue where to start debugging?
> >
> > Forgot to mention, once this happens "usb 3-1.4: clear tt 1 (9061) error -75"
> > starts showing in the syslog. Also "cdc_acm 3-1.4.3:1.0: failed to set dtr/rts",
> > but this one is there normally.
>
> The translation transactor in the hub is reporting an error.
> That should be reported to the driver, but there is no good
> error handling.
>
> static void acm_read_bulk_callback(struct urb *urb)
> {
> struct acm_rb *rb = urb->context;
> struct acm *acm = rb->instance;
> unsigned long flags;
> int status = urb->status;
>
> dev_vdbg(&acm->data->dev, "%s - urb %d, len %d\n", __func__,
> rb->index, urb->actual_length);
>
> if (!acm->dev) {
> set_bit(rb->index, &acm->read_urbs_free);
> dev_dbg(&acm->data->dev, "%s - disconnected\n", __func__);
> return;
> }
>
> if (status) {
> set_bit(rb->index, &acm->read_urbs_free);
> dev_dbg(&acm->data->dev, "%s - non-zero urb status: %d\n",
> __func__, status);
> if ((status != -ENOENT) || (urb->actual_length == 0))
> return;
> }
>
> Can you please switch on dynamic debugging for cdc_acm to see what
> is being reported?
The core of this problem is hardware related. I do not have a scope here
at the moment, but it seems that supply voltage drops too low once usb
modem tries to connect to network. Here's log what's happens before I'm
unable to read from device:
[ 45.765411] cdc_acm 3-1.4.3:1.1: submitted urb 0
[ 45.848327] PPP generic driver version 2.4.2
[ 45.869354] cdc_acm 3-1.4.3:1.1: got urb 5, len 14, status 0
[ 45.869445] cdc_acm 3-1.4.3:1.1: submitted urb 5
[ 45.870361] cdc_acm 3-1.4.3:1.1: got urb 6, len 7, status 0
[ 45.870452] cdc_acm 3-1.4.3:1.1: submitted urb 6
[ 45.871337] cdc_acm 3-1.4.3:1.1: got urb 7, len 16, status 0
[ 45.871459] cdc_acm 3-1.4.3:1.1: submitted urb 7
[ 45.872985] cdc_acm 3-1.4.3:1.1: got urb 8, len 8, status 0
[ 45.873077] cdc_acm 3-1.4.3:1.1: submitted urb 8
[ 45.873352] cdc_acm 3-1.4.3:1.1: got urb 9, len 17, status 0
[ 45.873443] cdc_acm 3-1.4.3:1.1: submitted urb 9
[ 45.874359] cdc_acm 3-1.4.3:1.1: got urb 10, len 9, status 0
[ 45.874481] cdc_acm 3-1.4.3:1.1: submitted urb 10
[ 45.875366] cdc_acm 3-1.4.3:1.1: got urb 11, len 8, status 0
[ 45.875457] cdc_acm 3-1.4.3:1.1: submitted urb 11
[ 45.876373] cdc_acm 3-1.4.3:1.1: got urb 12, len 10, status 0
[ 45.876464] cdc_acm 3-1.4.3:1.1: submitted urb 12
[ 45.877349] cdc_acm 3-1.4.3:1.1: got urb 13, len 15, status 0
[ 45.877471] cdc_acm 3-1.4.3:1.1: submitted urb 13
[ 45.878356] cdc_acm 3-1.4.3:1.1: got urb 14, len 2, status 0
[ 45.878479] cdc_acm 3-1.4.3:1.1: submitted urb 14
[snip...]
[ 46.344360] cdc_acm 3-1.4.3:1.1: got urb 15, len 14, status 0
[ 46.344482] cdc_acm 3-1.4.3:1.1: submitted urb 15
[ 46.464355] cdc_acm 3-1.4.3:1.1: got urb 1, len 7, status 0
[ 46.464447] cdc_acm 3-1.4.3:1.1: submitted urb 1
[ 46.465332] cdc_acm 3-1.4.3:1.1: got urb 2, len 2, status 0
[ 46.465423] cdc_acm 3-1.4.3:1.1: submitted urb 2
[ 46.628265] PPP BSD Compression module registered
[ 46.754638] PPP Deflate Compression module registered
[ 46.829711] cdc_acm 3-1.4.3:1.1: got urb 3, len 0, status -32
[ 46.994323] cdc_acm 3-1.4.3:1.1: got urb 4, len 0, status -32
[ 47.003601] cdc_acm 3-1.4.3:1.1: got urb 0, len 0, status -32
[ 47.008178] cdc_acm 3-1.4.3:1.1: got urb 5, len 0, status -32
[ 47.012695] cdc_acm 3-1.4.3:1.1: got urb 6, len 0, status -32
[ 47.035827] cdc_acm 3-1.4.3:1.1: got urb 7, len 0, status -32
[ 47.045074] cdc_acm 3-1.4.3:1.1: got urb 8, len 0, status -32
[ 47.049804] cdc_acm 3-1.4.3:1.1: got urb 9, len 0, status -32
[ 47.054321] cdc_acm 3-1.4.3:1.1: got urb 10, len 0, status -32
[ 47.079650] cdc_acm 3-1.4.3:1.1: got urb 11, len 0, status -71
[ 47.086547] cdc_acm 3-1.4.3:1.1: got urb 12, len 0, status -32
[ 47.095794] cdc_acm 3-1.4.3:1.1: got urb 13, len 0, status -32
[ 47.105163] cdc_acm 3-1.4.3:1.1: got urb 14, len 0, status -32
[ 47.111541] cdc_acm 3-1.4.3:1.1: got urb 15, len 8, status 0
[ 47.111663] cdc_acm 3-1.4.3:1.1: submitted urb 15
[ 47.112335] cdc_acm 3-1.4.3:1.1: got urb 1, len 37, status 0
[ 47.112426] cdc_acm 3-1.4.3:1.1: submitted urb 1
[ 47.113311] cdc_acm 3-1.4.3:1.1: got urb 2, len 8, status 0
[ 47.113433] cdc_acm 3-1.4.3:1.1: submitted urb 2
[ 47.114318] cdc_acm 3-1.4.3:1.1: got urb 15, len 0, status -32
[ 47.115325] cdc_acm 3-1.4.3:1.1: got urb 1, len 26, status 0
[ 47.115417] cdc_acm 3-1.4.3:1.1: submitted urb 1
[ 47.116333] cdc_acm 3-1.4.3:1.1: got urb 2, len 10, status 0
[ 47.116424] cdc_acm 3-1.4.3:1.1: submitted urb 2
[ 47.117462] cdc_acm 3-1.4.3:1.1: got urb 1, len 8, status 0
[ 47.117553] cdc_acm 3-1.4.3:1.1: submitted urb 1
[ 47.120330] cdc_acm 3-1.4.3:1.1: got urb 2, len 9, status 0
[ 47.120422] cdc_acm 3-1.4.3:1.1: submitted urb 2
[ 47.123596] cdc_acm 3-1.4.3:1.1: got urb 1, len 0, status -32
[ 47.132354] cdc_acm 3-1.4.3:1.1: got urb 2, len 0, status -32
No more characters are read. Sometimes voltage probably drops so
low, that device reconnects:
[ 43.190368] cdc_acm 3-1.4.3:1.1: submitted urb 8
[ 43.192230] cdc_acm 3-1.4.3:1.1: got urb 9, len 2, status 0
[ 43.192321] cdc_acm 3-1.4.3:1.1: submitted urb 9
[ 43.194122] cdc_acm 3-1.4.3:1.1: got urb 10, len 16, status 0
[ 43.194213] cdc_acm 3-1.4.3:1.1: submitted urb 10
[ 43.195037] cdc_acm 3-1.4.3:1.1: got urb 11, len 34, status 0
[ 43.195159] cdc_acm 3-1.4.3:1.1: submitted urb 11
[ 43.198059] cdc_acm 3-1.4.3:1.1: got urb 12, len 2, status 0
[ 43.198181] cdc_acm 3-1.4.3:1.1: submitted urb 12
[ 43.388275] cdc_acm 3-1.4.3:1.1: got urb 13, len 0, status -32
[ 43.397399] cdc_acm 3-1.4.3:1.1: got urb 14, len 0, status -32
[ 43.462219] cdc_acm 3-1.4.3:1.1: got urb 15, len 0, status -32
[ 43.466979] cdc_acm 3-1.4.3:1.1: got urb 1, len 0, status -32
[ 43.471649] cdc_acm 3-1.4.3:1.1: got urb 2, len 0, status -32
[ 43.481933] cdc_acm 3-1.4.3:1.1: got urb 0, len 0, status -32
[ 43.590179] cdc_acm 3-1.4.3:1.1: got urb 3, len 16, status 0
[ 43.590301] cdc_acm 3-1.4.3:1.1: submitted urb 3
[ 43.591247] cdc_acm 3-1.4.3:1.1: got urb 4, len 34, status 0
[ 43.591369] cdc_acm 3-1.4.3:1.1: submitted urb 4
[ 43.594024] cdc_acm 3-1.4.3:1.1: got urb 8, len 2, status 0
[ 43.594146] cdc_acm 3-1.4.3:1.1: submitted urb 8
[ 43.861541] cdc_acm 3-1.4.3:1.1: got urb 9, len 0, status -71
[ 43.872772] cdc_acm 3-1.4.3:1.1: got urb 10, len 0, status -32
[ 43.932739] cdc_acm 3-1.4.3:1.1: got urb 11, len 0, status -32
[ 43.941986] cdc_acm 3-1.4.3:1.1: got urb 12, len 0, status -32
[ 43.946624] cdc_acm 3-1.4.3:1.1: got urb 3, len 0, status -32
[ 44.099029] cdc_acm 3-1.4.3:1.1: got urb 4, len 0, status -32
[ 44.329956] cdc_acm 3-1.4.3:1.1: got urb 8, len 0, status -32
[ 47.246948] cdc_acm 3-1.4.3:1.0: acm_ctrl_irq - nonzero urb status received: -32
[ 47.375366] cdc_acm 3-1.4.3:1.0: acm_ctrl_irq - nonzero urb status received: -32
[ 47.504516] usb 3-1.4: USB disconnect, device number 5
[ 47.504577] usb 3-1.4.3: USB disconnect, device number 6
[ 47.518585] cdc_acm 3-1.4.3:1.0: acm_ctrl_irq - urb shutting down with status: -108
[ 47.538574] cdc_acm 3-1.4.3:1.0: acm_ctrl_msg - rq 0x22, val 0x0, len 0x0, result -19
[ 47.538604] cdc_acm 3-1.4.3:1.0: failed to set dtr/rts
[ 49.026275] PPP generic driver version 2.4.2
[ 49.091979] usb 3-1.4: new high-speed USB device number 9 using ehci-omap
[ 49.601928] usb 3-1.4: new high-speed USB device number 10 using ehci-omap
[ 49.755584] usb 3-1.4: New USB device found, idVendor=05e3, idProduct=0608
[ 49.755615] usb 3-1.4: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 49.755615] usb 3-1.4: Product: USB2.0 Hub
[ 49.773162] hub 3-1.4:1.0: USB hub found
[ 49.779479] hub 3-1.4:1.0: 4 ports detected
[ 49.974822] PPP BSD Compression module registered
[ 50.121948] usb 3-1.4.3: new full-speed USB device number 11 using ehci-omap
[ 50.140777] PPP Deflate Compression module registered
[ 50.276885] usb 3-1.4.3: New USB device found, idVendor=0483, idProduct=5740
[ 50.276916] usb 3-1.4.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 50.276947] usb 3-1.4.3: Product: Virtual COM Port
[ 50.276947] usb 3-1.4.3: Manufacturer: MEDIARESEARCH
[ 50.276947] usb 3-1.4.3: SerialNumber: VCP48D9738D3830
[ 50.281616] cdc_acm 3-1.4.3:1.0: The data interface has switched endpoints
[ 50.281646] cdc_acm 3-1.4.3:1.0: interfaces are valid
[ 50.282318] cdc_acm 3-1.4.3:1.0: ttyACM1: USB ACM device
[ 50.290191] cdc_acm 3-1.4.3:1.0: acm_ctrl_msg - rq 0x20, val 0x0, len 0x7, result 7
[ 50.486724] cdc_acm 3-1.4.3:1.1: submitted urb 0
[ 50.486755] cdc_acm 3-1.4.3:1.1: submitted urb 1
[ 50.486785] cdc_acm 3-1.4.3:1.1: submitted urb 2
[ 50.486816] cdc_acm 3-1.4.3:1.1: submitted urb 3
[ 50.486907] cdc_acm 3-1.4.3:1.1: got urb 0, len 31, status 0
[ 50.486999] cdc_acm 3-1.4.3:1.1: submitted urb 0
[ 50.487030] cdc_acm 3-1.4.3:1.1: submitted urb 4
[ 50.487060] cdc_acm 3-1.4.3:1.1: submitted urb 5
[ 50.487091] cdc_acm 3-1.4.3:1.1: submitted urb 6
[ 50.487121] cdc_acm 3-1.4.3:1.1: submitted urb 7
[ 50.487152] cdc_acm 3-1.4.3:1.1: submitted urb 8
[ 50.487152] cdc_acm 3-1.4.3:1.1: submitted urb 9
[ 50.487182] cdc_acm 3-1.4.3:1.1: submitted urb 10
[ 50.487213] cdc_acm 3-1.4.3:1.1: submitted urb 11
[ 50.487243] cdc_acm 3-1.4.3:1.1: submitted urb 12
[ 50.487243] cdc_acm 3-1.4.3:1.1: submitted urb 13
[ 50.487274] cdc_acm 3-1.4.3:1.1: submitted urb 14
[ 50.487304] cdc_acm 3-1.4.3:1.1: submitted urb 15
[ 50.487640] cdc_acm 3-1.4.3:1.1: 2 bytes from tty layer
[ 50.487670] cdc_acm 3-1.4.3:1.1: writing 2 bytes
[ 50.487731] cdc_acm 3-1.4.3:1.1: 2 bytes from tty layer
[ 50.487762] cdc_acm 3-1.4.3:1.1: writing 2 bytes
[ 50.487792] cdc_acm 3-1.4.3:1.1: 2 bytes from tty layer
[ 50.487823] cdc_acm 3-1.4.3:1.1: writing 2 bytes
[ 50.487915] cdc_acm 3-1.4.3:1.1: 2 bytes from tty layer
[ 50.487945] cdc_acm 3-1.4.3:1.1: writing 2 bytes
[ 50.491333] cdc_acm 3-1.4.3:1.0: acm_ctrl_msg - rq 0x22, val 0x3, len 0x0, result 0
[ 50.491455] cdc_acm 3-1.4.3:1.0: acm_tty_set_termios - set line: 115200 0 0 8
[ 50.502990] cdc_acm 3-1.4.3:1.0: acm_ctrl_msg - rq 0x20, val 0x0, len 0x7, result 7
[ 50.512298] cdc_acm 3-1.4.3:1.1: 43 bytes from tty layer
[ 50.512359] cdc_acm 3-1.4.3:1.1: writing 43 bytes
[ 50.525817] cdc_acm 3-1.4.3:1.1: got urb 1, len 14, status 0
[ 50.525909] cdc_acm 3-1.4.3:1.1: submitted urb 1
[ 50.526794] cdc_acm 3-1.4.3:1.1: got urb 2, len 37, status 0
[ 50.526916] cdc_acm 3-1.4.3:1.1: submitted urb 2
[ 50.529815] cdc_acm 3-1.4.3:1.1: got urb 3, len 2, status 0
Device operates normally after reconnect. So it seems you were right,
there's no handling for EPIPE and EPROTO errors reported to acm_read_bulk_callback.
Following patch fixes it for me, if it looks okay for you, I'll resend it
properly.
diff --git a/drivers/usb/class/cdc-acm.c b/drivers/usb/class/cdc-acm.c
index e62a703..ee7c533 100644
--- a/drivers/usb/class/cdc-acm.c
+++ b/drivers/usb/class/cdc-acm.c
@@ -425,15 +425,25 @@ static void acm_read_bulk_callback(struct urb *urb)
return;
}
- if (status) {
- set_bit(rb->index, &acm->read_urbs_free);
- if ((status != -ENOENT) || (urb->actual_length == 0))
- return;
+ switch (status) {
+ case 0:
+ usb_mark_last_busy(acm->dev);
+ acm_process_read_urb(acm, urb);
+ break;
+ case -ECONNRESET:
+ case -ENOENT:
+ case -ESHUTDOWN:
+ dev_dbg(&acm->control->dev,
+ "%s - urb shutting down with status: %d\n",
+ __func__, status);
+ return;
+ default:
+ dev_dbg(&acm->control->dev,
+ "%s - nonzero urb status received: %d\n",
+ __func__, status);
+ break;
}
- usb_mark_last_busy(acm->dev);
-
- acm_process_read_urb(acm, urb);
/*
* Unthrottle may run on another CPU which needs to see events
* in the same order. Submission has an implict barrier
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
