> -----Original Message----- > From: Alan Stern [mailto:stern@xxxxxxxxxxxxxxxxxxx] > Sent: Tuesday, April 02, 2013 7:04 AM > To: Oliver Neukum > Cc: Mike Verstegen; linux-usb@xxxxxxxxxxxxxxx > 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 majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
