SRX Services Gateway
Highlighted
SRX Services Gateway

Issue reconnecting terminated PPPoE Session

[ Edited ]
‎06-29-2016 12:55 AM

Hi folks,

 

I have a problem reconnecting terminated PPPoE sessions on 4 srx100h2.

 

Here's the pppoe log:

Jun 28 18:00:29 === Configuration Reload succeeded ===
Jun 28 18:00:29 pppoed_ifl_msg_handler pp0.0 ifl 72 op 2 flag 0xc010
Jun 28 18:00:29 In Parse TLV: opts 0x0 0xa fe-0/0/0.0
Jun 28 18:00:29 pppoed_change_ifl_options: ifname pp0.0
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 session mode client
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 session up, kernsync false
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 session id=5634 (current 5634)
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 credit interval set to 0
Jun 28 18:00:29 pppoed_change_ifl_options: pp0.0 session id=5634
Jun 28 18:00:29 pppoed_change_ifl: ifname pp0.0
Jun 28 18:01:04 SIGHUP received
Jun 28 18:01:05 === Configuration Reload succeeded ===

My note: No reboot or power down here, but over six hours no pppoe logging?!?
Jun 29 00:04:53 pppoed_uifd_msg_handler fe-0/0/2 ifd 136 op 2 flag 0xc001 Jun 29 00:04:53 pppoed_change_uifd: uifd fe-0/0/2 enter Jun 29 04:04:05 SIGTERM received Jun 29 04:09:24 === Configuration load succeeded === Jun 29 04:09:24 PPPOED release 12.1X46-D40.2 built by builder on 2015-09-26 04:39:43 UTC starting, pid 1508 Jun 29 04:09:25 allocated 4096 bytes at 0x513000 Jun 29 04:09:25 Scanning ifds ... Jun 29 04:09:25 Scanning ifls ... Jun 29 04:09:25 Done scanning ifls Jun 29 04:10:18 pppoed_ifd_msg_handler pp0 ifd 128 op 2 flag 0x8010 Jun 29 04:10:18 pppoed_change_ifd ifd pp0 enter Jun 29 04:10:27 pppoed_uifd_msg_handler fe-0/0/0 ifd 134 op 1 flag 0xc001 Jun 29 04:10:27 allocated 88 bytes at 0x505100 Jun 29 04:10:27 pppoed_uifd_msg_handler fe-0/0/1 ifd 135 op 1 flag 0x3 Jun 29 04:10:27 allocated 88 bytes at 0x505180 Jun 29 04:10:27 pppoed_uifd_msg_handler fe-0/0/0 ifd 134 op 2 flag 0xc001 Jun 29 04:10:27 pppoed_change_uifd: uifd fe-0/0/0 enter Jun 29 04:10:27 pppoed_uifl_msg_handler fe-0/0/0.0 ifl 71 op 1 flag 0xc000 Jun 29 04:10:27 pppoed_add_uifl: ifname fe-0/0/0.0 Jun 29 04:10:27 allocated 212 bytes at 0x51c000 Jun 29 04:10:27 allocated 4 bytes at 0x5040c0 Jun 29 04:10:27 allocated 4 bytes at 0x5040d0 Jun 29 04:10:27 pppoed_add_uifl: unrecognized tlv 117440767 on fe-0/0/0.0 Jun 29 04:10:27 pppoed_add_uifl: unrecognized tlv 285 on fe-0/0/0.0 Jun 29 04:10:27 pppoed_uifd_msg_handler fe-0/0/2 ifd 136 op 1 flag 0x3 Jun 29 04:10:27 allocated 88 bytes at 0x505200 Jun 29 04:10:27 pppoed_ifl_msg_handler pp0.0 ifl 72 op 1 flag 0xc011 Jun 29 04:10:27 pppoed_add_ifl: ifname pp0.0 Jun 29 04:10:27 allocated 592 bytes at 0x518000 Jun 29 04:10:27 In Parse TLV: opts 0x0 0xa fe-0/0/0.0 Jun 29 04:10:27 pppoed_change_ifl_options: ifname pp0.0 Jun 29 04:10:27 pppoed_change_ifl_options: pp0.0 session auto rec timer changed when session not connected Jun 29 04:10:27 Discovery Init: uifl not found for pp0.0! Jun 29 04:10:27 pppoed_change_ifl_options: pp0.0 session mode client Jun 29 04:10:27 pppoed_change_ifl_options: pp0.0 session down, kernsync false Jun 29 04:10:27 pppoed_change_ifl_options: pp0.0 session id=0 (current 0) Jun 29 04:10:27 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535 Jun 29 04:10:27 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0 Jun 29 04:10:27 Add pp0.0 to fe-0/0/0.0 Jun 29 04:10:27 pppoe_ifl_params_change: ifl pp0.0, ifl sid 0, param sid 0 Jun 29 04:10:28 pppoed_ifl_params_sync: Doing sync for ifl: pp0.0 Jun 29 04:10:28 pppoed_ifl_params_sync: TLVs present. Parsing them Jun 29 04:10:28 In Parse TLV: opts 0x0 0xa fe-0/0/0.0 Jun 29 04:10:28 pppoed_change_ifl_options: ifname pp0.0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session mode client Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session down, kernsync true Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session id=1 (current 0) Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credit interval set to 0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session id=0 Jun 29 04:10:28 add ifl to uifl, session id=0 after sync with kernel for pp0.0 Jun 29 04:10:28 allocated 8 bytes at 0x5040e0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credit interval set to 0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session id=0 Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/0.0 ifl 71 op 2 flag 0xc000 Jun 29 04:10:28 pppoed_change_uifl: ifname fe-0/0/0.0 iflm_flags=0xc000 Jun 29 04:10:28 pppoed_change_uifl: unrecognized tlv 117440767 on fe-0/0/0.0 Jun 29 04:10:28 pppoed_change_uifl: unrecognized tlv 285 on fe-0/0/0.0 Jun 29 04:10:28 pppoed_uifl_dynifbw: disabled dynamic interface bw on fe-0/0/0.0 Jun 29 04:10:28 pppoed_ifl_msg_handler pp0.0 ifl 72 op 2 flag 0xc011 Jun 29 04:10:28 In Parse TLV: opts 0x0 0xa fe-0/0/0.0 Jun 29 04:10:28 pppoed_change_ifl_options: ifname pp0.0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session mode client Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session down, kernsync false Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session id=1 (current 0) Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 credit interval set to 0 Jun 29 04:10:28 pppoed_change_ifl_options: pp0.0 session id=0 Jun 29 04:10:28 pppoed_change_ifl: ifname pp0.0 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/1 ifd 135 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/1 enter Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/3 ifd 137 op 1 flag 0x3 Jun 29 04:10:28 allocated 88 bytes at 0x505280 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/2 ifd 136 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/2 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/1.0 ifl 73 op 1 flag 0xc000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/4 ifd 138 op 1 flag 0x3 Jun 29 04:10:28 allocated 88 bytes at 0x505300 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/5 ifd 139 op 1 flag 0x3 Jun 29 04:10:28 allocated 88 bytes at 0x505380 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/7 ifd 141 op 1 flag 0x3 Jun 29 04:10:28 allocated 88 bytes at 0x505400 Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/2.0 ifl 74 op 1 flag 0xc000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/6 ifd 140 op 1 flag 0x3 Jun 29 04:10:28 allocated 88 bytes at 0x505480 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/3 ifd 137 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/3 enter Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/2 ifd 136 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/2 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/3.0 ifl 75 op 1 flag 0x8000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/7 ifd 141 op 2 flag 0x3 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/7 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/3.0 ifl 75 op 2 flag 0xc000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/4 ifd 138 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/4 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/4.0 ifl 76 op 1 flag 0x8000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/3 ifd 137 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/3 enter Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/5 ifd 139 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/5 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/4.0 ifl 76 op 2 flag 0xc000 Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/5.0 ifl 77 op 1 flag 0x8000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/4 ifd 138 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/4 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/5.0 ifl 77 op 2 flag 0xc000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/6 ifd 140 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/6 enter Jun 29 04:10:28 pppoed_uifl_msg_handler fe-0/0/6.0 ifl 78 op 1 flag 0x8000 Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/5 ifd 139 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/5 enter Jun 29 04:10:28 pppoed_uifd_msg_handler fe-0/0/7 ifd 141 op 2 flag 0xc001 Jun 29 04:10:28 pppoed_change_uifd: uifd fe-0/0/7 enter Jun 29 04:10:29 pppoed_uifd_msg_handler fe-0/0/6 ifd 140 op 2 flag 0xc001 Jun 29 04:10:29 pppoed_change_uifd: uifd fe-0/0/6 enter Jun 29 04:10:29 pppoed_uifl_msg_handler fe-0/0/7.0 ifl 79 op 1 flag 0x8000 Jun 29 04:10:29 pppoed_uifl_msg_handler fe-0/0/6.0 ifl 78 op 2 flag 0xc000 Jun 29 04:10:29 pppoed_uifl_msg_handler fe-0/0/7.0 ifl 79 op 2 flag 0xc000 Jun 29 04:10:29 pppoed_uifd_msg_handler fe-0/0/7 ifd 141 op 2 flag 0xc001 Jun 29 04:10:29 pppoed_change_uifd: uifd fe-0/0/7 enter Jun 29 04:10:31 pppoed_uifd_msg_handler fe-0/0/0 ifd 134 op 2 flag 0xc001 Jun 29 04:10:31 pppoed_change_uifd: uifd fe-0/0/0 enter Jun 29 04:10:31 pppoed_uifd_msg_handler fe-0/0/1 ifd 135 op 2 flag 0xc001 Jun 29 04:10:31 pppoed_change_uifd: uifd fe-0/0/1 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/2 ifd 136 op 2 flag 0xc001 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/2 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/3 ifd 137 op 2 flag 0xc001 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/3 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/4 ifd 138 op 2 flag 0xc001 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/4 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/5 ifd 139 op 2 flag 0xc001 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/5 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/6 ifd 140 op 2 flag 0xc001 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/6 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/7 ifd 141 op 2 flag 0xc001 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/7 enter Jun 29 04:10:32 pppoed_uifd_msg_handler fe-0/0/0 ifd 134 op 2 flag 0xc000 Jun 29 04:10:32 pppoed_change_uifd: uifd fe-0/0/0 enter Jun 29 04:10:32 ***Discovery Init: pp0.0 Jun 29 04:10:32 allocated 1510 bytes at 0x519000 Jun 29 04:10:32 *totlen=0x6 tp->len=0x2 ntohs(tplen)=0x2 tot=0x6 MAX_L=0x1502 Jun 29 04:10:32 *totlen=0xa tp->len=0x0 ntohs(tplen)=0x0 tot=0xa MAX_L=0x1502 Jun 29 04:10:32 *totlen=0xe tp->len=0x0 ntohs(tplen)=0x0 tot=0xe MAX_L=0x1502 Jun 29 04:10:32 IO send ... PADI for pp0.0 Jun 29 04:10:33 Discovery Input: PADO packet received on uifl (idx 71) Jun 29 04:10:33 Received AC name KIEX42-erx\x01\x03 configured AC name on uifl (idx 71) Jun 29 04:10:33 code: 7 outlen=0x1e pt->len: 0xa Jun 29 04:10:33 *totlen=0x2c tp->len=0xa ntohs(tplen)=0xa tot=0x2c MAX_L=0x1502 Jun 29 04:10:33 code: 7 outlen=0x2c pt->len: 0x10 Jun 29 04:10:33 *totlen=0x40 tp->len=0x10 ntohs(tplen)=0x10 tot=0x40 MAX_L=0x1502 Jun 29 04:10:33 *totlen=0x44 tp->len=0x0 ntohs(tplen)=0x0 tot=0x44 MAX_L=0x1502 Jun 29 04:10:33 IO send ... PADR for pp0.0 Jun 29 04:10:33 Discovery Input: PADS packet received on uifl (idx 71) Jun 29 04:10:33 pppoe_ifl_params_change: ifl pp0.0, ifl sid 2078, param sid 2078 Jun 29 04:10:33 pppoed_ifl_msg_handler pp0.0 ifl 72 op 2 flag 0xc011 Jun 29 04:10:33 In Parse TLV: opts 0x0 0xa fe-0/0/0.0 Jun 29 04:10:33 pppoed_change_ifl_options: ifname pp0.0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session mode client Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session up, kernsync false Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session id=2078 (current 2078) Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credit interval set to 0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session id=2078 Jun 29 04:10:33 pppoed_change_ifl: ifname pp0.0 Jun 29 04:10:33 pppoed_ifl_msg_handler pp0.0 ifl 72 op 2 flag 0xc011 Jun 29 04:10:33 In Parse TLV: opts 0x0 0xa fe-0/0/0.0 Jun 29 04:10:33 pppoed_change_ifl_options: ifname pp0.0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session mode client Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session up, kernsync false Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session id=2078 (current 2078) Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credit interval set to 0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session id=2078 Jun 29 04:10:33 pppoed_change_ifl: ifname pp0.0 Jun 29 04:10:33 pppoed_ifl_msg_handler pp0.0 ifl 72 op 2 flag 0xc011 Jun 29 04:10:33 In Parse TLV: opts 0x0 0xa fe-0/0/0.0 Jun 29 04:10:33 pppoed_change_ifl_options: ifname pp0.0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session mode client Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session up, kernsync false Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session id=2078 (current 2078) Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credit scale 0 max 65535 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credits disabled, interval 0, scale 0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 credit interval set to 0 Jun 29 04:10:33 pppoed_change_ifl_options: pp0.0 session id=2078 Jun 29 04:10:33 pppoed_change_ifl: ifname pp0.0

PPPoE Config:

set interfaces fe-0/0/0 unit 0 encapsulation ppp-over-ether
set interfaces pp0 unit 0 apply-macro telekom
set interfaces pp0 unit 0 ppp-options chap default-chap-secret "$9$uqaLBcyrevWxNSy24aZji0B1Ryl"
set interfaces pp0 unit 0 ppp-options chap local-name "0019042754695502686306980001@t-online.de"
set interfaces pp0 unit 0 ppp-options chap no-rfc2486
set interfaces pp0 unit 0 ppp-options chap passive
set interfaces pp0 unit 0 ppp-options pap local-name "0019042754695502686306980001@t-online.de"
set interfaces pp0 unit 0 ppp-options pap no-rfc2486
set interfaces pp0 unit 0 ppp-options pap local-password "secret"
set interfaces pp0 unit 0 ppp-options pap passive
set interfaces pp0 unit 0 pppoe-options underlying-interface fe-0/0/0.0
set interfaces pp0 unit 0 pppoe-options idle-timeout 0
set interfaces pp0 unit 0 pppoe-options auto-reconnect 10
set interfaces pp0 unit 0 family inet mtu 1492
set interfaces pp0 unit 0 family inet negotiate-address
set routing-options static route 0.0.0.0/0 next-hop pp0.0
set security zones security-zone Internet interfaces pp0.0

I have to reboot the remote device in order to get the pppoe session up again.

The four srx in question are running all JUNOS 12.1X46-D40.2.

Can anybody see my mistake? Or is there no mistake in my config?

 

 

Kind regards

 

Andy

3 REPLIES 3
Highlighted
SRX Services Gateway

Re: Issue reconnecting terminated PPPoE Session

‎06-29-2016 02:22 AM

Hi, 

 

The config looks ok to me.

Do you see any PADT in the logs to signal termination of the session.

Can you check "show pppoe statistics" for the PPPoE messages sent and received.

 

Did you try resetting the interfaces before reboot?

 

Cheers,

Ashvin

Highlighted
SRX Services Gateway

Re: Issue reconnecting terminated PPPoE Session

‎06-29-2016 02:43 AM

Hi,

 

here's the "show pppoe statistics" output:

show pppoe statistics 
Active PPPoE sessions: 1
  PacketType                       Sent         Received
    PADI                              1                0
    PADO                              0                1
    PADR                              1                0
    PADS                              0                1
    PADT                              0                0
    Service name error                0                0
    AC system error                   0                0
    Generic error                     0                0
    Malformed packets                 0                0
    Unknown packets                   0                0
  Timeout
    PADI                              0
    PADO                              0
    PADR                              0
  Receive Error Counters
    PADI                              0
    PADO                              0
    PADR                              0
    PADS                              0

 

No, I didn't try resetting the interfaces before reboot, because there's no one on the remote location who could do it.

 

Any further ideas?

 

Regards

Andy

Highlighted
SRX Services Gateway

Re: Issue reconnecting terminated PPPoE Session

[ Edited ]
‎06-29-2016 06:51 AM

Hi,

 

Unfortunately, the statistics seem to have reset post the reboot and we don't see any PADT or "session down" in the log. If the pppoe session went down would have expected something like:

 

Discovery Input: PADT packet received on uifl (idx xx)
Bringing session down for pp0.0

 

Can't see any PADI from the SRX between 18:01 and 04:04. Not sure if the pppoe session did go down on the SRX between this interval. I assume SRX was rebooted around 04:04 and the pppoe session then came up.

 

I would suggest adding:

set interfaces pp0 unit 0 pppoe-options client

and setting an idle timeout [reasonably long enough not to cause intermittent re-dials] so that the pppoe session drops when idle.

 

Hope it works.

 

Cheers,

Ashvin