Hi,
I'm enocuntering an issue with the cdc-acm USB serial driver. I have an
embedded device that acts as a USB serial device, and is recognized USB
ACM device:
Apr 21 14:59:12 tomodachi kernel: [12207.024066] usb 1-1: new full speed
USB device using uhci_hcd and address 15
Apr 21 14:59:13 tomodachi kernel: [12207.188440] usb 1-1: configuration
#1 chosen from 1 choice
Apr 21 14:59:13 tomodachi kernel: [12207.198678] cdc_acm 1-1:1.0:
ttyACM0: USB ACM device
I'm using a very simple communication protocol with the device. here's
some sample C++ code that just asks a status, and waits for a reply:
#include <iostream>
#include <boost/asio.hpp>
using namespace boost::asio;
static const std::string serial_device("/dev/ttyACM0");
static const unsigned char status_message[] = { 6, 10, 0, 0, 0, 0 };
static unsigned char status_ack_message[64];
int main(int argc, char **argv) {
io_service io;
serial_port sp(io);
std::cerr << "opening serial device " << serial_device << std::endl;
sp.open(serial_device);
std::cerr << "serial port open: " << sp.is_open() << std::endl;
std::cerr << "setting serial port parameters" << std::endl;
sp.set_option(serial_port_base::baud_rate(19200));
sp.set_option(serial_port_base::character_size(8));
sp.set_option(serial_port_base::flow_control(
serial_port_base::flow_control::none));
sp.set_option(serial_port_base::parity(
serial_port_base::parity::none));
sp.set_option(serial_port_base::stop_bits(
serial_port_base::stop_bits::one));
std::size_t written = write(sp, buffer(status_message));
std::cerr << "written bytes: " << written << std::endl;
std::size_t read = sp.read_some(buffer(status_ack_message));
std::cerr << "read bytes: " << read << std::endl;
return 0;
}
now, this all works fine on kernel 2.6.24 (ubuntu 8.04, gcc 4.2.4,
kernel 2.6.24-23-generic x86_64):
$ ./asio_serial
opening serial device /dev/ttyACM0
serial port open: 1
setting serial port parameters
written bytes: 6
read bytes: 48
the related strace is:
...
writev(5, [{"\6\n\0\0\0\0", 6}], 1) = 6
write(2, "written bytes: ", 15written bytes: ) = 15
write(2, "6", 16) = 1
write(2, "\n", 1
) = 1
readv(5, 0x7fffb6ee8f90, 1) = -1 EAGAIN (Resource
temporarily unavailable)
poll([{fd=5, events=POLLIN, revents=POLLIN}], 1, -1) = 1
readv(5, [{"0\v\0\0\0\0X\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
64}], 1) = 48
write(2, "read bytes: ", 12read bytes: ) = 12
write(2, "48", 248) = 2
write(2, "\n", 1
) = 1
epoll_ctl(3, EPOLL_CTL_DEL, 5, {0, {u32=0, u64=0}}) = 0
close(5) = 0
close(3) = 0
close(4) = 0
exit_group(0) = ?
Process 24775 detached
now, if I run the same on 2.6.27 (ubuntu 8.10, kernel 2.6.27-11-generic
x86_64), the above hangs att the poll() call:
$ ./asio_serial
opening serial device /dev/ttyACM0
serial port open: 1
setting serial port parameters
written bytes: 6
the related strace is:
writev(5, [{"\6\n\0\0\0\0", 6}], 1) = 6
write(2, "written bytes: ", 15written bytes: ) = 15
write(2, "6", 16) = 1
write(2, "\n", 1
) = 1
readv(5, 0x7fff135ac650, 1) = -1 EAGAIN (Resource
temporarily unavailable)
poll( <unfinished ...>
and it just hangs there forever.
from the kernel changelog, I saw there were changes made to the cdc-acm
mobule between 2.6.24 and 2.6.27. might those changes by in relation to
the above effect?
any help is appreciated...
Akos
Am Dienstag 21 April 2009 15:04:13 schrieb Maróy Ákos:
> and it just hangs there forever.
>
> from the kernel changelog, I saw there were changes made to the cdc-acm
> mobule between 2.6.24 and 2.6.27. might those changes by in relation to
> the above effect?
>
> any help is appreciated...
Does it happen with 2.6.29?
Could you get dmesg of 2.6.2(7/9) with CONFIG_USB_DEBUG and debug
activated in drivers/usb/class/cdc-acm.c ?
Regards
Oliver
Oliver,
> Does it happen with 2.6.29?
haven't tried yet. I'm just upgrading to ubuntu 9.04, which has 2.6.28
built in.
I also see cdc-acm fixes in the 2.6.28 Changelog, like:
USB: gadget: cdc-acm deadlock fix
> Could you get dmesg of 2.6.2(7/9) with CONFIG_USB_DEBUG and debug
> activated in drivers/usb/class/cdc-acm.c ?
ok, let me upgrade to 2.6.28 first, and if the proplem still persists,
I'll compile 2.6.29 with the above settings manually.
Akos
Am Dienstag 21 April 2009 15:33:03 schrieb Maróy Ákos:
> Oliver,
>
> > Does it happen with 2.6.29?
>
> haven't tried yet. I'm just upgrading to ubuntu 9.04, which has 2.6.28
> built in.
>
> I also see cdc-acm fixes in the 2.6.28 Changelog, like:
>
> USB: gadget: cdc-acm deadlock fix
That's gadget code. Your problem is on the host's side.
>
> > Could you get dmesg of 2.6.2(7/9) with CONFIG_USB_DEBUG and debug
> > activated in drivers/usb/class/cdc-acm.c ?
>
> ok, let me upgrade to 2.6.28 first, and if the proplem still persists,
> I'll compile 2.6.29 with the above settings manually.
Thanks.
Regards
Oliver
Oliver,
>> ok, let me upgrade to 2.6.28 first, and if the proplem still persists,
>> I'll compile 2.6.29 with the above settings manually.
FYI, I upgraded to 2.6.28 (ubuntu 9.04), and the problem still persists.
will go ahead and compile 2.6.29.
Akos
Dear Olvier,
>>> Could you get dmesg of 2.6.2(7/9) with CONFIG_USB_DEBUG and debug
>>> activated in drivers/usb/class/cdc-acm.c ?
FYI, I compiled 2.6.29.1, and it doesn't work with this kernel either.
I'll compiple with the above flag, and will provide output. should I
just paste dmesg for when the cdc-acm module is loaded?
Akos
Am Dienstag 21 April 2009 18:55:28 schrieb Maróy Ákos:
> I'll compiple with the above flag, and will provide output. should I
> just paste dmesg for when the cdc-acm module is loaded?
Yes.
Regards
Oliver
Oliver,
> Does it happen with 2.6.29?
> Could you get dmesg of 2.6.2(7/9) with CONFIG_USB_DEBUG and debug
> activated in drivers/usb/class/cdc-acm.c ?
interesting, the dmesg output is not that talkative:
Apr 22 11:50:37 tomodachi kernel: [ 623.236068] usb 2-1: new full speed
USB device using uhci_hcd and address 2
Apr 22 11:50:37 tomodachi kernel: [ 623.400102] usb 2-1: New USB device
found, idVendor=ffff, idProduct=0005
Apr 22 11:50:37 tomodachi kernel: [ 623.400107] usb 2-1: New USB device
strings: Mfr=1, Product=2, SerialNumber=3
Apr 22 11:50:37 tomodachi kernel: [ 623.400111] usb 2-1: Product: USBSerial
Apr 22 11:50:37 tomodachi kernel: [ 623.400114] usb 2-1: Manufacturer:
LPCUSB
Apr 22 11:50:37 tomodachi kernel: [ 623.400117] usb 2-1: SerialNumber:
DEADC0DE
Apr 22 11:50:37 tomodachi kernel: [ 623.400654] usb 2-1: configuration
#1 chosen from 1 choice
Apr 22 11:50:37 tomodachi kernel: [ 623.453590] cdc_acm 2-1:1.0:
ttyACM0: USB ACM device
Apr 22 11:50:37 tomodachi kernel: [ 623.457094] usbcore: registered new
interface driver cdc_acm
Apr 22 11:50:37 tomodachi kernel: [ 623.457100] cdc_acm: v0.26:USB
Abstract Control Model driver for USB modems and ISDN adapters
even though:
$ zcat /proc/config.gz | grep CONFIG_USB_DEBUG
CONFIG_USB_DEBUG=y
maybe it did not recompile the cdc-acm module after I changed the
CONFIG_USB_DEBUG setting in .config? I'll do a clean recompile..
Akos
Oliver,
I made additional tests: made a clean compilation of 2.6.29.1 with
CONFIG_USB_DEBUG=y , but the dmesg output is the same.
Strangely enough, I compiled 2.6.24.7, and got the same results (the
communication hangs at the poll() call), on the same machine. This is
despite the fact that when running the same application on an ubuntu
8.04, it runs fine, which reports a kernel version of 2.6.24-23-generic.
one interesting message I get on the console when plugging in the device is:
drivers/usb/class/cdc-acm.c: This device cannot do calls on its own. It
is no modem.
the dmesg output for 2.6.29.1 when inserting the device is:
Apr 22 14:08:19 tomodachi kernel: [ 259.088065] usb 2-1: new full speed
USB device using uhci_hcd and address 2
Apr 22 14:08:19 tomodachi kernel: [ 259.245307] usb 2-1: New USB device
found, idVendor=ffff, idProduct=0005
Apr 22 14:08:19 tomodachi kernel: [ 259.245312] usb 2-1: New USB device
strings: Mfr=1, Product=2, SerialNumber=3
Apr 22 14:08:19 tomodachi kernel: [ 259.245316] usb 2-1: Product: USBSerial
Apr 22 14:08:19 tomodachi kernel: [ 259.245319] usb 2-1: Manufacturer:
LPCUSB
Apr 22 14:08:19 tomodachi kernel: [ 259.245322] usb 2-1: SerialNumber:
DEADC0DE
Apr 22 14:08:19 tomodachi kernel: [ 259.245842] usb 2-1: configuration
#1 chosen from 1 choice
Apr 22 14:08:19 tomodachi kernel: [ 259.294225] cdc_acm 2-1:1.0:
ttyACM0: USB ACM device
Apr 22 14:08:19 tomodachi kernel: [ 259.297156] usbcore: registered new
interface driver cdc_acm
Apr 22 14:08:19 tomodachi kernel: [ 259.297162] cdc_acm: v0.26:USB
Abstract Control Model driver for USB modems and ISDN adapters
for 2.6.24.7, it is:
Apr 22 14:13:47 tomodachi kernel: [ 181.049644] usb 2-1: new full speed
USB device using uhci_hcd and address 2
Apr 22 14:13:47 tomodachi kernel: [ 181.210892] usb 2-1: configuration
#1 chosen from 1 choice
Apr 22 14:13:47 tomodachi kernel: [ 181.213045] usb 2-1: Product: USBSerial
Apr 22 14:13:47 tomodachi kernel: [ 181.213047] usb 2-1: Manufacturer:
LPCUSB
Apr 22 14:13:47 tomodachi kernel: [ 181.213050] usb 2-1: SerialNumber:
DEADC0DE
Apr 22 14:13:48 tomodachi kernel: [ 181.240322] cdc_acm 2-1:1.0:
ttyACM0: USB ACM device
Apr 22 14:13:48 tomodachi kernel: [ 181.243117] usbcore: registered new
interface driver cdc_acm
Apr 22 14:13:48 tomodachi kernel: [ 181.243127]
drivers/usb/class/cdc-acm.c: v0.25:USB Abstract Control Model driver for
USB modems and ISDN adapters
what could be the problem?
Akos
Oliver,
I saw this post: http://marc.info/?l=linux-usb&m=123921902417985&w=2
and tried the same as described there:
- blacklisted cdc-acm
- loaded the usbserial module manually
and I get a /dev/ttyUSB0 device, and it works like a charm..
(this is on ubunutu's 2.6.27 kernel, for some reason they don't have the
usbserial module on their 2.6.28 kernel)
Sorry for dripping information in small chunks...
Akos
Am Mittwoch 22 April 2009 14:34:31 schrieb Maróy Ákos:
> what could be the problem?
That's odd. I can't tell from the log. Can you make a usbmon trace?
Regards
Oliver
Oliver,
> That's odd. I can't tell from the log. Can you make a usbmon trace?
sure:
cat /sys/kernel/debug/usbmon/1u
ffff880088545300 2462700154 S Ii:1:006:1 -115:8 8 <
ffff8800884b2600 2462700171 S Co:1:006:0 s 21 22 0003 0000 0000 0
ffff8800884b2600 2462701898 C Co:1:006:0 0 0
ffff880088545240 2462702064 S Bo:1:006:7 -115 6 = 060a0000 0000
ffff880088545900 2462702133 S Bi:1:006:2 -115 128 <
ffff880088545cc0 2462702142 S Bi:1:006:2 -115 128 <
ffff880088545600 2462702146 S Bi:1:006:2 -115 128 <
ffff8800885450c0 2462702150 S Bi:1:006:2 -115 128 <
ffff8800885453c0 2462702154 S Bi:1:006:2 -115 128 <
ffff880088545480 2462702158 S Bi:1:006:2 -115 128 <
ffff880088545180 2462702162 S Bi:1:006:2 -115 128 <
ffff8800885456c0 2462702166 S Bi:1:006:2 -115 128 <
ffff880088545540 2462702170 S Bi:1:006:2 -115 128 <
ffff880088545000 2462702174 S Bi:1:006:2 -115 128 <
ffff8800885459c0 2462702179 S Bi:1:006:2 -115 128 <
ffff880088545840 2462702183 S Bi:1:006:2 -115 128 <
ffff880088545f00 2462702187 S Bi:1:006:2 -115 128 <
ffff880088545c00 2462702191 S Bi:1:006:2 -115 128 <
ffff880088545b40 2462702199 S Bi:1:006:2 -115 128 <
ffff880088545a80 2462702202 S Bi:1:006:2 -115 128 <
this is where it hangs on poll(). then I press CTRL-C for the
application, then I get:
ffff88007c8e2b40 2502550672 S Co:1:006:0 s 21 22 0000 0000 0000 0
ffff88007c8e2b40 2502552140 C Co:1:006:0 0 0
ffff880088545300 2502553133 C Ii:1:006:1 -2:8 0
ffff880088545240 2502554132 C Bo:1:006:7 -2 0
ffff880088545a80 2502555132 C Bi:1:006:2 -2 0
ffff880088545b40 2502556132 C Bi:1:006:2 -2 0
ffff880088545c00 2502557132 C Bi:1:006:2 -2 0
ffff880088545f00 2502558132 C Bi:1:006:2 -2 0
ffff880088545840 2502559132 C Bi:1:006:2 -2 0
ffff8800885459c0 2502560131 C Bi:1:006:2 -2 0
ffff880088545000 2502561130 C Bi:1:006:2 -2 0
ffff880088545540 2502562126 C Bi:1:006:2 -2 0
ffff8800885456c0 2502563132 C Bi:1:006:2 -2 0
ffff880088545180 2502564131 C Bi:1:006:2 -2 0
ffff880088545480 2502565130 C Bi:1:006:2 -2 0
ffff8800885453c0 2502566125 C Bi:1:006:2 -2 0
ffff8800885450c0 2502567134 C Bi:1:006:2 -2 0
ffff880088545600 2502568134 C Bi:1:006:2 -2 0
ffff880088545cc0 2502569134 C Bi:1:006:2 -2 0
ffff880088545900 2502570134 C Bi:1:006:2 -2 0
Akos
Am Mittwoch 22 April 2009 15:25:00 schrieb Maróy Ákos:
> Oliver,
>
> > That's odd. I can't tell from the log. Can you make a usbmon trace?
>
> sure:
>
> cat /sys/kernel/debug/usbmon/1u
Please try setting ACM_NW in cdc-acm.h to 1. If that does not help,
please provide an usbmon trace of that modified kernel and 2.6.24.
Regards
Oliver
Oliver,
> Please try setting ACM_NW in cdc-acm.h to 1. If that does not help,
doesn't seem to help:
# rmmod cdc_acm
# grep ACM_NW `find . -name cdc-acm.h`
#define ACM_NW 1
struct acm_wb wb[ACM_NW];
# make && make modules_install
...
# lsmod | grep cdc
# tail -f /var/log/messages
...
Apr 24 12:08:36 tomodachi kernel: [ 400.784055] usb 2-1: new full speed
USB device using uhci_hcd and address 3
Apr 24 12:08:36 tomodachi kernel: [ 400.948109] usb 2-1: New USB device
found, idVendor=ffff, idProduct=0005
Apr 24 12:08:36 tomodachi kernel: [ 400.948113] usb 2-1: New USB device
strings: Mfr=1, Product=2, SerialNumber=3
Apr 24 12:08:36 tomodachi kernel: [ 400.948118] usb 2-1: Product: USBSerial
Apr 24 12:08:36 tomodachi kernel: [ 400.948121] usb 2-1: Manufacturer:
LPCUSB
Apr 24 12:08:36 tomodachi kernel: [ 400.948124] usb 2-1: SerialNumber:
DEADC0DE
Apr 24 12:08:36 tomodachi kernel: [ 400.948274] usb 2-1: configuration
#1 chosen from 1 choice
Apr 24 12:08:36 tomodachi kernel: [ 400.977961] cdc_acm 2-1:1.0:
ttyACM0: USB ACM device
Apr 24 12:08:36 tomodachi kernel: [ 401.001223] usbcore: registered new
interface driver cdc_acm
Apr 24 12:08:36 tomodachi kernel: [ 401.001229] cdc_acm: v0.26:USB
Abstract Control Model driver for USB modems and ISDN adapters
and strangely enough, when first running the application, I get:
$ ./asio_serial
opening serial device /dev/ttyACM0
terminate called after throwing an instance of
'boost::exception_detail::clone_impl<boost::exception_detail::error_info_injector<boost::system::system_error>
>'
what(): No such file or directory
Aborted
on the second run, it hangs at the same poll() call:
$ ./asio_serial
opening serial device /dev/ttyACM0
serial port open: 1
setting serial port parameters
written bytes: 6
the end of the strace of the first run is:
write(2, "opening serial device "..., 22opening serial device ) = 22
write(2, "/dev/ttyACM0"..., 12/dev/ttyACM0) = 12
write(2, "\n"..., 1
) = 1
open("/dev/ttyACM0", O_RDWR|O_NOCTTY|O_NONBLOCK) = -1 ENOENT (No such
file or directory)
futex(0x7f75df826190, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(2, "terminate called after throwing a"..., 48terminate called
after throwing an instance of ') = 48
write(2, "boost::exception_detail::clone_im"...,
111boost::exception_detail::clone_impl<boost::exception_detail::error_info_injector<boost::system::system_error>
>) = 111
write(2, "'\n"..., 2'
) = 2
write(2, " what(): "..., 11 what(): ) = 11
write(2, "No such file or directory"..., 25No such file or directory) = 25
write(2, "\n"..., 1
) = 1
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
tgkill(10563, 10563, SIGABRT) = 0
--- SIGABRT (Aborted) @ 0 (0) ---
+++ killed by SIGABRT +++
> please provide an usbmon trace of that modified kernel and 2.6.24.
this is what I get:
# cat /sys/kernel/debug/usbmon/1u
...
ffff81003f351540 2696262407 S Ii:1:008:1 -115:8 8 <
ffff81006c2c1840 2696262434 S Co:1:008:0 s 21 22 0003 0000 0000 0
ffff81006c2c1840 2696262558 C Co:1:008:0 0 0
ffff810035a5e600 2696262648 S Bo:1:008:7 -115 6 = 060a0000 0000
ffff810035a5ee40 2696262668 S Bi:1:008:2 -115 128 <
ffff810035a5ecc0 2696262670 S Bi:1:008:2 -115 128 <
ffff810035a5ed80 2696262671 S Bi:1:008:2 -115 128 <
ffff81006c1fb840 2696262675 S Bi:1:008:2 -115 128 <
ffff81006c1fb480 2696262676 S Bi:1:008:2 -115 128 <
ffff81006c1fbd80 2696262677 S Bi:1:008:2 -115 128 <
ffff81006c1fba80 2696262678 S Bi:1:008:2 -115 128 <
ffff81006c1fbc00 2696262679 S Bi:1:008:2 -115 128 <
ffff81006c1fbf00 2696262680 S Bi:1:008:2 -115 128 <
ffff81006c1fb180 2696262681 S Bi:1:008:2 -115 128 <
ffff81006c1fbcc0 2696262683 S Bi:1:008:2 -115 128 <
ffff81006c1fb540 2696262684 S Bi:1:008:2 -115 128 <
ffff81006c1fb300 2696262685 S Bi:1:008:2 -115 128 <
ffff81006c1fb3c0 2696262685 S Bi:1:008:2 -115 128 <
ffff81006c1fb0c0 2696262686 S Bi:1:008:2 -115 128 <
ffff81003f351780 2696262687 S Bi:1:008:2 -115 128 <
ffff810035a5e600 2696262804 C Bo:1:008:7 0 6 >
ffff810035a5ee40 2696263055 C Bi:1:008:2 0 48 = 300b0000 00005802
00000000 00000000 00000000 00000000 00000000 00000000
ffff810035a5ee40 2696263064 S Bi:1:008:2 -115 128 <
ffff81006c2c1840 2696263122 S Co:1:008:0 s 21 22 0000 0000 0000 0
ffff81006c2c1840 2696263180 C Co:1:008:0 0 0
ffff81003f351540 2696263212 C Ii:1:008:1 -2:8 0
ffff81003f351780 2696263305 C Bi:1:008:2 -2 0
ffff81006c1fb0c0 2696263554 C Bi:1:008:2 -2 0
ffff81006c1fb3c0 2696263679 C Bi:1:008:2 -2 0
ffff81006c1fb300 2696263804 C Bi:1:008:2 -2 0
ffff81006c1fb540 2696263929 C Bi:1:008:2 -2 0
ffff81006c1fbcc0 2696264054 C Bi:1:008:2 -2 0
ffff81006c1fb180 2696264179 C Bi:1:008:2 -2 0
ffff81006c1fbf00 2696264304 C Bi:1:008:2 -2 0
ffff81006c1fbc00 2696264429 C Bi:1:008:2 -2 0
ffff81006c1fba80 2696264554 C Bi:1:008:2 -2 0
ffff81006c1fbd80 2696264679 C Bi:1:008:2 -2 0
ffff81006c1fb480 2696264804 C Bi:1:008:2 -2 0
ffff81006c1fb840 2696264929 C Bi:1:008:2 -2 0
ffff810035a5ed80 2696265054 C Bi:1:008:2 -2 0
ffff810035a5ecc0 2696265179 C Bi:1:008:2 -2 0
ffff810035a5ee40 2696265304 C Bi:1:008:2 -2 0
Akos