Enhance DNS logs and make them consistent (#13429)

Motivation: Always include information that helps to correlate log events. Modifications: - Always include `Channel` at the beginning of every log, when channel is available; - Always include `[queryId: sender]` when available; - `DnsQueryContext`: include expected values when logging at `WARN` level; Result: Consistent logging, easier to correlate log events.
netty · Jun 7, 2023 · 3be71e0 · 3be71e0
1 parent 0a8e737
commit 3be71e0
Show file tree

Hide file tree

Showing 4 changed files with 28 additions and 22 deletions.
diff --git a/codec-dns/src/main/java/io/netty5/handler/codec/dns/DnsMessageUtil.java b/codec-dns/src/main/java/io/netty5/handler/codec/dns/DnsMessageUtil.java
@@ -80,6 +80,7 @@ private static void appendQueryHeader(StringBuilder buf, DnsQuery msg) {
            .append('(');
 
         appendAddresses(buf, msg)
+           .append("id: ")
            .append(msg.id())
            .append(", ")
            .append(msg.opCode());
@@ -99,6 +100,7 @@ private static void appendResponseHeader(StringBuilder buf, DnsResponse msg) {
            .append('(');
 
         appendAddresses(buf, msg)
+           .append("id: ")
            .append(msg.id())
            .append(", ")
            .append(msg.opCode())

diff --git a/resolver-dns/src/main/java/io/netty5/resolver/dns/DnsNameResolver.java b/resolver-dns/src/main/java/io/netty5/resolver/dns/DnsNameResolver.java
@@ -190,9 +190,9 @@ protected DnsResponse decodeResponse(ChannelHandlerContext ctx, DatagramPacket p
                 response.setTruncated(true);
 
                 if (logger.isDebugEnabled()) {
-                    logger.debug(
-                            "{} RECEIVED: UDP truncated packet received, consider adjusting maxPayloadSize for the {}.",
-                            ctx.channel(), StringUtil.simpleClassName(DnsNameResolver.class));
+                    logger.debug("{} RECEIVED: UDP [{}: {}] truncated packet received, consider adjusting "
+                                    + "maxPayloadSize for the {}.", ctx.channel(), response.id(), packet.sender(),
+                            StringUtil.simpleClassName(DnsNameResolver.class));
                 }
             }
             return response;
@@ -1296,14 +1296,12 @@ private final class DnsResponseHandler implements ChannelHandler {
         public void channelRead(ChannelHandlerContext ctx, Object msg) {
             final DatagramDnsResponse res = (DatagramDnsResponse) msg;
             final int queryId = res.id();
-
-            if (logger.isDebugEnabled()) {
-                logger.debug("{} RECEIVED: UDP [{}: {}], {}", ch, queryId, res.sender(), res);
-            }
+            logger.debug("{} RECEIVED: UDP [{}: {}], {}", ch, queryId, res.sender(), res);
 
             final DnsQueryContext qCtx = queryContextManager.get(res.sender(), queryId);
             if (qCtx == null) {
-                logger.debug("Received a DNS response with an unknown ID: UDP [{}: {}]", ch, queryId);
+                logger.debug("{} Received a DNS response with an unknown ID: UDP [{}: {}]",
+                        ch, queryId, res.sender());
                 res.release();
                 return;
             }
@@ -1322,7 +1320,8 @@ public void channelRead(ChannelHandlerContext ctx, Object msg) {
             bs.connect(res.sender()).addListener(future -> {
                 if (future.isFailed()) {
                     if (logger.isDebugEnabled()) {
-                        logger.debug("{} Unable to fallback to TCP [{}]", queryId, future.cause());
+                        logger.debug("{} Unable to fallback to TCP [{}: {}]",
+                                ch, queryId, res.sender(), future.cause());
                     }
 
                     // TCP fallback failed, just use the truncated response.
@@ -1346,10 +1345,9 @@ public void channelRead(ChannelHandlerContext ctx1, Object msg1) {
                         int queryId1 = response.id();
 
                         if (logger.isDebugEnabled()) {
-                            logger.debug("{} RECEIVED: TCP [{}: {}], {}", channel, queryId1,
+                            logger.debug("{} RECEIVED: TCP [{}: {}], {}", channel, queryId,
                                     channel.remoteAddress(), response);
                         }
-
                         DnsQueryContext foundCtx = queryContextManager.get(res.sender(), queryId1);
                         if (foundCtx == tcpCtx) {
                             tcpCtx.finish(new AddressedEnvelopeAdapter(
@@ -1359,8 +1357,10 @@ public void channelRead(ChannelHandlerContext ctx1, Object msg1) {
                         } else {
                             response.release();
                             tcpCtx.tryFailure("Received TCP DNS response with unexpected ID", null, false);
-                            logger.debug("Received a DNS response with an unexpected ID: TCP [{}: {}]",
-                                    channel, queryId);
+                            if (logger.isDebugEnabled()) {
+                                logger.debug("{} Received a DNS response with an unexpected ID: TCP [{}: {}]",
+                                        channel, queryId, channel.remoteAddress());
+                            }
                         }
                     }
 
@@ -1398,9 +1398,9 @@ public void channelActive(ChannelHandlerContext ctx) {
         @Override
         public void channelExceptionCaught(ChannelHandlerContext ctx, Throwable cause) {
             if (cause instanceof CorruptedFrameException) {
-                logger.debug("Unable to decode DNS response: UDP [{}]", ctx.channel(), cause);
+                logger.debug("{} Unable to decode DNS response: UDP", ctx.channel(), cause);
             } else {
-                logger.warn("Unexpected exception: UDP [{}]", ctx.channel(), cause);
+                logger.warn("{} Unexpected exception: UDP", ctx.channel(), cause);
             }
         }
     }

diff --git a/resolver-dns/src/main/java/io/netty5/resolver/dns/DnsQueryContext.java b/resolver-dns/src/main/java/io/netty5/resolver/dns/DnsQueryContext.java
@@ -207,9 +207,11 @@ private void onQueryWriteCompletion(Future<?> writeFuture, Promise<Void> writePr
     void finish(AddressedEnvelope<? extends DnsResponse, InetSocketAddress> envelope) {
         final DnsResponse res = envelope.content();
         if (res.count(DnsSection.QUESTION) != 1) {
-            logger.warn("Received a DNS response with invalid number of questions: {}", envelope);
+            logger.warn("{} Received a DNS response with invalid number of questions. Expected: 1, found: {}",
+                    channel(), envelope);
         } else if (!question().equals(res.recordAt(DnsSection.QUESTION))) {
-            logger.warn("Received a mismatching DNS response: {}", envelope);
+            logger.warn("{} Received a mismatching DNS response. Expected: [{}], found: {}",
+                    channel(), question(), envelope);
         } else if (trySuccess(envelope)) {
             return; // Ownership transferred, don't release
         }

diff --git a/resolver-dns/src/main/java/io/netty5/resolver/dns/DnsResolveContext.java b/resolver-dns/src/main/java/io/netty5/resolver/dns/DnsResolveContext.java
@@ -826,9 +826,10 @@ private void onExpectedResponse(
                     }
                     if (resolved == null) {
                         if (logger.isDebugEnabled()) {
-                            logger.debug("Ignoring record {} as it contains a different name than the " +
-                                            "question name [{}]. Cnames: {}, Search domains: {}",
-                                    r.toString(), questionName, cnames, parent.searchDomains());
+                            logger.debug("{} Ignoring record {} for [{}: {}] as it contains a different name than " +
+                                            "the question name [{}]. Cnames: {}, Search domains: {}",
+                                    parent.ch, r.toString(), response.id(), envelope.sender(), questionName, cnames,
+                                    parent.searchDomains());
                         }
                         continue;
                     }
@@ -838,8 +839,9 @@ private void onExpectedResponse(
             final T converted = convertRecord(r, hostname, additionals, parent.executor());
             if (converted == null) {
                 if (logger.isDebugEnabled()) {
-                    logger.debug("Ignoring record {} as the converted record is null. hostname [{}], Additionals: {}",
-                            r.toString(), hostname, additionals);
+                    logger.debug("{} Ignoring record {} for [{}: {}] as the converted record is null. "
+                                    + "Hostname [{}], Additionals: {}",
+                            parent.ch, r.toString(), response.id(), envelope.sender(), hostname, additionals);
                 }
                 continue;
             }