PPPoE won't reconnect : state change Closed
-
Hello
I am using 2x SG-1100 devices at different locations. The same ISP provides connection via PPPoE. Recently the Internet connection went down multiple times on both SG-1100 devices at night and after rebooting the devices in the morning the Internet started working.
I am pretty sure that instead of rebooting the devices a manual PPPoE reconnect would help as well.I see identical logs on both SG-1100 devices. The last entry before reboot is "LCP: state change Closed --> Initial"
Jun 30 00:45:00 ppp [wan] IFACE: Up event Jun 30 00:45:00 ppp [wan] IFACE: Rename interface ng0 to pppoe0 Jul 2 02:21:46 ppp [wan] IPCP: rec'd Configure Request #2 (Opened) Jul 2 02:21:46 ppp [wan] IPADDR 198.x.x.x Jul 2 02:21:46 ppp [wan] 198.x.x.x is OK Jul 2 02:21:46 ppp [wan] IPCP: LayerDown Jul 2 02:21:47 ppp [wan] IFACE: Down event Jul 2 02:21:47 ppp [wan] IFACE: Rename interface pppoe0 to pppoe0 Jul 2 02:21:47 ppp [wan] IPCP: SendConfigReq #76 Jul 2 02:21:47 ppp [wan] IPADDR 199.x.x.x Jul 2 02:21:47 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:21:47 ppp [wan] SECDNS 203.x.x.x Jul 2 02:21:47 ppp [wan] IPCP: SendConfigAck #2 Jul 2 02:21:47 ppp [wan] IPADDR 198.x.x.x Jul 2 02:21:47 ppp [wan] IPCP: state change Opened --> Ack-Sent Jul 2 02:21:50 ppp [wan] IPCP: SendConfigReq #77 Jul 2 02:21:50 ppp [wan] IPADDR 199.x.x.x Jul 2 02:21:50 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:21:50 ppp [wan] SECDNS 203.x.x.x Jul 2 02:21:52 ppp [wan] IPCP: SendConfigReq #78 Jul 2 02:21:52 ppp [wan] IPADDR 199.x.x.x Jul 2 02:21:52 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:21:52 ppp [wan] SECDNS 203.x.x.x Jul 2 02:21:54 ppp [wan] IPCP: SendConfigReq #79 Jul 2 02:21:54 ppp [wan] IPADDR 199.x.x.x Jul 2 02:21:54 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:21:54 ppp [wan] SECDNS 203.x.x.x Jul 2 02:21:56 ppp [wan] IPCP: rec'd Configure Request #3 (Ack-Sent) Jul 2 02:21:56 ppp [wan] IPADDR 198.x.x.x Jul 2 02:21:56 ppp [wan] 198.x.x.x is OK Jul 2 02:21:56 ppp [wan] IPCP: SendConfigAck #3 Jul 2 02:21:56 ppp [wan] IPADDR 198.x.x.x Jul 2 02:21:56 ppp [wan] IPCP: SendConfigReq #80 Jul 2 02:21:56 ppp [wan] IPADDR 199.x.x.x Jul 2 02:21:56 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:21:56 ppp [wan] SECDNS 203.x.x.x Jul 2 02:21:58 ppp [wan] IPCP: SendConfigReq #81 Jul 2 02:21:58 ppp [wan] IPADDR 199.x.x.x Jul 2 02:21:58 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:21:58 ppp [wan] SECDNS 203.x.x.x Jul 2 02:22:00 ppp [wan] IPCP: SendConfigReq #82 Jul 2 02:22:00 ppp [wan] IPADDR 199.x.x.x Jul 2 02:22:00 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:22:00 ppp [wan] SECDNS 203.x.x.x Jul 2 02:22:02 ppp [wan] IPCP: SendConfigReq #83 Jul 2 02:22:02 ppp [wan] IPADDR 199.x.x.x Jul 2 02:22:02 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:22:02 ppp [wan] SECDNS 203.x.x.x Jul 2 02:22:04 ppp [wan] IPCP: SendConfigReq #84 Jul 2 02:22:04 ppp [wan] IPADDR 199.x.x.x Jul 2 02:22:04 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:22:04 ppp [wan] SECDNS 203.x.x.x Jul 2 02:22:06 ppp [wan] IPCP: rec'd Configure Request #4 (Ack-Sent) Jul 2 02:22:06 ppp [wan] IPADDR 198.x.x.x Jul 2 02:22:06 ppp [wan] 198.x.x.x is OK Jul 2 02:22:06 ppp [wan] IPCP: SendConfigAck #4 Jul 2 02:22:06 ppp [wan] IPADDR 198.x.x.x Jul 2 02:22:06 ppp [wan] IPCP: SendConfigReq #85 Jul 2 02:22:06 ppp [wan] IPADDR 199.x.x.x Jul 2 02:22:06 ppp [wan] PRIDNS 200.x.x.x Jul 2 02:22:06 ppp [wan] SECDNS 203.x.x.x Jul 2 02:22:08 ppp [wan] IPCP: parameter negotiation failed Jul 2 02:22:08 ppp [wan] IPCP: state change Ack-Sent --> Stopped Jul 2 02:22:08 ppp [wan] IPCP: LayerFinish Jul 2 02:22:08 ppp [wan] Bundle: No NCPs left. Closing links... Jul 2 02:22:08 ppp [wan] Bundle: closing link "wan_link0"... Jul 2 02:22:08 ppp [wan_link0] Link: CLOSE event Jul 2 02:22:08 ppp [wan_link0] LCP: Close event Jul 2 02:22:08 ppp [wan_link0] LCP: state change Opened --> Closing Jul 2 02:22:08 ppp [wan_link0] Link: Leave bundle "wan" Jul 2 02:22:08 ppp [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Jul 2 02:22:08 ppp [wan] IPCP: Close event Jul 2 02:22:08 ppp [wan] IPCP: state change Stopped --> Closed Jul 2 02:22:08 ppp [wan] IPV6CP: Close event Jul 2 02:22:08 ppp [wan] IPV6CP: state change Stopped --> Closed Jul 2 02:22:08 ppp [wan] IPCP: Down event Jul 2 02:22:08 ppp [wan] IPCP: state change Closed --> Initial Jul 2 02:22:08 ppp [wan] IPV6CP: Down event Jul 2 02:22:08 ppp [wan] IPV6CP: state change Closed --> Initial Jul 2 02:22:08 ppp [wan_link0] LCP: SendTerminateReq #42 Jul 2 02:22:08 ppp [wan_link0] LCP: LayerDown Jul 2 02:22:10 ppp [wan_link0] LCP: SendTerminateReq #43 Jul 2 02:22:12 ppp [wan_link0] LCP: state change Closing --> Closed Jul 2 02:22:12 ppp [wan_link0] LCP: LayerFinish Jul 2 02:22:12 ppp [wan_link0] Link: DOWN event Jul 2 02:22:12 ppp [wan_link0] LCP: Down event Jul 2 02:22:12 ppp [wan_link0] LCP: state change Closed --> Initial Jul 2 12:01:11 ppp Multi-link PPP daemon for FreeBSD Jul 2 12:01:11 ppp process 22725 started, version 5.8
It can happen that the ISP might do some upgrades at night which cause the PPPoE link to go down and pfSense doesn't keep trying to re-establish the PPPoE connection.
My SG-1100s are running 2.4.5_p1 and would upgrade only to 2.5 if there is a fix for this issue.
I see a fix for 2.5.0 where the issue is similar https://redmine.pfsense.org/issues/9148 however the log messages are different therefore I might have a different issue.Do you know any workaround by chance?
Thank you!