Query Log shows an extra query for some lookups

[agneevX]

Prerequisites

• [x] I am running the latest version
• [ ] I checked the documentation and found no answer
• [x] I checked to make sure that this issue has not already been filed

Environment

• Version of AdGuard Home server:
  • v0.107.7
• How did you install AdGuard Home:
  • Docker
• How did you setup DNS configuration:
• If it's a router or IoT, please write device model:
• CPU architecture:
  • arm64
• Operating system and version:

Description

AdGuard shows two queries when one is made to AGH. This is definitely a bug, because the first query here took 11ms, which is not possible, because the DNS server is ~40ms away. The second query takes a more sensible 47ms.

If I look at logs from the upstream, I see just one query made:

Additional Information

Issue split from #4364.

EDIT: add environment details

[JsBergbau]

Could it be that this is an issue in your upstream DNS server logging? It looks like upstream DNS Server has only a time resolution of seconds. If now two requests arrive within the same second it may be possible that only one of this request is recorded for that second and domain. Since in the originating issue identical DNS requests were within a timeframe of about 5-30 ms (just having a quick glance) it will be very unlikely to happen within two different seconds. Still there is only 11 ms processing time whereas the server is 40 ms away, but maybe thats a different bug with showing wrong processing time. How is upstream DNS configured? Plain UDP 53? If so using tcpdump port 53 could show how many requests really arrive.

[agneevX]

It's not. If two requests come in, it will get logged.

[agneevX]

but maybe thats a different bug with showing wrong processing time.

Could be, not willing to rule that out.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[agneevX]

Bad bot

[EugeneOne1]

@agneevX, hello and apologies for the late response.

Are you able to reproduce it with one of the latest builds? If yes, could you please collect a verbose log for us? Also, if you still have this or analogous part of the query log file? It'd be really helpful to take a look at the written data. You may send any of above to [email protected].

Could you please also give some information about the used environment? Which OS/Architecture AGH runs on? Which client performs the request?

[agneevX]

Are you able to reproduce it with one of the latest builds?

Could you please also give some information about the used environment? Which OS/Architecture AGH runs on?

@EugeneOne1 I've updated the initial post with some more details.

Which client performs the request?

This was from a standard Windows client.

While I no longer have the log, I think this is too easy to reproduce. Opening a couple of websites shows multiple lookups bearing the same domain name. Usually the first one has a lower than possible response time, while the second one shows the true (or possible) response time.

[valantur]

I'm glad to see this is being looked at. My query logs are full of examples like this one:

[cyb3rz3us]

@valantur --- Just an FYI, what you posted is normal behavior as those are not double log entires. Those are entries for 2 different queries.

[valantur]

@cyb3rz3us --- Oops sorry, wrong screenshot. Here it goes:

I'm running Unbound on the same VM. Both entries say the request was processed by Unbound. I guess Unbound had it cached the second time around and that's why it responded in 1ms, but still AGH is sending two requests with minimal time in-between. I swear I saw worse examples, but I cleared my query log recently... oh well.

[CodeSapiens]

Same issue here Multiple queries for the same items, all coming from the same PC.