Problem: WAN PPPoE reconnects multiple times every day
-
Hi fellows,
Another PPPoE problem. My PPPoE connection keeps restarting multiple times every day and every time the following message is logged in my gateways log: apinger: SIGHUP received, reloading configuration.
Why this is happening?
I spoke with my ISP provider – they don’t have any problems in my area. There is another user near my address, who is connected from the last 12 days. The problem is somewhere in my box.
Here are some details about my box:
pfSense version 2.1.5-RELEASE (amd64), FreeBSD 8.3-RELEASE-p16 updated from 2.1-RELEASE-amd64 (2.1 Release was originally installed back in February, afterwards everything was jut updates from WebGUI).
2 NIC adapters: Realtek 8111F
WAN port – directly connected to my ISP via PPPoE.
LAN port – connected to switch.Running 2 OpenVPN servers – one TUN and one TAP bridged with my DHCP server.
Below I have attached my system log and my gateway log for the last two days. It's been like this for weeks. For security reasons I have masked some IP addresses.
I will appreciate some help from you guys, because this is a big issue for me.
Gateways Log:
Nov 7 16:29:49 pfsense apinger: SIGHUP received, reloading configuration. Nov 8 12:21:27 pfsense apinger: SIGHUP received, reloading configuration. Nov 8 12:21:35 pfsense apinger: SIGHUP received, reloading configuration. Nov 8 21:38:16 pfsense apinger: SIGHUP received, reloading configuration. Nov 8 21:38:16 pfsense apinger: SIGHUP received, reloading configuration. Nov 8 21:38:24 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 02:59:41 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 02:59:49 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 04:30:33 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 04:30:41 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 04:45:31 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 04:45:39 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 05:00:33 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 05:00:41 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 07:57:16 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 07:57:24 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 09:44:49 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 09:44:57 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 10:44:00 pfsense apinger: SIGHUP received, reloading configuration. Nov 9 10:44:08 pfsense apinger: SIGHUP received, reloading configuration.
System Log:
Nov 9 02:59:32 pfsense ppp: [wan_link0] LCP: rec'd Terminate Request #3 (Opened) Nov 9 02:59:32 pfsense ppp: [wan_link0] LCP: state change Opened --> Stopping Nov 9 02:59:32 pfsense ppp: [wan_link0] Link: Leave bundle "wan" Nov 9 02:59:32 pfsense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Nov 9 02:59:32 pfsense ppp: [wan] IPCP: Close event Nov 9 02:59:32 pfsense ppp: [wan] IPCP: state change Opened --> Closing Nov 9 02:59:32 pfsense ppp: [wan] IPCP: SendTerminateReq #4 Nov 9 02:59:32 pfsense ppp: [wan] IPCP: LayerDown Nov 9 02:59:32 pfsense ppp: [wan] IFACE: Delete route 0.0.0.0/0 XX.XX.128.45 failed: No such process Nov 9 02:59:32 pfsense kernel: in_scrubprefix: err=65, prefix delete failed Nov 9 02:59:32 pfsense ppp: [wan] IFACE: Down event Nov 9 02:59:32 pfsense ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0 Nov 9 02:59:32 pfsense ppp: [wan] IPV6CP: Close event Nov 9 02:59:32 pfsense ppp: [wan] IPV6CP: state change Stopped --> Closed Nov 9 02:59:32 pfsense ppp: [wan] IPCP: Down event Nov 9 02:59:32 pfsense ppp: [wan] IPCP: LayerFinish Nov 9 02:59:32 pfsense ppp: [wan] Bundle: No NCPs left. Closing links... Nov 9 02:59:32 pfsense ppp: [wan] IPCP: state change Closing --> Initial Nov 9 02:59:32 pfsense ppp: [wan] IPV6CP: Down event Nov 9 02:59:32 pfsense ppp: [wan] IPV6CP: state change Closed --> Initial Nov 9 02:59:32 pfsense ppp: [wan_link0] LCP: SendTerminateAck #4 Nov 9 02:59:32 pfsense ppp: [wan_link0] LCP: LayerDown Nov 9 02:59:32 pfsense check_reload_status: Rewriting resolv.conf Nov 9 02:59:34 pfsense ppp: [wan_link0] LCP: state change Stopping --> Stopped Nov 9 02:59:34 pfsense ppp: [wan_link0] LCP: LayerFinish Nov 9 02:59:34 pfsense ppp: [wan_link0] PPPoE: connection closed Nov 9 02:59:34 pfsense ppp: [wan_link0] Link: DOWN event Nov 9 02:59:34 pfsense ppp: [wan_link0] LCP: Down event Nov 9 02:59:34 pfsense ppp: [wan_link0] LCP: state change Stopped --> Starting Nov 9 02:59:34 pfsense ppp: [wan_link0] LCP: LayerStart Nov 9 02:59:34 pfsense ppp: [wan_link0] Link: reconnection attempt 1 in 2 seconds Nov 9 02:59:36 pfsense ppp: [wan_link0] Link: reconnection attempt 1 Nov 9 02:59:36 pfsense ppp: [wan_link0] PPPoE: Connecting to '' Nov 9 02:59:36 pfsense ppp: PPPoE: rec'd ACNAME "ISPName" Nov 9 02:59:36 pfsense ppp: [wan_link0] PPPoE: connection successful Nov 9 02:59:36 pfsense ppp: [wan_link0] Link: UP event Nov 9 02:59:36 pfsense ppp: [wan_link0] LCP: Up event Nov 9 02:59:36 pfsense ppp: [wan_link0] LCP: state change Starting --> Req-Sent Nov 9 02:59:36 pfsense ppp: [wan_link0] LCP: SendConfigReq #5 Nov 9 02:59:36 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 02:59:36 pfsense ppp: [wan_link0] MRU 1492 Nov 9 02:59:36 pfsense ppp: [wan_link0] MAGICNUM 31514dba Nov 9 02:59:36 pfsense ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent) Nov 9 02:59:36 pfsense ppp: [wan_link0] MRU 1492 Nov 9 02:59:36 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 02:59:36 pfsense ppp: [wan_link0] MAGICNUM b5e6ab01 Nov 9 02:59:36 pfsense ppp: [wan_link0] LCP: SendConfigAck #1 Nov 9 02:59:36 pfsense ppp: [wan_link0] MRU 1492 Nov 9 02:59:36 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 02:59:36 pfsense ppp: [wan_link0] MAGICNUM b5e6ab01 Nov 9 02:59:36 pfsense ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: SendConfigReq #6 Nov 9 02:59:38 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 02:59:38 pfsense ppp: [wan_link0] MRU 1492 Nov 9 02:59:38 pfsense ppp: [wan_link0] MAGICNUM 31514dba Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: rec'd Configure Reject #6 (Ack-Sent) Nov 9 02:59:38 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: SendConfigReq #7 Nov 9 02:59:38 pfsense ppp: [wan_link0] MRU 1492 Nov 9 02:59:38 pfsense ppp: [wan_link0] MAGICNUM 31514dba Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: rec'd Configure Ack #7 (Ack-Sent) Nov 9 02:59:38 pfsense ppp: [wan_link0] MRU 1492 Nov 9 02:59:38 pfsense ppp: [wan_link0] MAGICNUM 31514dba Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing Nov 9 02:59:38 pfsense ppp: [wan_link0] PAP: using authname "username@isp.com" Nov 9 02:59:38 pfsense ppp: [wan_link0] PAP: sending REQUEST #1 len: 42 Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: LayerUp Nov 9 02:59:38 pfsense ppp: [wan_link0] PAP: rec'd ACK #1 len: 17 Nov 9 02:59:38 pfsense ppp: [wan_link0] MESG: Password OK Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: authorization successful Nov 9 02:59:38 pfsense ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Nov 9 02:59:38 pfsense ppp: [wan_link0] Link: Join bundle "wan" Nov 9 02:59:38 pfsense ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Nov 9 02:59:38 pfsense ppp: [wan] IPCP: Open event Nov 9 02:59:38 pfsense ppp: [wan] IPCP: state change Initial --> Starting Nov 9 02:59:38 pfsense ppp: [wan] IPCP: LayerStart Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: Open event Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: state change Initial --> Starting Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: LayerStart Nov 9 02:59:38 pfsense ppp: [wan] IPCP: Up event Nov 9 02:59:38 pfsense ppp: [wan] IPCP: state change Starting --> Req-Sent Nov 9 02:59:38 pfsense ppp: [wan] IPCP: SendConfigReq #5 Nov 9 02:59:38 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 02:59:38 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 02:59:38 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 02:59:38 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: Up event Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: state change Starting --> Req-Sent Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: SendConfigReq #2 Nov 9 02:59:38 pfsense ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent) Nov 9 02:59:38 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] XX.XX.128.45 is OK Nov 9 02:59:38 pfsense ppp: [wan] IPCP: SendConfigAck #1 Nov 9 02:59:38 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent Nov 9 02:59:38 pfsense ppp: [wan] IPCP: rec'd Configure Reject #5 (Ack-Sent) Nov 9 02:59:38 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 02:59:38 pfsense ppp: [wan] IPCP: SendConfigReq #6 Nov 9 02:59:38 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 02:59:38 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 02:59:38 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: rec'd Protocol Reject #2 (Opened) Nov 9 02:59:38 pfsense ppp: [wan_link0] LCP: protocol IPV6CP was rejected Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: protocol was rejected by peer Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Nov 9 02:59:38 pfsense ppp: [wan] IPV6CP: LayerFinish Nov 9 02:59:38 pfsense ppp: [wan] IPCP: rec'd Configure Nak #6 (Ack-Sent) Nov 9 02:59:38 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 02:59:38 pfsense ppp: [wan] “My Public IP Address” is OK Nov 9 02:59:38 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] IPCP: SendConfigReq #7 Nov 9 02:59:38 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 02:59:38 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] IPCP: rec'd Configure Ack #7 (Ack-Sent) Nov 9 02:59:38 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 02:59:38 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 02:59:38 pfsense ppp: [wan] IPCP: state change Ack-Sent --> Opened Nov 9 02:59:38 pfsense ppp: [wan] IPCP: LayerUp Nov 9 02:59:38 pfsense ppp: [wan] “My Public IP Address” -> XX.XX.128.45 Nov 9 02:59:38 pfsense check_reload_status: Rewriting resolv.conf Nov 9 02:59:39 pfsense check_reload_status: rc.newwanip starting pppoe0 Nov 9 02:59:39 pfsense ppp: [wan] IFACE: Up event Nov 9 02:59:39 pfsense ppp: [wan] IFACE: Rename interface ng0 to pppoe0 Nov 9 02:59:41 pfsense php: rc.newwanip: rc.newwanip: Informational is starting pppoe0. Nov 9 02:59:41 pfsense php: rc.newwanip: rc.newwanip: on (IP address: “My Public IP Address”) (interface: WAN[wan]) (real interface: pppoe0). Nov 9 02:59:41 pfsense php: rc.newwanip: ROUTING: setting default route to XX.XX.128.45 Nov 9 02:59:46 pfsense php: rc.newwanip: Resyncing OpenVPN instances for interface WAN. Nov 9 02:59:46 pfsense kernel: ovpns1: link state changed to DOWN Nov 9 02:59:46 pfsense check_reload_status: Reloading filter Nov 9 02:59:47 pfsense check_reload_status: Reloading filter Nov 9 02:59:47 pfsense kernel: ovpns1: link state changed to UP Nov 9 02:59:47 pfsense check_reload_status: rc.newwanip starting ovpns1 Nov 9 02:59:47 pfsense kernel: ovpns2: link state changed to DOWN Nov 9 02:59:47 pfsense php: rc.newwanip: Creating rrd update script Nov 9 02:59:47 pfsense kernel: ovpns2: link state changed to UP Nov 9 02:59:47 pfsense check_reload_status: rc.newwanip starting ovpns2 Nov 9 02:59:49 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns1. Nov 9 02:59:49 pfsense php: rc.newwanip: rc.newwanip: on (IP address: ) (interface: OPENVPN[opt1]) (real interface: ovpns1). Nov 9 02:59:49 pfsense php: rc.newwanip: pfSense package system has detected an ip change “My Public IP Address” -> “My Public IP Address” ... Restarting packages. Nov 9 02:59:49 pfsense check_reload_status: Starting packages Nov 9 02:59:49 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns2. Nov 9 02:59:49 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.1.1) (interface: []) (real interface: ovpns2). Nov 9 02:59:49 pfsense php: rc.newwanip: pfSense package system has detected an ip change -> 192.168.1.1 ... Restarting packages. Nov 9 02:59:49 pfsense check_reload_status: Starting packages Nov 9 02:59:51 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 02:59:51 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 02:59:51 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 02:59:52 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 02:59:54 pfsense php: rc.newwanip: Creating rrd update script Nov 9 02:59:56 pfsense php: rc.newwanip: pfSense package system has detected an ip change 0.0.0.0 -> ... Restarting packages. Nov 9 03:00:01 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:30:24 pfsense ppp: [wan_link0] LCP: rec'd Terminate Request #3 (Opened) Nov 9 04:30:24 pfsense ppp: [wan_link0] LCP: state change Opened --> Stopping Nov 9 04:30:24 pfsense ppp: [wan_link0] Link: Leave bundle "wan" Nov 9 04:30:24 pfsense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Nov 9 04:30:24 pfsense ppp: [wan] IPCP: Close event Nov 9 04:30:24 pfsense ppp: [wan] IPCP: state change Opened --> Closing Nov 9 04:30:24 pfsense ppp: [wan] IPCP: SendTerminateReq #8 Nov 9 04:30:24 pfsense ppp: [wan] IPCP: LayerDown Nov 9 04:30:24 pfsense check_reload_status: Rewriting resolv.conf Nov 9 04:30:24 pfsense ppp: [wan] IFACE: Delete route 0.0.0.0/0 XX.XX.128.45 failed: No such process Nov 9 04:30:24 pfsense ppp: [wan] IFACE: Down event Nov 9 04:30:24 pfsense kernel: in_scrubprefix: err=65, prefix delete failed Nov 9 04:30:24 pfsense ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0 Nov 9 04:30:24 pfsense ppp: [wan] IPV6CP: Close event Nov 9 04:30:24 pfsense ppp: [wan] IPV6CP: state change Stopped --> Closed Nov 9 04:30:24 pfsense ppp: [wan] IPCP: Down event Nov 9 04:30:24 pfsense ppp: [wan] IPCP: LayerFinish Nov 9 04:30:24 pfsense ppp: [wan] Bundle: No NCPs left. Closing links... Nov 9 04:30:24 pfsense ppp: [wan] IPCP: state change Closing --> Initial Nov 9 04:30:24 pfsense ppp: [wan] IPV6CP: Down event Nov 9 04:30:24 pfsense ppp: [wan] IPV6CP: state change Closed --> Initial Nov 9 04:30:24 pfsense ppp: [wan_link0] LCP: SendTerminateAck #8 Nov 9 04:30:24 pfsense ppp: [wan_link0] LCP: LayerDown Nov 9 04:30:26 pfsense ppp: [wan_link0] LCP: state change Stopping --> Stopped Nov 9 04:30:26 pfsense ppp: [wan_link0] LCP: LayerFinish Nov 9 04:30:26 pfsense ppp: [wan_link0] PPPoE: connection closed Nov 9 04:30:26 pfsense ppp: [wan_link0] Link: DOWN event Nov 9 04:30:26 pfsense ppp: [wan_link0] LCP: Down event Nov 9 04:30:26 pfsense ppp: [wan_link0] LCP: state change Stopped --> Starting Nov 9 04:30:26 pfsense ppp: [wan_link0] LCP: LayerStart Nov 9 04:30:26 pfsense ppp: [wan_link0] Link: reconnection attempt 1 in 2 seconds Nov 9 04:30:28 pfsense ppp: [wan_link0] Link: reconnection attempt 1 Nov 9 04:30:28 pfsense ppp: [wan_link0] PPPoE: Connecting to '' Nov 9 04:30:28 pfsense ppp: PPPoE: rec'd ACNAME "ISPName" Nov 9 04:30:28 pfsense ppp: [wan_link0] PPPoE: connection successful Nov 9 04:30:28 pfsense ppp: [wan_link0] Link: UP event Nov 9 04:30:28 pfsense ppp: [wan_link0] LCP: Up event Nov 9 04:30:28 pfsense ppp: [wan_link0] LCP: state change Starting --> Req-Sent Nov 9 04:30:28 pfsense ppp: [wan_link0] LCP: SendConfigReq #9 Nov 9 04:30:28 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 04:30:28 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:30:28 pfsense ppp: [wan_link0] MAGICNUM 049260e1 Nov 9 04:30:28 pfsense ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent) Nov 9 04:30:28 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:30:28 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 04:30:28 pfsense ppp: [wan_link0] MAGICNUM 88cf9b57 Nov 9 04:30:28 pfsense ppp: [wan_link0] LCP: SendConfigAck #1 Nov 9 04:30:28 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:30:28 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 04:30:28 pfsense ppp: [wan_link0] MAGICNUM 88cf9b57 Nov 9 04:30:28 pfsense ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: SendConfigReq #10 Nov 9 04:30:30 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 04:30:30 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:30:30 pfsense ppp: [wan_link0] MAGICNUM 049260e1 Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: rec'd Configure Reject #10 (Ack-Sent) Nov 9 04:30:30 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: SendConfigReq #11 Nov 9 04:30:30 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:30:30 pfsense ppp: [wan_link0] MAGICNUM 049260e1 Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: rec'd Configure Ack #11 (Ack-Sent) Nov 9 04:30:30 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:30:30 pfsense ppp: [wan_link0] MAGICNUM 049260e1 Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing Nov 9 04:30:30 pfsense ppp: [wan_link0] PAP: using authname "username@isp.com" Nov 9 04:30:30 pfsense ppp: [wan_link0] PAP: sending REQUEST #1 len: 42 Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: LayerUp Nov 9 04:30:30 pfsense ppp: [wan_link0] PAP: rec'd ACK #1 len: 17 Nov 9 04:30:30 pfsense ppp: [wan_link0] MESG: Password OK Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: authorization successful Nov 9 04:30:30 pfsense ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Nov 9 04:30:30 pfsense ppp: [wan_link0] Link: Join bundle "wan" Nov 9 04:30:30 pfsense ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Nov 9 04:30:30 pfsense ppp: [wan] IPCP: Open event Nov 9 04:30:30 pfsense ppp: [wan] IPCP: state change Initial --> Starting Nov 9 04:30:30 pfsense ppp: [wan] IPCP: LayerStart Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: Open event Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: state change Initial --> Starting Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: LayerStart Nov 9 04:30:30 pfsense ppp: [wan] IPCP: Up event Nov 9 04:30:30 pfsense ppp: [wan] IPCP: state change Starting --> Req-Sent Nov 9 04:30:30 pfsense ppp: [wan] IPCP: SendConfigReq #9 Nov 9 04:30:30 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 04:30:30 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 04:30:30 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 04:30:30 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: Up event Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: state change Starting --> Req-Sent Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: SendConfigReq #3 Nov 9 04:30:30 pfsense ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent) Nov 9 04:30:30 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] XX.XX.128.45 is OK Nov 9 04:30:30 pfsense ppp: [wan] IPCP: SendConfigAck #1 Nov 9 04:30:30 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent Nov 9 04:30:30 pfsense ppp: [wan] IPCP: rec'd Configure Reject #9 (Ack-Sent) Nov 9 04:30:30 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 04:30:30 pfsense ppp: [wan] IPCP: SendConfigReq #10 Nov 9 04:30:30 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 04:30:30 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 04:30:30 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: rec'd Protocol Reject #2 (Opened) Nov 9 04:30:30 pfsense ppp: [wan_link0] LCP: protocol IPV6CP was rejected Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: protocol was rejected by peer Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Nov 9 04:30:30 pfsense ppp: [wan] IPV6CP: LayerFinish Nov 9 04:30:30 pfsense ppp: [wan] IPCP: rec'd Configure Nak #10 (Ack-Sent) Nov 9 04:30:30 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 04:30:30 pfsense ppp: [wan] “My Public IP Address” is OK Nov 9 04:30:30 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] IPCP: SendConfigReq #11 Nov 9 04:30:30 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 04:30:30 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] IPCP: rec'd Configure Ack #11 (Ack-Sent) Nov 9 04:30:30 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 04:30:30 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 04:30:30 pfsense ppp: [wan] IPCP: state change Ack-Sent --> Opened Nov 9 04:30:30 pfsense ppp: [wan] IPCP: LayerUp Nov 9 04:30:30 pfsense ppp: [wan] “My Public IP Address” -> XX.XX.128.45 Nov 9 04:30:30 pfsense check_reload_status: Rewriting resolv.conf Nov 9 04:30:31 pfsense check_reload_status: rc.newwanip starting pppoe0 Nov 9 04:30:31 pfsense ppp: [wan] IFACE: Up event Nov 9 04:30:31 pfsense ppp: [wan] IFACE: Rename interface ng0 to pppoe0 Nov 9 04:30:33 pfsense php: rc.newwanip: rc.newwanip: Informational is starting pppoe0. Nov 9 04:30:33 pfsense php: rc.newwanip: rc.newwanip: on (IP address: “My Public IP Address”) (interface: WAN[wan]) (real interface: pppoe0). Nov 9 04:30:33 pfsense php: rc.newwanip: ROUTING: setting default route to XX.XX.128.45 Nov 9 04:30:38 pfsense php: rc.newwanip: Resyncing OpenVPN instances for interface WAN. Nov 9 04:30:38 pfsense kernel: ovpns1: link state changed to DOWN Nov 9 04:30:38 pfsense check_reload_status: Reloading filter Nov 9 04:30:38 pfsense check_reload_status: Reloading filter Nov 9 04:30:38 pfsense kernel: ovpns1: link state changed to UP Nov 9 04:30:38 pfsense kernel: ovpns2: link state changed to DOWN Nov 9 04:30:38 pfsense check_reload_status: rc.newwanip starting ovpns1 Nov 9 04:30:39 pfsense php: rc.newwanip: Creating rrd update script Nov 9 04:30:39 pfsense kernel: ovpns2: link state changed to UP Nov 9 04:30:39 pfsense check_reload_status: rc.newwanip starting ovpns2 Nov 9 04:30:41 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns1. Nov 9 04:30:41 pfsense php: rc.newwanip: rc.newwanip: on (IP address: ) (interface: OPENVPN[opt1]) (real interface: ovpns1). Nov 9 04:30:41 pfsense php: rc.newwanip: pfSense package system has detected an ip change “My Public IP Address” -> “My Public IP Address” ... Restarting packages. Nov 9 04:30:41 pfsense check_reload_status: Starting packages Nov 9 04:30:41 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns2. Nov 9 04:30:41 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.1.1) (interface: []) (real interface: ovpns2). Nov 9 04:30:41 pfsense php: rc.newwanip: pfSense package system has detected an ip change -> 192.168.1.1 ... Restarting packages. Nov 9 04:30:41 pfsense check_reload_status: Starting packages Nov 9 04:30:43 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:30:43 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 04:30:43 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:30:43 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 04:30:46 pfsense php: rc.newwanip: Creating rrd update script Nov 9 04:30:48 pfsense php: rc.newwanip: pfSense package system has detected an ip change 0.0.0.0 -> ... Restarting packages. Nov 9 04:30:53 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:45:21 pfsense ppp: [wan_link0] LCP: rec'd Terminate Request #3 (Opened) Nov 9 04:45:21 pfsense ppp: [wan_link0] LCP: state change Opened --> Stopping Nov 9 04:45:21 pfsense ppp: [wan_link0] Link: Leave bundle "wan" Nov 9 04:45:21 pfsense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Nov 9 04:45:21 pfsense ppp: [wan] IPCP: Close event Nov 9 04:45:21 pfsense ppp: [wan] IPCP: state change Opened --> Closing Nov 9 04:45:21 pfsense ppp: [wan] IPCP: SendTerminateReq #12 Nov 9 04:45:21 pfsense ppp: [wan] IPCP: LayerDown Nov 9 04:45:21 pfsense check_reload_status: Rewriting resolv.conf Nov 9 04:45:21 pfsense ppp: [wan] IFACE: Delete route 0.0.0.0/0 XX.XX.128.45 failed: No such process Nov 9 04:45:21 pfsense ppp: [wan] IFACE: Down event Nov 9 04:45:21 pfsense kernel: in_scrubprefix: err=65, prefix delete failed Nov 9 04:45:21 pfsense ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0 Nov 9 04:45:21 pfsense ppp: [wan] IPV6CP: Close event Nov 9 04:45:21 pfsense ppp: [wan] IPV6CP: state change Stopped --> Closed Nov 9 04:45:21 pfsense ppp: [wan] IPCP: Down event Nov 9 04:45:21 pfsense ppp: [wan] IPCP: LayerFinish Nov 9 04:45:21 pfsense ppp: [wan] Bundle: No NCPs left. Closing links... Nov 9 04:45:21 pfsense ppp: [wan] IPCP: state change Closing --> Initial Nov 9 04:45:21 pfsense ppp: [wan] IPV6CP: Down event Nov 9 04:45:21 pfsense ppp: [wan] IPV6CP: state change Closed --> Initial Nov 9 04:45:21 pfsense ppp: [wan_link0] LCP: SendTerminateAck #12 Nov 9 04:45:21 pfsense ppp: [wan_link0] LCP: LayerDown Nov 9 04:45:23 pfsense ppp: [wan_link0] LCP: state change Stopping --> Stopped Nov 9 04:45:23 pfsense ppp: [wan_link0] LCP: LayerFinish Nov 9 04:45:23 pfsense ppp: [wan_link0] PPPoE: connection closed Nov 9 04:45:23 pfsense ppp: [wan_link0] Link: DOWN event Nov 9 04:45:23 pfsense ppp: [wan_link0] LCP: Down event Nov 9 04:45:23 pfsense ppp: [wan_link0] LCP: state change Stopped --> Starting Nov 9 04:45:23 pfsense ppp: [wan_link0] LCP: LayerStart Nov 9 04:45:23 pfsense ppp: [wan_link0] Link: reconnection attempt 1 in 3 seconds Nov 9 04:45:26 pfsense ppp: [wan_link0] Link: reconnection attempt 1 Nov 9 04:45:26 pfsense ppp: [wan_link0] PPPoE: Connecting to '' Nov 9 04:45:26 pfsense ppp: PPPoE: rec'd ACNAME "ISPName" Nov 9 04:45:26 pfsense ppp: [wan_link0] PPPoE: connection successful Nov 9 04:45:26 pfsense ppp: [wan_link0] Link: UP event Nov 9 04:45:26 pfsense ppp: [wan_link0] LCP: Up event Nov 9 04:45:26 pfsense ppp: [wan_link0] LCP: state change Starting --> Req-Sent Nov 9 04:45:26 pfsense ppp: [wan_link0] LCP: SendConfigReq #13 Nov 9 04:45:26 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 04:45:26 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:45:26 pfsense ppp: [wan_link0] MAGICNUM d19bac14 Nov 9 04:45:26 pfsense ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent) Nov 9 04:45:26 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:45:26 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 04:45:26 pfsense ppp: [wan_link0] MAGICNUM 3189c11c Nov 9 04:45:26 pfsense ppp: [wan_link0] LCP: SendConfigAck #1 Nov 9 04:45:26 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:45:26 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 04:45:26 pfsense ppp: [wan_link0] MAGICNUM 3189c11c Nov 9 04:45:26 pfsense ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: SendConfigReq #14 Nov 9 04:45:28 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 04:45:28 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:45:28 pfsense ppp: [wan_link0] MAGICNUM d19bac14 Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: rec'd Configure Reject #14 (Ack-Sent) Nov 9 04:45:28 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: SendConfigReq #15 Nov 9 04:45:28 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:45:28 pfsense ppp: [wan_link0] MAGICNUM d19bac14 Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: rec'd Configure Ack #15 (Ack-Sent) Nov 9 04:45:28 pfsense ppp: [wan_link0] MRU 1492 Nov 9 04:45:28 pfsense ppp: [wan_link0] MAGICNUM d19bac14 Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing Nov 9 04:45:28 pfsense ppp: [wan_link0] PAP: using authname "username@isp.com" Nov 9 04:45:28 pfsense ppp: [wan_link0] PAP: sending REQUEST #1 len: 42 Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: LayerUp Nov 9 04:45:28 pfsense ppp: [wan_link0] PAP: rec'd ACK #1 len: 17 Nov 9 04:45:28 pfsense ppp: [wan_link0] MESG: Password OK Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: authorization successful Nov 9 04:45:28 pfsense ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Nov 9 04:45:28 pfsense ppp: [wan_link0] Link: Join bundle "wan" Nov 9 04:45:28 pfsense ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Nov 9 04:45:28 pfsense ppp: [wan] IPCP: Open event Nov 9 04:45:28 pfsense ppp: [wan] IPCP: state change Initial --> Starting Nov 9 04:45:28 pfsense ppp: [wan] IPCP: LayerStart Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: Open event Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: state change Initial --> Starting Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: LayerStart Nov 9 04:45:28 pfsense ppp: [wan] IPCP: Up event Nov 9 04:45:28 pfsense ppp: [wan] IPCP: state change Starting --> Req-Sent Nov 9 04:45:28 pfsense ppp: [wan] IPCP: SendConfigReq #13 Nov 9 04:45:28 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 04:45:28 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 04:45:28 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 04:45:28 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: Up event Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: state change Starting --> Req-Sent Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: SendConfigReq #4 Nov 9 04:45:28 pfsense ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent) Nov 9 04:45:28 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] XX.XX.128.45 is OK Nov 9 04:45:28 pfsense ppp: [wan] IPCP: SendConfigAck #1 Nov 9 04:45:28 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent Nov 9 04:45:28 pfsense ppp: [wan] IPCP: rec'd Configure Reject #13 (Ack-Sent) Nov 9 04:45:28 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 04:45:28 pfsense ppp: [wan] IPCP: SendConfigReq #14 Nov 9 04:45:28 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 04:45:28 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 04:45:28 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: rec'd Protocol Reject #2 (Opened) Nov 9 04:45:28 pfsense ppp: [wan_link0] LCP: protocol IPV6CP was rejected Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: protocol was rejected by peer Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Nov 9 04:45:28 pfsense ppp: [wan] IPV6CP: LayerFinish Nov 9 04:45:28 pfsense ppp: [wan] IPCP: rec'd Configure Nak #14 (Ack-Sent) Nov 9 04:45:28 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 04:45:28 pfsense ppp: [wan] “My Public IP Address” is OK Nov 9 04:45:28 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] IPCP: SendConfigReq #15 Nov 9 04:45:28 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 04:45:28 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] IPCP: rec'd Configure Ack #15 (Ack-Sent) Nov 9 04:45:28 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 04:45:28 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 04:45:28 pfsense ppp: [wan] IPCP: state change Ack-Sent --> Opened Nov 9 04:45:28 pfsense ppp: [wan] IPCP: LayerUp Nov 9 04:45:28 pfsense ppp: [wan] “My Public IP Address” -> XX.XX.128.45 Nov 9 04:45:28 pfsense check_reload_status: Rewriting resolv.conf Nov 9 04:45:29 pfsense check_reload_status: rc.newwanip starting pppoe0 Nov 9 04:45:29 pfsense ppp: [wan] IFACE: Up event Nov 9 04:45:29 pfsense ppp: [wan] IFACE: Rename interface ng0 to pppoe0 Nov 9 04:45:31 pfsense php: rc.newwanip: rc.newwanip: Informational is starting pppoe0. Nov 9 04:45:31 pfsense php: rc.newwanip: rc.newwanip: on (IP address: “My Public IP Address”) (interface: WAN[wan]) (real interface: pppoe0). Nov 9 04:45:31 pfsense php: rc.newwanip: ROUTING: setting default route to XX.XX.128.45 Nov 9 04:45:36 pfsense php: rc.newwanip: Resyncing OpenVPN instances for interface WAN. Nov 9 04:45:36 pfsense kernel: ovpns1: link state changed to DOWN Nov 9 04:45:36 pfsense check_reload_status: Reloading filter Nov 9 04:45:37 pfsense check_reload_status: Reloading filter Nov 9 04:45:37 pfsense kernel: ovpns1: link state changed to UP Nov 9 04:45:37 pfsense check_reload_status: rc.newwanip starting ovpns1 Nov 9 04:45:37 pfsense kernel: ovpns2: link state changed to DOWN Nov 9 04:45:37 pfsense php: rc.newwanip: Creating rrd update script Nov 9 04:45:37 pfsense kernel: ovpns2: link state changed to UP Nov 9 04:45:37 pfsense check_reload_status: rc.newwanip starting ovpns2 Nov 9 04:45:39 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns1. Nov 9 04:45:39 pfsense php: rc.newwanip: rc.newwanip: on (IP address: ) (interface: OPENVPN[opt1]) (real interface: ovpns1). Nov 9 04:45:39 pfsense php: rc.newwanip: pfSense package system has detected an ip change “My Public IP Address” -> “My Public IP Address” ... Restarting packages. Nov 9 04:45:39 pfsense check_reload_status: Starting packages Nov 9 04:45:39 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns2. Nov 9 04:45:39 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.1.1) (interface: []) (real interface: ovpns2). Nov 9 04:45:39 pfsense php: rc.newwanip: pfSense package system has detected an ip change -> 192.168.1.1 ... Restarting packages. Nov 9 04:45:39 pfsense check_reload_status: Starting packages Nov 9 04:45:41 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:45:41 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 04:45:41 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:45:42 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 04:45:44 pfsense php: rc.newwanip: Creating rrd update script Nov 9 04:45:46 pfsense php: rc.newwanip: pfSense package system has detected an ip change 0.0.0.0 -> ... Restarting packages. Nov 9 04:45:51 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 04:45:52 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 05:00:19 pfsense ppp: [wan_link0] LCP: rec'd Terminate Request #3 (Opened) Nov 9 05:00:19 pfsense ppp: [wan_link0] LCP: state change Opened --> Stopping Nov 9 05:00:19 pfsense ppp: [wan_link0] Link: Leave bundle "wan" Nov 9 05:00:19 pfsense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Nov 9 05:00:19 pfsense ppp: [wan] IPCP: Close event Nov 9 05:00:19 pfsense ppp: [wan] IPCP: state change Opened --> Closing Nov 9 05:00:19 pfsense ppp: [wan] IPCP: SendTerminateReq #16 Nov 9 05:00:19 pfsense ppp: [wan] IPCP: LayerDown Nov 9 05:00:19 pfsense check_reload_status: Rewriting resolv.conf Nov 9 05:00:19 pfsense ppp: [wan] IFACE: Delete route 0.0.0.0/0 XX.XX.128.45 failed: No such process Nov 9 05:00:19 pfsense ppp: [wan] IFACE: Down event Nov 9 05:00:19 pfsense kernel: in_scrubprefix: err=65, prefix delete failed Nov 9 05:00:19 pfsense ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0 Nov 9 05:00:19 pfsense ppp: [wan] IPV6CP: Close event Nov 9 05:00:19 pfsense ppp: [wan] IPV6CP: state change Stopped --> Closed Nov 9 05:00:19 pfsense ppp: [wan] IPCP: Down event Nov 9 05:00:19 pfsense ppp: [wan] IPCP: LayerFinish Nov 9 05:00:19 pfsense ppp: [wan] Bundle: No NCPs left. Closing links... Nov 9 05:00:19 pfsense ppp: [wan] IPCP: state change Closing --> Initial Nov 9 05:00:19 pfsense ppp: [wan] IPV6CP: Down event Nov 9 05:00:19 pfsense ppp: [wan] IPV6CP: state change Closed --> Initial Nov 9 05:00:19 pfsense ppp: [wan_link0] LCP: SendTerminateAck #16 Nov 9 05:00:19 pfsense ppp: [wan_link0] LCP: LayerDown Nov 9 05:00:21 pfsense ppp: [wan_link0] LCP: state change Stopping --> Stopped Nov 9 05:00:21 pfsense ppp: [wan_link0] LCP: LayerFinish Nov 9 05:00:21 pfsense ppp: [wan_link0] PPPoE: connection closed Nov 9 05:00:21 pfsense ppp: [wan_link0] Link: DOWN event Nov 9 05:00:21 pfsense ppp: [wan_link0] LCP: Down event Nov 9 05:00:21 pfsense ppp: [wan_link0] LCP: state change Stopped --> Starting Nov 9 05:00:21 pfsense ppp: [wan_link0] LCP: LayerStart Nov 9 05:00:21 pfsense ppp: [wan_link0] Link: reconnection attempt 1 in 4 seconds Nov 9 05:00:25 pfsense ppp: [wan_link0] Link: reconnection attempt 1 Nov 9 05:00:25 pfsense ppp: [wan_link0] PPPoE: Connecting to '' Nov 9 05:00:25 pfsense ppp: PPPoE: rec'd ACNAME "ISPName" Nov 9 05:00:25 pfsense ppp: [wan_link0] PPPoE: connection successful Nov 9 05:00:25 pfsense ppp: [wan_link0] Link: UP event Nov 9 05:00:25 pfsense ppp: [wan_link0] LCP: Up event Nov 9 05:00:25 pfsense ppp: [wan_link0] LCP: state change Starting --> Req-Sent Nov 9 05:00:25 pfsense ppp: [wan_link0] LCP: SendConfigReq #17 Nov 9 05:00:25 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 05:00:25 pfsense ppp: [wan_link0] MRU 1492 Nov 9 05:00:25 pfsense ppp: [wan_link0] MAGICNUM 59c9a793 Nov 9 05:00:25 pfsense ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent) Nov 9 05:00:25 pfsense ppp: [wan_link0] MRU 1492 Nov 9 05:00:25 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 05:00:25 pfsense ppp: [wan_link0] MAGICNUM ea6b382b Nov 9 05:00:25 pfsense ppp: [wan_link0] LCP: SendConfigAck #1 Nov 9 05:00:25 pfsense ppp: [wan_link0] MRU 1492 Nov 9 05:00:25 pfsense ppp: [wan_link0] AUTHPROTO PAP Nov 9 05:00:25 pfsense ppp: [wan_link0] MAGICNUM ea6b382b Nov 9 05:00:25 pfsense ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: SendConfigReq #18 Nov 9 05:00:27 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 05:00:27 pfsense ppp: [wan_link0] MRU 1492 Nov 9 05:00:27 pfsense ppp: [wan_link0] MAGICNUM 59c9a793 Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: rec'd Configure Reject #18 (Ack-Sent) Nov 9 05:00:27 pfsense ppp: [wan_link0] PROTOCOMP Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: SendConfigReq #19 Nov 9 05:00:27 pfsense ppp: [wan_link0] MRU 1492 Nov 9 05:00:27 pfsense ppp: [wan_link0] MAGICNUM 59c9a793 Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: rec'd Configure Ack #19 (Ack-Sent) Nov 9 05:00:27 pfsense ppp: [wan_link0] MRU 1492 Nov 9 05:00:27 pfsense ppp: [wan_link0] MAGICNUM 59c9a793 Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing Nov 9 05:00:27 pfsense ppp: [wan_link0] PAP: using authname "username@isp.com" Nov 9 05:00:27 pfsense ppp: [wan_link0] PAP: sending REQUEST #1 len: 42 Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: LayerUp Nov 9 05:00:27 pfsense ppp: [wan_link0] PAP: rec'd ACK #1 len: 17 Nov 9 05:00:27 pfsense ppp: [wan_link0] MESG: Password OK Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: authorization successful Nov 9 05:00:27 pfsense ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Nov 9 05:00:27 pfsense ppp: [wan_link0] Link: Join bundle "wan" Nov 9 05:00:27 pfsense ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Nov 9 05:00:27 pfsense ppp: [wan] IPCP: Open event Nov 9 05:00:27 pfsense ppp: [wan] IPCP: state change Initial --> Starting Nov 9 05:00:27 pfsense ppp: [wan] IPCP: LayerStart Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: Open event Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: state change Initial --> Starting Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: LayerStart Nov 9 05:00:27 pfsense ppp: [wan] IPCP: Up event Nov 9 05:00:27 pfsense ppp: [wan] IPCP: state change Starting --> Req-Sent Nov 9 05:00:27 pfsense ppp: [wan] IPCP: SendConfigReq #17 Nov 9 05:00:27 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 05:00:27 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 05:00:27 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 05:00:27 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: Up event Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: state change Starting --> Req-Sent Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: SendConfigReq #5 Nov 9 05:00:27 pfsense ppp: [wan] IPCP: rec'd Configure Reject #17 (Req-Sent) Nov 9 05:00:27 pfsense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Nov 9 05:00:27 pfsense ppp: [wan] IPCP: SendConfigReq #18 Nov 9 05:00:27 pfsense ppp: [wan] IPADDR 0.0.0.0 Nov 9 05:00:27 pfsense ppp: [wan] PRIDNS 0.0.0.0 Nov 9 05:00:27 pfsense ppp: [wan] SECDNS 0.0.0.0 Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: rec'd Protocol Reject #2 (Opened) Nov 9 05:00:27 pfsense ppp: [wan_link0] LCP: protocol IPV6CP was rejected Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: protocol was rejected by peer Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Nov 9 05:00:27 pfsense ppp: [wan] IPV6CP: LayerFinish Nov 9 05:00:27 pfsense ppp: [wan] IPCP: rec'd Configure Nak #18 (Req-Sent) Nov 9 05:00:27 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 05:00:27 pfsense ppp: [wan] “My Public IP Address” is OK Nov 9 05:00:27 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 05:00:27 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 05:00:27 pfsense ppp: [wan] IPCP: SendConfigReq #19 Nov 9 05:00:27 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 05:00:27 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 05:00:27 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 05:00:27 pfsense ppp: [wan] IPCP: rec'd Configure Ack #19 (Req-Sent) Nov 9 05:00:27 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 05:00:27 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 05:00:27 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 05:00:27 pfsense ppp: [wan] IPCP: state change Req-Sent --> Ack-Rcvd Nov 9 05:00:29 pfsense ppp: [wan] IPCP: state change Ack-Rcvd --> Req-Sent Nov 9 05:00:29 pfsense ppp: [wan] IPCP: SendConfigReq #20 Nov 9 05:00:29 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 05:00:29 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 05:00:29 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 05:00:29 pfsense ppp: [wan] IPCP: rec'd Configure Ack #20 (Req-Sent) Nov 9 05:00:29 pfsense ppp: [wan] IPADDR “My Public IP Address” Nov 9 05:00:29 pfsense ppp: [wan] PRIDNS XX.XX.128.45 Nov 9 05:00:29 pfsense ppp: [wan] SECDNS XX.XX.128.45 Nov 9 05:00:29 pfsense ppp: [wan] IPCP: state change Req-Sent --> Ack-Rcvd Nov 9 05:00:30 pfsense ppp: [wan] IPCP: rec'd Configure Request #1 (Ack-Rcvd) Nov 9 05:00:30 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 05:00:30 pfsense ppp: [wan] XX.XX.128.45 is OK Nov 9 05:00:30 pfsense ppp: [wan] IPCP: SendConfigAck #1 Nov 9 05:00:30 pfsense ppp: [wan] IPADDR XX.XX.128.45 Nov 9 05:00:30 pfsense ppp: [wan] IPCP: state change Ack-Rcvd --> Opened Nov 9 05:00:30 pfsense ppp: [wan] IPCP: LayerUp Nov 9 05:00:30 pfsense ppp: [wan] “My Public IP Address” -> XX.XX.128.45 Nov 9 05:00:30 pfsense check_reload_status: Rewriting resolv.conf Nov 9 05:00:31 pfsense check_reload_status: rc.newwanip starting pppoe0 Nov 9 05:00:31 pfsense ppp: [wan] IFACE: Up event Nov 9 05:00:31 pfsense ppp: [wan] IFACE: Rename interface ng0 to pppoe0 Nov 9 05:00:33 pfsense php: rc.newwanip: rc.newwanip: Informational is starting pppoe0. Nov 9 05:00:33 pfsense php: rc.newwanip: rc.newwanip: on (IP address: “My Public IP Address”) (interface: WAN[wan]) (real interface: pppoe0). Nov 9 05:00:33 pfsense php: rc.newwanip: ROUTING: setting default route to XX.XX.128.45 Nov 9 05:00:38 pfsense php: rc.newwanip: Resyncing OpenVPN instances for interface WAN. Nov 9 05:00:38 pfsense kernel: ovpns1: link state changed to DOWN Nov 9 05:00:38 pfsense check_reload_status: Reloading filter Nov 9 05:00:39 pfsense check_reload_status: Reloading filter Nov 9 05:00:39 pfsense kernel: ovpns1: link state changed to UP Nov 9 05:00:39 pfsense check_reload_status: rc.newwanip starting ovpns1 Nov 9 05:00:39 pfsense kernel: ovpns2: link state changed to DOWN Nov 9 05:00:39 pfsense php: rc.newwanip: Creating rrd update script Nov 9 05:00:39 pfsense kernel: ovpns2: link state changed to UP Nov 9 05:00:39 pfsense check_reload_status: rc.newwanip starting ovpns2 Nov 9 05:00:41 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns1. Nov 9 05:00:41 pfsense php: rc.newwanip: rc.newwanip: on (IP address: ) (interface: OPENVPN[opt1]) (real interface: ovpns1). Nov 9 05:00:41 pfsense php: rc.newwanip: pfSense package system has detected an ip change “My Public IP Address” -> “My Public IP Address” ... Restarting packages. Nov 9 05:00:41 pfsense check_reload_status: Starting packages Nov 9 05:00:41 pfsense php: rc.newwanip: rc.newwanip: Informational is starting ovpns2. Nov 9 05:00:41 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.1.1) (interface: []) (real interface: ovpns2). Nov 9 05:00:41 pfsense php: rc.newwanip: pfSense package system has detected an ip change -> 192.168.1.1 ... Restarting packages. Nov 9 05:00:41 pfsense check_reload_status: Starting packages Nov 9 05:00:43 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 05:00:43 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 05:00:44 pfsense php: rc.start_packages: Restarting/Starting all packages. Nov 9 05:00:44 pfsense php: rc.start_packages: The command '/usr/local/etc/rc.d/cron.sh stop' returned exit code '1', the output was '' Nov 9 05:00:46 pfsense php: rc.newwanip: Creating rrd update script Nov 9 05:00:48 pfsense php: rc.newwanip: pfSense package system has detected an ip change 0.0.0.0 -> ... Restarting packages. Nov 9 05:00:53 pfsense php: rc.start_packages: Restarting/Starting all packages.
I'm looking forward to hearing from you guys!
P.S. I couldn't post bigger part of my sys log, because it's too long. If you need more info feel free to ask.
Regards,
Nick -
SIGHUP is the ISP telling pppd to hangup and refresh itself.
-
Hi KurianOfBorg,
Thank you for your reply. I contacted my ISP and it confirmed, that their system is not sending any hangup requests. Other users on the same address have uninterrupted connections for months.
To be honest, I'm suspecting my configuration. I thing some process is initiating pppoe restart, but I need some help to find it. I've checked my IDLE timeout - it's 0 (disabled), so it's not that one.
I'm looking forward to hearing from you guys.
Regards,
Nick -
Hi fellows,
Happy New Year and all the best in the new 2015!
A quick update to my issue:
I did a fresh install of pfsense 2.1.5, the latest stable release. I've checked all the wiring and I couldn't find any problems. Moreover when I use a simple old netgear router my pppoe connection is solid stable, no recconections at all, but as soon as I switch to my pfsense box it stars reconnecting after random amount of time.
In a few words, the problem still exists.
Can you help me please with some suggestions?
My isp is providing my internet via utp cable, so there is no modem before my pfsense box.
I'm looking forward to hearing from you guys!
Kind Regards,
Nikolay Zhelev -
Can you try 2.2 RC?
-
Hi firewalluser,
Thank you for your reply. Unfortunatelly I would like to avoid 2.2 RC, due to the OpenVPN TAP issue, because I'm actively using OpenVPN in bridged configuration.
Any ideas regarding 2.1.5?
Regards,
Nick -
Hi fellows,
An update to my case:
I've updated from pfSense 2.1.5 to 2.2 couple of days ago and today the problem came again.
Feb 15 11:02:53 system log: check_reload_status: Rewriting resolv.conf
Feb 15 11:03:02 gateway log: apinger: SIGHUP received, reloading configuration.
Feb 15 11:02:53 ppp log: ppp: [wan_link0] LCP: state change Opened –> StoppingI really need some help. I've contacted my ISP and they confirmed, that other users on my street connected to the same switch didn't have any connection drop, which means the problems is in my box.
Any ideas?
I'm looking forward to hearing from you guys.
Kind Regards,
Nick -
A quick update:
I've checked my quality graphs for the time when the reconnection occurred, there are no drops and no packet losses. There are no apinger gateway down event, no alarm is triggered, which makes me think, that internal process is sending sighup to close the pppoe connection.
Is that possible and how can I identify that?
Regards,
Nick -
Hi fellows,
I started digging in my pppoe configuration files and I came across one unusual thing:
As seen from the picture below, my wan interface configuration is set to IPv4 -> PPPoE and IPv6 -> None (my ISP offers me only IPv4 static address).
but when I checked my mpd_wan.conf file, located in /var/etc/ the content was "set bundle enable ipv6cp", as seen from the code below:
startup: # configure the console set console close # configure the web server set web close default: pppoeclient: create bundle static wan set bundle enable ipv6cp set iface name pppoe0 set iface route default set iface disable on-demand set iface idle 0 set iface enable tcpmssfix set iface up-script /usr/local/sbin/ppp-linkup set iface down-script /usr/local/sbin/ppp-linkdown set ipcp ranges 0.0.0.0/0 0.0.0.0/0 set ipcp enable req-pri-dns set ipcp enable req-sec-dns #log -bund -ccp -chat -iface -ipcp -lcp -link create link static wan_link0 pppoe set link action bundle wan set link disable multilink set link keep-alive 10 60 set link max-redial 0 set link disable chap pap set link accept chap pap eap set link disable incoming set link mtu 1492 set auth authname "username@isp.com" set auth password isppassword set pppoe service "" set pppoe iface re1 open
I found this a bit unusual, therefore I started looking from where the mpd_wan.conf file is generated.
I traced the source to: etc/inc/interfaces.inc where I noticed, that by default the "set bundle enable" line is set to ipv6cp, ignoring the web interface "None" selection. Also, I noticed, that "keep-alive 10 60" is set by default, without any option to disable it.
Unfortunately I don't have deep knowledge in scriting and I'm not sure whether I'm correct in my troubleshooting, so I'll appreciate your comments here.
Shall I change ipv6cp in interfaces.inc to ipcp and also disable keep-alive, by setting "keep-alive 0 60" or not?
Regards,
Nick -
Interesting find. Do what you like in /var, it gets rebuilt at boot anyway. Backup the old file first if you mod anything else.
Some input from a higher source:
https://forum.pfsense.org/index.php?topic=32653.msg168773#msg168773Steve
-
Hi Steve,
Thank you very much for your reply!
I've backed up mpd_wan.conf and interfaces.inc and changed the "set bundle enable ipv6cp" to "set bundle enable ipcp" in the mpd_wan.conf. Also I modified interfaces.inc, because otherwise after reboot it will revert back to ipv6cp.
Out of curiosity I've disabled keep-alive and enabled verbosity logging so we'll see how it will go.
After couple of days I'll share my results.
Regards,
Nick -
New discoveries:
The initial problem still persists, however I’ve discovered something very interesting.
Currently I'm located in UK. My pfsense router is in another country.
While I was talking with a person located at the same place as my router, using router’s local network, suddenly all traffic initiated from outside of my router’s network was blocked, but I was still able to communicate with the person using the local network. There was an Internet connection from the local network, but I was unable to access my router remotely, not even ping it.
I’ve contacted my ISP (router side) and they confirmed, that they are unable to test the channel, because the firewall (pfsense) is blocking everything.
Shortly, I was in a situation, where pfsense was blocking every incoming connection, but LAN side Internet access was fine.
After couple of minutes, pfsense dropped the PPPoE WAN connection and re-initiated it again. After that I was able to access the router remotely and everything was running as it should be.
When I checked the apinger log file there were two identical messages:apinger: SIGHUP received, reloading configuration.
Any ideas, why that happened?
I’m looking forward to hearing from you.
Regards,
Nick -
Not really I'm afraid.
That output you are seeing 'apinger: SIGHUP received' is apinger being told to reload for whatever reason, usually because the WAN address has changed or potentially changed. It should correspond with something else in the system logs giving a reason for the call.
http://en.wikipedia.org/wiki/SIGHUP#Modern_usageSo when this incident occurred you were still able to initiate new connections from inside the firewall but rules to allow traffic to the firewall from outside no longer appeared to function? Odd.
Steve
-
Hi Steve,
Thank you again for your time!
The wikipedia article is very nice, now I know what exactly SIGHUP is.
I think the situation becomes more clear now. Please correct me if I'm not on the right track, but I think this could be a firewall issue, rather than a PPPoE problem.
My ISP indeed closes the connection, by sending me SIGHUP signal, but I think that is the result of all inbound traffic being blocked randomly by my firewall (the issue I've experienced yesterday). If I'm not replying to any of the ISP request, then my ISP thinks that the connection is dead, therefore it closes the channel. Am I on the right track?
Regards,
Nick -
Nope that's not your ISP sending the SIGHUP signal that's internal signalling between processes in pfSense.
Check the ppp logs for what your ISP is sending.Steve
-
Thanks Steve!
I'm giving up. I'm trying to sort out this problem for 5 months and I just can't find what is wrong. I'm pretty sure that is some sort of very stupid mistake form my side, but I just can't find it.
I'm happy to pay to someone to trouble shoot the problem. Please let me know if someone is interested.
Regards,
Nick -
Dear fellows,
Finally the problem is solved!
That was quite a tricky problem, due to the fact that I was trouble shooting it from distance.
One of the computers behind the pfsense firewall was running uTorrent with enabled DHT. When the computer was ON and uTorrent was in IDLE mode (no active seeding/leeching, just the app running) the WAN interface was constantly dropping my PPPoE connection. However, when uTorrent was running (actively seeding/leeching), there is no problem, but as soon as it goes to IDLE - pfsense restarts all services.
As soon as I disabled DHT on uTorrent the problem disappeared. Unfortunately I couldn't identify why with DHT enabled and uTorrent in idle, pfsense was restarting the services, but at least the problem is gone.
More on the uTorrent issue: https://forum.pfsense.org/index.php?topic=93812.0
Thank for all the help.
Regards,
Nick