WAN periodically Rebooting

[Gertjan]

@diyhouse said in WAN periodically Rebooting:

Although I had created at listing limit of 100000lines...

That a GUI setting.
100000 lines in a GUI is ... 'bad' as PHP is very low with 'thoudands' and things go downhill after hundreds of thousands. Until PHP breaks trying to show it.
Big log files are meant to be show 'on the command line'. Or use SSH+FTP = SFTP, which supports stuf like this in the blink of an eye.

@diyhouse said in WAN periodically Rebooting:

some more appro. units,.. eg meg bytes, or gig bytes,... pls
thankyou

Would be nice for the ones who are asking ... but never looked / found the log files.
The ones who 'know', don't bother, they go straight to the source, as things down there are the same dor the last several decades already ^^

Btw : huge log files are 'nice', because it gives you a big overview of what heppens.
But then pfSense has to rotate them, and that takes a lot of resource (CPU power etc) and not every pfSense has big drives, and endless write cycles, etc.
Running out of disk space is a known issue also.

[diyhouse]

@Gertjan Tx for the comments,..
I will drop the GUI max lines down though,...
BTW,.. Log files,.. where are they stored in the file structure?
this is my current file system

Filesystem                          Size    Used   Avail Capacity  Mounted on
zroot/ROOT/default                  100G    1.2G     99G     1%    /
devfs                               1.0K      0B    1.0K     0%    /dev
zroot/tmp                            99G    356K     99G     0%    /tmp
zroot/var                            99G    413M     99G     0%    /var
zroot                                99G     88K     99G     0%    /zroot
zroot/reservation                   110G     96K    110G     0%    /zroot/reservation
zroot/ROOT/default/var_cache_pkg     99G    177M     99G     0%    /var/cache/pkg
zroot/ROOT/default/var_db_pkg        99G    5.4M     99G     0%    /var/db/pkg
tmpfs                               4.0M    152K    3.9M     4%    /var/run

[stephenw10]

They are in /var/log. For the purposes of testing here I wouldn't worry about having larger log files but I would probably set them back when you're done.

[diyhouse]

@stephenw10
Just a quick up date,.. still waiting for a failure event,.. had been running for 15hrs+ then hit midnight Sunday forced WAN reset,.. 7.5hrs on the clock and counting,..
disk space still good,.. although I have used / lost 1gig of available storage..
But looking in /var/log I have this now as the big hitters on files,
I guess as folks have commented,. we'll see how much horsepower my cpu has to cope with the compression etc,.. when the file get rotated..

-rw-------  1 root wheel 68420964 Aug 18 07:42 system.log
-rw-------  1 root wheel 68386081 Aug 18 07:42 ppp.log
-rw-------  1 root wheel 10161552 Aug 18 07:42 filter.log
-rw-------  1 root wheel  4329357 Aug 18 07:42 nginx.log
-rw-------  1 root wheel  1226791 Aug 18 07:42 dhcpd.log
-rw-------  1 root wheel   511488 Sep  6  2020 relayd.log
-rw-r--r--  1 root wheel   135309 Sep  6  2020 bsdinstall_log
-rw-------  1 root wheel    99799 Aug 18 07:37 gateways.log
-rw-------  1 root wheel    66259 Aug 13 22:12 dhcpd.log.1.bz2

[diyhouse]

@diyhouse
PPP_Log Failure.zip
WAN has just fallen over @14:10
My the 'force' be with you,... ( hope this is the bits you need )
EDIT: replace txt file with compressed zip file

[diyhouse]

@diyhouse
Had to save file as attachment,.. as broke the 32K char. submission limit
Thanks...

[diyhouse]

@diyhouse
Just realised these statements entries are the indicators that things have failed, I think... IMHO,..

Aug 18 14:32:14	ppp	67004	[wan] OUT util: total 81% 10% 67% 109% 4% 39% 255%
Aug 18 14:32:14	ppp	67004	[wan] IN util: total 5511% 8% 8374% 0% 5% 7560% 17117%

So have gone back trough the logs pre 14:10...
PPP_PreFailog.zip
compressed Log file attached
As background,.. Netflix was in full HD stream,.. as well as streaming some YouTube,.. and there was an Alexa sound streaming going on as well...
And its just died again...
EDIT: changed file to compressed version

[diyhouse]

@diyhouse
PPP_FullFAILlog.zip

Hope this helps some more,.. 2nd event will full events before and after

[stephenw10]

Hmm, that first disconnect looks different. It logged an LCP timeout which is more like what I expect:

[wan_link0] LCP: no reply to 5 echo request(s)
Aug 18 14:10:15
ppp
67004
EVENT: Processing timer "FsmKeepAlive" FsmEchoTimeout()
Aug 18 14:10:15
ppp
67004

It then reconnects 9s later.

[wan_link0] PPPoE: connection successful
Aug 18 14:10:24

Same thing happened on that last disconnect:

Aug 18 15:02:13	ppp	67004	[wan_link0] LCP: no reply to 5 echo request(s)

So both those are a reaction to the upstream server failing to respond to the LCP echos.
However I would expect to see those logged with the default logging settings and we did not see that previously.

[diyhouse]

@stephenw10 Many Tx for the feedback Stephen,..
I have tried to do some more 'searching',.. for events,.. have tried 'vi ppp.log' in ssh window,.. but not enough privs.. and using the file edit function, causes a php crash,..
So all I can probably do for now is wait for some more events,. and pull the associated logs as and when,. unless you have any other suggestions..
Also thinking,.. I did notice the re-connection stuff happens a while after the actual WAN looses connectivity ( obviously.. ) ,.. could it be I did not go back far enough in the logs initially?
I have tried to go back to these logs,. but I guess they are archived now.. is there any way to pull these logs,.. USB stick and copy files,..
I can see this would blow holes in any security,.. so I'm guessing that's a no no...

[stephenw10]

You can copy off or download the compressed log files if they still exist. You have to be logged in to do that so there's no real security issue IMO.

I would have expected to see that LCP echo reply error in the logs we looked at earlier. That's usually pretty close in the logs. But I guess it's possible.

[diyhouse]

@stephenw10 Just looking at getting the log files off pfsense,.. and noticed log files are all the same date,.. so old logs have been cycled out,..
Only after the point when I increased log file size do I have events,...
Just waiting for the next log rotation,...

-rw-------  1 root wheel 161270661 Aug 19 08:39 ppp.log
-rw-------  1 root wheel      4599 Aug 17 13:06 ppp.log.0.bz2

[diyhouse]

@diyhouse :update---
Nearly 2.5days of continuous running since last WAN reboot..

But did get this crash log today..

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:
[20-Aug-2024 13:52:51 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.

Unrelated,.. ( I assume ) but just in case for info..
Tx

[stephenw10]

Hmm, yes that seems unrelated. Though odd, I've not seen that before. Is that the first time you've seen that.

[diyhouse]

@stephenw10
yes... (And now 2days 18hrs 44Mins...)
Edit 5pm 22nd Aug: Uptime: 4d 01:52:12...
Edit 5pm 23rd Aug: Uptime: 5d 02:32:21

and the log files sizes as follows,.. I would have hoped they would have been rotated by now... as they are getting quite large, even for a text file..

-rw-------  1 root wheel     67068 Aug 22 04:13 dhcpd.log.0.bz2
-rw-------  1 root wheel     69926 Aug 23 16:57 ntpd.log
-rw-------  1 root wheel    118511 Aug 23 00:24 gateways.log
-rw-r--r--  1 root wheel    135309 Sep  6  2020 bsdinstall_log
-rw-------  1 root wheel    511488 Sep  6  2020 relayd.log
-rw-------  1 root wheel   1184280 Aug 23 17:35 dhcpd.log
-rw-------  1 root wheel  33500421 Aug 23 17:36 nginx.log
-rw-------  1 root wheel  74443513 Aug 23 17:36 filter.log
-rw-------  1 root wheel 551582783 Aug 23 17:36 ppp.log
-rw-------  1 root wheel 551721292 Aug 23 17:36 system.log

[stephenw10]

Mmm, I would certainly expect that. The default log size is 512KB. Did you change it to something much larger?

Having said that perhaps Openreach finally realised there was a problem and fixed it. Whenever I've had issues it was always a failing line card upstream.

[diyhouse]

@stephenw10 said in WAN periodically Rebooting:

Did you change it to something much larger?

Yes,.. to 2000000000 bytes... like 2gig..
I have now dropped it a power of 10,.. to 200,000,000 bytes...

I to was wondering if BT had got wise to my troubles and changed something upstream of my modem...
But we shall see..

I will leave the high logging in place for now... ( lets see if I can get to 10days...) then I will revert back,.. and see what happens.

Funny,.. things may have changed since I contacted BT,.. for account and passwd,. maybe an issue was raised,.. and something changed,.. but who knows..
I cat 'top' in a shell.. and see it is busy compressing,..

-rw-------  1 root wheel     4599 Aug 17 13:06 ppp.log.1.bz2
-rw-------  1 root wheel   635473 Aug 23 20:46 ppp.log
-rw-------  1 root wheel 16623975 Aug 23 20:36 ppp.log.0.bz2

[diyhouse]

@diyhouse
One question I have,.. whilst in 'limbo'... the logs generated, have lots of the following;

Aug 25 09:22:30	ppp	67004	[wan] OUT util: total 29% 12% 61% 36% 6% 29% 27%
Aug 25 09:22:30	ppp	67004	[wan] IN util: total 625% 21% 2280% 1205% 108% 22% 111%

Are you able to spread any light on what the % values mean,...
Many tx
uptime currently running at 6d 18hrs

[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