[Dnsmasq-discuss] [BUG] Logged IDs incorrect

[Simon Kelley]

On 16/10/2021 12:57, Dominik Derigs wrote:
> Hey Simon,
> 
> We received reports that the IDs of some log lines can be
> incorrect ("log-queries=extra" is enabled).
> 
> I attach three representative log snippets that highlight the
> issue (comments therein). Logs 1 and 2 seem to have the same
> reason. I'd have provided a patch but I'm not sure about the
> exact code path in this case: How is the query "forwarded ... to"
> without a "query[A] ... from ..." line?
> 
> Be that as it may, even when I'm unable to reproduce this myself,
> the source of the wrong IDs seems to be in forward_query():
> 
>>   /* If a query is retried, use the log_id for the retry when
>> logging the answer. */
>>   forward->frec_src.log_id = daemon->log_id;
> 
> The issue seems clear: When dnsmasq retries the queries itself
> (i.e. without a corresponding "query[...]" line in the log),
> daemon->log_id still points to the previous (entirely unrelated)
> query. Setting the ID is incorrect at this point.
> 
> The third log is somewhat different, it may be a separate issue.
> I cannot reproduce the issue in the first two logs but I can pass
> on a patch.
> 
> Best,
> Dominik
> 


It took some head-scratching to work out, but the code path which causes
the first two logs is

Client sends query.
Dnsmasq forwards to a single server
Sever above returns SERVFAIL or REFUSED.
Dnsmasq forwards query again to all available servers.
Not (REFUSED or SERVFAIL) reply arrives and is returned to client.


The third log is a bit different.

Query arrives from 127.0.0.1/38902
Query send upstream.
Same query arrives from 127.0.0.1/33293
Query not sent upstream, since it's a duplicate.
Answer arrives and is validated.
Answer returned to 127.0.0.1/38902 (but ID wrong)
Answer returned to 127.0.0.1/33293, (ID right, logged as duplicate)

Whilst looking at this I found another case that's broken.

Query arrives
Query send upstream
Answer returned, which requires another query to DNSSEC validate.
DNSSEC query sent, but no answer yet.
Original query retried by original client, causes DNSSEC query to be
sent upstream again.
Resent DNSSEC query has log-ID of original query.

You've correctly found the bad line of code, writing its replacements
needed the information above. Thanks for the clear description of the
problem.  Fix pushed to git.


Cheers,

Simon.