PPPoE Interface don´t reconnect - VE R80.40

[lonardoni]

Hello all,

I have a PPPoE interface attached to a eth0 in a VE environment (VMWare).

After a modem hangup, this pppoe interface lease his IP address and stop to communicate.

I need to login in gateway Web page, go to interfaces, edit the pppoe interface and set to off, save and set to on again.

Only after this, I have communication again on this interface.

So, there is a command, or a job to do this OFF, ON automatically when this interfaces losing communication?

There is any command to avoid this hangup?

Here are the logs from /var/messages when Modem hangup and when I put OFF / ON the interface.

Aug 9 11:11:41 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 8
Aug 9 11:11:49 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 13
Aug 9 11:12:02 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 14
Aug 9 11:12:16 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 14
Aug 9 11:12:30 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 12
Aug 9 11:12:42 2020 gwckp01 dhclient: No DHCPOFFERS received.
Aug 9 11:12:42 2020 gwckp01 dhclient: No working leases in persistent database - sleeping.
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: LCP terminated by peer
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: Connect time 2880.0 minutes.
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: Sent 11231907 bytes, received 5368495 bytes.
Aug 9 11:16:29 2020 gwckp01 kernel: [fw4_0];update_if_info: SIM is not active for device 0
Aug 9 11:16:29 2020 gwckp01 kernel: [SIM4];drv_if_remove_interface: Invalid ifn -1
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: Modem hangup
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: Connection terminated.
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: Failed to disconnect PPPoE socket: 114 Operation already in progress
Aug 9 11:16:29 2020 gwckp01 pppd[27326]: Exit.
Aug 9 11:16:30 2020 gwckp01 ntpd[10195]: Deleting interface #12 pppoe1, XXX.XXX.XXX.XXX#123, interface stats: received=0, sent=0, dropped=0, active_time=172800 secs
Aug 9 11:17:48 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
Aug 9 11:17:55 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 9
Aug 9 11:18:04 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 19
Aug 9 11:18:23 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
Aug 9 11:18:30 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 8
Aug 9 11:18:38 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 11

Aug 10 10:15:26 2020 gwckp01 xpand[10193]: show_asset CDK: asset_get_proc started.
Aug 10 10:15:26 2020 gwckp01 xpand[10193]: netis_get_driver_info:Cannot get driver information for pppoe1, No such device
Aug 10 10:15:35 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 15
Aug 10 10:15:48 2020 gwckp01 xpand[10193]: PPPoE_Finalize reconfiguring pppoe1
Aug 10 10:15:50 2020 gwckp01 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 16
Aug 10 10:15:50 2020 gwckp01 xpand[10193]: log info: objectName: Interfaces,administrator: admin, operation: Set Object, facility: Web-UI, message: Logical interface (pppoe1) state is set to off
Aug 10 10:15:50 2020 gwckp01 xpand[10193]: admin localhost t +pppoe:1:state off
Aug 10 10:15:50 2020 gwckp01 xpand[10193]: admin localhost t +interface:pppoe1:state off
Aug 10 10:15:50 2020 gwckp01 xpand[10193]: Configuration changed from localhost by user admin
Aug 10 10:15:50 2020 gwckp01 cpd: auditLogClient::sendLog>Send log successfully
Aug 10 10:15:50 2020 gwckp01 xpand[10193]: Configuration changed from localhost by user admin
Aug 10 10:15:50 2020 gwckp01 ipstcl2: regStrCmp: Match found of the string msg at pattern msg (0,3)
Aug 10 10:15:50 2020 gwckp01 ipstcl2: check_special_char: The key msg is allowed to have special character at it's value
Aug 10 10:16:06 2020 gwckp01 dhclient: No DHCPOFFERS received.
Aug 10 10:16:06 2020 gwckp01 dhclient: No working leases in persistent database - sleeping.
Aug 10 10:17:40 2020 gwckp01 xpand[10193]: PPPoE_Finalize reconfiguring pppoe1
Aug 10 10:17:41 2020 gwckp01 pppd[28633]: Plugin rp-pppoe.so loaded.
Aug 10 10:17:41 2020 gwckp01 pppd[28633]: RP-PPPoE plugin version 3.3 compiled against pppd 2.4.4
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: pppd 2.4.4 started by admin, uid 0
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: PPP session is 1
Aug 10 10:17:41 2020 gwckp01 kernel: [fw4_0];create_oftab_entry: Global gave ifn 10 for ppp0, but it's used for pppoe1
Aug 10 10:17:41 2020 gwckp01 kernel: [fw4_0];fwlinux_register_new_if: failed to create new oftab entry for ppp0
Aug 10 10:17:41 2020 gwckp01 kernel: [fw4_0];fwlinux_kern_device_event: could not find ifn for interface ppp0
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: Using interface pppoe1
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: Connect: pppoe1 <--> eth0
Aug 10 10:17:41 2020 gwckp01 kernel: [SIM4]; drv_if_update_interface: global ifnum not found for (vsid = 0)
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: Remote message: Login ok
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: PAP authentication succeeded
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: peer from calling number XX:XX:XX:XX:XX:XX authorized
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: local IP address XXX.XXX.XXX.XXX
Aug 10 10:17:41 2020 gwckp01 pppd[28638]: remote IP address XXX.XXX.XXX.XXX
Aug 10 10:17:41 2020 gwckp01 kernel: [fw4_0];update_if_info: SIM is not active for device 0
Aug 10 10:17:42 2020 gwckp01 xpand[10193]: log info: objectName: Interfaces,administrator: admin, operation: Set Object, facility: Web-UI, message: Logical interface (pppoe1) state is set to on
Aug 10 10:17:42 2020 gwckp01 xpand[10193]: admin localhost t +pppoe:1:state on
Aug 10 10:17:42 2020 gwckp01 xpand[10193]: admin localhost t +interface:pppoe1:state on

[Allen_Fambro]

Hello,

  I am able to also replicate this issue on my 3200 appliance running R80.40 with JHF Take 78.  On my PPPoE interface when the lease expires I get the following logs in my /var/log/messages.log file...

Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: LCP terminated by peer (connect time expired)
Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: Connect time 10079.7 minutes.
Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: Sent 1034966629 bytes, received 851705935 bytes.
Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: Modem hangup
Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: Connection terminated.
Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: Failed to disconnect PPPoE socket: 114 Operation already in progress
Sep 24 09:31:03 2020 Als-Home-GW pppd[5089]: Exit.

The log entry shows that the gateway is clearly unable to properly disconnect the PPPoE socket.  At this point manual intervention is required to properly disconnect the PPPoE socket and ultimately allow the LCP connection to reestablish.  Usually simply cycling the up/down state of the PPPoE interface resolves the issue.

This definitely appears to be a bug and as such, I would open a support case with TAC.  I'll also open a case and update this forum accordingly.

[Allen_Fambro]

As a work around I was able to create a script that will bounce the interface.  Then use Job scheduler to run the script daily at a specific time...

Step 1 - Login to the gateway via SSH in expert mode and create the script in the scripts directory...

vi  /opt/CPsuite-R80.40/fw1/scripts/bounce_interface_pppoe1.sh

contents of the script should be...

#!/bin/sh
# This script is used to bounce an interface.

clish -c "lock database override"
clish -c "set interface pppoe1 state off"
clish -c "set interface pppoe1 state on"

Step 2 - Make the script executable...

chmod 777 /opt/CPsuite-R80.40/fw1/scripts/bounce_interface_pppoe1.sh

Step 3 - Log into the gateway via the Gaia GUI and create the scheduled job that will reference the script...

Step 4 - Verify that its working by checking the /var/log/messages file and grep for pppd logs.  

 

[lonardoni]

Hello Allen,

Thanks for your reply.

Sorry for not reply earlier.

As a workaround, I created a daily job that put interface down, wait for 30 seconds and set interface up again.

This reset the PPPoE connection timeout.

It´s very similar that your last post.

Thanks again.

[lonardoni]

[Expert@gwckp01:0]# cat pppoe.sh
#!/bin/sh

clish -c "lock database override"
clish -c "set interface pppoe1 state off"
sleep 30
clish -c "set interface pppoe1 state on"

[Hugh_McGauran]

Just a little addition to the many great scripts added already. THis one adds logging for tracking what has happened and when

### BEGIN SCRIPT ###
#!/usr/bin/bash
curDate=`date "+%d/%m/%Y %H:%M"`
logFile=/var/log/moninternet.log
source /etc/profile.d/CP.sh

if ! ping -c 1 -w 5 "8.8.8.8" &>/dev/null ; then
echo $curDate "Internet is unreachable, PPPOE is down, restarting PPPOE" >> $logFile
clish -c "lock database override"
clish -c "set interface pppoe1 state off"
sleep 30
clish -c "set interface pppoe1 state on"
else
echo $curDate "Internet is reachable, PPPOE is up, do nothing" >> $logFile
fi
#### END SCRIPT ###

make sure you dos2unix the script after pasting it in.

see this SK as to how to schedule it to run more frequently
https://supportcenter.checkpoint.com/supportcenter/portal?eventSubmit_doGoviewsolutiondetails=&solut...

[hemh]

Hi, I just modified the script according to what it is said in SK77300:

###BEGIN SCRIPT ###
#!/bin/bash -f
source /opt/CPshrd-R80.40/tmp/.CPprofile.sh
curDate=`date "+%d/%m/%Y %H:%M"`
logFile=/var/log/moninternet.log

if ! ping -c 1 -w 5 "8.8.8.8" &>/dev/null ; then
echo $curDate "Internet is unreachable, PPPOE is down, restarting PPPOE" >> $logFile
clish -c "lock database override"
clish -c "set interface pppoe1 state off"
sleep 30
clish -c "set interface pppoe1 state on"
else
echo $curDate "Internet is reachable, PPPOE is up, do nothing" >> $logFile
fi
#### END SCRIPT ###

I put the script in /bin, here is my crontab:

[Expert@calabfw01:0]# crontab -u jobuser -l
*/5 * * * * /bin/bounce_interface_pppoe1.sh

But I have these logs in /var/log/messages:

Jul 15 14:40:06 2021 calabfw01 clish[12043]: User jobuser finished running clish -c due to an error from CLI shell
Jul 15 14:40:06 2021 calabfw01 clish[12047]: User not logged in. He has no configured role.
Jul 15 14:40:06 2021 calabfw01 clish[12047]: User jobuser finished running clish -c due to an error from CLI shell
Jul 15 14:40:36 2021 calabfw01 clish[12227]: User not logged in. He has no configured role.
Jul 15 14:40:36 2021 calabfw01 clish[12227]: User jobuser finished running clish -c due to an error from CLI shell

Any idea why it is not working? It work if I launch the script from the shell

[Marcovb]

I have fixed this by adding an admin role to this user:

"add rba user jobuser roles adminRole"