unbound : request queue exceeded

[planetf1]

I see in my unbound stats that I am getting 'request queue exceeded' using unbound.

I have probably ~30 devices but nothing too heavy really beyond apply tv/2 laptops/few ipads/phones.

Network is 500/70 fibre with a decent consistent low latency ~4-5ms to london data centres.

My unbound configuration includes
 - using quad9 for upstream DoT
 - upping the cache to 25/50MB
 - enabling prefetch & serving of expired queries (config as per RFC)

The default number of queues per thread is 1024, and I have 4 threads, so I struggle to see why I ever exceed the queue. Any ideas?

Here's my current stats (unbound was restarted in the last day or so)


Recursion time (average):   0.043278
Recursion time (median):   0.0211664
TCP usage:   0
IP ratelimited queries:   0
Recursive replies:   64758
Cache misses:   64787
Cache hits:   92166
Serve expired:   132
Prefetch:   4290
Queries:   156953
Request queue avg:   0.634118
Request queue max:   18
Request queue overwritten:   0
Request queue exceeded:   29
Request queue size (all):   0
Request queue size (client):   0

[dinguz]

I noticed this as well, but can't remember it from previous unbound versions. Maybe it is a new stat or something that has always been there but never shown? Unfortunately, I couldn't find any documentation on how to mitigate this.

[planetf1]

There are a couple of places in the code that it can occur -- for example if there are too many queries for that thread, there are issues with the buffer the request is using, or if we hit some wait limit thresholds.

My max request queue size never gets high though, but perhaps the backlog is counted earlier. I don't know the code well enough and haven't gone through it in detail.

[planetf1]

The cases seem to be
 - "Too many queries waiting from the IP" (wait limits)
 - "Too many queries. dropping" (buffer space to store them)
 - "Too many requests queued." (too many reply addresses)
 - "Too many queries. dropped prefetch." (occurs in 2 different places)
 - "drop reply, it is older than discard-timeout" (occurs in 2 different places)

That text should be seen in a level 4 or higher log (most are ALGO)

In my case, I can now see the following log entries

2024-05-28T16:44:35   Debug   unbound   [21070:0] debug: drop reply, it is older than discard-timeout

The docs are here: https://unbound.docs.nlnetlabs.nl/en/latest/manpages/unbound.conf.html

In my case I do use the serve staling option.. the reason being that some 'distant' queries ie for Chinese domains can take a while to resolve - 3.4.5 seconds sometimes. So in this case I have unbound set to return an expired response (if available) within 1800ms, but the query is outstanding (even though client is responded to). It then comes in later than 1900ms and gets discarded, presumably even if it otherwise would update the cache

I checked, and my value is indeed 1900

As the docs say
It is nice to be a bit larger than serve-expired-client-timeout if that is enabled

Vague... but it seems as if 100ms extra beyond the time a stale entry is returned is pointless.

I've seen some requests take up to 5s, so I'm going with 3000. There is a general default 3000ms timeout to authoritative servers (tcp-auth-query-timeout) in any case, and I don't want to be too radical, even though this is just a small personal server.

[planetf1]

What I don't know how to do is to make this change permanent, as it's not supported on the UI

Trying to update any of the config files didn't work, as opnsense just overwrites when the service is restarted...

[planetf1]

For my case I opened up https://github.com/opnsense/core/issues/7493 to request adding support for this timeout