some change in ppp 2.4.3: tcflush failed: Bad file descriptor

some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[Arkadiusz Miskiewicz]

Hi,

Something changed in ppp 2.4.3. Now after disconnect I'm getting:

Nov 17 16:00:23 arm pppd[17641]: local  IP address xx
Nov 17 16:00:24 arm pppd[17641]: remote IP address xx
Nov 17 16:00:24 arm pppd[17641]: primary   DNS address xx
Nov 17 16:00:24 arm pppd[17641]: secondary DNS address xx
Nov 18 16:00:21 arm pppd[17641]: LCP terminated by peer
Nov 18 16:00:21 arm pppd[17641]: Connect time 1440.0 minutes.
Nov 18 16:00:21 arm pppd[17641]: Sent 97298679 bytes, received 1835111999 
bytes.
Nov 18 16:00:22 arm pppd[17641]: Child process /etc/ppp/ip-down (pid 19630) 
terminated with signal 15
Nov 18 16:00:24 arm pppd[17641]: Connection terminated.
Nov 18 16:00:25 arm pppd[17641]: Using interface ppp0
Nov 18 16:00:25 arm pppd[17641]: Connect: ppp0 <--> /dev/pts/12
Nov 18 16:00:56 arm pppd[17641]: LCP terminated by peer
Nov 18 16:00:59 arm pppd[17641]: Connection terminated.
Nov 18 16:00:59 arm pppd[17641]: tcflush failed: Bad file descriptor
Nov 18 16:00:59 arm pppd[17641]: Using interface ppp0
Nov 18 16:00:59 arm pppd[17641]: Connect: ppp0 <--> /dev/pts/13
Nov 18 16:01:29 arm pppd[17641]: LCP terminated by peer
Nov 18 16:01:32 arm pppd[17641]: Connection terminated.
Nov 18 16:01:32 arm pppd[17641]: tcflush failed: Bad file descriptor
Nov 18 16:01:32 arm pppd[17641]: Using interface ppp0
Nov 18 16:01:32 arm pppd[17641]: Connect: ppp0 <--> /dev/pts/15
Nov 18 16:02:02 arm pppd[17641]: LCP terminated by peer
Nov 18 16:02:05 arm pppd[17641]: Connection terminated.
Nov 18 16:02:05 arm pppd[17641]: tcflush failed: Bad file descriptor
Nov 18 16:02:05 arm pppd[17641]: Using interface ppp0

With 2.4.2 there was no problem with ,,tcflush failed: Bad file descriptor'' 
on the same kernel.

pppd is called with:
/usr/sbin/pppd lock persist holdoff 30 maxfail 0 crtscts asyncmap 00000000 
defaultroute usepeerdns mtu 1480 user xyz noauth unit 0 pty "pppoa -I eth1" 
ipparam ppp0 linkname ppp0

where pppoa comes from eagle-usb.

Did anyone seen such problem with new ppp?
-- 
Arkadiusz Mi¶kiewicz                    PLD/Linux Team
http://www.t17.ds.pwr.wroc.pl/~misiek/  http://ftp.pld-linux.org/

Re: some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[James Carlson]

Arkadiusz Miskiewicz writes:
> Nov 18 16:00:25 arm pppd[17641]: Using interface ppp0
> Nov 18 16:00:25 arm pppd[17641]: Connect: ppp0 <--> /dev/pts/12
> Nov 18 16:00:56 arm pppd[17641]: LCP terminated by peer
> Nov 18 16:00:59 arm pppd[17641]: Connection terminated.

Try running with debug enabled.  The 'LCP terminated by peer' message
indicates that something went wrong when trying to negotiate with the
peer system.  Perhaps there's an authentication problem.

> With 2.4.2 there was no problem with ,,tcflush failed: Bad file descriptor'' 
> on the same kernel.

I've seen it before, but I don't think it's actually harmful.

-- 
James Carlson                                 <carlsonj@workingcode.com>

Re: some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[Arkadiusz Miskiewicz]

On Tuesday 23 of November 2004 17:06, James Carlson wrote:
> Arkadiusz Miskiewicz writes:
> > Nov 18 16:00:25 arm pppd[17641]: Using interface ppp0
> > Nov 18 16:00:25 arm pppd[17641]: Connect: ppp0 <--> /dev/pts/12
> > Nov 18 16:00:56 arm pppd[17641]: LCP terminated by peer
> > Nov 18 16:00:59 arm pppd[17641]: Connection terminated.
>
> Try running with debug enabled.  The 'LCP terminated by peer' message
> indicates that something went wrong when trying to negotiate with the
> peer system.  Perhaps there's an authentication problem.
Nov 24 12:19:10 arm pppd[5447]: Connect: ppp0 <--> /dev/pts/65
Nov 24 12:19:11 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:14 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:18 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:21 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:25 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:28 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:32 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:36 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:39 arm pppd[5447]: sent [LCP ConfReq id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfReq id=0xab <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:40 arm pppd[5447]: sent [LCP ConfNak id=0xab <auth pap>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfReq id=0xac <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:40 arm pppd[5447]: sent [LCP ConfNak id=0xac <auth pap>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfReq id=0xad <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:40 arm pppd[5447]: sent [LCP ConfNak id=0xad <auth pap>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfReq id=0xae <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:40 arm pppd[5447]: sent [LCP ConfNak id=0xae <auth pap>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfReq id=0xaf <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:40 arm pppd[5447]: sent [LCP ConfNak id=0xaf <auth pap>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfReq id=0xb0 <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:40 arm pppd[5447]: sent [LCP ConfRej id=0xb0 <auth chap MD5>]
Nov 24 12:19:40 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfReq id=0xb1 <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:41 arm pppd[5447]: sent [LCP ConfRej id=0xb1 <auth chap MD5>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfReq id=0xb2 <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:41 arm pppd[5447]: sent [LCP ConfRej id=0xb2 <auth chap MD5>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfReq id=0xb3 <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:41 arm pppd[5447]: sent [LCP ConfRej id=0xb3 <auth chap MD5>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfAck id=0x3c <asyncmap 0x0> <magic 0xf68ca3b4> <pcomp> <accomp>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfReq id=0xb4 <mru 9178> <auth chap MD5> <magic 0x7efec34d>]
Nov 24 12:19:41 arm pppd[5447]: sent [LCP ConfRej id=0xb4 <auth chap MD5>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP ConfReq id=0xb5 <mru 9178> <magic 0x7efec34d>]
Nov 24 12:19:41 arm pppd[5447]: sent [LCP ConfAck id=0xb5 <mru 9178> <magic 0x7efec34d>]
Nov 24 12:19:41 arm pppd[5447]: sent [LCP EchoReq id=0x0 magic=0xf68ca3b4]
Nov 24 12:19:41 arm pppd[5447]: sent [CCP ConfReq id=0x3c <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Nov 24 12:19:41 arm pppd[5447]: sent [IPCP ConfReq id=0x3e <compress VJ 0f 01> <addr 83.27.15.78> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Nov 24 12:19:41 arm pppd[5447]: rcvd [LCP TermReq id=0xb6]
Nov 24 12:19:41 arm pppd[5447]: LCP terminated by peer
Nov 24 12:19:41 arm pppd[5447]: sent [LCP TermAck id=0xb6]
Nov 24 12:19:44 arm pppd[5447]: Connection terminated.
Nov 24 12:19:44 arm pppd[5447]: tcflush failed: Bad file descriptor
Nov 24 12:19:44 arm pppd[5447]: using channel 197
Nov 24 12:19:44 arm pppd[5447]: Using interface ppp0
Nov 24 12:19:45 arm pppd[5447]: Connect: ppp0 <--> /dev/pts/66
Nov 24 12:19:46 arm pppd[5447]: sent [LCP ConfReq id=0x3d <asyncmap 0x0> <magic 0x688721d3> <pcomp> <accomp>]
Nov 24 12:19:49 arm pppd[5447]: sent [LCP ConfReq id=0x3d <asyncmap 0x0> <magic 0x688721d3> <pcomp> <accomp>]

> > With 2.4.2 there was no problem with ,,tcflush failed: Bad file
> > descriptor'' on the same kernel.
>
> I've seen it before, but I don't think it's actually harmful.
Well, after such disconnect new pppd runs pppoa -I eth1 multiple times
without killing old one and this causes huge load (it's hard to do anything
on the system then). Old, not killed pppoa processes reports multiple
Nov 25 16:18:15 arm pppoa[6387]: Packet not from driver (mac:  0:60:4c:41:53:74)
Nov 25 16:18:15 arm pppoa[6387]: Packet not from driver (mac:  0:60:4c:41:53:74)
Nov 25 16:18:15 arm pppoa[6328]: Packet not from driver (mac:  0:60:4c:41:53:74)
Nov 25 16:18:15 arm pppoa[6328]: Packet not from driver (mac:  0:60:4c:41:53:74)

Shouldn't pppd kill old pty "command" before running new one?

-- 
Arkadiusz Mi¶kiewicz                    PLD/Linux Team
http://www.t17.ds.pwr.wroc.pl/~misiek/  http://ftp.pld-linux.org/

Re: some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[Arkadiusz Miskiewicz]

On Thursday 25 of November 2004 16:44, Arkadiusz Miskiewicz wrote:

> Well, after such disconnect new pppd runs pppoa -I eth1 multiple times
> without killing old one and this causes huge load (it's hard to do anything
> on the system then). Old, not killed pppoa processes reports multiple
> Nov 25 16:18:15 arm pppoa[6387]: Packet not from driver (mac: 
> 0:60:4c:41:53:74) Nov 25 16:18:15 arm pppoa[6387]: Packet not from driver
> (mac:  0:60:4c:41:53:74) Nov 25 16:18:15 arm pppoa[6328]: Packet not from
> driver (mac:  0:60:4c:41:53:74) Nov 25 16:18:15 arm pppoa[6328]: Packet not
> from driver (mac:  0:60:4c:41:53:74)
>
> Shouldn't pppd kill old pty "command" before running new one?

It looks like this:
[root@arm misiek]# pstree -lpu | grep ppp
        |-pppd(17285)-+-sh(17286)---pppoa(17287)
        |             |-sh(17479)---pppoa(17484)
        |             `-sh(17539)---pppoa(17540)
        |-sh(8386)---pppoa(8390)

new pppoa is created at each retry

-- 
Arkadiusz Mi¶kiewicz                    PLD/Linux Team
http://www.t17.ds.pwr.wroc.pl/~misiek/  http://ftp.pld-linux.org/

Re: some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[Paul Mackerras]

Arkadiusz Miskiewicz writes:

> Shouldn't pppd kill old pty "command" before running new one?

pppd will close its side of the pty device, leading to the program
running on the other side (the script specified in the pty option)
getting an end-of-file on its standard input.  It should clean up and
exit when it gets that.

Alternatively you can use a disconnect script to kill it, if your pty
command is too lame to exit on EOF.

Paul.

Re: some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[Arkadiusz Miskiewicz]

On Thursday 25 of November 2004 22:27, Paul Mackerras wrote:
> Arkadiusz Miskiewicz writes:
> > Shouldn't pppd kill old pty "command" before running new one?
>
> pppd will close its side of the pty device, leading to the program
> running on the other side (the script specified in the pty option)
> getting an end-of-file on its standard input.  It should clean up and
> exit when it gets that.
>
> Alternatively you can use a disconnect script to kill it, if your pty
> command is too lame to exit on EOF.

Looking into pppoa code I see that read() of 0 is handled (exit(0) in such 
case). Did anything change between 2.4.2 and 2.4.3 in this area? 2.4.2 causes 
that pppoa terminates properly while 2.4.3 not.

tcflush failed: Bad file descriptor comes from ioctl on -1 descriptor, doesn't 
look correct
4196  ioctl(8, JFFS_PRINT_HASH or PPPIOCGFLAGS, 0xbffff3a0) = 0
4196  ioctl(-1, TCFLSH, 0x2)            = -1 EBADF (Bad file descriptor)
4196  time([1101422552])                = 1101422552
4196  stat64("/etc/localtime",  <unfinished ...>
4555  <... select resumed> )            = 0 (Timeout)
4196  <... stat64 resumed> {st_mode=S_IFREG|0644, st_size–1, ...}) = 0
4555  select(4, [0 3], NULL, NULL, {0, 250} <unfinished ...>
4196  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size–1, ...}) = 0
4196  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size–1, ...}) = 0
4196  rt_sigaction(SIGPIPE, {0xb7f0a140, [], 0}, {SIG_IGN}, 8) = 0
4196  send(3, "<28>Nov 25 23:42:32 pppd[4196]: tcflush failed: Bad file 
descriptor\0", 68, 0) = 68

isn't tcflush failing a reason for a pppoa to not terminate?
> Paul.

-- 
Arkadiusz Mi¶kiewicz                    PLD/Linux Team
http://www.t17.ds.pwr.wroc.pl/~misiek/  http://ftp.pld-linux.org/

Re: some change in ppp 2.4.3: tcflush failed: Bad file descriptor

[Paul Mackerras]

Arkadiusz Miskiewicz writes:

> Looking into pppoa code I see that read() of 0 is handled (exit(0) in such 
> case). Did anything change between 2.4.2 and 2.4.3 in this area? 2.4.2 causes 
> that pppoa terminates properly while 2.4.3 not.

Interesting.  2.4.3 has some changes to make sure that we don't leak
file descriptors or leave them open when we shouldn't, but maybe
there's still a bug.  Can you send me the whole strace log?

> isn't tcflush failing a reason for a pppoa to not terminate?

Nope.

Paul.