Hi Linux serial & PPP experts,
For a long time now I have been chasing a problem in my PPP connection.
The fault scenario is as follows:
- After reboot establishing a PPP connection works OK
- Network communication over PPP works OK
- The PPP connection is restarted - could be for any of several reasons; peer
drops the connection gracefully, local restart due to network problems,
local restart due to user request, et.c.
- After closing down the connection, it is not possible to re-connect again.
The Error messages from pppd looks something like:
Jan 1 01:04:42 mymachine local2.err chat[631]: Can't get terminal parameters: Input/output error
Jan 1 01:04:42 mymachine daemon.debug pppd[629]: Script /usr/sbin/chat -v -f /etc/ppp/chats/gprs-conn -T my-apn (pid 630), status = 0x2
Jan 1 01:04:42 mymachine daemon.err pppd[629]: Connect script failed
Some data about the system:
- PPP daemon v2.4.5
- Linux kernel v3.2.51 (same error with v2.6.35 though)
- CPU PowerPC e300c4 (MPC5125)
- Cinterion GPRS modem
- The serial device driver is based on main-line drivers for MPC5200 and
MPC5121 (mpc52xx_uart.c) but with some custom extensions. Works fine for
other applications.
By running strace I have found that it is the ioctl's the PPPD tries to
execute on the tty device that fails after disconnect (I have also tried
including fcntl64 in the strace trace list but not found any such calls that
fails):
-------------------------------------------------------------------------------
root@mymachine:~# strace -e trace=open,close,ioctl pppd dump debug nodetach call gprs
<snip>
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
close(4) = 0
open("/home/root/.ppprc", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ppp/peers/gprs", O_RDONLY) = 4
open("/etc/ppp/peers/ip-connect", O_RDONLY) = 5
close(5) = 0
close(4) = 0
open("/etc/ppp/options.ttyPSC4", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/dev/ppp", O_RDWR) = 4
close(4) = 0
open("/usr/share/zoneinfo/UTC", O_RDONLY) = -1 ENOENT (No such file or directory)
pppd options in effect:
debug # (from command line)
nodetach # (from command line)
holdoff 2 # (from /etc/ppp/peers/gprs)
linkname gprs # (from /etc/ppp/peers/gprs)
maxfail 5 # (from /etc/ppp/peers/gprs)
unit 0 # (from /etc/ppp/peers/gprs)
dump # (from command line)
noauth # (from /etc/ppp/peers/gprs)
name mycon # (from /etc/ppp/peers/ip-connect)
/dev/ttyPSC4 # (from /etc/ppp/peers/gprs)
115200 # (from /etc/ppp/peers/gprs)
lock # (from /etc/ppp/options)
connect /usr/sbin/chat -v -f /etc/ppp/chats/gprs-conn -T my-apn # (from /etc/ppp/peers/ip-connect)
crtscts # (from /etc/ppp/peers/gprs)
modem # (from /etc/ppp/peers/gprs)
lcp-echo-failure 3 # (from /etc/ppp/peers/gprs)
lcp-echo-interval 10 # (from /etc/ppp/peers/gprs)
ipcp-accept-local # (from /etc/ppp/peers/gprs)
ipcp-accept-remote # (from /etc/ppp/peers/gprs)
noipdefault # (from /etc/ppp/peers/gprs)
defaultroute # (from /etc/ppp/peers/gprs)
replacedefaultroute # (from /etc/ppp/peers/gprs)
usepeerdns # (from /etc/ppp/peers/gprs)
noccp # (from /etc/ppp/peers/gprs)
open("/dev/null", O_RDWR) = 4
open("/var/run/pppd2.tdb", O_RDWR|O_CREAT, 0644) = 6
ioctl(0, TCGETS, {B115200 opost isig icanon echo ...}) = 0
open("/var/run/utmp", O_RDWR|O_LARGEFILE|O_CLOEXEC) = 7
close(7) = 0
open("/var/run/ppp-gprs.pid", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 7
close(7) = 0
open("/var/lock/LCK..ttyPSC4", O_RDWR|O_CREAT|O_EXCL, 0644) = 7
close(7) = 0
open("/dev/ttyPSC4", O_RDWR|O_NONBLOCK) = 7
ioctl(7, TIOCMBIS, [TIOCM_DTR]) = -1 EIO (Input/output error)
ioctl(7, TCGETS, 0xbf817378) = -1 EIO (Input/output error)
ioctl(7, TIOCMBIC, [TIOCM_DTR]) = -1 EIO (Input/output error)
ioctl(7, TIOCMBIS, [TIOCM_DTR]) = -1 EIO (Input/output error)
close(8) = 0
close(9) = 0
close(8) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
Script /usr/sbin/chat -v -f /etc/ppp/chats/gprs-conn -T my-apn finished (pid 3770), status = 0x2
Connect script failed
ioctl(7, TCFLSH, 0x2) = -1 EIO (Input/output error)
ioctl(7, TIOCMBIC, [TIOCM_DTR]) = -1 EIO (Input/output error)
close(7) = 0
root@mymachine:~#
-------------------------------------------------------------------------------
Something that makes the error difficult to debug is that it's occurence is
highly timing dependent. E.g. the use of strace can make the error occur when
it didn't or make it disappear when it did. Also it seems like something in
the network (timing?) also affects the occurance. Given an identical test
setup, some days it won't happen at all, some days it's intermittent and other
days it happens consistently.
Rebooting linux makes it possible to connect again. Sometimes it is enough to
let pppd retry by itself (persist) for a couple of times and the error will go
away but sometimes this is not enough and the pppd will continue trying forever
with the same error.
I have tried chasing the error by inserting printk statements in the kernel code
(mainly in tty_io.c and serial_core.c) but every time the error has suddenly
stopped occuring, I guess as an effect of the changed timing caused by the
printk's.
The gut feeling I have (no hard evidence though) is that there is a state
corruption in the kernel. After the PPP is finnished negotiating a disconnect
it matters when the tty is "hung up". If one goes well before the other
everything is OK but sometimes they collide and leave the tty hanging in limbo.
The following is from a test-run where the peer disconnects and the pppd tries
to reconnect (persist) and fails on the first attempt but not the second
(additional printk's labeled "MAKR:", the calls to "hung_up_tty_ioctl" below
would all have returned EIO, kernel v2.6.35):
-------------------------------------------------------------------------------
<snip>
Jan 7 17:22:52 mymachine daemon.debug pppd[609]: Script /etc/ppp/ip-up finished (pid 32381), status = 0x0
Jan 7 18:22:51 mymachine daemon.debug pppd[609]: rcvd [LCP TermReq id=0x0 "Normal Termination by NCP"]
Jan 7 18:22:51 mymachine daemon.info pppd[609]: LCP terminated by peer (Normal Termination by NCP)
Jan 7 18:22:51 mymachine daemon.info pppd[609]: Connect time 60.0 minutes.
Jan 7 18:22:51 mymachine daemon.info pppd[609]: Sent 0 bytes, received 0 bytes.
Jan 7 18:22:51 mymachine daemon.debug pppd[609]: Script /etc/ppp/ip-down started (pid 1421)
Jan 7 18:22:51 mymachine daemon.debug pppd[609]: sent [LCP TermAck id=0x0]
Jan 7 18:22:51 mymachine daemon.debug pppd[609]: Script /etc/ppp/ip-down finished (pid 1421), status = 0x0
Jan 7 18:22:51 mymachine daemon.info pppd[609]: Hangup (SIGHUP) code 128
Jan 7 18:22:51 mymachine daemon.notice pppd[609]: Modem hangup
Jan 7 18:22:51 mymachine daemon.notice pppd[609]: Connection terminated.
Jan 7 18:22:51 mymachine user.debug kernel: MAKR: uart_shutdown set ttyPSC4 40a0a
Jan 7 18:22:51 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x5417,0xbfba0418) ENOTTY/EIO 1 ?
Jan 7 18:22:52 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x802c7416,0xbfba03d8) ENOTTY/EIO 1 ?
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: uart_startup set ttyPSC4 a02
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: uart_startup clr ttyPSC4 a00
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: uart_block_til_ready
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: tty_ioctl 0x5416 on ttyPSC4 ret 0 at 2
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: tty_ioctl 0x402c7413 on ttyPSC4 ret 0 at 5
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: tty_ioctl 0x802c7416 on ttyPSC4 ret 0 at 5
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: tty_ioctl 0x5417 on ttyPSC4 ret 0 at 2
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: uart_shutdown set ttyPSC4 40a02
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x5416,0xbfba0398) ENOTTY/EIO 1 ?
Jan 7 18:22:55 mymachine local2.err chat[1435]: Can't get terminal parameters: Input/output error
Jan 7 18:22:55 mymachine daemon.debug pppd[609]: Script /usr/sbin/chat -v -f /etc/ppp/chats/gprs-conn -T my-apn finished (pid 1434), status = 0x2
Jan 7 18:22:55 mymachine daemon.err pppd[609]: Connect script failed
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x402c7413,0xbf893768) ENOTTY/EIO 1 ?
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x2000741f,0x2) ENOTTY/EIO 1 ?
Jan 7 18:22:55 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x5417,0xbfba0428) ENOTTY/EIO 1 ?
Jan 7 18:22:56 mymachine daemon.info pppd[609]: Hangup (SIGHUP) code 128
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: hung_up_tty_ioctl(0x802c7416,0xbfba03e8) ENOTTY/EIO 1 ?
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: uart_startup set ttyPSC4 a02
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: uart_startup clr ttyPSC4 a00
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: uart_block_til_ready
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: tty_ioctl 0x5416 on ttyPSC4 ret 0 at 2
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: tty_ioctl 0x402c7413 on ttyPSC4 ret 0 at 5
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: tty_ioctl 0x802c7416 on ttyPSC4 ret 0 at 5
Jan 7 18:22:56 mymachine user.debug kernel: MAKR: tty_ioctl 0x5417 on ttyPSC4 ret 0 at 2
Jan 7 18:22:57 mymachine user.debug kernel: MAKR: tty_ioctl 0x5416 on ttyPSC4 ret 0 at 2
Jan 7 18:22:57 mymachine local2.info chat[1437]: abort on (ERROR)
Jan 7 18:22:57 mymachine local2.info chat[1437]: timeout set to 10 seconds
Jan 7 18:22:57 mymachine local2.info chat[1437]: send (AT^M)
Jan 7 18:22:57 mymachine user.debug kernel: MAKR: tty_ioctl 0x402c7413 on ttyPSC4 ret 0 at 5
Jan 7 18:22:57 mymachine user.debug kernel: MAKR: tty_ioctl 0x802c7414 on ttyPSC4 ret 0 at 5
Jan 7 18:22:57 mymachine local2.info chat[1437]: expect (OK)
Jan 7 18:22:57 mymachine local2.info chat[1437]: AT^M^M
Jan 7 18:22:57 mymachine local2.info chat[1437]: OK
<snip>
-------------------------------------------------------------------------------
If anyone have any good suggestion about where to go next, I'm eager to hear.
Need more information? Please ask!
Best regards,
Mats
--
To unsubscribe from this list: send the line "unsubscribe linux-ppp" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
