Bug 30072

Summary:	USB-to-serial problems in 2.6.37.1+ (pl2303)
Product:	Drivers	Reporter:	akwatts
Component:	USB	Assignee:	Alan (alan)
Status:	RESOLVED INSUFFICIENT_DATA
Severity:	high	CC:	alan, florian, greg, libor.pechacek, maciej.rutecki, rjw
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.37.1	Subsystem:
Regression:	Yes	Bisected commit-id:
Bug Depends on:
Bug Blocks:	27352

Description akwatts 2011-02-28 12:39:52 UTC

As of 2.6.37.1, using a pl2303 usb<->serial converter (trendnet tu-s9) 
connected to an external serial modem fails on re-connect 
(disconnect -> connect cycle).

Sometimes, after disconnecting ppp (either with SIGKILL, SIGTERM, or SIGHUP)
and trying to reconnect, wvdial (the dialer) uses 100% of cpu and hangs at
the following lines:

  wvdial: WvDial: Internet dialer version 1.61
  wvdial: Initializing modem. 
  wvdial: Sending: ATZ [sometimes hangs at previous line]

This behavior is noticed most when the ppp line remains open but the
connection has died (upstream). A keep-alive type script detects that
the line is effectively dead and tries to restart ppp.

I've identified the commit which causes this behavior as:

  commit d14fc1a74e846d7851f24fc9519fe87dc12a1231
  Author: Libor Pechacek <lpechacek@suse.cz>
  Date:   Fri Jan 14 14:30:21 2011 +0100
  USB: serial: handle Data Carrier Detect changes

Backing this commit out returns the system to normal behavior and the 
pl2303-driven modem can disconnect/reconnect without issues.

~ Andy

Comment 1 Libor Pecháček 2011-03-02 07:28:27 UTC

Andy, can you post an strace of the wvdial process so that I can see what it's doing?  100% CPU utilization suggests that it's looping, possibly with some syscalls that can reveal what went wrong.

Comment 2 akwatts 2011-03-04 09:09:33 UTC

Libor, I had strace attach to a runaway wvdial process and it repeats lines like these:

  select(1, [0], [], [], {0, 0})          = 1 (in [0], left {0, 0})  
  gettimeofday({1299228753, 209610}, NULL) = 0
  gettimeofday({1299228753, 209653}, NULL) = 0
  select(1, [0], [], [], {0, 0})          = 1 (in [0], left {0, 0})
  gettimeofday({1299228753, 209743}, NULL) = 0
  gettimeofday({1299228753, 209780}, NULL) = 0

I thought that it might be due to multiple instances running (the hangup not killing everything) but it isn't that. I monitor all instances of pppd and/or wvdial to ensure clean closing of old processes.

Please let me know what other information would be useful.

~ Andy

Comment 3 Libor Pecháček 2011-03-10 14:17:16 UTC

I'm curious what FD 0 is.  Can i get a complete strace of the process from the start until you terminate it?  I.e. start wvdial like 'strace -o /tmp/wvdial.str wvdial ...'.  I guess from the initial comment that you can reliably duplicate the problem, so that should not be much work for you.

In the meantime I'll also try to duplicate the hang.  TIA

Comment 4 Libor Pecháček 2011-03-14 09:15:24 UTC

> In the meantime I'll also try to duplicate the hang.

So I connected Czech Tiscali with wvdial, and tried to break the connection by
sending PPP daemon HUP signal several times.  wvdial did not hang.

Just for record - my test setup:

dhcp28:~ # lsusb -s 4:2
Bus 004 Device 002: ID 067b:2303 Prolific Technology, Inc. PL2303 Serial Port
dhcp28:~ # wvdial --version
WvDial 1.60
Copyright (c) 1997-2005 Net Integration Technologies, Inc.
dhcp28:~ # pppd --version
pppd version 2.4.5
dhcp28:~ # cat /etc/wvdial.conf 
[Dialer Defaults]
Modem = /dev/ttyUSB0
Baud = 57600
Init1 = ATZ
Init2 = ATQ0 V1 E1 S0=0 &C1 &D2
Init3 =
Area Code =
Phone = 971100811
Username = tiscali
Password = tiscali
Ask Password = 0
Dial Command = ATDT
Stupid Mode = 1
Compuserve = 0
Force Address =
Idle Seconds = 300
DialMessage1 =
DialMessage2 =
ISDN = 0
Auto DNS = 1
Auto Reconnect = 1
dhcp28:~ # uname -a
Linux dhcp28.suse.cz 2.6.37.2-0.0.5.8e49073-desktop #1 SMP PREEMPT 2011-03-02 01:08:52 +0100 x86_64 x86_64 x86_64 GNU/Linux
dhcp28:~ # cat /etc/SuSE-release
openSUSE 11.4 RC 1 (x86_64)
VERSION = 11.4
CODENAME = Celadon

Modem was US Robotics Courier X2 V.Everything.

Ad the strace from comment 2 - FD 0 is usually stdin, don't know if wvdial
reuses the file handle for another data stream.  If FD 0 is really stdin, then
it seems wvdial is waiting for some input from the user on the controlling
terminal.

For further work on this bug I need to know:
* Linux distro brand and version
* wvdial version
* pppd version
* wvdial config (remove login credentials from there)
* strace of the wvdial process from the start to the end (so that I can see the
  whole userspace/kernel interaction until the hang)

Closing as RESOLVED/INSUFFICIENT_DATA for now.

Comment 5 akwatts 2011-06-14 19:50:45 UTC

The problem persists through 2.6.37.6 (on the 37 branch) and is still present in 2.6.39.x (both 2.6.39 and 2.6.39.1).

I estimate it occurs to me once every 20 or so connections, on average. I have been unable to systematically reproduce except by turning the modem off/on physically (i.e. connect to ISP; disconnect; turn off modem; turn on modem; try to connect). 

My specs:

 - USR Sportster v.90 56K
 - ppp 2.4.5
 - wvdial 1.61
 - wvstreams 4.6.1

Below is the strace of a typical "problem" wvial attempt (cut off where the lines begin to repeat ad infinitum). Contrast the ioctl line after connect() with a good attempt when it looks like:

    ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B115200 -opost -isig
    -icanon -echo ...}) = 0

At the end are my configurations.

~ Andy

==  wvdial trace ==
execve("/usr/bin/wvdial", ["/usr/bin/wvdial", "--chat"], [/* 33 vars */]) = 0
brk(0)                                  = 0x8ca0000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb779f000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=207161, ...}) = 0
mmap2(NULL, 207161, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb776c000
close(3)                                = 0
open("/usr/lib/libuniconf.so.4.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20\220"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=358064, ...}) = 0
mmap2(NULL, 361668, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7713000
mmap2(0xb7769000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x55) = 0xb7769000
close(3)                                = 0
open("/usr/lib/libwvstreams.so.4.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\336"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=852364, ...}) = 0
mmap2(NULL, 851900, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7643000
mmap2(0xb770e000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xcb) = 0xb770e000
close(3)                                = 0
open("/usr/lib/libwvutils.so.4.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\247\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=156256, ...}) = 0
mmap2(NULL, 1210212, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb751b000
mmap2(0xb7540000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25) = 0xb7540000
mmap2(0xb7541000, 1054564, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7541000
close(3)                                = 0
open("/usr/lib/libwvbase.so.4.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\31"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=538708, ...}) = 0
mmap2(NULL, 550700, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7494000
mmap2(0xb7514000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x80) = 0xb7514000
mmap2(0xb7518000, 10028, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7518000
close(3)                                = 0
open("/usr/lib/libstdc++.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`\33\4\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=913552, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7493000
mmap2(NULL, 942988, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb73ac000
mmap2(0xb7487000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xda) = 0xb7487000
mmap2(0xb748c000, 25484, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb748c000
close(3)                                = 0
open("/lib/libm.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\2004\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=593491, ...}) = 0
mmap2(NULL, 151680, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7386000
mmap2(0xb73aa000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x23) = 0xb73aa000
close(3)                                = 0
open("/usr/lib/libgcc_s.so.1", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\36\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=104144, ...}) = 0
mmap2(NULL, 103208, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb736c000
mmap2(0xb7385000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19) = 0xb7385000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360m\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=8246087, ...}) = 0
mmap2(NULL, 1542504, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb71f3000
mprotect(0xb7365000, 4096, PROT_NONE)   = 0
mmap2(0xb7366000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x172) = 0xb7366000
mmap2(0xb7369000, 10600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7369000
close(3)                                = 0
open("/usr/lib/libz.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\25"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=77688, ...}) = 0
mmap2(NULL, 80308, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb71df000
mmap2(0xb71f2000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12) = 0xb71f2000
close(3)                                = 0
open("/usr/lib/libssl.so.0", O_RDONLY)  = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0p\300\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0555, st_size=314141, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb71de000
mmap2(NULL, 282072, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7199000
mmap2(0xb71da000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x40) = 0xb71da000
close(3)                                = 0
open("/usr/lib/libcrypto.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0{\3\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0555, st_size=1466011, ...}) = 0
mmap2(NULL, 1297336, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb705c000
mmap2(0xb7180000, 90112, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x123) = 0xb7180000
mmap2(0xb7196000, 11192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7196000
mprotect(0xbfcdd000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC|PROT_GROWSDOWN) = 0
close(3)                                = 0
open("/lib/libcrypt.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 \7\0\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=112251, ...}) = 0
mmap2(NULL, 205148, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7029000
mmap2(0xb7033000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9) = 0xb7033000
mmap2(0xb7035000, 155996, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7035000
close(3)                                = 0
open("/lib/libdl.so.2", O_RDONLY)       = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 \n\0\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=103398, ...}) = 0
mmap2(NULL, 12408, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7025000
mmap2(0xb7027000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1) = 0xb7027000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7024000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7023000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb70236d0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb7027000, 4096, PROT_READ)   = 0
mprotect(0xb7033000, 4096, PROT_READ)   = 0
mprotect(0xb71df000, 77824, PROT_READ|PROT_WRITE) = 0
mprotect(0xb71df000, 77824, PROT_READ|PROT_EXEC) = 0
mprotect(0xb7366000, 8192, PROT_READ)   = 0
mprotect(0xb73aa000, 4096, PROT_READ)   = 0
mprotect(0xb7487000, 16384, PROT_READ)  = 0
mprotect(0xb77c0000, 4096, PROT_READ)   = 0
munmap(0xb776c000, 207161)              = 0
brk(0)                                  = 0x8ca0000
brk(0x8cc1000)                          = 0x8cc1000
gettimeofday({1301785683, 579112}, NULL) = 0
dup(2)                                  = 3
rt_sigaction(SIGTERM, {0x804cc68, [TERM], SA_RESTART}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGINT, {0x804cc68, [INT], SA_RESTART}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGHUP, {0x804cc68, [HUP], SA_RESTART}, {SIG_DFL}, 8) = 0
access("/etc/wvdial.conf", F_OK)        = 0
open("/etc/wvdial.conf", O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 4
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
fstat64(4, {st_mode=S_IFREG|0644, st_size=319, ...}) = 0
gettimeofday({1301785683, 581069}, NULL) = 0
select(5, [4], [], [], NULL)            = 1 (in [4])
gettimeofday({1301785683, 582715}, NULL) = 0
read(4, "\n[Dialer Defaults]\nInit1 = ATZ\nI"..., 1024) = 319
gettimeofday({1301785683, 583363}, NULL) = 0
select(5, [4], [], [], NULL)            = 1 (in [4])
gettimeofday({1301785683, 583449}, NULL) = 0
read(4, "", 1024)                       = 0
close(4)                                = 0
access("/root/.wvdialrc", F_OK)         = -1 ENOENT (No such file or directory)
getpid()                                = 6610
gettimeofday({1301785683, 584788}, NULL) = 0
write(3, "--> ", 4)                     = 4
write(3, "WvDial: Internet dialer version "..., 36) = 36
write(3, "\n", 1)                       = 1
gettimeofday({1301785683, 584988}, NULL) = 0
time(NULL)                              = 1301785683
open("/etc/localtime", O_RDONLY)        = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=395, ...}) = 0
fstat64(4, {st_mode=S_IFREG|0644, st_size=395, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb779e000
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\3\0\0\0\3\0\0"..., 4096) = 395
_llseek(4, -6, [389], SEEK_CUR)         = 0
read(4, "\n\n", 4096)                   = 6
close(4)                                = 0
munmap(0xb779e000, 4096)                = 0
socket(PF_FILE, 0x80002 /* SOCK_??? */, 0) = 4
connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
send(4, "<30>wvdial[6610]"..., 71, MSG_NOSIGNAL) = 71
fcntl64(0, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(0, F_GETFL)                     = 0x2 (flags O_RDWR)
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfcdc168) = -1 EIO (Input/output error)
gettimeofday({1301785683, 587585}, NULL) = 0
write(3, "--> ", 4)                     = 4
write(3, "Initializing modem.", 19)     = 19
write(3, "\n", 1)                       = 1
gettimeofday({1301785683, 587739}, NULL) = 0
time(NULL)                              = 1301785683
send(4, "<30>wvdial[6610]"..., 54, MSG_NOSIGNAL) = 54
write(0, "\r\r\r\r\r", 5)               = -1 EIO (Input/output error)
gettimeofday({1301785683, 588077}, NULL) = 0
gettimeofday({1301785683, 588133}, NULL) = 0
select(1, [0], [], [], {0, 0})          = 1 (in [0], left {0, 0})
gettimeofday({1301785683, 588224}, NULL) = 0
gettimeofday({1301785683, 588275}, NULL) = 0
select(1, [0], [], [], {0, 0})          = 1 (in [0], left {0, 0})
gettimeofday({1301785683, 588358}, NULL) = 0
gettimeofday({1301785683, 588392}, NULL) = 0
select(1, [0], [], [], {0, 0})          = 1 (in [0], left {0, 0})
gettimeofday({1301785683, 588475}, NULL) = 0
===================

===  PPP CONFIG ===
noauth
name wvdial
connect "/usr/bin/wvdial --chat"
/dev/ttyUSB0
115200
modem
crtscts
defaultroute
usehostname
user <removed>
noipdefault 
usepeerdns 
idle 3600 
logfd 6
debug
===================

== WVDIAL CONFIG ==
[Dialer Defaults]
Init1 = ATZ
Init2 = AT&F1E0Q0V1&C1&D2S0=0 
Init3 =
Modem = /dev/ttyUSB0
Phone = <removed>
Idle Seconds = 300
Password = <removed>
Modem Type = Analog Modem
Stupid Mode = 1
Compuserve = 0
Baud = 115200
Auto DNS = 1
Dial Command = ATDT
Ask Password = 0
ISDN = 0
Username = <removed>
Carrier Check = no
Dial Timeout=60
====================

Comment 6 Libor Pecháček 2011-06-30 08:02:03 UTC

Sorry, I haven't checked my bugzilla.kernel.org mail for a long time.  I'll have a look.

Comment 7 Libor Pecháček 2011-07-01 08:13:58 UTC

Ad the strace - I didn't know that you use wvdial in chat mode.  That explains why we saw wvdial fiddle with stdin.  The strace also shows that ioctl() and write() to the fd returns -EIO.

That means we need to focus on pppd, as it's the process that opens the serial port.  Would you be so kind as to capture strace of the pppd process in the same situation, preferably with option -f so that I can see all processes it spawns?  In addition I'm curious if there are any interesting messages in /var/log/messages and the kernel log (dmesg).

BTW it's pity that wvdial does not handle -EIO and falls into infinite loop.

Comment 8 akwatts 2011-07-03 08:54:21 UTC

I have conducted a few more tests on 2.6.39.2 comparing behavior with and without commit d14fc1a7:

Testing file I/O (dd count=0 if=/dev/ttyUSB0)

	                     2.6.39.2       2.6.39.2
	                     w/o d14fc1a7   mainline

   at boot                        fine      fine
   during ppp conn                fine      fine
   after ppp disconn              fine      hangs
   after ppp disconn+modem cycle  fine      /dev/ttyUSB0: Input/output error (*)
	
   (*) this happens only on the first attempt; afterwards it just hangs.
---

The problem arises with that single I/O Error on /dev/ttyUSB0. This can be triggered by turning the modem off & on (after having connected/disconnected ppp at least once). It also occurs sporadically after many disconnect/connect cycles (the original reason for my report).

The seemingly relevant portion of a problem ppp strace is:

   open("/dev/ttyUSB0", O_RDWR|O_NONBLOCK) = 8
   --- SIGHUP (Hangup) @ 0 (0) ---
   --- SIGCONT (Continued) @ 0 (0) ---
   sigreturn()                             = ? (mask now [])
   fcntl64(8, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
   fcntl64(8, F_SETFL, O_RDWR)             = 0
   ioctl(8, TIOCMBIS, [TIOCM_DTR])         = -1 EIO (Input/output error)
   ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbf926478) = -1 EIO (Input/output error)
   ioctl(8, TIOCMBIC, [TIOCM_DTR])         = -1 EIO (Input/output error)
   rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
   rt_sigaction(SIGCHLD, NULL, {0x80509ac, [HUP INT USR2 TERM CHLD], 0}, 8) = 0
   rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
   nanosleep({1, 0}, {1, 0})               = 0
   ioctl(8, TIOCMBIS, [TIOCM_DTR])         = -1 EIO (Input/output error)

~ Andy

PS I cannot change from NEEDINFO to any open-type status.

Comment 9 Libor Pecháček 2011-07-08 05:05:12 UTC

Many thanks for valuable info and testing.  The SIGHUP right after open might be related to the commit in question.

(In reply to comment #8)
> after having connected/disconnected ppp at least once

To be sure how to reproduce the bug, I'd like to know what it means "disconnect ppp" - does it mean sending HUP or TERM signal to PPP daemon, or something else?

Comment 10 akwatts 2011-07-08 09:03:21 UTC

Glad the info was helpful.

I have been using the poff script included with pppd which sends a SIGTERM to the daemon.

Comment 11 akwatts 2012-06-07 16:46:07 UTC

Hello. This bug was changed to RESOLVED and later OBSOLETE. However, it is neither, afaik. The last message from the commit author (Libor) is #9 above dated 7/2011. This is after I supplied all the information requested. I tried posting follow-ups to the usb list (while kernel.org was down) but that didn't get anywhere.

I don't use my pl2303 any longer but can dust it off to test proposed fixes, if need be.

Thanks.

Comment 12 Alan 2012-06-07 16:49:36 UTC

By all means, at this point I don't see anything in your report which is actually a bug but with a bit more info we can try and pin that down


Can you give it a test on a more recent kernel (3.2 - 3.4). I suspect the behaviour will be the same but that will mean we know where to work from.

Alan