WAN periodically Rebooting

stephenw10

Not really. I've never tried turning up the logs to 11 like that before.

Edit: Appears to be the calculated bandwidth utilization:
https://sourceforge.net/p/mpd/svn/HEAD/tree/tags/RELEASE_5_9/src/bund.c#l1620

Not sure how applicable that is to PPPoE. Clearly it isn't actually pushing > 2000% of the available upload!

diyhouse

@stephenw10 Well I got to 9 days,.. and a bit,.. and WAN has fallen over,...
Looks similar to before,.. but I will leave it for you to pass definitive comment on the details..
KR

pfsenselogfail27Aug.zip

stephenw10

Hmm, that's not the same. It looks like something local called the interface down:
(reversed)

Aug 27 20:14:57	ppp	67004	[wan_link0] Link: DOWN event
Aug 27 20:14:57	ppp	67004	[wan_link0] device: DOWN event
Aug 27 20:14:57	ppp	67004	[wan_link0] PPPoE: connection closed
Aug 27 20:14:57	ppp	67004	EVENT: Processing event EVENT_READ PppoeCtrlReadEvent()

Is that the full system log or just the ppp log? Anything else logged if it's the latter?

diyhouse

@stephenw10
Tried to access logs.. but they have now gone,.. compressed I suspect
But subsequently I have had another failure of the WAN around 2:25pm today
Have tried to apply a time filter as follows

Aug 28 14:2[1-8]

But this does not present anything to display, even when set to 17:2[1-8]
Also suspect php is struggling with the large GUI no. of lines,.. as it does seem to take a long time..

Have looked at the /etc/group file,.. and considering adding my user to the wheel group so I can at least copy and vi the log file... Yes I'm ok with vi..
then I can at least look further back at the compressed files...
Is this a BAD idea...?

stephenw10

Probably fine. Or just login as admin which should have root access to everything.

diyhouse

@stephenw10 durr,.. I assumed admin was a restricted account..

Hey now were cookin,.. so much easier as root
it seems on quick glance things started failing much sooner...
does this log file help,.. ??

logfail1400.7z

and BTW,,. I also have another one of these

PHP errors
PHP ERROR: Type: 1, File: /usr/local/www/widgets/widgets/suricata_alerts.widget.php, Line: 188, Message: Uncaught ValueError: date_create_from_format(): Argument #2 ($datetime) must not contain any null bytes in /usr/local/www/widgets/widgets/suricata_alerts.widget.php:188
Stack trace:
#0 /usr/local/www/widgets/widgets/suricata_alerts.widget.php(188): date_create_from_format('m/d/Y-H:i:s.u', '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...')
#1 /usr/local/www/widgets/widgets/suricata_alerts.widget.php(78): suricata_widget_get_alerts()
#2 {main}
thrown @ 2024-08-20 13:52:51

stephenw10

Not seeing any issues in that log. It only covers 30s though. You can see it receiving and sending LCP echos.

diyhouse

@stephenw10
Sorry,.. I thought the stuff at the start was the initial falling over of the WAN

This certainly has the WAN falling over and restarting

logfile1425.7z

stephenw10

Right. Same as before. It processes the timer events every second. But at 14:23:21 it sees a new event:

Aug 28 14:23:21 pfSense ppp[67004]: EVENT: Processing event EVENT_READ PppoeCtrlReadEvent()
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] device: DOWN event
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] Link: DOWN event
Aug 28 14:23:21 pfSense ppp[67004]: EVENT: Starting timer "PhysOpen" LinkReopenTimeout() for 3000 ms at link.c:313
Aug 28 14:23:21 pfSense ppp[67004]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 28 14:23:21 pfSense ppp[67004]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] LCP: Down event
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] LCP: state change Opened --> Starting
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] LCP: phase shift NETWORK --> DEAD
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] Link: Leave bundle "wan"
...

Something appears to be actively closing the connection. But I have no idea what that might be.

I don't suppose you have ever set dial-on-demand or an idle timeout on that ppp config? Not that it appeared to be idle before that happened.

diyhouse

@stephenw10
Steve,.. vi'd a copy of the ppp.log file.. (950k lines ) and did a search on

LinkReopenTimeout

and 'word-count' to my dismay I have found 27 occurrences in the last couple of days...

where would I set,..

idle timeout on that ppp config

Not that I recall ever setting one,.. as it would not have made sense to me,.. I would have selected a continuous connection,.. power usage is / was minimal...
But,.. where would I set one if required?

Just a thought,.. could this be temperature related,.. it is approx, 30C in my loft currently..

Gertjan

@diyhouse said in WAN periodically Rebooting:

But,.. where would I set one if required?

Under Advanced Option :

diyhouse

@Gertjan Thanks for the hint.. found it..
I can confirm all options under advanced are 'not ticked'
However, . 'configure NULL service' is enabled in the 'ppp config', and the associated field is blank,. if that means anything??
and periodic reset is disabled, and link type is PPPoE..

And I now have another one of these crash logs

Crash report begins.  Anonymous machine information:

amd64
14.0-CURRENT
FreeBSD 14.0-CURRENT amd64 1400094 #1 RELENG_2_7_2-n255948-8d2b56da39c: Wed Dec  6 20:45:47 UTC 2023     root@freebsd:/var/jenkins/workspace/pfSense-CE-snapshots-2_7_2-main/obj/amd64/StdASW5b/var/jenkins/workspace/pfSense-CE-snapshots-2_7_2-main/sources/F

Crash report details:

PHP Errors:
[29-Aug-2024 16:18:41 Europe/London] PHP Fatal error:  Uncaught ValueError: date_create_from_format(): Argument #2 ($datetime) must not contain any null bytes in /usr/local/www/widgets/widgets/suricata_alerts.widget.php:188
Stack trace:
#0 /usr/local/www/widgets/widgets/suricata_alerts.widget.php(188): date_create_from_format('m/d/Y-H:i:s.u', '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...')
#1 /usr/local/www/widgets/widgets/suricata_alerts.widget.php(78): suricata_widget_get_alerts()
#2 {main}
  thrown in /usr/local/www/widgets/widgets/suricata_alerts.widget.php on line 188



No FreeBSD crash data found.

stephenw10

Mmm, those PHP errors are odd. However it's only in the Suricata widget. It's not going to affect the PPPoE connection.

Do you also see 27 (or the same number) when searching for PppoeCtrlReadEvent?

diyhouse

@stephenw10
Hi Stephen,.. doing a

grep -o 'PppoeCtrlReadEvent' ppp.log | wc -l

I get 54 occurrences... humm twice the number of LinkReopenTimeout..

stephenw10

Hmm, OK yup that actually appears a bunch of times during the reconnect

PPPoE: connection closed only appears once per disconnect though.

diyhouse

@stephenw10
....

grep -o 'connection closed' ppp.log | wc -l

Only occurs 6 times...

stephenw10

Ok seems more reasonable. Over what period?

I still don't expect to see it at all though.

diyhouse

@diyhouse
You mean you dont want all 950K lines... :-)
but will this do?

../log2: grep 'connection closed' ppp.log
Aug 28 14:23:21 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed
Aug 29 08:13:28 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed
Aug 29 09:28:46 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed
Aug 29 10:53:47 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed
Aug 29 11:21:08 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed
Aug 29 15:49:07 pfSense ppp[67004]: [wan_link0] PPPoE: connection closed

stephenw10

Close to 24hrs. Ouch!

Hmm, it's got to be coming from upstream somehow. Anything pfSense was doing would be logged. I'm surprised mpd5 doesn't log more though with that level of logging though.

If you can swap out some other router that would be a good test. If some other PPPoE client keeps the link up with the same modem that would seem prove it is pfSense.

diyhouse

@stephenw10
Thanks for the feedback,.. I was wondering if this might be a next step,..

The only thing I can do 'quickly' is to swap to a BT Smart Hub 2.
I only ever took the hub as a backup incase pfSense fell down a black hole...
So maybe now I need to get it out of its box, and config it up...
Leave it with me,.. I'll keep you posted...