IPCP: deflink: Oops, RCR in Initial.

Tue Nov 26 22:11:04 UTC 2013

Googling around this problem occasionally comes up, but I have yet to find a definitive answer.  An ISP is changing out their LACs and when they are doing a hot cut, this sometimes messes up the pppoe ppp process so it gets stuck in a loop and never recovers.  Killing off the ppp process and restarts it works and all is fixed.

But this still on rare occasion will come up.  Does anyone know the cause or work around ? I did manage to catch one and up the debug logs.

None debug looks like

Nov 26 15:30:01 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(10) state = Initial
Nov 26 15:30:01 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 15:30:01 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 15:30:03 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(11) state = Initial
Nov 26 15:30:03 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 15:30:03 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 15:30:04 s0332 ppp[1620]: tun1: LCP: deflink: RecvEchoRequest(174) state = Opened
Nov 26 15:30:04 s0332 ppp[1620]: tun1: LCP: deflink: SendEchoReply(174) state = Opened
Nov 26 15:30:05 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(12) state = Initial

Config is simple

pppoe:
 add 10.6.153.2 HISADDR
 add default HISADDR
 set device PPPoE:vr0
 set server /var/run/spdsl-internet "" 0177
 set speed sync
 enable echo
 disable ipv6cp
 disable vjcomp 
 set cd 15
 set dial
 set login
 set timeout 0
 set lqrperiod 10
 set authname s0332 at realm
 set authkey xxxxxxxx
 set ifaddr 10.0.0.1/0 10.0.0.2/0 255.255.255.0 255.255.255.0

With debugging

Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: Select returns 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Physical: read
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Physical:  80 21 01 97 00 0a 03 06 43 2b 80 0e              .!......C+..
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Debug: deflink: DescriptorRead: read 12/2048 from 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Sync: Read
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Sync:  80 21 01 97 00 0a 03 06 43 2b 80 0e              .!......C+..
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Debug: proto_LayerPull: unknown -> 0x8021
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Debug: link_PullPacket: Despatch proto 0x8021
Nov 26 16:53:20 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(151) state = Initial
Nov 26 16:53:20 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 16:53:20 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: deflink: fdset(r) 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: deflink: fdset(e) 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: server: fdset(r) 9
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: prompt /var/run/spdsl-internet: fdset(r) 2
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: Select returns -1
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: ---- Begin of Timer Service List---
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: physical throughput timer[0x28411068]: freq = 1.00s, next = 0.00s, state = running
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: lqm timer[0x28413df4]: freq = 10.00s, next = 2.40s, state = running
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: hdlc timer[0x28413db0]: freq = 60.00s, next = 52.40s, state = running
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: ---- End of Timer Service List ---
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: timer_Start: Inserting physical throughput timer[0x28411068] before lqm timer[0x28413df4], delta = 10
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: deflink: fdset(r) 1
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: deflink: fdset(e) 1
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: server: fdset(r) 9
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: prompt /var/run/spdsl-internet: fdset(r) 2
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: Select returns -1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: ---- Begin of Timer Service List---
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: physical throughput timer[0x28411068]: freq = 1.00s, next = 0.00s, state = running
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: lqm timer[0x28413df4]: freq = 10.00s, next = 1.40s, state = running
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: hdlc timer[0x28413db0]: freq = 60.00s, next = 51.40s, state = running
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: ---- End of Timer Service List ---
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: timer_Start: Inserting physical throughput timer[0x28411068] before lqm timer[0x28413df4], delta = 10
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink: fdset(r) 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink: fdset(e) 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: server: fdset(r) 9
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: prompt /var/run/spdsl-internet: fdset(r) 2
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: Select returns 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Physical: read
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Physical:  80 21 01 98 00 0a 03 06 43 2b 80 0e              .!......C+..
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Debug: deflink: DescriptorRead: read 12/2048 from 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Sync: Read
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Sync:  80 21 01 98 00 0a 03 06 43 2b 80 0e              .!......C+..
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Debug: proto_LayerPull: unknown -> 0x8021
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Debug: link_PullPacket: Despatch proto 0x8021
Nov 26 16:53:22 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(152) state = Initial
Nov 26 16:53:22 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 16:53:22 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0

-- 
-------------------
Mike Tancsa, tel +1 519 651 3400
Sentex Communications, mike at sentex.net
Providing Internet services since 1994 www.sentex.net
Cambridge, Ontario Canada   http://www.tancsa.com/