> -----Original Message-----
> From: Alan Stern [mailto:[email protected]]
> Sent: Tuesday, April 02, 2013 7:04 AM
> To: Oliver Neukum
> Cc: Mike Verstegen; [email protected]
> Subject: Re: cdc_acm device - unexpected characters sent to USB device
>
> On Tue, 2 Apr 2013, Oliver Neukum wrote:
>
> > On Monday 01 April 2013 22:05:47 Mike Verstegen wrote:
> >
> > Hi,
> >
> > > Such a simple question you asked -- but it lead to a
> useful discovery.
> > >
> > > My logs show that acm_tty_write is called multiple times
> > >
> > > - The application opens the device and then calls write() to send
> > > the 4 byte message to the fd. This results in a call to
> > > acm_tty_write
> > > - From somewhere else, acm_tty_write is called several
> times, each with a count=1 and one of the offending
> characters noted above.
> > >
> > > To get find out where the unexpected calls to
> acm_tty_write were coming from, I added a dump_stack at the
> entry point to acm_tty_write. From those stack frames, I can
> see that the first acm_tty_write call is from my application,
> but the second and subsequent calls are from a kworker thread.
> >
> > This is unexpected.
> >
> > > So at this point, it doesn't look like a cdc_acm driver
> problem, but instead an unexpected call to acm_tty_write from
> another process. Having briefly looked the trace output of
> the kworker queue, it may a challenge to find out what thread
> in there is making this call.
> >
> > I am afraid I have no idea on debugging for worker threads
> but people
> > on LKML might know.
>
> Mike, why don't you post one of the stack dumps for the
> kworker thread?
>
> Alan Stern
>
>
Hi Alan
Here is the trace of my application (scan_example, PID 6215) sending the 4 byte
00 00 00 01 command to the Bluetooth Low Energy (BLED) dongle culminating in
the application receiving a return from the write() call with no error.
Everything looks good.
Apr 1 14:54:33 localhost cpcenter: Sending ble_cmd_system_hello
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - top count = 4 buf
contains: 0x00 0x00 0x00 0x01
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - top - stack dump
- how did we get here?Pid: 6215, comm: scan_example Tainted: G O
3.5.3-1.el6.elrepo.i686 #1
Apr 1 14:54:33 localhost kernel: Call Trace:
Apr 1 14:54:33 localhost kernel: [<f9f648d5>] acm_tty_write+0x75/0x220
[cdc_acm]
Apr 1 14:54:33 localhost kernel: [<f9f640a3>] ? acm_wb_is_avail+0x43/0x50
[cdc_acm]
Apr 1 14:54:33 localhost kernel: [<f9f64134>] ? acm_tty_write_room+0x34/0x50
[cdc_acm]
Apr 1 14:54:33 localhost kernel: [<c12c62fa>] process_output_block+0x9a/0x190
Apr 1 14:54:33 localhost kernel: [<c12c7153>] n_tty_write+0x133/0x2a0
Apr 1 14:54:33 localhost kernel: [<c1077db0>] ? try_to_wake_up+0x230/0x230
Apr 1 14:54:33 localhost cpcenter: 1364842473.758958 write: data1: len=4
contains: 00 00 00 01
Apr 1 14:54:33 localhost kernel: [<c12c3921>] tty_write+0x151/0x210
Apr 1 14:54:33 localhost kernel: [<c11493a8>] ? rw_verify_area+0x68/0x110
Apr 1 14:54:33 localhost kernel: [<c12c7020>] ? n_tty_ioctl+0xf0/0xf0
Apr 1 14:54:33 localhost kernel: [<c11497c2>] vfs_write+0xa2/0x170
Apr 1 14:54:33 localhost kernel: [<c10b6776>] ?
__audit_syscall_exit+0x386/0x3d0
Apr 1 14:54:33 localhost kernel: [<c12c37d0>] ? tty_write_lock+0x60/0x60
Apr 1 14:54:33 localhost kernel: [<c1149962>] sys_write+0x42/0x70
Apr 1 14:54:33 localhost kernel: [<c14de81f>] sysenter_do_call+0x12/0x28
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - 1
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - 2
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_write_start
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_start_wb
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - 4
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_write_bulk
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_write_done
Apr 1 14:54:33 localhost cpcenter: BLED write 1 OK: ret = 4 (errno = 0)
The very next line in the logs show the unexpected bytes starting to be sent by
kworker/1:2 PID 818. This is repeated 8 times.
Apr 1 14:54:33 localhost cpcenter: df2d8b00 2025758302 S Bi:2:016:4 -115 128 <
Apr 1 14:54:33 localhost cpcenter: df2d8bc0 2025758317 S Bi:2:016:4 -115 128 <
Apr 1 14:54:33 localhost cpcenter: df2d8c80 2025758327 S Bi:2:016:4 -115 128 <
Apr 1 14:54:33 localhost cpcenter: df2d8d40 2025758337 S Bi:2:016:4 -115 128 <
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm read_bulk_callback
Apr 1 14:54:33 localhost kernel: MDV 1 acm_read_bulk_callback - urb 0, len 4
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_process_read_urb
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_submit_read_urb
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - top count = 1 buf
contains: 0x5e
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - top - stack dump
- how did we get here?Pid: 818, comm: kworker/1:2 Tainted: G O
3.5.3-1.el6.elrepo.i686 #1
Apr 1 14:54:33 localhost kernel: Call Trace:
Apr 1 14:54:33 localhost kernel: [<f9f648d5>] acm_tty_write+0x75/0x220
[cdc_acm]
Apr 1 14:54:33 localhost kernel: [<f9f640a3>] ? acm_wb_is_avail+0x43/0x50
[cdc_acm]
Apr 1 14:54:33 localhost kernel: [<c12c20a3>] tty_put_char+0x33/0x40
Apr 1 14:54:33 localhost kernel: [<c12c6757>] process_echoes+0x117/0x2c0
Apr 1 14:54:33 localhost kernel: [<c12c8409>] n_tty_receive_char+0x379/0x770
Apr 1 14:54:33 localhost kernel: [<c121fce4>] ? rb_erase+0xb4/0x120
Apr 1 14:54:33 localhost kernel: [<c12c89f6>] n_tty_receive_buf+0x1f6/0x380
Apr 1 14:54:33 localhost kernel: [<c14d62cb>] ? __schedule+0x39b/0x6d0
Apr 1 14:54:33 localhost kernel: [<c12ca192>] ? tty_ldisc_try+0x42/0x50
Apr 1 14:54:33 localhost kernel: [<c12cb30f>] flush_to_ldisc+0x15f/0x170
Apr 1 14:54:33 localhost kernel: [<c105ed8b>] process_one_work+0x10b/0x3b0
Apr 1 14:54:33 localhost kernel: [<c12cb1b0>] ? tty_buffer_free_all+0x70/0x70
Apr 1 14:54:33 localhost kernel: [<c1060e80>] worker_thread+0x140/0x3a0
Apr 1 14:54:33 localhost kernel: [<c1060d40>] ? manage_workers+0x110/0x110
Apr 1 14:54:33 localhost kernel: [<c106564c>] kthread+0x7c/0x90
Apr 1 14:54:33 localhost kernel: [<c10655d0>] ?
kthread_freezable_should_stop+0x60/0x60
Apr 1 14:54:33 localhost kernel: [<c14dedbe>] kernel_thread_helper+0x6/0x10
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - 1
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - 2
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_write_start
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_start_wb
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - 4
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - top count = 1 buf
contains: 0x40
Apr 1 14:54:33 localhost kernel: MDV:cdc-acm acm_tty_write - top - stack dump
- how did we get here?Pid: 818, comm: kworker/1:2 Tainted: G O
3.5.3-1.el6.elrepo.i686 #1
Apr 1 14:54:33 localhost kernel: Call Trace:
In studying the stack trace from the kworker call, I see that there appears to
be tty style line discipline (erase...) being applied. Though I had managed the
line discipline for the USB Serial devices (/dev/ttyUSB...) in other parts of
this project, I had not included any line discipline code previously when
dealing with ACM style devices (/dev/ttyACM...). I guess I was just lucky. I've
just copied over some code to set this device to raw mode.
struct termios usb_termio;
// set the USB to raw mode at 115 kbps
memset(&usb_termio, 0, sizeof(usb_termio)); // clear the structure
cfmakeraw(&usb_termio);
// with VMIN=0, VTIME serves as a timeout for the initial character
usb_termio.c_cc[VTIME] = 10; /* inter-character timer 0.1 sec */
usb_termio.c_cc[VMIN] = 0; /* blocking read until x chars received */
//cfsetospeed(&usb_termio, B115200);
//cfsetispeed(&usb_termio, B115200);
if (tcsetattr(BLED_fd, TCSANOW, &usb_termio)< 0)
{
perror("tcsetattr usb");
return(1);
}
After adding this code, the sample application appears to run - yeah! I'll do
some more complete testing today to verify.
A couple of follow up questions if you don't mind:
- For the cdc_acm driver, is the bit rate in termios just ignored?
- Similarly, are VMIN and VTIME used?
- Any idea why previous releases worked fine but a line discipline is now
applied to this cdc_acm port in the current release?
Thanks
Mike--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
