25.07 unbound - pfblocker - python - syslog

[jrey]

@stephenw10

Seems more interesting this morning.

Early morning Friday 1:30am our graylog server shuts itself down, does some maintenance and starts back up (usually takes < 5 minutes). - not a issue previously - system would come back up and logging would resume as normal.

Got going this morning with this

nothing from the netgate logged since and until I restarted both syslog and unbound

a down syslog server should not be stopping the service - that seem wrong.

makes me think syslog itself is having issues (or perhaps this as a result of the handlers not playing nice in unbound.

Note: note other systems that log to the same graylog server, worked as expected. That is simply resumed/continued spewing as soon as the system came back online.

[jrey]

Observation - from a netgate reboot

the messages identified as kernel are not duplicated.

there are then 2 messages from sshguard (looks like this could be a duplicate)
next message is from check_reload_status - this is NOT duplicated.
next messages are from filterdns "Adding Action" these are all duplicated
then there is a message from php-frm (rc.start ... ) NOT Duplicated
then a couple of messages from apcupsd - NOT Duplicated
then a couple more from check_reload_status - NOT Duplicated
one from root. - Boot up Complete - NOT duplicated
the more from filterdns (more perhaps still continuing) "Adding Action" ALL duplicated
then a single kernel "done" message
then two from login (seem like a duplicate)
then two from php-frm (Successful Login ... not sure have to track it down in the local log)
then one from ntpd (NOT duplicated)
then one from syslogd (NOT duplicated)
then unbound messages start (All messages are Duplicated)

In the case of filterdns and unbound the local log file only has a single entry - that's likely true of the others that are duplicated (but I have not checked each case) --

After the netgate was running running - I shutdown the remote syslog server as a test)
the syslogd service stopped again on the netgate.

this is what I am sending to syslog

[jrey]

Restarted ntpd (because why not) - all logged no duplicates in syslog,

Seems the only thing actually duplicating messages might be filterdns and unbound.
none of the duplicated messages in syslog appear in the local source log file.

to answer @Gertjan it seems less likely to be related specifically to python mode and/or pfblocker specifically because well. filterdns comes up first according to the sequence noted above and filterdns messages are duplicated right from the start, unbound enters the startup logging sequence later and they are duplicated with the first message.

syslog service abruptly stopping if the logging server goes away is also a big problem, it shouldn't do that.

my next test, when I have time, will be to uncheck the logging for unbound / filterdns - then restart the syslog server to see if doing that still brings the syslog service on the netgate to a stop.

[stephenw10]

Hmm, are the logs duplicated both locally and in the remote syslog server?

It 'feels' like maybe Unbound is sending logs independently as well as the local syslogd service. Though I've never seen that before. Or have any idea how it could happen.

I agree the remote syslog server temporarily going down should not stop the service sending. Can you see open states for it when it fails? Is it in a local subnet? In the ARP table?

[Gertjan]

@jrey

What happens when you temporary select :

?

[jrey]

said in 25.07 unbound - pfblocker - python - syslog:

In the case of filterdns and unbound the local log file only has a single entry -

They are only duplicated in the syslog not the local file.

@stephenw10 said in 25.07 unbound - pfblocker - python - syslog:

Or have any idea how it could happen.

the only thing, I can think of is that (supported by many web articles) comes back to a problem with the handlers

said in 25.07 unbound - pfblocker - python - syslog:

"duplicate syslog messages in Python can occur when multiple handlers are attached to the same logger or when log messages propagate through multiple loggers"

I would imagine that it is perhaps not only a python issue, but rather a problem with the way these two application (filterdns and unbound) are initializing their log handlers ?.

[jrey]

@Gertjan

Not sure why that would make any difference since the only ones selected are for the services running on the netgate.

the unselected ones have never been selected, no point. these are not used
Netgate Nexus - not used
DHCP (is not running at all on the netgate, never has, DHCP is handled on a different server)
PPP - not used
Captive Portal - Not used.
Routing Daemon Events - Not used
Wireless - not used

in fact the associated local files (for example dhcp.log, wireless.log, ppp.log etc and the others are all zero bytes on disk).

I can add this to the list of things to try however, Thanks

[jrey]

@stephenw10

Step 1: uncheck logging for DNS Events (nothing bad happened)
Step 2: stop the syslog server machine (nothing bad happened)
Step 3: force a restart of ntpd because this would generate logging to the now offline server. (nothing bad happened (syslogd did not stop running)
Step 4: start syslog server machine
Step 5: force another restart of ntpd (nothing logged to syslog) it says the syslog is running (there is a entry in the arp table, and states exist)
Step 6: restart syslogd - logging starts (maybe if I had waited longer before doing this restart it may have eventually stopped the service)
Step 7: restart ntpd - now logs the startup on the syslog (no duplicates here never have been)
Step 8: recheck the logging for DNS events (nothing changes)
Step 9: restart unbound (unbound and startup messages as noted above all duplicated)

It seems it is a "new feature" in 25.07 for sure.

Guess I have to spin up a version 2.8 virtual and see if I can recreate it there.
It is pretty basic logging -
My test 2.7 version still works as expected.

I guess I could also reboot back to the boot environment - but it was working fine there, so likely a waste of time. All I have to do is look back to the syslog history and I can see the messages are not duplicated before the update.

[stephenw10]

@jrey said in 25.07 unbound - pfblocker - python - syslog:

Step 5: force another restart of ntpd (nothing logged to syslog) it says the syslog is running (there is a entry in the arp table, and states exist)

It still logs locally though? Just not sending to the remote syslog server?

[jrey]

said in 25.07 unbound - pfblocker - python - syslog:

Everything ... I can add this to the list of things to try however, Thanks

@Gertjan @stephenw10

WTH - (I may have used stronger language here)

but selecting "Everything" and restarting syslogd and unbound seems to have stopped the duplicates.

So now the question is why ? The previously unselected items on the list are not even running.. (their associated log files are still all zero bytes. ). Must be in the syslog handler init (order things start maybe?) or top level when everything is selected vs individual items and you end up with a duplicate handler ?

and since that seemed to work, I've shut the syslog server down yet again to see when it comes back up is the netgate resumes without manual intervention on syslog and unbound.
the answer to that is apparently no - because the syslogd service died

required a restart of both the syslogd and unbound services to make things "normal" again

[stephenw10]

Hmm, WTH indeed!

Good clue though.

Seems like that's probably independent of syslogd dying locally.

[jrey]

@stephenw10 said in 25.07 unbound - pfblocker - python - syslog:

It still logs locally though? Just not sending to the remote syslog server?

yes - still locally - local logging hasn't changed or stopped

yes not sending to syslog (ie didn't recover after the syslog server came back up)

after switching to "everything". the duplicates have stopped, but syslogd just outright died again with I took the syslog server down

I restarted both syslogd and unbound still no duplicates at this point.

something is still not playing nice together. syslog itself or syslog/unbound

and looking at the live stream of data coming into the syslog server
I suddenly remembered why I have turned off "everything" and selected the individual services I had

I'm now seeing a /usr/sbin/cron message for newsyslog (checking every minute if it need to roll local files over ) and the application nginx is sending it's log file when I navigate the any web page.

So "everything" likely includes some things that are not included/available in individual selection.

changing anything on the selection list and hitting save, requires a manual restart of unbound looking at the live stream on the syslog server other events are still coming through

I temporarily changed the setting from Everything back to my list so I could grab the appropriate pfSense.conf file that is generated for syslog.d
and then changed it back to Everything -

I was looking for a specific reference to either cron and/or nginx logging - leaving the system on the dashboard is currently flooding the syslog stream with the everything being done. But hey no duplicates.

Still looking for clues as to why it might hang/die if the remote server goes off line. And if I could specifically stop the nginx messaging that would be cool,

pondering which is worse actually --- duplicate messages from filterdns/unbound or 100's of nginx messages / minute I will simply never use. sitting on the dashboard = bad, sitting on any static page = no messages
the /usr/sbin/cron (messages) are 1 per minute minumum more if other cron jobs run. /usr/sbin/newsyslog every minute seems a bit aggressive to determine if log files need to roll over.

the hanging/dead syslogd is still going to be a problem. can likely "fix" that temporarily with a monitor on the service -

in hind sight I now say to myself you had to push upgrade didn't you. The system was working perfectly with 255+ days of uptime and zero issues. The other side says where is the fun in that.

[jrey]

@stephenw10

For what it is worth

After sitting turned off for almost 260 days, I started and upgraded a virtual from 2.7.x install to 2.8

the same "duplicate" syslog problem exists there.
when I had the same individual syslog options checked there as I did on my production box) which is the way the virtual was last turned off.

duplicates from unbound

changed setting to "everything".
Duplicates gone

and "bonus" cron and nginx messages

[postilion]

@jrey
Yesterday we upgraded three recently installed Netgate 8300-Max firewalls from 24.11 to 25.07. One of the problems we noticed was that our syslogd would die shortly after starting. Last messages in /var/log/system.log were always "syslogd: sendto: Connection refused"

A fourth firewall, which was upgraded to 25.07 prior to deployment did not exhibit this problem.

After reading your experiences I went to the syslog config page and found that an old Graylog server was still referred to in the three problem installs. I removed those entries, and syslogd has been running just fine ever since.

So I can confirm that an unreachable target seems to be enough to kill the syslogd process. This is a bug.
-nic

[stephenw10]

Hmm, just to be clear is the remote syslog server here in a subnet local to pfSense?

I'm failing to replicate it so far with a missing server. I just get 'host is down' log spam.

[postilion]

@stephenw10
No, in this case the remote syslog receiver was remote, on a different subnet. And for completeness, the destination subnet is not a connected network from the firewall perspective.
-nic

[jrey]

@postilion

Interesting - by syslog config page you mean system logs settings ?

So I have two syslog servers so there are two IP addresses listed there.

Netgate -> syslog1
Netgate -> syslog2

Here is a different observation -
syslog1 shuts itself down and does some automated system maintenance twice a week ( the downtime usually lasts just a few minutes) and it comes back up. (other systems in the network have no issue logging to it before it goes down and/or after it auto restarts.

as syslog2 is running throughout -- it never misses a record (including from the netgate)

front the netgate everything that would normally go to both syslogs continues to write to the local files and syslog2 while syslog1 is offline. when it syslog1 is back online the netgate does not resume sending to syslog1.

In my case restarting syslogd alone does not resolve the problem, restarting unbound alone does not resolve the problem
But if I restart syslogd and unbound in that order (from the services page) - it resumes

I think that when syslog1 goes down, syslogd and unbound are not playing well together, one of them or in combination are not restarting the connection when it fails and resumes.

because syslog1 maintenance happens in the wee hours of the morning
I wrote a little script to monitor the syslog1 going down and then taking the appropriate action when it comes back up (because the syslogd and unbound don't actually stop they are both still running throughout) service watchdog for example won't see a problem.

some output from a test run of the script. (192.168.0.35 is my syslog1 server)

++ date
+ echo 'Mon 11 Aug 2025 08:43:30 EDT: 192.168.0.35 is offline.'
Mon 11 Aug 2025 08:43:30 EDT: 192.168.0.35 is offline.
+ ip_status=1
+ sleep 300
+ true
+ ping -c 1 192.168.0.35
+ '[' 1 -eq 1 ']'
++ date
+ echo 'Mon 11 Aug 2025 08:48:30 EDT: 192.168.0.35 is back online. Restarting syslogd and unbound...'
Mon 11 Aug 2025 08:48:30 EDT: 192.168.0.35 is back online. Restarting syslogd and unbound...

The network and various system are very stable -- 260+ days on 24.11 never failed. 0 issues. Data tells the story. (the change is colour is based on unbound pid) only ever changed as a result of pfblocker restarting unbound when needed (usually every couple of days)

above the graph I have drawn some lines, from left to right
the first 2 I was upgrading the syslog system the small gap represents the reboots of that system (the colour in the graph didn't change so the pid didn't change).
the third small gap, (aug 4) - again no change in pid
the 4 line just after the Aug 6 marker is where I upgraded from 24.11 to 25.07
the horizontal line is where the whole doubling of data thing was happening. Lots of bouncing around trying various things. Within that horizontal the large empty block starting at the "8" in "Aug 8" 1:30am mark is where the first automated syslog1 maintenance happened. No data from 1:30am until I kicked the services in the morning.

Corrected the doubling up issue last vertical at the end of the horizontal, which is also just not right fix if you don't want "everything". (but for now the "Everything" setting stops that and the data level returns to "normal" and I've been playing

[jrey]

@stephenw10

for clarity in my case both of the syslog servers I referenced in my response to @postilion are both in the same subnet

[stephenw10]

Hmm, maybe I misread this then. What circumstances cause syslogd to stop in pfSense?

[postilion]

@stephenw10
In our case syslogd would stop shortly after boot. Restarting syslogd, it would stop again a short time later. I don't have exact timings, as I was dealing with other update-related issues at the time, and this was a lower priority.

After reading @jrey 's message, however, I went back into the syslog settings panel, removed the graylog server, since it's currently down, and saved. This caused syslogd to start again, and it's now been running smoothly for the past two hours.

Note: This is on three (3) separate 8300-Max units, all installed within the past month, and all updated from 24.11 to 25.07 yesterday (8/10/25).
-nic