rec: Some "common" error messages are no longer hidden behind log-common-errors

[rgacogne]

• Program: Recursor
• Issue type: Bug report

Short description

As reported by qvr on IRC, we might be logging messages by default that used to / should have been hidden behind log-common-errors:

10:41  qvr i'm upgrading to rec5.0 and we're seeing a lot of error level log messages for "PIPE function created an exception", apparently before #14185 these could be suppressed with log-common-errors=no but now they will always come through, but ratelimited?
10:41  PowerIssue pull #14185 omoerbeek (closed,merged): rec: log vm.max_map_count possibly being too low and log a few exceptions (with rate limiting) https://github.com/PowerDNS/pdns/pull/14185
10:44  qvr well, "a lot" is a hyperbole, but every minute and they are annoying :)
10:45  cmouse qvr: is there any details?
10:45  rgacogne qvr: it looks that way, yes, but note that these errors should probably not be happening. do you have any idea what is triggering them?
10:46  qvr broken clients and/or queries, most common seems: Error parsing packet of 51 bytes (rd=1), out of bounds: dnsname issue: Found an invalid label length in qname
10:46  qvr other one is Query with QD > 1 (18)
10:46  rgacogne ah
10:47  rgacogne ok, I was wrongly assuming these were caught in a different place
10:47  rgacogne this seems like a bug then, because errors like these should indeed remain hidden behind log-common-errors IMHO

[omoerbeek]

While investigating this, I created some packets with invalid queries.

I can reproduce the QD > 1 case with pdns_distributes_queries: true. In that case the log line is indeed generated independent of log_common_errors.

But the other case (Error parsing packet) not, both values of pdns_distributes_queries only log if log_common_errors is true. So my test packet is probably hitting a different case.

I would like to see the full log messages, they might contain hints where the exception is generated. Also, things like pdns_distributes_query value matters here.

[omoerbeek]

Played a bit more and now I can reproduce.

x.pcap.gz (invalid qd)
y.pcap.gz (invalid query record (length > remaining packet length)

The trick for the y.pcap is to have a name length that extends past the record, buit not past the packet.

[omoerbeek]

Ok, fix seems simple: also catch MOADNSEXception in handlePipeRequest and guard the logging with g_logCommonErrors. I need to decide if we also want rate limiting here.