Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    25.07 unbound - pfblocker - python - syslog

    Scheduled Pinned Locked Moved General pfSense Questions
    8 Posts 3 Posters 107 Views 3 Watching
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • J Offline
      jrey
      last edited by

      Since the update to 25.07 when unbound restarts -- pfb_unbound.py (python mode) and with syslog enabled -

      messages that are sent with the log_info function are duplicated (sent twice) to the syslog
      all messages are identified as application "unbound"

      the issue is that event rules that look for certain items are thinking for example that unbound has started twice, and that someone should be notified as one example..

      (there are many admin type messages that use the log_info function inside the pfp_unbound.py - and other related code - these messages are all duplicated

      you can see below filtered "start" message - before the update 1.22.0 (one message)
      after the update 1.23.0 (duplicates of every time stamp)

      from what I can gather - the problem may have been introduced in python 3.11 and default syslog handling from python - haven't found a reasonable solution.

      Screenshot 2025-08-07 at 3.00.22 PM.png

      Before Update (24.11)
      Screenshot 2025-08-07 at 3.20.20 PM.png

      After Update (25.07)
      Screenshot 2025-08-07 at 3.21.39 PM.png

      J 1 Reply Last reply Reply Quote 0
      • J Offline
        jrey @jrey
        last edited by

        Screenshot 2025-08-07 at 3.34.01 PM.png

        I should likely point out that filterdns messages for example are not duplicated, only those from unbound.

        1 Reply Last reply Reply Quote 0
        • stephenw10S Online
          stephenw10 Netgate Administrator
          last edited by

          Hmm, so you only see this when you have Python mode enabled? And presumably only for events triggered by pfBlocker using Python mode?

          J 2 Replies Last reply Reply Quote 0
          • J Offline
            jrey @stephenw10
            last edited by

            @stephenw10

            perhaps not just python mode --

            the "start of service" message for example is duplicated and is found in this binary file

            fgrep -r "start of service" ./*
            Binary file ./sbin/unbound matches
            

            the summaries that are duplicated are located in

             fgrep -r "lower(secs) upper" ./*
            Binary file ./lib/libunbound.so.8.1.31 matches
            Binary file ./lib/libunbound.a matches
            Binary file ./sbin/unbound-control matches
            Binary file ./sbin/unbound-checkconf matches
            Binary file ./sbin/unbound matches
            
            

            another line that is duplicated is found in

            fgrep -r "histogram of recursion processing times" ./*
            Binary file ./lib/libunbound.so.8.1.31 matches
            Binary file ./lib/libunbound.a matches
            Binary file ./sbin/unbound-control matches
            Binary file ./sbin/unbound-checkconf matches
            Binary file ./sbin/unbound matches
            

            also found that application name filterdns, also logged some duplicates,
            specifically the ones related to Adding Action
            seems to come from here:

            fgrep -r "Adding Action" ./*
            Binary file ./sbin/filterdns matches
            

            the only messages the I have source to at the moment is the messages that come from specifically log_info in pfb_unbound.py

            so messages like "init_standard script loaded" and "pfb_unbound.py script existing" are all generated with a call to log_info

            interesting enough none of these messages where duplicated before the upgrade.
            Also interesting to note that I modified pfb_unbound.py as an easy test and immediately prior to the line logging "pfb_unbound.py script loaded". I added 3 lines
            log_info('Bob')
            log_info('is your')
            log_info('uncle')

            I got 6 lines in the syslog file
            Bob
            Bob
            is your
            is your
            uncle
            uncle

            what got me thinking python only (and it still could be) is the duplication of the message pfb_unbound.py exiting / loading as the case may be.

            Several web articles indicate that "duplicate syslog messages in Python can occur when multiple handlers are attached to the same logger or when log messages propagate through multiple loggers"
            Not sure I have control of the binaries to find out what handlers are involved, but there is a further suggestion to ensure you only have one handler for each logger or adjust the propagate setting to prevent redundancy.

            other stuff areas I am sending to syslog from the netgate, don't seem to be doubling up.
            mostly unbound and the few that are coming from filterdns as discussed above.

            I haven't specifically tried without python mode at this point either

            GertjanG 1 Reply Last reply Reply Quote 0
            • GertjanG Offline
              Gertjan @jrey
              last edited by

              @jrey

              When you disable pfBlockerng and/or disable Pyhton mode, both in pfBlockerng and unbound, the unbound log lines keep on doubling ?
              If, it's unbound doping the double log.

              Nothing in the GUI "Custom options" (unbound) ?

              No "help me" PM's please. Use the forum, the community will thank you.
              Edit : and where are the logs ??

              1 Reply Last reply Reply Quote 0
              • J Offline
                jrey @stephenw10
                last edited by

                @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

                Screenshot 2025-08-08 at 6.10.57 AM.png

                Screenshot 2025-08-08 at 6.12.07 AM.png

                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.

                J 1 Reply Last reply Reply Quote 0
                • J Offline
                  jrey @jrey
                  last edited by

                  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

                  Screenshot 2025-08-08 at 8.18.49 AM.png

                  J 1 Reply Last reply Reply Quote 0
                  • J Offline
                    jrey @jrey
                    last edited by

                    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.

                    1 Reply Last reply Reply Quote 0
                    • First post
                      Last post
                    Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.