[RP-PPPoE] Can't attach PPP right after detach
Martinez Marcos
Marcos.Martinez at technicolor.com
Mon Nov 22 07:51:33 EST 2010
This is the result of performing the following operations:
1. attach PPP
2. wait 1.25 min
3. detach PPP
4. attach again
Nov 22 11:53:41 autom_mms pppd[30231]: pppd 2.4.4 started by root, uid 0
Nov 22 11:53:41 autom_mms pppd[30231]: using channel 779
Nov 22 11:53:41 autom_mms pppd[30231]: Using interface ppp0
Nov 22 11:53:41 autom_mms pppd[30231]: Connect: ppp0 <--> /dev/pts/3
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [LCP ConfReq id=0x1 <mru 1492> <magic 0x51ead36b>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0x9148fe52> <accomp>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP ConfRej id=0x1 <mru 1492>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [LCP ConfRej id=0x1 <accomp>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP ConfReq id=0x2 <auth chap MD5> <magic 0x9148fe52>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [LCP ConfReq id=0x2 <magic 0x51ead36b>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP ConfAck id=0x2 <magic 0x51ead36b>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [LCP ConfAck id=0x2 <auth chap MD5> <magic 0x9148fe52>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP EchoReq id=0x0 magic=0x9148fe52]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [CHAP Challenge id=0x49 <d7aac21fc14c4c5004ef7e260c1efe583d1cee4472f2>, name = "autom_mms"]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [LCP EchoReq id=0x0 magic=0x51ead36b]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP EchoRep id=0x0 magic=0x9148fe52]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [LCP EchoRep id=0x0 magic=0x51ead36b]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [CHAP Response id=0x49 <6f3578f235c64bd7b2dfd8758facf4a1>, name = "bench84"]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [CHAP Success id=0x49 "Access granted"]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 192.168.1.100>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0> <ms-wins 0.0.0.0>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [IPCP ConfRej id=0x1 <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0> <ms-wins 0.0.0.0>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [IPV6CP ConfReq id=0x1 <addr fe80::0226:44ff:fe00:0224>]
Nov 22 11:53:41 autom_mms pppd[30231]: Unsupported protocol 'IPv6 Control Protovol' (0x8057) received
Nov 22 11:53:41 autom_mms pppd[30231]: sent [LCP ProtRej id=0x3 80 57 01 01 00 0e 01 0a 02 26 44 ff fe 00 02 24]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [IPCP ConfReq id=0x2 <addr 192.168.1.100>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [IPCP ConfReq id=0x2 <addr 0.0.0.0>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [IPCP ConfNak id=0x2 <addr 192.168.1.188>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [IPCP ConfAck id=0x2 <addr 192.168.1.100>]
Nov 22 11:53:41 autom_mms pppd[30231]: rcvd [IPCP ConfReq id=0x3 <addr 192.168.1.188>]
Nov 22 11:53:41 autom_mms pppd[30231]: sent [IPCP ConfAck id=0x3 <addr 192.168.1.188>]
Nov 22 11:53:41 autom_mms pppd[30231]: local IP address 192.168.1.100
Nov 22 11:53:41 autom_mms pppd[30231]: remote IP address 192.168.1.188
Nov 22 11:53:41 autom_mms pppd[30231]: Script /etc/ppp/ip-up started (pid 30235)
Nov 22 11:53:41 autom_mms pppd[30231]: Script /etc/ppp/ip-up finished (pid 30235), status = 0x0
Nov 22 13:19:18 autom_mms pppd[30231]: rcvd [LCP TermReq id=0x3 "User request"]
Nov 22 13:19:18 autom_mms pppd[30231]: LCP terminated by peer (User request)
Nov 22 13:19:18 autom_mms pppd[30231]: Connect time 85.7 minutes.
Nov 22 13:19:18 autom_mms pppd[30231]: Sent 0 bytes, received 0 bytes.
Nov 22 13:19:18 autom_mms pppd[30231]: Script /etc/ppp/ip-down started (pid 30253)
Nov 22 13:19:18 autom_mms pppd[30231]: sent [LCP TermAck id=0x3]
Nov 22 13:19:18 autom_mms pppd[30231]: Script /etc/ppp/ip-down finished (pid 30253), status = 0x0
Nov 22 13:19:18 autom_mms pppoe-server[30229]: Sent PADT
Nov 22 13:19:21 autom_mms pppd[30231]: Connection terminated.
Nov 22 13:19:21 autom_mms pppd[30231]: Modem hangup
Nov 22 13:19:21 autom_mms pppd[30231]: Waiting for 1 child processes...
Nov 22 13:19:21 autom_mms pppd[30231]: script /usr/sbin/pppoe -n -I eth1 -e 1:00:26:44:00:02:24 -S 'DSL-Service', pid 30232
Nov 22 13:19:21 autom_mms pppd[30231]: Script /usr/sbin/pppoe -n -I eth1 -e 1:00:26:44:00:02:24 -S 'DSL-Service' finished (pid 30232), status = 0x1
Nov 22 13:19:21 autom_mms pppd[30231]: Exit.
Nov 22 13:19:21 autom_mms pppoe[30232]: read (asyncReadFromPPP): Session 1: Input/output error
Nov 22 13:19:45 autom_mms pppd[30257]: pppd 2.4.4 started by root, uid 0
Nov 22 13:19:45 autom_mms pppd[30257]: using channel 780
Nov 22 13:19:45 autom_mms pppd[30257]: Using interface ppp0
Nov 22 13:19:45 autom_mms pppd[30257]: Connect: ppp0 <--> /dev/pts/3
Nov 22 13:19:45 autom_mms pppoe-server[30229]: Session 1 closed for client 00:26:44:00:02:24 (10.67.15.1) on eth1
Nov 22 13:19:45 autom_mms pppoe-server[30229]: Session 2 closed for client 00:26:44:00:02:24 (10.67.15.2) on eth1
Nov 22 13:19:45 autom_mms pppoe-server[30229]: Sent PADT
Nov 22 13:19:46 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:19:49 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:19:52 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:19:55 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:19:58 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:20:01 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:20:04 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:20:07 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:20:10 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:20:14 autom_mms pppd[30257]: sent [LCP ConfReq id=0x1 <auth chap MD5> <magic 0xad93d0b8> <accomp>]
Nov 22 13:20:17 autom_mms pppd[30257]: LCP: timeout sending Config-Requests
Nov 22 13:20:17 autom_mms pppd[30257]: Connection terminated.
Nov 22 13:20:17 autom_mms pppd[30257]: Modem hangup
Nov 22 13:20:17 autom_mms pppd[30257]: Waiting for 1 child processes...
Nov 22 13:20:17 autom_mms pppd[30257]: script /usr/sbin/pppoe -n -I eth1 -e 2:00:26:44:00:02:24 -S 'DSL-Service', pid 30258
Nov 22 13:20:17 autom_mms pppd[30257]: Script /usr/sbin/pppoe -n -I eth1 -e 2:00:26:44:00:02:24 -S 'DSL-Service' finished (pid 30258), status = 0x1
Nov 22 13:20:17 autom_mms pppd[30257]: Exit.
Nov 22 13:20:17 autom_mms pppoe[30258]: read (asyncReadFromPPP): Session 2: Input/output error
autom_mms ppp #
autom_mms ppp # pppoe-server -I eth1 -C Dummy-DSLAM -S DSL-Service
autom_mms ppp # ps auxw
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.0 1656 500 ? Ss Nov16 0:03 init [3]
root 2 0.0 0.0 0 0 ? S< Nov16 0:00 [kthreadd]
root 3 0.0 0.0 0 0 ? S< Nov16 0:00 [migration/0]
root 4 0.0 0.0 0 0 ? S< Nov16 0:00 [ksoftirqd/0]
root 5 0.0 0.0 0 0 ? S< Nov16 0:00 [watchdog/0]
root 6 0.0 0.0 0 0 ? S< Nov16 0:00 [cpuset]
root 7 0.0 0.0 0 0 ? S< Nov16 0:00 [events/0]
root 8 0.0 0.0 0 0 ? S< Nov16 0:00 [work_on_cpu/0]
root 9 0.0 0.0 0 0 ? S< Nov16 0:00 [khelper]
root 178 0.0 0.0 0 0 ? S< Nov16 0:00 [kblockd/0]
root 181 0.0 0.0 0 0 ? S< Nov16 0:00 [kacpid]
root 182 0.0 0.0 0 0 ? S< Nov16 0:00 [kacpi_notify]
root 240 0.0 0.0 0 0 ? S< Nov16 0:00 [ata/0]
root 241 0.0 0.0 0 0 ? S< Nov16 0:00 [ata_aux]
root 242 0.0 0.0 0 0 ? S< Nov16 0:00 [ksuspend_usbd]
root 248 0.0 0.0 0 0 ? S< Nov16 0:00 [khubd]
root 251 0.0 0.0 0 0 ? S< Nov16 0:00 [kseriod]
root 296 0.0 0.0 0 0 ? S Nov16 0:00 [pdflush]
root 297 0.0 0.0 0 0 ? S Nov16 0:00 [pdflush]
root 298 0.0 0.0 0 0 ? S< Nov16 0:00 [kswapd0]
root 299 0.0 0.0 0 0 ? S< Nov16 0:00 [aio/0]
root 572 0.0 0.0 0 0 ? S< Nov16 0:00 [scsi_tgtd/0]
root 585 0.0 0.0 0 0 ? S< Nov16 0:00 [iscsi_eh]
root 655 0.0 0.0 0 0 ? S< Nov16 0:00 [scsi_eh_2]
root 657 0.0 0.0 0 0 ? S< Nov16 0:00 [scsi_eh_3]
root 742 0.0 0.0 0 0 ? S< Nov16 0:00 [kpsmoused]
root 747 0.0 0.0 0 0 ? S< Nov16 0:00 [hid_compat]
root 1917 0.0 0.0 0 0 ? S< Nov16 0:00 [kjournald]
root 2026 0.0 0.0 1920 436 ? S<s Nov16 0:03 /sbin/udevd --daemon
root 3481 0.0 0.0 2260 692 ? Ss Nov16 0:01 /usr/sbin/syslog-ng
root 3752 0.0 0.0 1868 380 ? Ss Nov16 0:10 /usr/sbin/gpm -m /dev/input/mice -t ps2
101 3808 0.0 0.0 2420 740 ? Ss Nov16 0:00 /usr/bin/dbus-daemon --system
104 3865 0.0 0.3 5032 2412 ? Ss Nov16 0:00 /usr/sbin/hald --use-syslog --verbose=no
root 3866 0.0 0.1 3192 1028 ? S Nov16 0:00 hald-runner
root 3869 0.0 0.1 3256 880 ? S Nov16 0:00 hald-addon-input: Listening on /dev/input/event4 /dev/input/event2
root 3877 0.0 0.1 3260 920 ? S Nov16 0:00 hald-addon-storage: no polling on /dev/fd0 because it is explicitly
root 3882 0.0 0.1 3260 920 ? S Nov16 0:00 hald-addon-storage: polling /dev/hdc (every 2 sec)
root 4832 0.0 0.1 12340 804 ? Ss Nov16 0:00 /usr/bin/gdm
root 4844 0.0 0.2 12844 1768 ? S Nov16 0:00 /usr/bin/gdm
root 4863 0.2 1.2 18032 9424 tty7 Ss+ Nov16 18:32 /usr/bin/X :0 -audit 0 -auth /var/gdm/:0.Xauth -nolisten tcp vt7
root 4895 0.0 0.0 1656 436 tty1 Ss+ Nov16 0:00 /sbin/agetty 38400 tty1 linux
root 4896 0.0 0.0 1656 436 tty2 Ss+ Nov16 0:00 /sbin/agetty 38400 tty2 linux
root 4897 0.0 0.0 1656 436 tty3 Ss+ Nov16 0:00 /sbin/agetty 38400 tty3 linux
root 4898 0.0 0.0 1656 436 tty4 Ss+ Nov16 0:00 /sbin/agetty 38400 tty4 linux
root 4899 0.0 0.0 1656 436 tty5 Ss+ Nov16 0:00 /sbin/agetty 38400 tty5 linux
root 4900 0.0 0.0 1656 436 tty6 Ss+ Nov16 0:00 /sbin/agetty 38400 tty6 linux
root 4951 0.0 0.6 23264 5108 ? Ssl Nov16 0:00 gnome-session
root 4964 0.0 0.0 3036 460 ? S Nov16 0:00 /usr/bin/dbus-launch --sh-syntax --exit-with-session
root 4965 0.0 0.1 2460 796 ? Ss Nov16 0:00 /usr/bin/dbus-daemon --fork --print-pid 6 --print-address 9 --sessi
root 4967 0.0 0.0 3812 248 ? Ss Nov16 0:00 /usr/bin/ssh-agent -- gnome-session
root 4970 0.0 0.3 4876 2620 ? S Nov16 0:00 /usr/libexec/gconfd-2
root 4976 0.0 0.9 29232 7284 ? Ssl Nov16 0:07 /usr/libexec/gnome-settings-daemon
root 4977 0.0 1.1 16172 8572 ? S Nov16 1:17 metacity
root 4978 0.1 2.2 38172 16992 ? S Nov16 10:35 gnome-panel
root 4982 0.0 3.0 59352 23432 ? S Nov16 1:36 nautilus --no-desktop --browser
root 4984 0.0 0.3 14456 2764 ? Ssl Nov16 0:00 /usr/libexec/bonobo-activation-server --ac-activate --ior-output-fd
root 4987 0.0 0.2 3776 1672 ? S Nov16 0:00 /usr/libexec/gvfsd
root 4993 0.0 0.5 18936 4536 ? Ss Nov16 0:00 /usr/libexec/gnome-volume-manager --sm-disable
root 5002 0.0 0.3 12604 2608 ? Sl Nov16 0:00 /usr/libexec/gvfs-hal-volume-monitor
root 5006 0.0 0.3 12692 2676 ? S Nov16 0:00 /usr/libexec/gvfsd-trash --spawner :1.9 /org/gtk/gvfs/exec_spaw/0
root 5019 0.0 9.1 93312 70572 ? Sl Nov16 5:39 gnome-terminal
root 5021 0.0 0.0 2724 684 ? S Nov16 0:00 gnome-pty-helper
root 5022 0.0 0.1 2972 1460 pts/0 Ss+ Nov16 0:00 -bash
root 5034 0.1 5.3 53372 40728 ? S Nov16 9:07 geany
root 5035 0.0 0.0 2724 596 ? S Nov16 0:00 gnome-pty-helper
root 5036 0.0 0.1 2844 1212 pts/1 Ss+ Nov16 0:00 /bin/bash
root 6301 0.0 0.2 2976 1644 pts/2 Rs Nov17 0:00 -bash
root 27216 0.0 0.1 4324 864 ? Ss Nov19 0:00 /usr/sbin/sshd
root 28587 0.0 6.0 83068 46296 ? S Nov19 0:30 wireshark
root 30154 0.0 0.5 7120 4572 ? S 11:36 0:00 putty
root 30425 0.0 0.0 1672 448 ? S 13:40 0:00 pppoe-server -I eth1 -C Dummy-DSLAM -S DSL-Service
root 30436 0.0 0.1 2684 784 ? Ss 13:40 0:00 pppd pty /usr/sbin/pppoe -n -I eth1 -e 2:00:26:44:00:02:24 -S 'DSL-
nobody 30437 0.0 0.0 1868 656 ? S 13:40 0:00 /usr/sbin/pppoe -n -I eth1 -e 2:00:26:44:00:02:24 -S DSL-Service
root 30440 0.0 0.1 2304 900 pts/2 R+ 13:40 0:00 ps auxw
Any ideas?
What is this read (asyncReadFromPPP): Session 1: Input/output error?
10.67.15.1 and 2: where are they coming from?
Marcos
-----Original Message-----
From: rp-pppoe-bounces at lists.roaringpenguin.com [mailto:rp-pppoe-bounces at lists.roaringpenguin.com] On Behalf Of Insane Laughing Clown
Sent: 19 November 2010 18:06
To: For users of RP-PPPoE client/server software
Subject: Re: [RP-PPPoE] Can't attach PPP right after detach
Martinez Marcos wrote:
> Hello,
>
> I am trying to connect a DSL modem to a PC via PPPoE.
>
> Steps:
>
> 1. I launch the PPPoE server on the PC
> 2. I attach the PPP interface from the modem
> 3. OK. PPP link is up
> 4. I detach the PPP interface from the modem
> 5. OK. PPP link is down
> 6. I attach again the PPP interface
> 7. PADI-PADO-PADR-PADS are sent
> 8. Server sends a PADT with error: RP-PPPoE: Child pppd process terminated
>
> Any idea of what's wrong?
>
> If I want to restablish the PPP connection, I have to kill and then reboot the pppoe-server
>
Sounds like a problem to drive you insane. ;-)
Turn on 'debug' in the server (/etc/ppp/options), then lets see the
following:
A copy of your syslog from the first and second connection attempts
a 'ps auxw" on the server after the second attempt fails.
a copy of the command line option you used to launch pppoe-server.
Also - what host operating system you got (linux version and so forth)?
-ILC
_______________________________________________
RP-PPPoE mailing list
RP-PPPoE at lists.roaringpenguin.com
http://lists.roaringpenguin.com/cgi-bin/mailman/listinfo/rp-pppoe
More information about the RP-PPPoE
mailing list