Hello, I would like to get back to this. I've been testing hso with debugging turned on. From what I see, there are sometimes problems with result detaching devices from the bus. From application point of view, at the beginning there is an IO timeout, and then device disappears. Current tests show that device reattaches in a while, application can reopen it and continue it's job. Previously (~ kernel 2.6.35) I had issues with device not reattaching automatically to the bus (I had to plug it out and plug it in again in order to use it). I didn't notice something like this currently. Maybe something has been fixed or I was lucky for now. I do not know if the problem I describe is caused by the device, hso driver, or any other part of the system. Logs from the moment of crash: Dec 16 16:22:45 katastrofa kernel: [2232734.562968] --- Got serial_read_bulk callback 00 --- Dec 16 16:22:45 katastrofa kernel: [2232734.562973] [1235:hso_std_serial_read_bulk_callback]: Actual length = 6 Dec 16 16:22:45 katastrofa kernel: [2232734.562975] Dec 16 16:22:45 katastrofa kernel: [2232734.562979] [2088:put_rxbuf_data]: data to push to tty Dec 16 16:22:45 katastrofa kernel: [2232734.569965] [1996:hso_std_serial_write_bulk_callback]: Dec 16 16:22:45 katastrofa kernel: [2232734.570841] [1234:hso_std_serial_read_bulk_callback]: Dec 16 16:22:45 katastrofa kernel: [2232734.570843] --- Got serial_read_bulk callback 00 --- Dec 16 16:22:45 katastrofa kernel: [2232734.570848] [1235:hso_std_serial_read_bulk_callback]: Actual length = 6 Dec 16 16:22:45 katastrofa kernel: [2232734.570850] Dec 16 16:22:45 katastrofa kernel: [2232734.570853] [2088:put_rxbuf_data]: data to push to tty Dec 16 16:22:46 katastrofa kernel: [2232735.122468] [1996:hso_std_serial_write_bulk_callback]: Dec 16 16:22:46 katastrofa kernel: [2232735.124275] [1234:hso_std_serial_read_bulk_callback]: Dec 16 16:22:46 katastrofa kernel: [2232735.124276] --- Got serial_read_bulk callback 00 --- Dec 16 16:22:46 katastrofa kernel: [2232735.124279] [1235:hso_std_serial_read_bulk_callback]: Actual length = 4 Dec 16 16:22:46 katastrofa kernel: [2232735.124280] Dec 16 16:22:46 katastrofa kernel: [2232735.124282] [2088:put_rxbuf_data]: data to push to tty Dec 16 16:22:46 katastrofa kernel: [2232735.225591] [1996:hso_std_serial_write_bulk_callback]: Dec 16 16:22:46 katastrofa kernel: [2232735.525716] [1996:hso_std_serial_write_bulk_callback]: Dec 16 16:22:47 katastrofa kernel: [2232735.817593] [717:handle_usb_error]: hso_std_serial_read_bulk_callback: received USB status - protocol error (-71) Dec 16 16:22:47 katastrofa kernel: [2232735.818088] [717:handle_usb_error]: hso_std_serial_read_bulk_callback: received USB status - device disabled (-108) Dec 16 16:22:47 katastrofa kernel: [2232735.818609] [717:handle_usb_error]: tiocmget_intr_callback: received USB status - device disabled (-108) Dec 16 16:22:47 katastrofa kernel: [2232735.831604] usb 1-3.1: USB disconnect, address 104 Dec 16 16:22:48 katastrofa kernel: [2232737.026845] [1996:hso_std_serial_write_bulk_callback]: Dec 16 16:22:48 katastrofa kernel: [2232737.028199] [1234:hso_std_serial_read_bulk_callback]: ----- normal communication on other modems ----- Dec 16 16:22:53 katastrofa kernel: [2232742.236393] usb 1-3.1: new high speed USB device using ehci_hcd and address 123 Dec 16 16:22:53 katastrofa kernel: [2232742.313739] usb 1-3.1: New USB device found, idVendor=0af0, idProduct=d055 Dec 16 16:22:53 katastrofa kernel: [2232742.313744] usb 1-3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=4 Dec 16 16:22:53 katastrofa kernel: [2232742.313751] usb 1-3.1: Product: Globetrotter GI0505 Dec 16 16:22:53 katastrofa kernel: [2232742.313755] usb 1-3.1: Manufacturer: Option Wireless Technology Dec 16 16:22:53 katastrofa kernel: [2232742.313759] usb 1-3.1: SerialNumber: Serial Number Dec 16 16:22:53 katastrofa kernel: [2232742.314566] scsi152 : usb-storage 1-3.1:1.0 Dec 16 16:22:54 katastrofa kernel: [2232743.606988] usb 1-3.1: USB disconnect, address 123 Dec 16 16:22:55 katastrofa kernel: [2232743.773534] usb 1-3.1: new high speed USB device using ehci_hcd and address 124 Dec 16 16:22:55 katastrofa kernel: [2232743.849481] usb 1-3.1: New USB device found, idVendor=0af0, idProduct=d055 Dec 16 16:22:55 katastrofa kernel: [2232743.849483] usb 1-3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Dec 16 16:22:55 katastrofa kernel: [2232743.849485] usb 1-3.1: Product: Globetrotter GI0505 Dec 16 16:22:55 katastrofa kernel: [2232743.849487] usb 1-3.1: Manufacturer: Option Wireless Technology Dec 16 16:22:55 katastrofa kernel: [2232744.446425] [1323:hso_serial_open]: Opening 52 Dec 16 16:22:55 katastrofa kernel: [2232744.446428] [1135:_hso_serial_set_termios]: port 52 Dec 16 16:22:55 katastrofa kernel: [2232744.447145] [1759:hso_serial_ioctl]: IOCTL cmd: 21505, arg: -1080845544 Dec 16 16:22:55 katastrofa kernel: [2232744.447151] [1759:hso_serial_ioctl]: IOCTL cmd: 21506, arg: -1080845540 Dec 16 16:22:55 katastrofa kernel: [2232744.447154] [1465:hso_serial_set_termios]: Termios called with: cflags new[7346] - old[5298] Dec 16 16:22:55 katastrofa kernel: [2232744.447156] [1135:_hso_serial_set_termios]: port 52 I'm attaching dmesg records from other crash of that type. It shows hso crash when application tries to open device shortly after such disconnection. On Sat, Nov 27, 2010 at 08:59:16AM +0100, Piotr Isajew wrote: > On Wed, Nov 24, 2010 at 06:50:15PM +0100, Filip Aben wrote: > > Digging deeper I found this gem: > > > > if (((port_spec & HSO_PORT_MASK) == HSO_PORT_NETWORK) && > > !disable_net) > > hso_dev = hso_create_net_device(interface, > > port_spec); > > else > > hso_dev = > > hso_create_bulk_serial_device(interface, > > port_spec); > > > > I applied the patch suggested by Filip (many thanks). Right now I > switched to hso with full debugging enabled and disable_net set. Let's > see if there will be any other problems.
[2557564.355614] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 1 [2557564.355638] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 1 [2557564.356002] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 2 [2557564.356002] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 3 [2557564.356683] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 2 [2557564.356861] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 4 [2557564.356982] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 3 [2557564.357231] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 4 [2557564.357238] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 5 [2557564.357481] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 5 [2557564.357611] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 6 [2557564.357856] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 6 [2557564.357985] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 7 [2557564.358106] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 7 [2557564.358357] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 8 [2557564.358363] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 8 [2557564.358731] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 9 [2557564.358737] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 9 [2557564.358981] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 10 [2557564.359110] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 10 [2557564.359232] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 11 [2557564.359485] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 11 [2557564.359606] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 12 [2557564.359856] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 13 [2557564.359861] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 12 [2557564.360107] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 14 [2557564.360234] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 13 [2557564.360482] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 15 [2557564.360609] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 14 [2557564.360732] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 16 [2557564.360980] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 17 [2557564.360986] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 15 [2557564.361359] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 18 [2557564.361366] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 16 [2557564.361607] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 19 [2557564.361735] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 17 [2557564.361856] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 20 [2557564.362111] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 18 [2557564.362232] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 21 [2557564.362481] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 22 [2557564.362488] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 19 [2557564.362732] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 23 [2557564.362860] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 20 [2557564.363107] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 24 [2557564.363236] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 21 [2557564.363357] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 25 [2557564.363607] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 26 [2557564.363613] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 22 [2557564.363982] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 27 [2557564.363989] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 23 [2557564.364233] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 28 [2557564.364360] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 24 [2557564.364482] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 29 [2557564.364735] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 25 [2557564.364857] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 30 [2557564.365107] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 31 [2557564.365114] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 26 [2557564.365358] ehci_hcd 0000:00:1d.7: devpath 3.4 ep3in 3strikes [2557564.365382] hso 1-3.4:1.0: forced unbind [2557564.365486] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 27 [2557564.365645] hso 1-3.4:1.1: forced unbind [2557564.365731] ehci_hcd 0000:00:1d.7: detected XactErr len 0/4096 retry 1 [2557564.365779] hso 1-3.4:1.2: forced unbind [2557564.365790] ehci_hcd 0000:00:1d.7: shutdown urb ea831980 ep3in-bulk [2557564.365865] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 28 [2557564.366242] ehci_hcd 0000:00:1d.7: detected XactErr len 0/10 retry 29 [2557564.366495] usb 1-3.4: unlink qh0-00ff/f5bd7d80 start 0 [1/0 us] [2557564.366556] ehci_hcd 0000:00:1d.7: shutdown urb ea831e80 ep4in-intr [2557564.366567] hso 1-3.4:1.4: forced unbind [2557564.378736] hub 1-3:1.0: logical disconnect on port 4 [2557564.378873] hub 1-3:1.0: state 7 ports 7 chg 0010 evt 0000 [2557564.379419] hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s [2557564.379618] usb 1-3.4: USB disconnect, address 32 [2557564.379620] usb 1-3.4: unregistering device [2557564.379622] usb 1-3.4: usb_disable_device nuking all URBs [2557564.379629] usb 1-3.4: unregistering interface 1-3.4:1.0 [2557564.379677] usb 1-3.4: unregistering interface 1-3.4:1.1 [2557564.379705] usb 1-3.4: unregistering interface 1-3.4:1.2 [2557564.379737] usb 1-3.4: unregistering interface 1-3.4:1.3 [2557564.379764] usb 1-3.4: unregistering interface 1-3.4:1.4 [2557564.484336] hub 1-3:1.0: debounce: port 4: total 100ms stable 100ms status 0x100 [2557568.807573] hub 1-3:1.0: state 7 ports 7 chg 0000 evt 0010 [2557568.807993] hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s [2557568.912420] hub 1-3:1.0: debounce: port 4: total 100ms stable 100ms status 0x100 [2557570.599542] hub 1-3:1.0: state 7 ports 7 chg 0000 evt 0010 [2557570.600867] hub 1-3:1.0: port 4, status 0101, change 0001, 12 Mb/s [2557570.705292] hub 1-3:1.0: debounce: port 4: total 100ms stable 100ms status 0x101 [2557570.767640] usb 1-3.4: new high speed USB device using ehci_hcd and address 33 [2557570.843490] usb 1-3.4: default language 0x0409 [2557570.844614] usb 1-3.4: udev 33, busnum 1, minor = 32 [2557570.844619] usb 1-3.4: New USB device found, idVendor=0af0, idProduct=d055 [2557570.844624] usb 1-3.4: New USB device strings: Mfr=1, Product=2, SerialNumber=4 [2557570.844629] usb 1-3.4: Product: Globetrotter GI0505 [2557570.844633] usb 1-3.4: Manufacturer: Option Wireless Technology [2557570.844637] usb 1-3.4: SerialNumber: Serial Number [2557570.844812] usb 1-3.4: usb_probe_device [2557570.844816] usb 1-3.4: configuration #1 chosen from 1 choice [2557570.845160] usb 1-3.4: adding 1-3.4:1.0 (config #1, interface 0) [2557570.845208] libusual 1-3.4:1.0: usb_probe_interface [2557570.845212] libusual 1-3.4:1.0: usb_probe_interface - got id [2557570.845223] usb-storage 1-3.4:1.0: usb_probe_interface [2557570.845226] usb-storage 1-3.4:1.0: usb_probe_interface - got id [2557570.845412] scsi170 : usb-storage 1-3.4:1.0 [2557570.963161] usb-storage 1-3.4:1.0: disconnect by usbfs [2557572.135921] hub 1-3:1.0: state 7 ports 7 chg 0000 evt 0010 [2557572.136354] hub 1-3:1.0: port 4, status 0101, change 0001, 12 Mb/s [2557572.136652] usb 1-3.4: USB disconnect, address 33 [2557572.136654] usb 1-3.4: unregistering device [2557572.136656] usb 1-3.4: usb_disable_device nuking all URBs [2557572.136661] usb 1-3.4: unregistering interface 1-3.4:1.0 [2557572.241320] hub 1-3:1.0: debounce: port 4: total 100ms stable 100ms status 0x101 [2557572.303109] usb 1-3.4: new high speed USB device using ehci_hcd and address 34 [2557572.379353] usb 1-3.4: config 1 interface 0 altsetting 0 bulk endpoint 0x81 has invalid maxpacket 64 [2557572.379357] usb 1-3.4: config 1 interface 1 altsetting 0 bulk endpoint 0x82 has invalid maxpacket 64 [2557572.379362] usb 1-3.4: config 1 interface 4 altsetting 0 bulk endpoint 0x86 has invalid maxpacket 64 [2557572.379721] usb 1-3.4: default language 0x0409 [2557572.381484] usb 1-3.4: udev 34, busnum 1, minor = 33 [2557572.381487] usb 1-3.4: New USB device found, idVendor=0af0, idProduct=d055 [2557572.381489] usb 1-3.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 [2557572.381492] usb 1-3.4: Product: Globetrotter GI0505 [2557572.381494] usb 1-3.4: Manufacturer: Option Wireless Technology [2557572.381662] usb 1-3.4: usb_probe_device [2557572.381665] usb 1-3.4: configuration #1 chosen from 1 choice [2557572.382146] usb 1-3.4: adding 1-3.4:1.0 (config #1, interface 0) [2557572.382212] hso 1-3.4:1.0: usb_probe_interface [2557572.382215] hso 1-3.4:1.0: usb_probe_interface - got id [2557572.382784] usb 1-3.4: adding 1-3.4:1.1 (config #1, interface 1) [2557572.382830] hso 1-3.4:1.1: usb_probe_interface [2557572.382833] hso 1-3.4:1.1: usb_probe_interface - got id [2557572.383350] usb 1-3.4: adding 1-3.4:1.2 (config #1, interface 2) [2557572.383397] hso 1-3.4:1.2: usb_probe_interface [2557572.383400] hso 1-3.4:1.2: usb_probe_interface - got id [2557572.384012] usb 1-3.4: adding 1-3.4:1.3 (config #1, interface 3) [2557572.384060] hso 1-3.4:1.3: usb_probe_interface [2557572.384063] hso 1-3.4:1.3: usb_probe_interface - got id [2557572.384503] usb 1-3.4: adding 1-3.4:1.4 (config #1, interface 4) [2557572.384545] hso 1-3.4:1.4: usb_probe_interface [2557572.384548] hso 1-3.4:1.4: usb_probe_interface - got id [2557573.258544] usb 1-3.4: link qh0-00ff/f19f4e00 start 0 [1/0 us] [2557588.151848] ------------[ cut here ]------------ [2557588.151856] WARNING: at drivers/net/usb/hso.c:1312 hso_serial_open+0x4c/0x1b1 [hso]() [2557588.151858] Hardware name: Compaq 500B Microtower [2557588.151860] Modules linked in: hso n_hdlc ppp_synctty ah6 ah4 esp6 esp4 xfrm4_mode_beet xfrm4_tunnel xfrm4_mode_tunnel xfrm4_mode_transport xfrm6_mode_transport xfrm6_mode_beet xfrm6_mode_tunnel ipcomp af_key rfkill ppp_deflate bsd_comp ppp_async crc_ccitt nfs lockd nfs_acl auth_rpcgss sunrpc deflate zlib_deflate zlib_inflate tunnel4 xfrm_ipcomp tun softdog ipv6 xt_mark fuse usb_storage [last unloaded: hso] [2557588.151890] Pid: 21364, comm: smsagent Tainted: G W 2.6.36 #4 [2557588.151892] Call Trace: [2557588.151899] [<c102e24f>] warn_slowpath_common+0x65/0x7a [2557588.151903] [<fb32b3e0>] ? hso_serial_open+0x4c/0x1b1 [hso] [2557588.151906] [<c102e273>] warn_slowpath_null+0xf/0x13 [2557588.151910] [<fb32b3e0>] hso_serial_open+0x4c/0x1b1 [hso] [2557588.151914] [<c11a397d>] tty_open+0x29f/0x3b0 [2557588.151918] [<c10b2832>] chrdev_open+0x100/0x117 [2557588.151922] [<c10aec32>] __dentry_open+0x138/0x227 [2557588.151925] [<c10aedba>] nameidata_to_filp+0x2c/0x40 [2557588.151927] [<c10b2732>] ? chrdev_open+0x0/0x117 [2557588.151930] [<c10b8474>] do_last+0x32f/0x413 [2557588.151933] [<c10b99d5>] do_filp_open+0x35c/0x401 [2557588.151936] [<c10b85a1>] ? getname+0x1b/0xb9 [2557588.151939] [<c10aea1a>] do_sys_open+0x48/0xc9 [2557588.151942] [<c10aeadd>] sys_open+0x1e/0x26 [2557588.151945] [<c135f61d>] syscall_call+0x7/0xb [2557588.151949] [<c1350000>] ? pci_bus_size_bridges+0x27b/0x4ca [2557588.151951] ---[ end trace 2377ee765f347d98 ]---
Attachment:
pgpoJ9aWOkD68.pgp
Description: PGP signature
