Unbound Validation Failure logs

bloater99 · 27 December 2024 13:21

I haven’t looked in the Unbound logs in a long time. The other day, I looked and noticed a bunch of INFO messages similar to:

22:27:53 	unbound: [3869:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
22:26:19 	unbound: [3869:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: key for validation resolver.arpa. is marked as invalid because of a previous

Everything appears to be working normally. I’m not seeing any lookup issues. These just appear to be informational logs.

I was curious if this had anything to do with Quad9 because they filter for malware. So I switched to Google DNS and got the same thing:

07:09:45 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no DNSSEC records from 8.8.4.4 for DS resolver.arpa. while building chain of trust

I then disabled DoT, switching back to UDP protocol and that seemed to quiet the logs.

Again, everything is working fine. These just seem like informational logs. But “validation failure” sounds more serious than just informational? Is this a known issue? Do I just ignore?

Thanks!

bonnietwin · 27 December 2024 13:45

NSEC3 is also related to DNSSEC so both those messages say that there was a failure in validating the DNSSEC status.

I would interpret this as some connection issue causing the DNSSEC validation to fail.

If you get this continuously, so hundreds or thousands of entries per day for this message then it might be an indicator of some sort of systemic problem, although what I don’t know.

I don’t use either of the DNS Servers you mentioned but I checked through my DNS logs for the whole of December for any NSEC3 or DNSSEC messages. I found only two related to NSEC3 and these were not a DNS Server but related to a website where it looks like it was giving a wrong or no feedback on the NSEC3 communication.

bloater99 · 27 December 2024 14:32

Thank you, Adolf. Are you using DNS over TLS? I only seem to see these messages when I am using DoT.

bonnietwin · 27 December 2024 14:37

Yes, I am using DoT.

I am also using the Recursor Mode, so with no DNS servers specified at all.

I have changed my system to using 5 specified DNS Servers and will see how that goes.

When you see those messages, do you see them at least once every day or is it more infrequent. That will give me a view of how long I need to run my system with this modified setup.

Here is the set of DNS servers that I have changed to. These were the set I used to use in the past before changing to Recursor Mode, which I have been using probably for a year or so now.

Again all of these listed servers are running with DoT.

bloater99 · 27 December 2024 14:53

It seems the more the internet is being used, the more log entries appear. I’m seeing anywhere from 5-20 entries per hour. I also just remoted into two other IPFires I manage and am seeing the same logs there. All three IPFires are set up the same way:

In the screenshot, Google DNS is disabled, but I did enable it as a test and I was getting log entries referring to Google’s DNS servers as well.

bonnietwin · 27 December 2024 15:05

I will run my setup then for a couple of hours and see if there is any issues.

With the cloudflare 1.0.0.2 and 1.1.1.2 entries and the quad9 entries, they do filtering and modification of the DNS response and this can show up as DNSSEC failure messages.

As far as I am aware google dns 8.8.8.8 does not do any filtering of the dns response with that server IP, so after a couple of hours I will try that out on my system.

I will feedback what I find.

bloater99 · 27 December 2024 15:07

Yes, that is why I tested Google DNS. I wanted to see if it was related to the filtering. It does not appear to be based on same log entries appearing for Google’s servers.

bonnietwin · 27 December 2024 19:02

I got no messages about DNSSEC or NSEC3 with my DNS server set and also not with dns.google. I had both sets running for 2 hours each.

bloater99 · 27 December 2024 19:45

Thank you for trying. Like I said, there is no noticeable problem with DNS and the lines suggest Information logs only, so I guess it’s no big deal?

bloater99 · 29 December 2024 12:10

From midnight to 6am, 54 log entries. So it’s happening even with minimal network activity. It is a curiosity, especially with me seeing it on three different IPFires. I’m curious if anyone else here has these INFO messages in their UNBOUND logs?

06:01:17 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
06:00:02 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
05:56:59 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
05:45:43 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
05:40:37 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
05:33:42 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
05:32:35 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
05:28:08 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
05:10:36 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
05:03:34 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
05:02:28 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
05:00:31 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
04:53:17 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
04:45:41 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
04:40:38 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
04:32:24 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
04:31:20 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
04:29:32 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
04:10:47 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
04:06:40 	unbound: [3871:0] 	info: generate keytag query _ta-4a5c-4f66. NULL IN
04:02:30 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
04:01:18 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: key for validation resolver.arpa. is marked as invalid because of a previous
04:00:31 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
03:40:36 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
03:33:39 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
03:31:13 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: key for validation resolver.arpa. is marked as invalid because of a previous
03:30:16 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
03:20:03 	unbound: [3871:0] 	info: generate keytag query _ta-4a5c-4f66. NULL IN
03:15:43 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 9.9.9.9 for DS resolver.arpa. while building chain of trust
03:06:47 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
03:01:17 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
02:58:49 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
02:45:35 	unbound: [3871:0] 	info: generate keytag query _ta-4a5c-4f66. NULL IN
02:43:59 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
02:40:42 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
02:31:07 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: key for validation resolver.arpa. is marked as invalid because of a previous
02:30:12 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
02:18:40 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
02:10:54 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
02:04:59 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
02:00:52 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
01:59:24 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
01:40:49 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
01:33:06 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
01:30:15 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
01:12:57 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
01:10:53 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
00:59:43 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
00:43:35 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
00:29:25 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust
00:28:20 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.1.1.2 for DS resolver.arpa. while building chain of trust
00:17:58 	unbound: [3871:0] 	info: generate keytag query _ta-4a5c-4f66. NULL IN
00:08:52 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 1.0.0.2 for DS resolver.arpa. while building chain of trust
00:02:37 	unbound: [3871:0] 	info: validation failure <_dns.resolver.arpa. SVCB IN>: no NSEC3 records from 149.112.112.112 for DS resolver.arpa. while building chain of trust

hvacguy · 29 December 2024 19:42

This is all from the 28th

Time	Section
00:45:50	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of se nds
03:25:35	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
04:02:52	unbound: [2244:0]	info: server stats for thread 0: 107670 queries, 30474 answers from cache, 7719 6 recursions, 2790 prefetch, 0 rejected by ip ratelimiting
04:02:52	unbound: [2244:0]	info: server stats for thread 0: requestlist max 41 avg 1.45452 exceeded 95 jos tled 0
04:02:52	unbound: [2244:0]	info: average recursion processing time 0.052296 sec
04:02:52	unbound: [2244:0]	info: histogram of recursion processing times
04:02:52	unbound: [2244:0]	info: [25%]=0.0122305 median[50%]=0.0330234 [75%]=0.06692
04:02:52	unbound: [2244:0]	info: lower(secs) upper(secs) recursions
04:02:52	unbound: [2244:0]	info: 0.000000 0.000001 4237
04:02:52	unbound: [2244:0]	info: 0.000032 0.000064 11
04:02:52	unbound: [2244:0]	info: 0.000064 0.000128 10
04:02:52	unbound: [2244:0]	info: 0.000128 0.000256 16
04:02:52	unbound: [2244:0]	info: 0.000256 0.000512 30
04:02:52	unbound: [2244:0]	info: 0.000512 0.001024 42
04:02:52	unbound: [2244:0]	info: 0.001024 0.002048 92
04:02:52	unbound: [2244:0]	info: 0.002048 0.004096 191
04:02:52	unbound: [2244:0]	info: 0.004096 0.008192 8812
04:02:52	unbound: [2244:0]	info: 0.008192 0.016384 11543
04:02:52	unbound: [2244:0]	info: 0.016384 0.032768 13131
04:02:52	unbound: [2244:0]	info: 0.032768 0.065536 18986
04:02:52	unbound: [2244:0]	info: 0.065536 0.131072 13898
04:02:52	unbound: [2244:0]	info: 0.131072 0.262144 4444
04:02:52	unbound: [2244:0]	info: 0.262144 0.524288 742
04:02:52	unbound: [2244:0]	info: 0.524288 1.000000 247
04:02:52	unbound: [2244:0]	info: 1.000000 2.000000 94
07:59:26	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
10:01:57	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
10:20:21	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
11:02:41	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
14:27:33	unbound: [2244:0]	info: service stopped (unbound 1.21.1).
14:27:33	unbound: [2244:0]	info: server stats for thread 0: 46939 queries, 11804 answers from cache, 35135 recursions, 1086 prefetch, 0 rejected by ip ratelimiting
14:27:33	unbound: [2244:0]	info: server stats for thread 0: requestlist max 74 avg 2.0071 exceeded 34 jost led 0
14:27:33	unbound: [2244:0]	info: average recursion processing time 0.053683 sec
14:27:33	unbound: [2244:0]	info: histogram of recursion processing times
14:27:33	unbound: [2244:0]	info: [25%]=0.0135552 median[50%]=0.0339746 [75%]=0.0680332
14:27:33	unbound: [2244:0]	info: lower(secs) upper(secs) recursions
14:27:33	unbound: [2244:0]	info: 0.000000 0.000001 1780
14:27:33	unbound: [2244:0]	info: 0.000128 0.000256 3
14:27:33	unbound: [2244:0]	info: 0.000256 0.000512 2
14:27:33	unbound: [2244:0]	info: 0.000512 0.001024 7
14:27:33	unbound: [2244:0]	info: 0.001024 0.002048 18
14:27:33	unbound: [2244:0]	info: 0.002048 0.004096 37
14:27:33	unbound: [2244:0]	info: 0.004096 0.008192 3478
14:27:33	unbound: [2244:0]	info: 0.008192 0.016384 5112
14:27:33	unbound: [2244:0]	info: 0.016384 0.032768 6584
14:27:33	unbound: [2244:0]	info: 0.032768 0.065536 8758
14:27:33	unbound: [2244:0]	info: 0.065536 0.131072 6200
14:27:33	unbound: [2244:0]	info: 0.131072 0.262144 2169
14:27:33	unbound: [2244:0]	info: 0.262144 0.524288 387
14:27:33	unbound: [2244:0]	info: 0.524288 1.000000 105
14:27:33	unbound: [2244:0]	info: 1.000000 2.000000 47
14:27:33	unbound: [2244:0]	notice: Restart of unbound 1.21.1.
14:27:33	unbound: [2244:0]	notice: init module 0: validator
14:27:33	unbound: [2244:0]	notice: init module 1: iterator
14:27:33	unbound: [2244:0]	info: start of service (unbound 1.21.1).
14:27:33	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
16:10:28	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
16:17:47	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
16:33:05	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN
19:47:05	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
19:47:05	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
19:47:22	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
19:47:22	unbound: [2244:0]	error: SERVFAIL : exceeded the maximum number of sends
21:02:31	unbound: [2244:0]	info: generate keytag query _ta-4a5c-4f66. NULL IN

bloater99 · 29 December 2024 21:53

I wonder if it’s my ISP. The one thing in common with all three IPFires I manage is the ISP.

jon · 29 December 2024 23:30

I am using TLS.

I asked quad9 about this type of issues in July 2024 and received this response:

See the last paragraph for their solution.

Since I wanted to used TLS I left it on and ignored their best practices…

EDIT: I added my original request (above)

bloater99 · 30 December 2024 10:57

Thanks, Jon. That still doesn’t explain why Adolf didn’t get the messages when he tested with Quad9, but your answer is good enough for me.