pfBlockerNG Cron Resetting DNS Resolver Cache (Intermittent Bug)

RobbieTT · Sep 14, 2023, 9:48 AM

@BBcan177
Every few pfBlocker CRON events the process erases all unbound cached data and the DNS cache has to rebuild again from scratch.

I have my updates set to every 6 hours and the actual failure period can be as short as 18hrs with the maximum achieved being 78hrs. Typically the issue tends to strike at the 0015hrs update, more often than not.

Running pfSense+ 23.09 dev on Netgate 6100 - 23.09.a.20230907.0600
Unbound - 1.18.0
pfBlockerNG - 3.2.0_6
Python Mode - Enabled
Message cache - 50 MB limit
RRset cache - 100 MB limit

Typical System Log (from this morning):

Sep 12 00:15:00	php	86319	[pfBlockerNG] Starting cron process.
Sep 12 00:15:33	php	86319	[pfBlockerNG] No changes to Firewall rules, skipping Filter Reload

Resolver log (relevant entries, with my notes in brackets):

Sep 12 00:14:50 Router-8 unbound[89421]: [89421:2] info: (...Normal Traffic)
(pfBlockerNG Cron job starts)
Sep 12 00:15:00 Router-8 unbound[89421]: [89421:2] info: 127.0.0.1 feodotracker.abuse.ch. A IN
Sep 12 00:15:16 Router-8 unbound[89421]: [89421:3] info: 127.0.0.1 v.firebog.net. AAAA IN
(Unbound service stops and stats are dumped)
Sep 12 00:15:23 Router-8 unbound[89421]: [89421:0] info: service stopped (unbound 1.18.0).
Sep 12 00:15:23 Router-8 unbound[89421]: [89421:0] info: server stats for thread 0: 28429 queries, 26486 answers from cache, 1943 recursions, 4842 prefetch, 0 rejected by ip ratelimiting
Sep 12 00:15:23 Router-8 unbound[89421]: [89421:0] info: [pfBlockerNG]: pfb_unbound.py script exiting
(pfBlockerNG restarts)
Sep 12 00:15:24 Router-8 unbound[54354]: [54354:0] notice: init module 0: python
Sep 12 00:15:24 Router-8 unbound[54354]: [54354:0] info: [pfBlockerNG]: pfb_unbound.py script loaded
Sep 12 00:15:26 Router-8 unbound[54354]: [54354:0] info: [pfBlockerNG]: init_standard script loaded
Sep 12 00:15:26 Router-8 unbound[54354]: [54354:0] notice: init module 1: iterator
(Unbound service starts again)
Sep 12 00:15:26 Router-8 unbound[54354]: [54354:0] info: start of service (unbound 1.18.0).
Sep 12 00:15:26 Router-8 unbound[54354]: [54354:0] info: 127.0.0.1 feodotracker.abuse.ch. A IN (etc...)

My current settings:

When the bug strikes all the associated stats are reset, along with deletion of the rrset and message data. For example:

Yesterday

total.num.queries=146599
total.num.cachehits=135785
mem.cache.rrset=3234068
mem.cache.message=4894522
msg.cache.count=17691
rrset.cache.count=10637
time.elapsed=207514.685481

Today

total.num.queries=24908
total.num.cachehits=22353
mem.cache.rrset=486834
mem.cache.message=581783
msg.cache.count=2066
rrset.cache.count=1582
time.elapsed=29305.332317

There are no noted failures elsewhere in pfSense and the cache wipes are only associated with a pfBlocker CRON job. It seems to make no difference if an actual update is needed or not.

Anyone any idea why this is happening or how to prevent it?

️

fireodo · Sep 12, 2023, 11:33 AM

@RobbieTT

Hi, I have no answer to your question but you should include BBcan177 in your thread because he is the official maintainer of pfblockerNG and the one who can answer/investigate your issue.

Regards,
fireodo

RobbieTT · Sep 12, 2023, 11:37 AM

@fireodo - Thanks and I have edited my post to include @BBcan177.

️

fireodo · Sep 14, 2023, 9:26 AM

@RobbieTT said in pfBlockerNG Wiping Unbound Resolver DNS Cache (Intermittent Bug):

Thanks and I have edited my post to include @BBcan177.

RobbieTT · Sep 14, 2023, 9:26 AM

@BBcan177 @stephenw10

After exactly 48hrs since the last unexplained reset, pfBlocker triggered the reset of the unbound cache again.

Sequence

13 Sep 23 Snapshot @ 2120hrs:

total.num.queries=173260
total.num.cachehits=152006
total.num.cachemiss=21254
total.num.prefetch=27814
total.num.expired=23979
total.num.recursivereplies=21254
mem.cache.rrset=1766078		( 1.77 / 100 MB limit )
mem.cache.message=2691409	( 2.69 / 50 MB limit )
msg.cache.count=9722
rrset.cache.count=5917
infra.cache.count=4
time.elapsed=162297.471465	( 45hrs 05min 57s and continued to run until 48hrs 00min 00s elapsed )

Relevant logs @ 0015hrs:

Sep 14 00:15:00	php	5131	[pfBlockerNG] Starting cron process.

Sep 14 00:15:12 Router-8 unbound[54354]: [54354:0] info: service stopped (unbound 1.18.0).
Sep 14 00:15:12 Router-8 unbound[54354]: [54354:0] info: server stats for thread 0: 23113 queries, 20520 answers from cache, 2593 recursions, 4340 prefetch, 0 rejected by ip ratelimiting

Sep 14 00:15:12 Router-8 unbound[54354]: [54354:0] info: [pfBlockerNG]: pfb_unbound.py script exiting
Sep 14 00:15:13 Router-8 unbound[29030]: [29030:0] notice: init module 0: python
Sep 14 00:15:13 Router-8 unbound[29030]: [29030:0] info: [pfBlockerNG]: pfb_unbound.py script loaded
Sep 14 00:15:14 Router-8 unbound[29030]: [29030:0] info: [pfBlockerNG]: init_standard script loaded
Sep 14 00:15:14 Router-8 unbound[29030]: [29030:0] notice: init module 1: iterator
Sep 14 00:15:14 Router-8 unbound[29030]: [29030:0] info: start of service (unbound 1.18.0).

Sep 14 00:15:22	php	5131	[pfBlockerNG] No changes to Firewall rules, skipping Filter Reload

14 Sep 23 Snapshot @ 0933hrs:

total.num.queries=28324
total.num.cachehits=24810
total.num.cachemiss=3514
total.num.prefetch=3716
total.num.expired=3012
total.num.recursivereplies=3514
mem.cache.rrset=537693		( 0.54 / 100 MB limit )
mem.cache.message=698017	( 0.70 / 50 MB limit )
msg.cache.count=2537
rrset.cache.count=1769
infra.cache.count=4
time.elapsed=33487.774174	( 9hrs 18min 07s ie unbound reset @ ~0015hrs again )

As this could be a pfSense 23.09d issue, I have also copied in @stephenw10 for his thoughts on why pfBlocker and the DNS resolver are tripping over each other.

️

RobbieTT · Sep 14, 2023, 4:39 PM

I think this is the process that should restore the DNS Resolver cache:

Saving DNSBL statistics... completed [ 09/14/23 00:15:09 ]
------------------------------------------------------------------------
Assembling DNSBL database...... completed [ 09/14/23 00:15:11 ]
Reloading Unbound Resolver (DNSBL python).
Stopping Unbound Resolver.
Unbound stopped in 2 sec.
Additional mounts (DNSBL python):
  No changes required.
Starting Unbound Resolver... completed [ 09/14/23 00:15:14 ]
Resolver cache restored
DNSBL update [ 244638 | PASSED  ]... completed [ 09/14/23 00:15:15 ]
------------------------------------------------------------------------

It states Resolver cache restored but clearly it isn't.

RobbieTT · Sep 16, 2023, 1:28 PM

Subsequent to the first post the DNS Resolver cache ran ok until 16 Sep @0615hrs - ie for 54 hours since pfBlockerNG last reset the DNS cache to zero.

At the time off this post the DNS has been running again for 8hrs 13 mins and completed the single Cron job at 1215hrs with no reset.

Not ideal.

️