sendto: 65 with UK ISP and PFsense

[F022Y]

Good Evening,

I'm running PFsense 2.5.2-RELEASE as a VM on a home lab server (HP Z620 Workstation with ESXI 6.7 u2).

For a while now my connection would randomly drop and I couldn't understand it. After a while i have documented things and i come here in the hopes someone could advise.

I have a VDSL service here in the UK (ISP = Cloudscape Connect), this feeds into a Vigor166 (was a vigor130 but i replaced it for this fault), this in turns feeds a WAN interface on the server machine with a LAN interface going off to PC, Laptops etc.

It appears almost like clockwork at 19:00 every 9 or so days the WAN interface goes down

I can still access the modem on it's IP so that link works and it in turn shows a sync'd connection

In the gateways log I get sendto error: 65

The only way i have found to get internet flowing on the LAN is to reboot the draytek.

I have asked this on the spicework forums and they were really helpful. My ISP seems to be saying they are fine so must be PFsense so come straight to you guys incase i have missed anything.

[stephenw10]

Send to error 65 implies there is no route to the gateway.
Though the fact it shows 'dynamic' there and not the actual gateway IP implies the PPP session has gone down, is that the case? Does it show down in Status > Interfaces?

You can still reach the modem interface so it doesn't appear to be a problem with the link there.
That also means you could run a packet capture on that interface and see the PPPoE traffic, if there is any.

First thing to do though is check the PPP logs to see what happened when it failed.

Steve

[F022Y]

@stephenw10 Thanks for the reply.

And the logs at the time of it going down.

[stephenw10]

Those are the logs after it disconnected showing it trying to reconnect.... and failing.

Really the logs covering when it actually failed would be be better. It does look like it's at least receiving something though.

Steve

[F022Y]

@stephenw10 I shall have to wait for it to fail again as the logs doesn't show anything before then.

I shall keep you updated

[F022Y]

So it actually went again but before just rebooting the draytek modem I tried a few things.

In ESXI i disconnected and reconnected the WAN virtual NIC - no difference
Rebooted PFsense VM - No difference

Here are the logs and what i saw.

As per before i reboot the modem and the link comes back.

[stephenw10]

What I expect to see there is either something like 'LCP echo timeout' or something from the servers side closing the connection. Unfortunately those would have been imediatelt preceding those logs if there were there.

[F022Y]

@stephenw10 Sorry nothing like that

[stephenw10]

Hmm, that implies it was closed deliberately for some reason. What do the system logs show at that time?

[F022Y]

@stephenw10 Status > System Logs > System > General doesn't show anything at that time.

I had snort installed but in monitor mode (no action) as a step i've removed it as it wasn't doing anything. I do have PfBlocker installed too if that has any baring.

[stephenw10]

The system log would at least show the WAN going down at that point, the gateway monitoring failing etc. There must be something shown?

[F022Y]

@stephenw10 So under Gateways i have this at time of fail.

From PPP

None of the other logs show anything at that time.

[stephenw10]

Nothing in the main system log? I expect to at least some duplicated entries there.

[F022Y]

@stephenw10 Where should I be looking in case im being stupid?

[stephenw10]

In the main system logs in Status > System Logs > System Tab you wiulkd usually see most of the ppp entries as well as gateway entries and, importantly, other things that may have triggered the connection to close.
"connection closed" is not normally the first log entry like that. If it was caused by something like the parent interface loosing link, that's where it would appear.
Trying to find an example but my own PPPoE has been up so long it's scrolled out of the logs.

Steve

[F022Y]

@stephenw10 In which case thats the logs i've given just dies off. Could it be the Vigor166 then? I have it in modem/bridge mode

[stephenw10]

This is what it looks like if the parent NIC loses link for example:

Jul 21 22:42:05 	kernel 		e6000sw0port3: link state changed to DOWN
Jul 21 22:42:05 	check_reload_status 	453 	Linkup starting $e6000sw0port3
Jul 21 22:42:06 	check_reload_status 	453 	Reloading filter
Jul 21 22:42:19 	rc.gateway_alarm 	99048 	>>> Gateway alarm: LAN3_PPPOE (Addr:10.0.10.254 Alarm:1 RTT:.855ms RTTsd:.123ms Loss:22%)
Jul 21 22:42:19 	check_reload_status 	453 	updating dyndns LAN3_PPPOE
Jul 21 22:42:19 	check_reload_status 	453 	Restarting ipsec tunnels
Jul 21 22:42:19 	check_reload_status 	453 	Restarting OpenVPN tunnels/interfaces
Jul 21 22:42:19 	check_reload_status 	453 	Reloading filter
Jul 21 22:42:21 	php-fpm 	63657 	/rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. ''
Jul 21 22:42:22 	php-fpm 	63657 	/rc.openvpn: Static Routes: Gateway IP could not be found for 192.168.140.0/24
Jul 21 22:42:22 	php-fpm 	63657 	/rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use LAN3_PPPOE.
Jul 21 22:42:25 	ppp 	72767 	[opt3_link0] LCP: no reply to 1 echo request(s)
Jul 21 22:42:35 	php-fpm 	25413 	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jul 21 22:42:35 	check_reload_status 	453 	Reloading filter
Jul 21 22:42:35 	ppp 	72767 	[opt3_link0] LCP: no reply to 2 echo request(s)
Jul 21 22:42:45 	ppp 	72767 	[opt3_link0] LCP: no reply to 3 echo request(s)
Jul 21 22:42:55 	ppp 	72767 	[opt3_link0] LCP: no reply to 4 echo request(s)
Jul 21 22:43:05 	ppp 	72767 	[opt3_link0] LCP: no reply to 5 echo request(s)
Jul 21 22:43:05 	ppp 	72767 	[opt3_link0] LCP: peer not responding to echo requests
Jul 21 22:43:05 	ppp 	72767 	[opt3_link0] LCP: state change Opened --> Stopping
Jul 21 22:43:05 	ppp 	72767 	[opt3_link0] Link: Leave bundle "opt3"
Jul 21 22:43:05 	ppp 	72767 	[opt3] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jul 21 22:43:05 	ppp 	72767 	[opt3] IPCP: Close event
Jul 21 22:43:05 	ppp 	72767 	[opt3] IPCP: state change Opened --> Closing
Jul 21 22:43:05 	ppp 	72767 	[opt3] IPCP: SendTerminateReq #4
Jul 21 22:43:05 	ppp 	72767 	[opt3] IPCP: LayerDown
Jul 21 22:43:06 	check_reload_status 	453 	Rewriting resolv.conf
Jul 21 22:43:06 	ppp 	72767 	[opt3] IFACE: Down event
Jul 21 22:43:06 	ppp 	72767 	[opt3] IFACE: Rename interface pppoe0 to pppoe0
Jul 21 22:43:06 	ppp 	72767 	[opt3] IPCP: Down event
Jul 21 22:43:06 	ppp 	72767 	[opt3] IPCP: LayerFinish
Jul 21 22:43:06 	ppp 	72767 	[opt3] Bundle: No NCPs left. Closing links...
Jul 21 22:43:06 	ppp 	72767 	[opt3] IPCP: state change Closing --> Initial
Jul 21 22:43:06 	ppp 	72767 	[opt3_link0] LCP: SendTerminateReq #3
Jul 21 22:43:06 	ppp 	72767 	[opt3_link0] LCP: LayerDown
Jul 21 22:43:09 	ppp 	72767 	[opt3_link0] LCP: SendTerminateReq #4
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] LCP: state change Stopping --> Stopped
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] LCP: LayerFinish
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] PPPoE: connection closed
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] Link: DOWN event
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] LCP: Down event
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] LCP: state change Stopped --> Starting
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] LCP: LayerStart
Jul 21 22:43:11 	ppp 	72767 	[opt3_link0] Link: reconnection attempt 1 in 3 seconds 

And this if you just disconnect the PPPoE manually:

Jul 21 22:53:06 	ppp 	72767 	caught fatal signal TERM
Jul 21 22:53:06 	ppp 	72767 	[opt3] IFACE: Close event
Jul 21 22:53:06 	ppp 	72767 	[opt3] IPCP: Close event
Jul 21 22:53:06 	ppp 	72767 	[opt3] IPCP: state change Opened --> Closing
Jul 21 22:53:06 	ppp 	72767 	[opt3] IPCP: SendTerminateReq #8
Jul 21 22:53:06 	ppp 	72767 	[opt3] IPCP: LayerDown
Jul 21 22:53:07 	check_reload_status 	453 	Rewriting resolv.conf
Jul 21 22:53:07 	ppp 	72767 	[opt3] IFACE: Down event
Jul 21 22:53:07 	ppp 	72767 	[opt3] IFACE: Rename interface pppoe0 to pppoe0
Jul 21 22:53:07 	ppp 	72767 	[opt3] IPCP: rec'd Terminate Ack #2 (Closing)
Jul 21 22:53:07 	ppp 	72767 	[opt3] IPCP: state change Closing --> Closed
Jul 21 22:53:07 	ppp 	72767 	[opt3] IPCP: LayerFinish
Jul 21 22:53:07 	ppp 	72767 	[opt3] Bundle: No NCPs left. Closing links...
Jul 21 22:53:07 	ppp 	72767 	[opt3] Bundle: closing link "opt3_link0"...
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] Link: CLOSE event
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: Close event
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: state change Opened --> Closing
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] Link: Leave bundle "opt3"
Jul 21 22:53:07 	ppp 	72767 	[opt3] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jul 21 22:53:07 	ppp 	72767 	[opt3] IPCP: Close event
Jul 21 22:53:07 	ppp 	72767 	[opt3] IPCP: Down event
Jul 21 22:53:07 	ppp 	72767 	[opt3] IPCP: state change Closed --> Initial
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: SendTerminateReq #94
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: LayerDown
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: rec'd Terminate Ack #3 (Closing)
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: state change Closing --> Closed
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: LayerFinish
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] Link: DOWN event
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: Down event
Jul 21 22:53:07 	ppp 	72767 	[opt3_link0] LCP: state change Closed --> Initial
Jul 21 22:53:09 	ppp 	72767 	[opt3] Bundle: Shutdown
Jul 21 22:53:09 	ppp 	72767 	[opt3_link0] Link: Shutdown
Jul 21 22:53:09 	ppp 	72767 	process 72767 terminated

Your logs do not match either.

[F022Y]

@stephenw10 Is there an export function of all the logs? Just thinking when it next happens i just export everything.

[stephenw10]

You can just download the full log files. The main system log for example is:
/var/log/system.log

You can download that from Diag > Command Prompt.

Steve

[F022Y]

@stephenw10 Thank you for the help, i've cleared the logs and will wait to see if it dies.