Unified Log Growing Infinitely (24 gigabytes and counting)

[planedrop]

@planedrop As an update, I did end up deleting the file and it cleared the full 24 gigabytes like expected.

But I'm still curious as to how this log got so big in the first place, is this a new bug maybe?

My log on my other firewall was 500k lines long, however my cron is daily on that firewall so it's possible it had just grown that much over the 20k allowed. I will continue to monitor things.

[planedrop]

Another update here, this is still happening, the Unified log is not being cleared upon cron for this specific firewall. Any ideas? I'll do some more digging but still seems odd, this is a pretty fresh pfB install too.

[jrey]

@planedrop said in Unified Log Growing Infinitely (24 gigabytes and counting):

pretty fresh pfB install

define "pretty fresh". what version ?

what do you see running these:

ls -l /var/log/pfblockerng/unified.log

wc -l /var/log/pfblockerng/unified.log

any errors messages in either error.log or pfblockerng.log ?

[planedrop]

@jrey Latest version, what I meant by fresh was that I reinstalled it recently to solve the HA sync issues it had (which required a reinstall even after the patch was issued). So 3.2.0_7

ls -l is giving me -rw-r--r-- 1 unbound unbound 287045076 (I cleared the log as I mentioned so it's not as big as it was, still much larger than it should be).

wc -l: 1672128 (when it was 24G it was nearly 300 million lines)

No errors in either of those logs that would pertain to this issue.

I do have other pfSense installs running this version and they aren't having the issue, so it's clearly something specific with my setup on this unit.

Appreciate the help here! For now I can just hand clear it every few weeks.

[jrey]

@planedrop

and the cron job is running?

What schedule ?

[planedrop]

@jrey it is running, and every hour on the hour is the current schedule. It's working fine for all other logs as well which is a bit odd, it's only the unified log that isn't being cleaned up on cron.

I also changed from 20k to 10k and saved down to see if that would help, but the log keeps growing.

[jrey]

@planedrop

Strange that others appear to be trimming as expected.

let's check a couple of things

ls -l /usr/bin/tai*

you should see 2 files (are they the same ?) Have seen cases where they are not and strange things happen. The _pfb version is actually linked on install and various other times during the run. However if they are different the only way I've found to correct the issue (is by uninstalling pfblocker, and reinstalling on the current os version) I doubt this is a problem in this case however as the cron job uses the base system tail command:

ssh in, if you run

/usr/bin/tail -n 10 /var/log/pfblockerng/unified.log

do you see the last 10 lines ?
do you get an error?
how long does this take ? (should be fast)

so basically what the code does is take the number of lines from the config (so default 20000)

the path/name of the file -- in this case unified.log

then it tails the 20000 lines into a temp file, tinkers with owner and group, and moves the tmp file over the current file

pretty much the only way it can bypass this is if cron doesn't run, or;
the file lines is set to no limit, or;
at some other high value and the file system is choking (taking too long) when performing the tail or mv (there is no specific time limit, but could be throwing an error) if you are now set at 10,000

it basically runs this

/usr/bin/tail -n 20000 (path)unified.log > (a temp filename)
chown (a temp filename) to unbound
chgrp (a temp filename) to unbound
/bin/mv -f (a temp filename) (path)unified.log

maybe want to just verify the settings have a sane value saved in the config

fgrep "log_max_unilog" /conf/config.xml

should return whatever value you have it set to (10000 now)
<log_max_unilog>20000</log_max_unilog>

strange it is only the one file. (because they all use the same code adjusted for the path/file name (depending on the name) dnslog, dnsreply and uni are the same code, the other logs are the same but slightly different)

Makes me wonder if one of the other files is experiencing an error that is stopping the loop from getting to the uni file (I'd have to check, but as I recall that is the last file processed in the loop)

what files do you have - here

ls -l /var/log/pfblockerng

ssh in, run this line by line

cd /var/log/pfblockerng
ls -l   (note: size of unified.log, showing only that line here)
 -rw-------  1 unbound unbound 2086537 Jan  6 09:32 unified.log
/usr/bin/tail -n 10000 unified.log > /tmp/mytest.log
chown unbound /tmp/mytest.log
chgrp unbound /tmp/mytest.log
/bin/mv -f /tmp/mytest.log unified.log
ls -l  (note: size of unified.log, showing only that line here)
-rw-r--r--  1 unbound unbound   10350 Jan  6 09:49 unified.log

Certainly trimmed it. (note: in my test I used -n 100 so the reduction was really obvious, but I'm showing the command above as 10000 as that is your current setting)

I've verified that it is still logging from the 100 lines I trimmed it to by running a browser
then in the pfblockerng log viewer confirmed,
File successfully loaded: Total Lines: 123

Edit: the other option is that the link of the file between /var/unbound/var/log/pfblockerng/unified.log and /var/log/pfblockerng/unified.log is broken/breaking
you could check that by (ls -l ) on each and seeing if they are the same size/time etc - they should be the same file.
if they are vastly different - you could try using the pfblockerng log ui select the unified.log and hit the trash can. that should delete the file completely and re-establish the correct link when it gets recreated.

ls -l /var/log/pfblockerng/unified.log; ls -l /var/unbound/var/log/pfblockerng/unified.log

should always be the same

[jrey]

@planedrop

for diagnostic purposes, I've add some logging on my test system, so the pfblockerng.log now contains entries indicating files where trimmed.

 UPDATE PROCESS ENDED [ 01/8/24 10:15:09 ]

Log trimmed(2): '/var/log/pfblockerng/pfblockerng.log' Lines: '6000'

Log trimmed(1): '/var/unbound/var/log/pfblockerng/dnsbl.log' Lines: '20000'

Log trimmed(2): '/var/log/pfblockerng/dnsbl_parsed_error.log' Lines: '20000'

Log trimmed(1): '/var/unbound/var/log/pfblockerng/dns_reply.log' Lines: '20000'

Log trimmed(1): '/var/unbound/var/log/pfblockerng/unified.log' Lines: '8000'

As I mentioned previously there are 2 paths through the code depending on the log file being trimmed. therefore trimmed(1) or trimmed(2) reflect the path used. this logging occurs after the file has been trimmed. and currently the Lines: is the setting it used. (i'll likely add what the final count is as well) but for now I can see it in the normal viewer after the process completes.

Interesting enough, while doing this I found a "bug". In the case of a live view (that is you are running cron manually from the update menu, it will run the trim function twice. (Really doesn't need to do that, IMHO, but doesn't hurt anything either)

[planedrop]

@jrey Thanks a ton for all the troubleshooting steps here, I will roll through as much of this as I can and get back, some of it I may skip just because this is a prod environment and I want to be super careful (and I can manually delete weekly for now).

But I did run fgrep "log_max_unilog" /conf/config.xml and got the 20k I expected (I changed it back to 20k the other day since it's default). So at least that's setup right in the config.

I suspect you are right that something before the Unified log is the issue so I'll dig there some.

[jrey]

@planedrop

So at least that's setup right in the config

yup that was a long shot that something was corrupt and not showing the correct value.

Sure thing.

@jrey said in Unified Log Growing Infinitely (24 gigabytes and counting):

ls -l /var/log/pfblockerng/unified.log; ls -l /var/unbound/var/log/pfblockerng/unified.log

you could try ^ and see if the files are exactly the same.
Actually so could I -- I'll just break it on my test box and see what happens.

I've actually went a little further on the logging of the logs being trimmed
T(Target) B(efore) A(After)
and at least now I have confirmation that logs are being trimmed.

Also discovered another annoyance (to me) -- there is no reason at all to go through the steps of making a temp, moving it back etc for a file that only has say 6 or 1 line in it. So I might change that some day as well.

 UPDATE PROCESS ENDED [ 01/8/24 14:31:00 ]

Log trimmed(2): '/var/log/pfblockerng/pfblockerng.log' Lines: T:10000 B:11110 A:10000

Log trimmed(2): '/var/log/pfblockerng/error.log' Lines: T:10000 B:6 A:6

Log trimmed(2): '/var/log/pfblockerng/ip_block.log' Lines: T:20000 B:20878 A:20000

Log trimmed(2): '/var/log/pfblockerng/ip_permit.log' Lines: T:20000 B:20031 A:20000

Log trimmed(1): '/var/unbound/var/log/pfblockerng/dnsbl.log' Lines: T:20000 B:20388 A:20000

Log trimmed(2): '/var/log/pfblockerng/dnsbl_parsed_error.log' Lines: T:10000 B:1 A:1

Log trimmed(1): '/var/unbound/var/log/pfblockerng/dns_reply.log' Lines: T:20000 B:24884 A:20000

Log trimmed(1): '/var/unbound/var/log/pfblockerng/unified.log' Lines: T:20000 B:26126 A:20000

(I liked the logging change enough to patch my production box - let that spin for a while)