Problem with Feed Unknown

jrey

Riddle me this...

Looking up the "feed name" seems to be rather hit and miss.. pfb 3.2.0_10
Screen capture entries 1 and (3,5) are even from the same subnet.

the corresponding unified log records (just showing the end fields, because that is where the important stuff should be )
for 1 = in,Unk,pfB_PRI1_v4,Unknown,Unknown,Unknown,wan,null,+

and for 3 and 5
for 3 = in,Unk,pfB_PRI1_v4,62.122.184.0/24,ET_Block_v4,Unknown,wan,null,+
for 5 = in,Unk,pfB_PRI1_v4,62.122.184.0/24,ET_Block_v4,Unknown,wan,null,+

so for address 64.122.184.111 it seems it doesn't even try to look it up (or fails)
and for 62.122.184.73 it is fine ..

very inconsistent with some working and some not.
the 79.110.62.76 is also in the file ET_Block_v4 79.110.62.0/24
as is the 194.26.135.66 in the file ET_Block_v4 194.26.135.0/24
the list has not changed in this timeframe.

Screen Shot 2024-08-20 at 12.42.53 PM.png

jrey

Somewhat resolved,

when I first posted the above observation, I was running about 55% of the records in unified.log showing the "Unknown, Unknown, Unknown"

Turns out it is an ip_cache.sqlite (the IP Caching) issue - resolved by cleaning up.

Not sure the exact root cause for each case, but I will take a look.

Item 1: there where several records in the data where the record's data field was actually "Unknown" haven't looked at how these may have got into the cache, but it likely should not be caching records with Unknown, as the cached value - a cache hit later would always return "Unknown" .

Resolved by

command prompt 
cd /var/db/pfblockerng
sqlite3
then at the sqlite prompt run: 

.open ip_cache.sqlite
select * from ipcache where q0 = 'Unknown';
delete from ipcache where q0 = 'Unknown';
select * from ipcache where q0 = 'Unknown';
.quit

(of course I only did the three statements to see the records, and there where a lot..) you could also just count(*) them - of course had I done that I would not have seen the duplicates (next item)

Item 2: during my investigation several "duplicate records" where discovered. Again not sure why, but I suspect that the insert doesn't respect unique values (or in fact have a unique index on the host value). Most records where just exact duplicates, however in a few cases they had different value where,
a) more than 2 records for the same IP (data the same) and/or
b) the same IP but with different cached values.

again just my opinion but the insert is not respecting the fact there may already be a record there for that host.

To clean this up, the following will check for duplicates.

select host, q0, q1, geoip, count(*) as count from ipcache group by host, q0, q1, geoip having count(*) > 1 order by host;

and the following will delete the duplicates.

delete from ipcache where rowid NOT IN (select min(rowid) from ipcache group by host, q0, q1, geoip);

As soon as I cleaned the up the cache, the naming went to 100% correct with no more "unknown" in the unified.log

Now it occurs to me that, if the list changes (because IP's do change), there is no mechanism in the code to replace an old value with a new one or/just remove the old one.
Is there a mechanism to remove all the cache entries for a given feed when the feed updates? my guess/observation that the answer is no. Should there be? the answer is likely yes.

Can't recall but I believe the database is replaced on reboot. (I'll have to test that) but I almost never reboot and shouldn't have too.) - I've now setup some monitoring to catch when/if a record gets inserted with "Unknown". I'd like to understand what the root cause of that might have been. It should then be an easy fix, but I want to understand how it gets there in the first place.

In the mean time, the sql above has corrected the issue and I'm now running 100% ip evaluation, unified log is correct and no more strike out ~~Unknown~~ on the alerts or other reports.

I happen to like 100% better than 45% accurate data - your mileage may vary
Cheers

Gertjan

@jrey

Thanks for the feedback.
Always want to to know what was in there, as it wasn't obvious by just 'reading' pfBlockerng.
And because I saw what you did, I found this right away.

jrey

@Gertjan

Sure people that don't understand SQL should have a guide I guess. I'm sure there are others around too. Thanks for adding that.

I just type SQL naturally

I'd be curious to know if you see either records with "Unknown" in the cache and or duplicates, might help me. (I don't need to see the detailed records) just if you have some yes or no

if you wanted to open the database as shown above then just run the following 2 queries

select count(*) from ipcache where q0 = 'Unknown';

should return 0
if it is not 0 you have records cached with 'Unknown'

and

select host, q0, q1, geoip, count(*) as count from ipcache group by host, q0, q1, geoip having count(*) > 1 order by host;

should return nothing
(if it does the last field shown on each recorded returned will be the number of duplicates for that record)

I'm running pfb 3.0.2_10 on 24.03

Thanks

Gertjan

@jrey said in Problem with Feed Unknown:

. (I don't need to see the detailed records) just if you have some yes or no

[24.03-RELEASE][root@pfSense.bhf.tld]/var/db/pfblockerng: sqlite3  SQLite version 3.44.0 2023-11-01 11:23:50
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> .open ip_cache.sqlite
sqlite> .mode list
sqlite> select * from ipcache;
90.50.46.41|FR_v4|90.48.0.0/13|FR
185.200.116.74|RO_rep_v4|185.200.116.0/23|SG
35.203.210.89|GB_v4|35.203.210.0/23|GB
185.200.116.67|RO_rep_v4|185.200.116.0/23|SG
185.200.116.76|RO_rep_v4|185.200.116.0/23|SG
185.114.175.11|ES_v4|185.114.172.0/22|ES
185.200.116.48|RO_rep_v4|185.200.116.0/23|SG
45.83.65.120|DE_v4|45.83.64.0/22|DE
35.176.52.67|GB_v4|35.176.0.0/14|GB
185.200.116.49|RO_rep_v4|185.200.116.0/23|SG
185.200.116.51|RO_rep_v4|185.200.116.0/23|SG
64.226.106.115|DE_v4|64.226.64.0/18|DE
165.227.144.70|DE_v4|165.227.128.0/19|DE
185.200.116.68|RO_rep_v4|185.200.116.0/23|SG
163.172.114.186|FR_v4|163.172.112.0/21|FR
185.200.118.47|GB_v4|185.200.118.0/24|GB
185.200.116.36|RO_rep_v4|185.200.116.0/23|SG
185.242.226.46|NL_v4|185.242.226.0/23|NL
193.163.125.245|GB_v4|193.163.125.0/24|GB
172.212.60.227|GB_rep_v4|172.212.0.0/16|US
45.83.66.118|DE_v4|45.83.64.0/22|DE
151.236.222.83|GB_v4|151.236.216.0/21|GB
43.157.64.235|DE_v4|43.157.0.0/17|DE
185.200.118.37|GB_v4|185.200.118.0/24|GB
185.200.116.41|RO_rep_v4|185.200.116.0/23|SG
84.54.51.42|BG_rep_v4|84.54.51.32/28|NL
142.93.110.143|DE_v4|142.93.96.0/20|DE
142.93.99.208|DE_v4|142.93.96.0/20|DE
185.200.116.86|RO_rep_v4|185.200.116.0/23|SG
185.200.116.40|RO_rep_v4|185.200.116.0/23|SG
185.200.118.81|GB_v4|185.200.118.0/24|GB
35.203.211.41|GB_v4|35.203.210.0/23|GB
212.129.11.163|FR_v4|212.129.0.0/19|FR
185.200.116.75|RO_rep_v4|185.200.116.0/23|SG
35.203.211.186|GB_v4|35.203.210.0/23|GB
35.203.211.64|GB_v4|35.203.210.0/23|GB
185.200.116.72|RO_rep_v4|185.200.116.0/23|SG
35.203.211.187|GB_v4|35.203.210.0/23|GB
45.83.66.223|DE_v4|45.83.64.0/22|DE
185.200.116.37|RO_rep_v4|185.200.116.0/23|SG
52.56.201.185|GB_v4|52.56.0.0/16|GB
51.158.30.232|FR_v4|51.158.24.0/21|FR
185.200.116.53|RO_rep_v4|185.200.116.0/23|SG
185.200.116.71|RO_rep_v4|185.200.116.0/23|SG
185.200.118.85|GB_v4|185.200.118.0/24|GB
185.200.116.35|RO_rep_v4|185.200.116.0/23|SG
92.184.98.3|FR_v4|92.184.0.0/16|FR
92.184.98.3|FR_v4|92.184.0.0/16|FR
92.184.98.51|FR_v4|92.184.0.0/16|FR
92.184.98.51|FR_v4|92.184.0.0/16|FR
92.184.98.86|FR_v4|92.184.0.0/16|FR
92.184.98.86|FR_v4|92.184.0.0/16|FR
92.184.98.229|FR_v4|92.184.0.0/16|FR
92.184.98.229|FR_v4|92.184.0.0/16|FR
82.127.26.108|FR_v4|82.124.0.0/14|FR
82.127.26.108|FR_v4|82.124.0.0/14|FR
185.242.226.34|NL_v4|185.242.226.0/23|NL
185.242.226.34|NL_v4|185.242.226.0/23|NL
35.203.211.9|GB_v4|35.203.210.0/23|GB
35.203.211.9|GB_v4|35.203.210.0/23|GB
92.184.98.214|FR_v4|92.184.0.0/16|FR
92.184.98.214|FR_v4|92.184.0.0/16|FR
45.128.232.216|BG_rep_v4|45.128.232.192/26|NL
45.128.232.216|BG_rep_v4|45.128.232.192/26|NL
185.200.116.45|RO_rep_v4|185.200.116.0/23|SG
185.200.116.45|RO_rep_v4|185.200.116.0/23|SG
45.83.67.85|DE_v4|45.83.64.0/22|DE
139.162.75.134|JP_v4|139.162.64.0/18|JP
185.200.116.83|RO_rep_v4|185.200.116.0/23|SG
92.184.107.192|FR_v4|92.184.0.0/16|FR
185.200.116.47|RO_rep_v4|185.200.116.0/23|SG
35.203.210.43|GB_v4|35.203.210.0/23|GB
164.90.218.169|DE_v4|164.90.208.0/20|DE
185.200.118.82|GB_v4|185.200.118.0/24|GB
172.168.41.85|GB_rep_v4|172.168.0.0/13|US
185.200.118.51|GB_v4|185.200.118.0/24|GB
162.62.124.140|DE_v4|162.62.96.0/19|DE
92.184.98.7|FR_v4|92.184.0.0/16|FR
51.8.223.89|DE_rep_v4|51.8.0.0/16|US
185.200.118.84|GB_v4|185.200.118.0/24|GB
185.200.118.49|GB_v4|185.200.118.0/24|GB
172.169.5.242|GB_rep_v4|172.168.0.0/13|US
45.83.65.41|DE_v4|45.83.64.0/22|DE
185.200.116.52|RO_rep_v4|185.200.116.0/23|SG
185.200.116.79|RO_rep_v4|185.200.116.0/23|SG
35.203.210.54|GB_v4|35.203.210.0/23|GB
68.183.223.151|DE_v4|68.183.208.0/20|DE
167.99.244.2|DE_v4|167.99.240.0/20|DE
185.200.116.73|RO_rep_v4|185.200.116.0/23|SG
51.8.223.202|DE_rep_v4|51.8.0.0/16|US
193.163.125.17|GB_v4|193.163.125.0/24|GB
45.147.250.208|IT_v4|45.147.250.0/24|IT
185.200.116.70|RO_rep_v4|185.200.116.0/23|SG
45.83.64.169|DE_v4|45.83.64.0/22|DE
185.200.118.79|GB_v4|185.200.118.0/24|GB
92.184.108.170|FR_v4|92.184.0.0/16|FR
92.184.108.37|FR_v4|92.184.0.0/16|FR
45.83.64.17|DE_v4|45.83.64.0/22|DE
139.162.156.134|DE_v4|139.162.128.0/18|DE
92.184.108.184|FR_v4|92.184.0.0/16|FR
92.184.108.138|FR_v4|92.184.0.0/16|FR
167.172.105.89|DE_v4|167.172.96.0/20|DE
167.99.240.245|DE_v4|167.99.240.0/20|DE
94.102.49.193|NL_v4|94.102.48.0/23|NL
176.178.95.246|FR_v4|176.176.0.0/12|FR
185.200.116.84|RO_rep_v4|185.200.116.0/23|SG
185.200.118.69|GB_v4|185.200.118.0/24|GB
172.212.60.107|GB_rep_v4|172.212.0.0/16|US
89.248.172.16|NL_v4|89.248.160.0/20|NL
165.232.79.167|DE_v4|165.232.64.0/20|DE
209.38.246.188|DE_v4|209.38.192.0/18|DE
161.35.215.114|DE_v4|161.35.192.0/19|DE
172.169.107.34|GB_rep_v4|172.168.0.0/13|US
185.47.172.136|IL_rep_v4|185.47.172.0/24|IT
185.200.116.82|RO_rep_v4|185.200.116.0/23|SG
43.157.63.14|DE_v4|43.157.0.0/17|DE
172.168.152.6|GB_rep_v4|172.168.0.0/13|US
45.83.64.80|DE_v4|45.83.64.0/22|DE
185.200.116.69|RO_rep_v4|185.200.116.0/23|SG
172.169.109.191|GB_rep_v4|172.168.0.0/13|US
35.203.211.246|GB_v4|35.203.210.0/23|GB
172.202.155.121|GB_rep_v4|172.202.0.0/15|US
185.200.116.44|RO_rep_v4|185.200.116.0/23|SG
172.169.111.25|GB_rep_v4|172.168.0.0/13|US
185.200.116.46|RO_rep_v4|185.200.116.0/23|SG
164.90.170.230|DE_v4|164.90.160.0/19|DE
103.214.4.206|NL_v4|103.214.4.0/22|NL
57.151.70.243|GB_rep_v4|57.151.0.0/17|US
185.200.116.58|RO_rep_v4|185.200.116.0/23|SG
185.200.118.44|GB_v4|185.200.118.0/24|GB
172.168.158.77|GB_rep_v4|172.168.0.0/13|US
172.206.143.159|GB_rep_v4|172.206.0.0/16|US
164.92.254.252|DE_v4|164.92.224.0/19|DE
165.227.138.172|DE_v4|165.227.128.0/19|DE
164.92.229.103|DE_v4|164.92.224.0/19|DE
45.83.67.220|DE_v4|45.83.64.0/22|DE
172.212.60.176|GB_rep_v4|172.212.0.0/16|US
89.82.46.92|FR_v4|89.80.0.0/12|FR
172.206.147.15|GB_rep_v4|172.206.0.0/16|US
57.152.56.31|GB_rep_v4|57.152.0.0/16|US
48.216.196.243|GB_rep_v4|48.216.128.0/17|US
185.200.116.42|RO_rep_v4|185.200.116.0/23|SG
90.120.32.50|FR_v4|90.112.0.0/12|FR
172.206.143.187|GB_rep_v4|172.206.0.0/16|US
207.154.215.48|DE_v4|207.154.192.0/19|DE
172.206.141.109|GB_rep_v4|172.206.0.0/16|US
95.160.28.219|PL_v4|95.160.0.0/16|PL
193.163.125.109|GB_v4|193.163.125.0/24|GB
8.211.47.177|DE_v4|8.211.0.0/17|DE
172.206.142.80|GB_rep_v4|172.206.0.0/16|US
80.82.70.133|NL_rep_v4|80.82.70.128/27|SC
45.83.66.160|DE_v4|45.83.64.0/22|DE
92.184.145.151|FR_v4|92.184.0.0/16|FR

No "unknown"

@jrey said in Problem with Feed Unknown:

I'm running pfb 3.0.2_10 on 24.03

Of course. Me too. Are there other versions ? ;)

jrey

@Gertjan said in Problem with Feed Unknown:

Are there other version ? ;)

sure I have my 2.7.2 test system 3.0_2_8 -- but why test there LOL - it is the production data that was and messing up the graylogs.

And see that's the mystery -- what caused the records to get there in the first place. (I know I'm not that only one. Because I see forum messages and screen captures of other alerts showing ~~unknown~~ lists crossed out and replaced by the report - and there is actually a redmine from 2022 that could be related.

Now i've been running clean for about 5 hours and have no Unknown or duplicates at this time,
But I also have not been through a list (feed) refresh so waiting for those events to happen naturally
also need to test a reboot cycle at some point, but the system runs for weeks without doing that, and as I recall the entire database is flushed on startup. Might confirm that over on the test machine later today.

Graylog will tell me if an unknown gets added.
Screen Shot 2024-08-21 at 11.33.30 AM.png

tinfoilmatt

Good post, good self-fix. Can't reproduce your issue nor do I have any "Unknown" entries in ip_cache DB.

Only thing similar I have is a handful of rows with "Unk" in the "geoip" column for some IP addresses whose country codes were apparently not obtained/parsed/conflicted somewhere/something.

@jrey said in Problem with Feed Unknown:

Now it occurs to me that, if the list changes (because IP's do change), there is no mechanism in the code to replace an old value with a new one or/just remove the old one.
Is there a mechanism to remove all the cache entries for a given feed when the feed updates? my guess/observation that the answer is no. Should there be? the answer is likely yes.

Can't recall but I believe the database is replaced on reboot. (I'll have to test that) but I almost never reboot and shouldn't have too.) - I've now setup some monitoring to catch when/if a record gets inserted with "Unknown". I'd like to understand what the root cause of that might have been. It should then be an easy fix, but I want to understand how it gets there in the first place.

Is it possible this box suffered an unsafe shutdown/power loss at any point?

Gertjan

@jrey said in Problem with Feed Unknown:

sure I have my 2.7.2 test system 3.0_2_8 -

A 2.7.2 is give or take identical to 24.03.
I'm not sure what differs between pfB .8 and .10.

I have only one pfSense to play with, that one at work (hotel), with the entire company behind it, and 50+ hotel clients (captive portal). So that's the system I use to test and fool around with. Surely not the one at home (a 2.7.2), that's way to dangerous, as that one is mission critical.

That said, I don't have big DNS and IP feeds on my pfBlockerng. Just the pure basics.

And I manged some how to keep my pfSense up and running for

which quiet a performance for me - check my uptime here.

jrey

@cyberconsultants said in Problem with Feed Unknown:

rows with "Unk" in the "geoip"

All of mine will be like that in the geoid field - I don't use the MaxMind Geo Data - I use a different source

But you are correct in your assessment "some IP addresses whose country codes were apparently not obtained/parsed/conflicted somewhere/something" Likely because as I recall MaxMind only updates once a week.

jrey

@Gertjan said in Problem with Feed Unknown:

up and running for

Sounds about right for the production box.
Usually the only time I reboot it is when there is an upgrade and a reboot is required or an extended power outage.

Will keep the netgate, fibre and full wifi up for -

Screen Shot 2024-08-21 at 12.32.05 PM.png

very rare for us to have a power outage that long.

Now I'm waiting for an Unknown or duplicate to show up --- some event put them there over time .. (for clarity that was the number of unified.log records with unknown between 4 and 5 am this morning).
Screen Shot 2024-08-21 at 12.36.41 PM.png

Then I did the clean up --- so far none since --- time will tell

jrey

@jrey

Strange a reboot (the only thing not tested and I finally had to do one) created 240 Unknown records.

Screen Shot 2024-08-28 at 7.43.50 PM.png

now deleted, no duplicates created, likely because I deleted them as soon as they appeared and before another hit from the same IP could look it up and write another record.

jrey

there it is

so as I expected that reboot is causing these 'Unknown' records to be added to the ip_cache database.

When the system is starting up
the filter starts blocking (as it should)..
but the "lists" that pfB would be using are not available (I think this is primarily where tmpfs is memory based - I need to test this on a virtual using disk not ram disk someday - lol)
so when the process goes to look it up of course they are Unknown.

The problem is the "Unknown" entries are being written to the cache and then
subsequent hits from the same IP lookup it up in the cache and find unknown.
even if the underlying list might now be available, it will read the "unknown" from cache and use that. - That's the problem

There is a better way, pondering, but for now the simple solution is don't cache "unknown"

$stmt->execute();

becomes this

if ($pfb_query[0] != 'Unknown') {
      $stmt->execute();
}

Now the records won't be cached (still blocked and reported that way during the startup process) but as soon as the underlying data is correct the records start caching with IP address again. - Confirmed by doing...

I'm ok with a couple of hundred block records saying unknown during the boot process, but then using the cached "unknown".. not so good.

Now it occurs to me as well, that the ip_cache appears to only get flushed on a reboot, but the underlying lists used by pfBlocker could change. An IP that was listed and therefore blocked yesterday, may have been removed from a list and therefore should not be cached against the previous list. ie a) it is not on a list anymore (not blocked) and/or b) it is on a different list and should not be listed against the old one (or both)

I'm thinking that when you see this

408 addresses added.337 addresses deleted.

you don't need to worry about the "added" ones - they will cache if/when used.
but the deleted ones (337 in this case) should be removed from the cache if they are there..
The quick solution here might be simply flush the entire cache and just let it start over, like on a reboot. I'm not seeing that it currently does either.(a seek and delete or a flush)

If you reboot often the cache is flushed every time you do, but if you typically run for weeks (like here) the cache will become bloated with IPs that may or may not be what they currently are.
The mechanism to remove stale ones and "update" existing one with fresher info doesn't seem to be there/work IMHO

Pondering continues.. Still need to look at the reports but I don't believe they use the cache and likely shouldn't, you want to report on what happened at that time (from the record) not what happened from a stale or incorrect cache. etc etc

Cheers