Linux cdc_acm 设备 - 发送到设备的意外字符答案

【问题标题】：Linux cdc_acm device - unexpected characters sent to deviceLinux cdc_acm 设备 - 发送到设备的意外字符
【发布时间】：2013-02-14 02:31:03
【问题描述】：

我在使用 cdc_acm 驱动程序在 USB 端口上发送意外字符时遇到问题。更令人困惑的是，代码在 Ubuntu 12.04（3.2 内核）上运行良好，但在 Centos 6（3.6 内核）上运行失败（这个问题的主题）

USB 设备是 Bluegiga BLED112 蓝牙智能加密狗。它的嵌入式微控制器将随时在其 USB 接口上出现意外输入时重置。

测试代码打开端口，写入 4 个字节（一个 hello 消息）并期望读取响应。读取永远不会完成，因为意外字符会导致设备重置，从而导致集线器丢弃设备并重新枚举。

为了解决问题，我做了以下工作：

已下载 cdc_acm 驱动程序的源代码。添加了一堆 printk 调试消息和 stack_dumps 来跟踪正在发生的事情。
我对“库存”cdc_acm 进行了 rmmod，并对我的检测模块进行了 insmod。所有的设备枚举工作，正确的驱动程序，等等。
由于代码在 Ubuntu 12.04/Linux 3.2 上运行，我获取了 3.2 cdc_acm 代码并在 Centos 6/Linux 3.6 平台上编译了该模块。使用 3.2 模块而不是 3.6 模块并没有什么不同。我恢复到 3.6 模块。
使用 usbmon 打开调试文件系统并观察 USB 流量。我可以看到 USB 接口上发送了额外的字符。
为了观察发生了什么，在 cdc_acm 模块中的 printk 之上，我合并了 usb mon (cat /sys/kernel/debug/usb/usbmon/3u | logger) 的输出和测试应用程序 (scan_example /dev/ttyACM0 | logger -s) 所以我有一个时间相关调试跟踪流。
在 USB 端点上发送的虚假字符是 x5E x40 x5E x40 x5E x40 x5E x40 x41（在 ASCII 中是 ^@^@^@^@A），看起来像是某种探测或试图引起注意调制解调器这些字符在应用程序的 write() 导致 4 个 hello 字节被发送到端点后立即发送。
由于 cdc_acm 设备应该是调制解调器，我尝试通过将其添加到 cdc_acm.c 中的 usb_device_id acm_ids[] 来关闭调制解调器控制
```
/* bluegiga BLED112*/
{ USB_DEVICE(0x2458, 0x0001),
.driver_info = NOT_A_MODEM,
},
```
重新编译和 insmod'd 和 syslog 显示这已被识别（怪癖为 8），但功能没有变化。

NetowrkManager 和 modem-manager 都没有运行，但我仍然怀疑某处有某种调制解调器控制功能，我只是不知道在哪里。

这是一个带注释的调试日志（MDV 是我添加到 cdc_acm 的那些 printk 的前缀）

Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done

这是应用程序发送的 4 个字节 00 00 00 01

Feb 13 18:14:32 localhost cpcenter: df046a80 3672670191 C Bi:3:006:4 0 4 = 00000001
Feb 13 18:14:32 localhost cpcenter: 1360797272.669690 write: data2: len=0 contains:

...这些附加字符意外出现 5e 40 5e 40 5e 40....

Feb 13 18:14:32 localhost cpcenter: df046a80 3672670232 S Bi:3:006:4 -115 128 <
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670297 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672670332 S Bo:3:006:4 -115 1 = 40
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670347 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670392 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost cpcenter: df2e1180 3672670426 S Bo:3:006:4 -115 1 = 40
Feb 13 18:14:32 localhost cpcenter: df2e1c00 3672670461 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost cpcenter: df2e1840 3672670496 S Bo:3:006:4 -115 1 = 40
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672670591 C Bo:3:006:4 0 1 >

此时我们会自发断开连接。

Feb 13 18:14:32 localhost kernel: usb 3-1: USB disconnect, device number 6
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 1, len 0
Feb 13 18:14:32 localhost kernel: MDV 3 acm_read_bulk_callback - non-zero urb status: -71
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 1, len 0
Feb 13 18:14:32 localhost kernel: MDV 3 acm_read_bulk_callback - non-zero urb status: -71
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 2, len 0
Feb 13 18:14:32 localhost cpcenter: df2e1d80 3672670629 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost kernel: MDV 3 acm_read_bulk_callback - non-zero urb status: -71
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672670677 S Bo:3:006:4 -115 1 = 41
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670802 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: df2e1180 3672671019 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: df2e1c00 3672671237 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: dfbf8c00 3672673193 C Ii:3:001:1 0:2048 1 = 02
Feb 13 18:14:32 localhost cpcenter: dfbf8c00 3672673207 S Ii:3:001:1 -115:2048 4 <
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673221 S Ci:3:001:0 s a3 00 0000 0001 0004 4 <
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_disconnect
Feb 13 18:14:32 localhost kernel: Pid: 29, comm: khubd Tainted: G           O 3.5.3-1.el6.elrepo.i686 #1

断开连接时的堆栈跟踪

Feb 13 18:14:32 localhost kernel: Call Trace:
Feb 13 18:14:32 localhost kernel: [<f82dabc5>] acm_disconnect+0x35/0x1f0 [cdc_acm]
Feb 13 18:14:32 localhost kernel: [<c13835db>] usb_unbind_interface+0x4b/0x180
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673239 C Ci:3:001:0 0 4 = 00010100
Feb 13 18:14:32 localhost kernel: [<c1318bfb>] __device_release_driver+0x5b/0xb0
Feb 13 18:14:32 localhost kernel: [<c1318d05>] device_release_driver+0x25/0x40
Feb 13 18:14:32 localhost kernel: [<c1317f0c>] bus_remove_device+0xcc/0x130
Feb 13 18:14:32 localhost kernel: [<c131612f>] ? device_remove_attrs+0x2f/0x90
Feb 13 18:14:32 localhost kernel: [<c1316275>] device_del+0xe5/0x180
Feb 13 18:14:32 localhost kernel: [<c1380326>] usb_disable_device+0x96/0x240    Feb 13 18:14:32 localhost kernel: [<c1379f91>] usb_disconnect+0x91/0x130
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: [<c137a2c0>] hub_port_connect_change+0xb0/0xa60
Feb 13 18:14:32 localhost kernel: [<c1380f4e>] ? usb_control_msg+0xce/0xe0
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: [<c137b296>] hub_events+0x536/0x810
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673243 S Co:3:001:0 s 23 01 0010 0001 0000 0
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673250 C Co:3:001:0 0 0
Feb 13 18:14:32 localhost kernel: [<c1065bdf>] ? finish_wait+0x4f/0x70
Feb 13 18:14:32 localhost kernel: [<c137b5aa>] hub_thread+0x3a/0x1d0
Feb 13 18:14:32 localhost cpcenter: df2e1840 3672673260 C Bo:3:006:4 -71 0
Feb 13 18:14:32 localhost kernel: [<c1065a70>] ? wake_up_bit+0x30/0x30
Feb 13 18:14:32 localhost kernel: [<c137b570>] ? hub_events+0x810/0x810
Feb 13 18:14:32 localhost kernel: [<c106564c>] kthread+0x7c/0x90
Feb 13 18:14:32 localhost cpcenter: f3c16c80 3672673292 C Bi:3:006:4 -71 0
Feb 13 18:14:32 localhost cpcenter: df2e1d80 3672673453 C Bo:3:006:4 -71 0
Feb 13 18:14:32 localhost cpcenter: f3c16d40 3672673553 C Bi:3:006:4 -71 0
Feb 13 18:14:32 localhost kernel: [<c10655d0>] ? kthread_freezable_should_stop+0x60/0x60
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: [<c14dedbe>] kernel_thread_helper+0x6/0x10
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 3, len 0
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm stop_data_traffic
Feb 13 18:14:32 localhost cpcenter: f3d19500 3672674474 C Ii:3:006:2 -108:64 0
Feb 13 18:14:32 localhost kernel: MDV 2 acm_read_bulk_callback - disconnected
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672674636 C Bo:3:006:4 -71 0
Feb 13 18:14:32 localhost cpcenter: f3c16140 3672674753 C Bi:3:006:4 -71 0

【问题讨论】：

标签： linux usb cdc

【解决方案1】：

发送到您设备的^@^@^@^A 字符串是内核中的终端子系统响应来自您设备的传入字节而执行的回显结果。

日志中的这一行：

Feb 13 18:14:32 localhost cpcenter: df046a80 3672670191 C Bi:3:006:4 0 4 = 00000001

实际上意味着您的设备向计算机发送了 4 个字节（Bi 表示“批量端点，输入”）。默认情况下，所有终端设备都启用了回显，因此内核将这些字节回显给设备，但由于这些字节在控制字符范围内，它们以转义形式回显：^@^@^@^A。这些回显的字节也在单独的 1 字节写入调用中发送，这对应于后续日志中的 1 字节批量输出 URB。

您需要修复您的测试程序，使其在尝试与您的设备通信之前关闭回显和其他 tty 处理。如果您的测试程序是 C/C++ 语言，则可以使用 cfmakeraw() 函数。

该程序可能在 Ubuntu 中运行，只是因为其他程序碰巧在您的测试程序之前接触了端口并更改端口设置以关闭回显。

【讨论】：

分析正确，有助于解决问题。查看内核跟踪，它显示localhost kernel: [<c12c6757>] process_echoes+0x117/0x2c0 localhost kernel: [<c12c8409>] n_tty_receive_char+0x379/0x770 localhost kernel: [<c121fce4>] ? rb_erase+0xb4/0x120 localhost kernel: [<c12c89f6>] n_tty_receive_buf+0x1f6/0x380 localhost kernel: [<c14d62cb>] ? __schedule+0x39b/0x6d0
分析正确，有助于解决问题。查看内核跟踪，它显示localhost kernel: [<c12c6757>] process_echoes+0x117/0x2c0 localhost kernel: [<c12c8409>] n_tty_receive_char+0x379/0x770 localhost kernel: [<c121fce4>] ? rb_erase+0xb4/0x120 localhost kernel: [<c12c89f6>] n_tty_receive_buf+0x1f6/0x380 localhost kernel: [<c14d62cb>] ? __schedule+0x39b/0x6d0，它显示 tty 子系统回显和擦除字符。我添加了使用 tcsetattr() 的代码，该代码与 cfmakeraw() 属于同一家族，以删除线路规则，现在它可以工作了
遇到了同样的问题，但有趣的是，使用相同的电缆和设备，我在 Olinuxino 板上遇到了问题，而在我的普通计算机上没有问题。我相信在这两种情况下都设置了 echo（两个主机上的 stty -a 输出相同）。这就是为什么我没有责怪它并求助于分析 usbmon 输出，在那里看到 5e40，谷歌搜索并发现了这个绝妙的问题：)
也遇到了这个问题。令人讨厌的是，这样的通用串行设备默认被操作系统解释为终端。但请注意，提供的解决方案并不能完全解决问题，因为必须在任何数据内核接收到设备之前禁用回显。否则，就像我的情况一样，它会受到竞争条件的影响。（在下一条评论中继续......）
(...continuation) 在我的情况下，设备是自定义 CDC ACM 设备，它在收到 D0=1（存在 DTE）的 SetControlLineState 命令后立即开始向主机发送数据，该命令由主机应用程序打开 tty 文件描述符时的主机内核/驱动程序。有时内核/驱动程序有时间接收此数据并在应用程序调用 cfmakeraw()/tcsetattr() 之前将其回显。这会导致设备接收到一些意外的垃圾信息。此外，它还会以某种方式破坏设备->主机方向的数据流。