WAN periodically Rebooting

[stephenw10]

@diyhouse said in WAN periodically Rebooting:

Aug 12 13:59:51 ppp 19091 [wan_link0] Link: DOWN event
Aug 12 13:59:51 ppp 19091 [wan_link0] PPPoE: connection closed
Aug 12 13:59:33 ppp 19091 [wan_link0] LCP: no reply to 1 echo request(s)
Aug 12 13:49:22 ppp 19091 [wan_link0] LCP: no reply to 1 echo request(s)
Aug 12 13:28:00 ppp 19091 [wan_link0] LCP: no reply to 2 echo request(s)
Aug 12 13:27:50 ppp 19091 [wan_link0] LCP: no reply to 1 echo request(s)
Aug 12 13:27:10 ppp 19091 [wan_link0] LCP: no reply to 1 echo request(s)
Aug 12 13:09:02 ppp 19091 [wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 12 13:09:00 ppp 19091 [wan] IFACE: Add description "1_WAN"
Aug 12 13:09:00 ppp 19091 [wan] IFACE: Rename interface ng0 to pppoe0
Aug 12 13:09:00 ppp 19091 [wan] IFACE: Up event

Huh that's interesting. I wonder if it's counting those 5 alerts as enough to reconnect even though they are not consecutive.

Though it doesn't show the LCP: peer not responding to echo requests message that would normally indicate it being triggered. And the value there should be a max time of 60s which would never be reached.

No you should not need any settings in the advanced options.

If you look in /var/etc/mpd_wan.conf you will see the generated conf file used to connect. It's possible to make a custom conf file by copying that to /conf and then editing it there. The mpd daemon will use a file there in preference.

[diyhouse]

@stephenw10 this is my 'mpd_wan.conf' file.. credentials removed,..
what do you suggest I modify,..
If I update this file how do I force it to be used,.. ie how do I force a 'reload'

I see these two values,.. set link keep-alive 10 60,.. what do you suggest,. 100 300,
ie 5 mins....
Can I not just edit the primary file,.. or does this get overwritten..

2.7.2-RELEASE][mark@pfSense.mylocal]/var/etc: cat mpd_wan.conf 
startup:
	# configure the console
	set console close
	# configure the web server
	set web close

default:
pppoeclient:
	create bundle static wan
	set bundle period 6
	set bundle lowat 0
	set bundle hiwat 0
	set bundle min-con 3
	set bundle min-dis 6
	set bundle enable bw-manage
	
	set iface name pppoe0
	set iface description "1_WAN"
	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 "account"
	set auth password passwd
	set pppoe service ""
	set pppoe iface igb0
	open

[stephenw10]

Indeed the file in /var/etc gets overwritten at boot or whenever the config is rebuilt so you have to copy it to /conf to make permanent changes to it.

I would start by setting link keep-alive to something just larger to see if that has any effect so maybe: 20 120

[diyhouse]

@stephenw10
Tx,..
Ok,.. just trying to copy file over to /conf... but insufficient privs,.. sudo does not work...
and from what I can read I have to use the shell window offered from the console,.. with a direct login at the h/w,.. or have I missed something..?

[stephenw10]

You can do it from the gui Diag > Command Prompt.

Then edit it from Diag > Edit File

[diyhouse]

@diyhouse well bit the bullet,.. suffered in 40C loft ambient
File copied ,. and edited with a bit of vi... followed by a reboot..
Now I wait for next event..
Thanks

[stephenw10]

Ha, hottest day of the year, clearly the best day for it.

For reference though you can do it from the GUI or by logging in as admin.

[diyhouse]

@stephenw10 Yep it was hot,.. But file edited,.. I did try ssh'ing into pfsense as 'admin',..
but this did not work,.
also how do I reload setting and force the new setting into play...?
( all good so far 20 mins in,.. no errors on PPP,.. )
Tx

[stephenw10]

Re-saving the WAN interface should do it.

[diyhouse]

@diyhouse,.. Well spoke to soon,.. had numerous reboots,.. around 5:30am this morning,.. and its been off several times since,.. These are the most recent PPP down... Any thoughts..

Aug 13 13:52:42	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 13:52:41	ppp	71373	[wan] IFACE: Add description "1_WAN"
Aug 13 13:52:41	ppp	71373	[wan] IFACE: Rename interface ng0 to pppoe0
Aug 13 13:52:41	ppp	71373	[wan] IFACE: Up event
Aug 13 13:52:40	ppp	71373	[wan] 109.147.50.193 -> 172.16.12.102
Aug 13 13:52:40	ppp	71373	[wan] IPCP: LayerUp
Aug 13 13:52:40	ppp	71373	[wan] IPCP: state change Ack-Sent --> Opened
Aug 13 13:52:40	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 13:52:40	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 109.147.50.193
Aug 13 13:52:40	ppp	71373	[wan] IPCP: rec'd Configure Ack #47 (Ack-Sent)
Aug 13 13:52:40	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 13:52:40	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 109.147.50.193
Aug 13 13:52:40	ppp	71373	[wan] IPCP: SendConfigReq #47
Aug 13 13:52:40	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 13:52:40	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 13:52:40	ppp	71373	[wan] 109.147.50.193 is OK
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 109.147.50.193
Aug 13 13:52:40	ppp	71373	[wan] IPCP: rec'd Configure Nak #46 (Ack-Sent)
Aug 13 13:52:40	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 13:52:40	ppp	71373	[wan] SECDNS 0.0.0.0
Aug 13 13:52:40	ppp	71373	[wan] PRIDNS 0.0.0.0
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 0.0.0.0
Aug 13 13:52:40	ppp	71373	[wan] IPCP: SendConfigReq #46
Aug 13 13:52:40	ppp	71373	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 13 13:52:40	ppp	71373	[wan] IPCP: rec'd Configure Reject #45 (Ack-Sent)
Aug 13 13:52:40	ppp	71373	[wan] IPCP: state change Req-Sent --> Ack-Sent
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 172.16.12.102
Aug 13 13:52:40	ppp	71373	[wan] IPCP: SendConfigAck #81
Aug 13 13:52:40	ppp	71373	[wan] 172.16.12.102 is OK
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 172.16.12.102
Aug 13 13:52:40	ppp	71373	[wan] IPCP: rec'd Configure Request #81 (Req-Sent)
Aug 13 13:52:40	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 13:52:40	ppp	71373	[wan] SECDNS 0.0.0.0
Aug 13 13:52:40	ppp	71373	[wan] PRIDNS 0.0.0.0
Aug 13 13:52:40	ppp	71373	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 13 13:52:40	ppp	71373	[wan] IPADDR 0.0.0.0
Aug 13 13:52:40	ppp	71373	[wan] IPCP: SendConfigReq #45
Aug 13 13:52:40	ppp	71373	[wan] IPCP: state change Starting --> Req-Sent
Aug 13 13:52:40	ppp	71373	[wan] IPCP: Up event
Aug 13 13:52:40	ppp	71373	[wan] IPCP: LayerStart
Aug 13 13:52:40	ppp	71373	[wan] IPCP: state change Initial --> Starting
Aug 13 13:52:40	ppp	71373	[wan] IPCP: Open event
Aug 13 13:52:40	ppp	71373	[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Aug 13 13:52:40	ppp	71373	[wan_link0] Link: Join bundle "wan"
Aug 13 13:52:40	ppp	71373	[wan_link0] Link: Matched action 'bundle "wan" ""'
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: authorization successful
Aug 13 13:52:40	ppp	71373	[wan_link0] MESG: CHAP authentication success
Aug 13 13:52:40	ppp	71373	[wan_link0] CHAP: rec'd SUCCESS #1 len: 31
Aug 13 13:52:40	ppp	71373	[wan_link0] CHAP: sending RESPONSE #1 len: 52
Aug 13 13:52:40	ppp	71373	[wan_link0] CHAP: Using authname "green-light@service.btclick.com"
Aug 13 13:52:40	ppp	71373	[wan_link0] Name: "acc-aln2.tbs"
Aug 13 13:52:40	ppp	71373	[wan_link0] CHAP: rec'd CHALLENGE #1 len: 60
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: LayerUp
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: auth: peer wants CHAP, I want nothing
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: state change Ack-Sent --> Opened
Aug 13 13:52:40	ppp	71373	[wan_link0] MAGICNUM 0x2128a255
Aug 13 13:52:40	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: rec'd Configure Ack #40 (Ack-Sent)
Aug 13 13:52:40	ppp	71373	[wan_link0] MAGICNUM 0x2128a255
Aug 13 13:52:40	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: SendConfigReq #40
Aug 13 13:52:40	ppp	71373	[wan_link0] PROTOCOMP
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: rec'd Configure Reject #39 (Ack-Sent)
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: state change Req-Sent --> Ack-Sent
Aug 13 13:52:40	ppp	71373	[wan_link0] MAGICNUM 0x04a69d35
Aug 13 13:52:40	ppp	71373	[wan_link0] AUTHPROTO CHAP MD5
Aug 13 13:52:40	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: SendConfigAck #159
Aug 13 13:52:40	ppp	71373	[wan_link0] MAGICNUM 0x04a69d35
Aug 13 13:52:40	ppp	71373	[wan_link0] AUTHPROTO CHAP MD5
Aug 13 13:52:40	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:52:40	ppp	71373	[wan_link0] LCP: rec'd Configure Request #159 (Req-Sent)
Aug 13 13:52:39	ppp	71373	[wan_link0] MAGICNUM 0x2128a255
Aug 13 13:52:39	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:52:39	ppp	71373	[wan_link0] PROTOCOMP
Aug 13 13:52:39	ppp	71373	[wan_link0] LCP: SendConfigReq #39
Aug 13 13:52:39	ppp	71373	[wan_link0] LCP: state change Starting --> Req-Sent
Aug 13 13:52:39	ppp	71373	[wan_link0] LCP: Up event
Aug 13 13:52:39	ppp	71373	[wan_link0] Link: UP event
Aug 13 13:52:39	ppp	71373	[wan_link0] PPPoE: connection successful
Aug 13 13:52:39	ppp	71373	PPPoE: rec'd ACNAME "acc-aln2.tbs"
Aug 13 13:52:33	ppp	71373	[wan_link0] PPPoE: Connecting to ''
Aug 13 13:52:33	ppp	71373	[wan_link0] Link: reconnection attempt 2
Aug 13 13:52:32	ppp	71373	[wan_link0] Link: reconnection attempt 2 in 1 seconds
Aug 13 13:52:32	ppp	71373	[wan_link0] LCP: Down event
Aug 13 13:52:32	ppp	71373	[wan_link0] Link: DOWN event
Aug 13 13:52:32	ppp	71373	[wan_link0] PPPoE connection timeout after 9 seconds
Aug 13 13:52:23	ppp	71373	[wan_link0] PPPoE: Connecting to ''
Aug 13 13:52:23	ppp	71373	[wan_link0] Link: reconnection attempt 1
Aug 13 13:52:21	ppp	71373	[wan_link0] Link: reconnection attempt 1 in 2 seconds
Aug 13 13:52:21	ppp	71373	[wan_link0] LCP: LayerDown
Aug 13 13:52:21	ppp	71373	[wan] Bundle: Last link has gone, no links for bw-manage defined
Aug 13 13:52:21	ppp	71373	[wan] IPCP: state change Closing --> Initial
Aug 13 13:52:21	ppp	71373	[wan] Bundle: No NCPs left. Closing links...
Aug 13 13:52:21	ppp	71373	[wan] IPCP: LayerFinish
Aug 13 13:52:21	ppp	71373	[wan] IPCP: Down event
Aug 13 13:52:21	ppp	71373	[wan] IFACE: Set description "1_WAN"
Aug 13 13:52:21	ppp	71373	[wan] IFACE: Rename interface pppoe0 to pppoe0
Aug 13 13:52:21	ppp	71373	[wan] IFACE: Down event
Aug 13 13:52:21	ppp	71373	[wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
Aug 13 13:52:21	ppp	71373	[wan] IPCP: LayerDown
Aug 13 13:52:21	ppp	71373	[wan] IPCP: SendTerminateReq #44
Aug 13 13:52:21	ppp	71373	[wan] IPCP: state change Opened --> Closing
Aug 13 13:52:21	ppp	71373	[wan] IPCP: Close event
Aug 13 13:52:21	ppp	71373	[wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 13 13:52:21	ppp	71373	[wan_link0] Link: Leave bundle "wan"
Aug 13 13:52:21	ppp	71373	[wan_link0] LCP: state change Opened --> Starting
Aug 13 13:52:21	ppp	71373	[wan_link0] LCP: Down event
Aug 13 13:52:21	ppp	71373	[wan_link0] Link: DOWN event
Aug 13 13:52:21	ppp	71373	[wan_link0] PPPoE: connection closed
Aug 13 13:52:16	ppp	71373	[wan_link0] LCP: no reply to 1 echo request(s)
Aug 13 13:21:58	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 13:21:56	ppp	71373	[wan] IFACE: Add description "1_WAN"
Aug 13 13:21:56	ppp	71373	[wan] IFACE: Rename interface ng0 to pppoe0
Aug 13 13:21:56	ppp	71373	[wan] IFACE: Up event
Aug 13 13:21:55	ppp	71373	[wan] 109.147.50.193 -> 172.16.12.102
Aug 13 13:21:55	ppp	71373	[wan] IPCP: LayerUp
Aug 13 13:21:55	ppp	71373	[wan] IPCP: state change Ack-Sent --> Opened
Aug 13 13:21:55	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 13:21:55	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 109.147.50.193
Aug 13 13:21:55	ppp	71373	[wan] IPCP: rec'd Configure Ack #43 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 13:21:55	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 109.147.50.193
Aug 13 13:21:55	ppp	71373	[wan] IPCP: SendConfigReq #43
Aug 13 13:21:55	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 13:21:55	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 13:21:55	ppp	71373	[wan] 109.147.50.193 is OK
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 109.147.50.193
Aug 13 13:21:55	ppp	71373	[wan] IPCP: rec'd Configure Nak #42 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 13:21:55	ppp	71373	[wan] SECDNS 0.0.0.0
Aug 13 13:21:55	ppp	71373	[wan] PRIDNS 0.0.0.0
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 0.0.0.0
Aug 13 13:21:55	ppp	71373	[wan] IPCP: SendConfigReq #42
Aug 13 13:21:55	ppp	71373	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 13 13:21:55	ppp	71373	[wan] IPCP: rec'd Configure Reject #41 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan] IPCP: state change Req-Sent --> Ack-Sent
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 172.16.12.102
Aug 13 13:21:55	ppp	71373	[wan] IPCP: SendConfigAck #224
Aug 13 13:21:55	ppp	71373	[wan] 172.16.12.102 is OK
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 172.16.12.102
Aug 13 13:21:55	ppp	71373	[wan] IPCP: rec'd Configure Request #224 (Req-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 13:21:55	ppp	71373	[wan] SECDNS 0.0.0.0
Aug 13 13:21:55	ppp	71373	[wan] PRIDNS 0.0.0.0
Aug 13 13:21:55	ppp	71373	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 13 13:21:55	ppp	71373	[wan] IPADDR 0.0.0.0
Aug 13 13:21:55	ppp	71373	[wan] IPCP: SendConfigReq #41
Aug 13 13:21:55	ppp	71373	[wan] IPCP: state change Starting --> Req-Sent
Aug 13 13:21:55	ppp	71373	[wan] IPCP: Up event
Aug 13 13:21:55	ppp	71373	[wan] IPCP: LayerStart
Aug 13 13:21:55	ppp	71373	[wan] IPCP: state change Initial --> Starting
Aug 13 13:21:55	ppp	71373	[wan] IPCP: Open event
Aug 13 13:21:55	ppp	71373	[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Aug 13 13:21:55	ppp	71373	[wan_link0] Link: Join bundle "wan"
Aug 13 13:21:55	ppp	71373	[wan_link0] Link: Matched action 'bundle "wan" ""'
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: authorization successful
Aug 13 13:21:55	ppp	71373	[wan_link0] MESG: CHAP authentication success
Aug 13 13:21:55	ppp	71373	[wan_link0] CHAP: rec'd SUCCESS #1 len: 31
Aug 13 13:21:55	ppp	71373	[wan_link0] CHAP: sending RESPONSE #1 len: 52
Aug 13 13:21:55	ppp	71373	[wan_link0] CHAP: Using authname "green-light@service.btclick.com"
Aug 13 13:21:55	ppp	71373	[wan_link0] Name: "acc-aln2.tbs"
Aug 13 13:21:55	ppp	71373	[wan_link0] CHAP: rec'd CHALLENGE #1 len: 55
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: LayerUp
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: auth: peer wants CHAP, I want nothing
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: state change Ack-Sent --> Opened
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0xfead80b7
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: rec'd Configure Ack #38 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0xfead80b7
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: SendConfigReq #38
Aug 13 13:21:55	ppp	71373	[wan_link0] PROTOCOMP
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: rec'd Configure Reject #37 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: state change Req-Sent --> Ack-Sent
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0x554ebe8a
Aug 13 13:21:55	ppp	71373	[wan_link0] AUTHPROTO CHAP MD5
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: SendConfigAck #190
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0x554ebe8a
Aug 13 13:21:55	ppp	71373	[wan_link0] AUTHPROTO CHAP MD5
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: rec'd Configure Request #190 (Req-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0xfead80b7
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] PROTOCOMP
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: SendConfigReq #37
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: state change Starting --> Req-Sent
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: Up event
Aug 13 13:21:55	ppp	71373	[wan_link0] Link: UP event
Aug 13 13:21:55	ppp	71373	[wan_link0] PPPoE: connection successful
Aug 13 13:21:55	ppp	71373	PPPoE: rec'd ACNAME "acc-aln2.tbs"
Aug 13 13:21:55	ppp	71373	[wan_link0] PPPoE: Connecting to ''
Aug 13 13:21:55	ppp	71373	[wan_link0] Link: reconnection attempt 2
Aug 13 13:21:53	ppp	71373	[wan_link0] Link: reconnection attempt 2 in 2 seconds
Aug 13 13:21:53	ppp	71373	[wan_link0] LCP: Down event
Aug 13 13:21:53	ppp	71373	[wan_link0] Link: DOWN event
Aug 13 13:21:53	ppp	71373	[wan_link0] PPPoE connection timeout after 9 seconds
Aug 13 13:21:44	ppp	71373	[wan_link0] PPPoE: Connecting to ''
Aug 13 13:21:44	ppp	71373	[wan_link0] Link: reconnection attempt 1
Aug 13 13:21:40	ppp	71373	[wan_link0] Link: reconnection attempt 1 in 4 seconds
Aug 13 13:21:40	ppp	71373	[wan_link0] LCP: LayerDown
Aug 13 13:21:40	ppp	71373	[wan] Bundle: Last link has gone, no links for bw-manage defined
Aug 13 13:21:40	ppp	71373	[wan] IPCP: state change Closing --> Initial
Aug 13 13:21:40	ppp	71373	[wan] Bundle: No NCPs left. Closing links...
Aug 13 13:21:40	ppp	71373	[wan] IPCP: LayerFinish
Aug 13 13:21:40	ppp	71373	[wan] IPCP: Down event
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Set description "1_WAN"
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Rename interface pppoe0 to pppoe0
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Down event
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
Aug 13 13:21:39	ppp	71373	[wan] IPCP: LayerDown
Aug 13 13:21:39	ppp	71373	[wan] IPCP: SendTerminateReq #40
Aug 13 13:21:39	ppp	71373	[wan] IPCP: state change Opened --> Closing
Aug 13 13:21:39	ppp	71373	[wan] IPCP: Close event
Aug 13 13:21:39	ppp	71373	[wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 13 13:21:39	ppp	71373	[wan_link0] Link: Leave bundle "wan"
Aug 13 13:21:39	ppp	71373	[wan_link0] LCP: state change Opened --> Starting
Aug 13 13:21:39	ppp	71373	[wan_link0] LCP: Down event
Aug 13 13:21:39	ppp	71373	[wan_link0] Link: DOWN event
Aug 13 13:21:39	ppp	71373	[wan_link0] PPPoE: connection closed
Aug 13 12:31:49	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 12:31:47	ppp	71373	[wan] IFACE: Add description "1_WAN"
Aug 13 12:31:47	ppp	71373	[wan] IFACE: Rename interface ng0 to pppoe0
Aug 13 12:31:47	ppp	71373	[wan] IFACE: Up event
Aug 13 12:31:46	ppp	71373	[wan] 86.153.138.131 -> 172.16.12.102
Aug 13 12:31:46	ppp	71373	[wan] IPCP: LayerUp
Aug 13 12:31:46	ppp	71373	[wan] IPCP: state change Ack-Sent --> Opened
Aug 13 12:31:46	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 12:31:46	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 12:31:46	ppp	71373	[wan] IPADDR 86.153.138.131
Aug 13 12:31:46	ppp	71373	[wan] IPCP: rec'd Configure Ack #39 (Ack-Sent)
Aug 13 12:31:46	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 12:31:46	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 12:31:46	ppp	71373	[wan] IPADDR 86.153.138.131
Aug 13 12:31:46	ppp	71373	[wan] IPCP: SendConfigReq #39
Aug 13 12:31:46	ppp	71373	[wan] SECDNS 81.139.57.100
Aug 13 12:31:46	ppp	71373	[wan] PRIDNS 81.139.56.100
Aug 13 12:31:46	ppp	71373	[wan] 86.153.138.131 is OK
Aug 13 12:31:46	ppp	71373	[wan] IPADDR 86.153.138.131
Aug 13 12:31:46	ppp	71373	[wan] IPCP: rec'd Configure Nak #38 (Ack-Sent)
Aug 13 12:31:46	ppp	71373	[wan_link0] rec'd unexpected protocol IPV6CP, rejecting
Aug 13 12:31:46	ppp	71373	[wan] SECDNS 0.0.0.0
Aug 13 12:31:46	ppp	71373	[wan] PRIDNS 0.0.0.0
Aug 13 12:31:46	ppp	71373	[wan] IPADDR 0.0.0.0
Aug 13 12:31:46	ppp	71373	[wan] IPCP: SendConfigReq #38

[stephenw10]

@diyhouse said in WAN periodically Rebooting:

Aug 13 13:21:39 ppp 71373 [wan_link0] Link: DOWN event
Aug 13 13:21:39 ppp 71373 [wan_link0] PPPoE: connection closed

Well it doesn't appear to be LCP echo requests timing out. In each case the first thing logged is the connection closing. Hmm. Nothing in the main log at that point?

[diyhouse]

@stephenw10 The Main system=>General Log looks as follows just prior to the connection lost..
Just in passing what does this mean,

Aug 13 13:21:40	ppp	71373	[wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address

Thankyou,....
and main system log:-

Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: LayerUp
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: auth: peer wants CHAP, I want nothing
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: state change Ack-Sent --> Opened
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0xfead80b7
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: rec'd Configure Ack #38 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0xfead80b7
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: SendConfigReq #38
Aug 13 13:21:55	ppp	71373	[wan_link0] PROTOCOMP
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: rec'd Configure Reject #37 (Ack-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: state change Req-Sent --> Ack-Sent
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0x554ebe8a
Aug 13 13:21:55	ppp	71373	[wan_link0] AUTHPROTO CHAP MD5
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: SendConfigAck #190
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0x554ebe8a
Aug 13 13:21:55	ppp	71373	[wan_link0] AUTHPROTO CHAP MD5
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: rec'd Configure Request #190 (Req-Sent)
Aug 13 13:21:55	ppp	71373	[wan_link0] MAGICNUM 0xfead80b7
Aug 13 13:21:55	ppp	71373	[wan_link0] MRU 1492
Aug 13 13:21:55	ppp	71373	[wan_link0] PROTOCOMP
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: SendConfigReq #37
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: state change Starting --> Req-Sent
Aug 13 13:21:55	ppp	71373	[wan_link0] LCP: Up event
Aug 13 13:21:55	ppp	71373	[wan_link0] Link: UP event
Aug 13 13:21:55	ppp	71373	[wan_link0] PPPoE: connection successful
Aug 13 13:21:55	ppp	71373	PPPoE: rec'd ACNAME "acc-aln2.tbs"
Aug 13 13:21:55	ppp	71373	[wan_link0] PPPoE: Connecting to ''
Aug 13 13:21:55	ppp	71373	[wan_link0] Link: reconnection attempt 2
Aug 13 13:21:53	ppp	71373	[wan_link0] Link: reconnection attempt 2 in 2 seconds
Aug 13 13:21:53	ppp	71373	[wan_link0] LCP: Down event
Aug 13 13:21:53	ppp	71373	[wan_link0] Link: DOWN event
Aug 13 13:21:53	ppp	71373	[wan_link0] PPPoE connection timeout after 9 seconds
Aug 13 13:21:44	ppp	71373	[wan_link0] PPPoE: Connecting to ''
Aug 13 13:21:44	ppp	71373	[wan_link0] Link: reconnection attempt 1
Aug 13 13:21:40	ppp	71373	[wan_link0] Link: reconnection attempt 1 in 4 seconds
Aug 13 13:21:40	ppp	71373	[wan_link0] LCP: LayerDown
Aug 13 13:21:40	ppp	71373	[wan] Bundle: Last link has gone, no links for bw-manage defined
Aug 13 13:21:40	ppp	71373	[wan] IPCP: state change Closing --> Initial
Aug 13 13:21:40	ppp	71373	[wan] Bundle: No NCPs left. Closing links...
Aug 13 13:21:40	ppp	71373	[wan] IPCP: LayerFinish
Aug 13 13:21:40	ppp	71373	[wan] IPCP: Down event
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Set description "1_WAN"
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Rename interface pppoe0 to pppoe0
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Down event
Aug 13 13:21:40	ppp	71373	[wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
Aug 13 13:21:40	check_reload_status	430	Rewriting resolv.conf
Aug 13 13:21:39	ppp	71373	[wan] IPCP: LayerDown
Aug 13 13:21:39	ppp	71373	[wan] IPCP: SendTerminateReq #40
Aug 13 13:21:39	ppp	71373	[wan] IPCP: state change Opened --> Closing
Aug 13 13:21:39	ppp	71373	[wan] IPCP: Close event
Aug 13 13:21:39	ppp	71373	[wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 13 13:21:39	ppp	71373	[wan_link0] Link: Leave bundle "wan"
Aug 13 13:21:39	ppp	71373	[wan_link0] LCP: state change Opened --> Starting
Aug 13 13:21:39	ppp	71373	[wan_link0] LCP: Down event
Aug 13 13:21:39	ppp	71373	[wan_link0] Link: DOWN event
Aug 13 13:21:39	ppp	71373	[wan_link0] PPPoE: connection closed
Aug 13 13:18:00	sshguard	19745	Now monitoring attacks.
Aug 13 13:18:00	sshguard	9383	Exiting on signal.
Aug 13 13:15:13	php	41056	[pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Aug 13 13:15:00	php	41056	[pfBlockerNG] Starting cron process.
Aug 13 13:07:00	sshguard	9383	Now monitoring attacks.
Aug 13 13:07:00	sshguard	23133	Exiting on signal.
Aug 13 12:57:00	sshguard	23133	Now monitoring attacks.

[diyhouse]

@diyhouse Looking in General=> Gateways...
I get the following errors...
I don't know if this is a 'red herring',.. but here it is

Aug 13 13:52:24	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:24	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:23	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:23	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:22	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:22	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:22:03	dpinger	19013	1_WAN_PPPOE 172.16.12.102: Alarm latency 0us stddev 0us loss 100%
Aug 13 13:22:01	dpinger	19013	send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 172.16.12.102 bind_addr 109.147.50.193 identifier "1_WAN_PPPOE "
Aug 13 13:22:01	dpinger	69150	exiting on signal 15
Aug 13 13:21:55	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:54	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:54	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:53	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:53	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:52	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:52	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:51	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:50	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:50	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:49	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:49	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:48	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:48	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:47	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:47	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:46	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:46	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:45	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:45	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:44	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:44	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:43	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:43	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:21:42	dpinger	69150	1_WAN_PPPOE 172.16.12.102: sendto error: 65

[stephenw10]

Hmm, all that looks like it's caused by the PPPoE connection closing. Really feels like the server is closing it. Might need to turn up the logging to see it which is not something I've ever tried for PPP. Let me see...

[diyhouse]

@stephenw10
Stephen,... In desperation,... I have just tried to setup an 'original BT Modem',.. and found the credentials I was using to access the broadband servers,.. were incorrect.!!
The credentials I have been using for maybe 6yrs+.... are old,..
Rang BT support,.. and they supplied a completely different set of credentials, which are ( as they say ) in line with my updated line,

Needless to say I am running with the new line config and credentials on pfsense,.. lets see how this pans out
upload/ download is now at 60/10,. which is in line with what I recall were the speeds when i 1st went pfsense FTTC....

So lets see how this pans out,... hopeful,.. but not holding my breath..

[diyhouse]

@diyhouse
Since use of new credentials..1hr 7mins . none of the following error: 65's...in Gateways logs... and PPP is also silent..
fingers crossed..

Aug 13 13:52:29	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:28	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65
Aug 13 13:52:28	dpinger	19013	1_WAN_PPPOE 172.16.12.102: sendto error: 65

[stephenw10]

Hmm, well that would be interesting!

As far as I know BT don't care what the login is, they use the physical link to authenticate you. Maybe that varies. I use bthomehub@btbroadband.com/1234 and it works fine.

I guess we'll see.

[diyhouse]

@stephenw10
Yes indeed,. I transitioned to BT back in 2013,.. ( I've just discovered ),..
at this transition point they gave me an account:-

green-light@service.btclick.com/Passwd to play with,..

which I have used ever since.

today they have said I need to use something similiar to :-N025134@hg70.btclick.com/Passwd

But as you say we shall see...

[diyhouse]

@diyhouse Update:..
Although runnning 'smoother',.. I only seem to be able to get run times on the WAN of around 15hrs...
Looking in system=>general log.. filtered by layer down...I have the following... is my issue related to suricata, they seem to occur and each layer down,.. but appreciate could just be a consequence of the WAN failure...

Aug 13 05:28:03	ppp	71373	[wan] IPCP: LayerDown
Aug 13 00:24:36	kernel		igb1: link state changed to DOWN
Aug 13 00:24:30	kernel		igb1: link state changed to DOWN
Aug 13 00:23:46	suricata	38573	[100852] <Error> -- error parsing signature "alert tcp $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"MALWARE-OTHER Win.Trojan.Zeus Spam 2013 dated zip/exe HTTP Response - potential malware download"; flow:to_client,established; content:"-2013.zip|0D 0A|"; fast_pattern:only; content:"-2013.zip|0D 0A|"; http_header; content:"-"; within:1; distance:-14; http_header; file_data; content:"-2013.exe"; content:"-"; within:1; distance:-14; metadata:impact_flag red, policy balanced-ips drop, policy max-detect-ips drop, policy security-ips drop, ruleset community, service http; reference:url,www.virustotal.com/en/file/2eff3ee6ac7f5bf85e4ebcbe51974d0708cef666581ef1385c628233614b22c0/analysis/; classtype:trojan-activity; sid:26470; rev:2;)" from file /usr/local/etc/suricata/suricata_41945_igb1/rules/suricata.rules at line 162
Aug 13 00:23:26	php-cgi	21038	[Suricata] ERROR: Snort VRT rules md5 download failed...
Aug 13 00:23:25	php-cgi	21038	[Suricata] Emerging Threats Open rules file update downloaded successfully.
Aug 13 00:23:24	php-cgi	21038	[Suricata] There is a new set of Emerging Threats Open rules posted. Downloading emerging.rules.tar.gz...
Aug 12 19:23:14	ppp	71373	[wan_link0] LCP: LayerDown
Aug 12 19:23:14	ppp	71373	[wan] IPCP: Down event
Aug 12 19:23:14	ppp	71373	[wan] IFACE: Down event
Aug 12 19:23:13	ppp	71373	[wan] IPCP: LayerDown
Aug 12 19:23:13	ppp	71373	[wan_link0] LCP: Down event
Aug 12 19:23:13	ppp	71373	[wan_link0] Link: DOWN event
Aug 12 18:42:07	kernel		igb1: link state changed to DOWN
Aug 12 18:42:01	kernel		igb1: link state changed to DOWN
Aug 12 18:41:14	suricata	67299	[100333] <Error> -- error parsing signature "alert tcp $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"MALWARE-OTHER Win.Trojan.Zeus Spam 2013 dated zip/exe HTTP Response - potential malware download"; flow:to_client,established; content:"-2013.zip|0D 0A|"; fast_pattern:only; content:"-2013.zip|0D 0A|"; http_header; content:"-"; within:1; distance:-14; http_header; file_data; content:"-2013.exe"; content:"-"; within:1; distance:-14; metadata:impact_flag red, policy balanced-ips drop, policy max-detect-ips drop, policy security-ips drop, ruleset community, service http; reference:url,www.virustotal.com/en/file/2eff3ee6ac7f5bf85e4ebcbe51974d0708cef666581ef1385c628233614b22c0/analysis/; classtype:trojan-activity; sid:26470; rev:2;)" from file /usr/local/etc/suricata/suricata_41945_igb1/rules/suricata.rules at line 162
Aug 12 18:40:54	kernel		igb1: link state changed to DOWN
Aug 12 18:37:28	kernel		igb1: link state changed to DOWN
Aug 12 18:37:22	kernel		igb1: link state changed to DOWN
Aug 12 18:36:35	suricata	85777	[100429] <Error> -- error parsing signature "alert tcp $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"MALWARE-OTHER Win.Trojan.Zeus Spam 2013 dated zip/exe HTTP Response - potential malware download"; flow:to_client,established; content:"-2013.zip|0D 0A|"; fast_pattern:only; content:"-2013.zip|0D 0A|"; http_header; content:"-"; within:1; distance:-14; http_header; file_data; content:"-2013.exe"; content:"-"; within:1; distance:-14; metadata:impact_flag red, policy balanced-ips drop, policy max-detect-ips drop, policy security-ips drop, ruleset community, service http; reference:url,www.virustotal.com/en/file/2eff3ee6ac7f5bf85e4ebcbe51974d0708cef666581ef1385c628233614b22c0/analysis/; classtype:trojan-activity; sid:26470; rev:2;)" from file /usr/local/etc/suricata/suricata_41945_igb1/rules/suricata.rules at line 162
Aug 12 18:36:16	kernel		igb1: link state changed to DOWN
Aug 12 18:34:32	shutdown	18862	power-down by root:
Aug 12 18:13:02	ppp	19091	[wan_link0] LCP: Down event
Aug 12 18:13:02	ppp	19091	[wan_link0] Link: DOWN event

[stephenw10]

That seems more likely to be a symptom rather than a cause. I assume you have Suricata running on LAN there and it's igb1? If it's running in in-line mode that will cause the re-link on igb1 when Suricata reloads. Suricata will be reloaded when the WAN reconnects. It still looks like the WAN disconnecting is the first thing that happens.