CC: dot@dotat.at MIME-Version: 1.0 In-Reply-To: X-Spam-Status: No, score=-4.9 required=5.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,RCVD_IN_DNSWL_MED,RCVD_IN_MSPIKE_H3, RCVD_IN_MSPIKE_WL,RP_MATCHES_RCVD autolearn=ham autolearn_force=no version=3.4.0 X-Cam-Antivirus: no malware found References: Message-ID: Content-Type: TEXT/PLAIN; charset="utf-8" X-X-Sender: fanf2@hermes-1.csi.cam.ac.uk X-RT-Original-Encoding: utf-8 Received: from mx.pao1.isc.org (mx.pao1.isc.org [149.20.64.53]) by bugs.isc.org (Postfix) with ESMTP id 052922D20571 for ; Fri, 8 Aug 2014 11:26:03 +0000 (UTC) Received: from ppsw-50.csi.cam.ac.uk (ppsw-50.csi.cam.ac.uk [131.111.8.150]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx.pao1.isc.org (Postfix) with ESMTPS id 1B1B63493C2 for ; Fri, 8 Aug 2014 11:26:00 +0000 (UTC) Received: from hermes-1.csi.cam.ac.uk ([131.111.8.51]:47311) by ppsw-50.csi.cam.ac.uk (smtp.hermes.cam.ac.uk [131.111.8.158]:25) with esmtpa (EXTERNAL:fanf2) id 1XFiJ5-0003ou-qY (Exim 4.82_3-c0e5623) (return-path ); Fri, 08 Aug 2014 12:25:59 +0100 Received: from fanf2 by hermes-1.csi.cam.ac.uk (hermes.cam.ac.uk) with local id 1XFiJ5-0002Eh-7T (Exim 4.72) (return-path ); Fri, 08 Aug 2014 12:25:59 +0100 Delivered-To: bind9-bugs@bugs.isc.org User-Agent: Alpine 2.00 (LSU 1167 2008-08-23) Subject: [ISC-Bugs #36624] [PATCH] Improve debug logging of packet contents Return-Path: X-Original-To: bind9-bugs@bugs.isc.org Date: Fri, 8 Aug 2014 12:25:59 +0100 Sender: Tony Finch X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on mx.pao1.isc.org To: bind9-bugs@isc.org X-Cam-Scannerinfo: http://www.cam.ac.uk/cs/email/scanner/ From: Tony Finch RT-Message-ID: Content-Length: 7027 This is an update of my earlier patch to log outgoing query packets as well as incoming packets, which now also logs the address of the remote server. --- lib/dns/include/dns/message.h | 12 +++++++----- lib/dns/message.c | 18 +++++++++++------ lib/dns/resolver.c | 45 ++++++++++++++++++++++--------------------- lib/dns/xfrin.c | 3 ++- 4 files changed, 44 insertions(+), 34 deletions(-) diff --git a/lib/dns/include/dns/message.h b/lib/dns/include/dns/message.h index de121c7..afec880 100644 --- a/lib/dns/include/dns/message.h +++ b/lib/dns/include/dns/message.h @@ -1368,18 +1368,20 @@ dns_message_gettimeadjust(dns_message_t *msg); */ void -dns_message_logpacket(dns_message_t *message, const char *description, +dns_message_logpacket(dns_message_t *message, + const char *description, isc_sockaddr_t *address, isc_logcategory_t *category, isc_logmodule_t *module, int level, isc_mem_t *mctx); void -dns_message_logfmtpacket(dns_message_t *message, const char *description, +dns_message_logfmtpacket(dns_message_t *message, + const char *description, isc_sockaddr_t *address, isc_logcategory_t *category, isc_logmodule_t *module, - const dns_master_style_t *style, int level, + int level, const dns_master_style_t *style, isc_mem_t *mctx); /*%< * Log 'message' at the specified logging parameters. - * 'description' will be emitted at the start of the message and will - * normally end with a newline. + * 'description' will be emitted at the start of the message followed + * by the formatted address and a newline. */ isc_result_t diff --git a/lib/dns/message.c b/lib/dns/message.c index 88c9239..3d763ac 100644 --- a/lib/dns/message.c +++ b/lib/dns/message.c @@ -3560,20 +3560,24 @@ dns_opcode_totext(dns_opcode_t opcode, isc_buffer_t *target) { } void -dns_message_logpacket(dns_message_t *message, const char *description, +dns_message_logpacket(dns_message_t *message, + const char *description, isc_sockaddr_t *address, isc_logcategory_t *category, isc_logmodule_t *module, int level, isc_mem_t *mctx) { - dns_message_logfmtpacket(message, description, category, module, - &dns_master_style_debug, level, mctx); + dns_message_logfmtpacket(message, description, address, + category, module, level, + &dns_master_style_debug, mctx); } void -dns_message_logfmtpacket(dns_message_t *message, const char *description, +dns_message_logfmtpacket(dns_message_t *message, + const char *description, isc_sockaddr_t *address, isc_logcategory_t *category, isc_logmodule_t *module, - const dns_master_style_t *style, int level, + int level, const dns_master_style_t *style, isc_mem_t *mctx) { + char addrbuf[ISC_SOCKADDR_FORMATSIZE]; isc_buffer_t buffer; char *buf = NULL; int len = 1024; @@ -3587,6 +3591,8 @@ dns_message_logfmtpacket(dns_message_t *message, const char *description, * to appear in the log after each message. */ + isc_sockaddr_format(address, addrbuf, sizeof(addrbuf)); + do { buf = isc_mem_get(mctx, len); if (buf == NULL) @@ -3598,7 +3604,7 @@ dns_message_logfmtpacket(dns_message_t *message, const char *description, len += 1024; } else if (result == ISC_R_SUCCESS) isc_log_write(dns_lctx, category, module, level, - "%s%.*s", description, + "%s %s\n%.*s", description, addrbuf, (int)isc_buffer_usedlength(&buffer), buf); } while (result == ISC_R_NOSPACE); diff --git a/lib/dns/resolver.c b/lib/dns/resolver.c index 421338f..a50c1f7 100644 --- a/lib/dns/resolver.c +++ b/lib/dns/resolver.c @@ -2229,6 +2229,17 @@ resquery_send(resquery_t *query) { } /* + * Log the outgoing packet. + */ + dns_message_logfmtpacket(fctx->qmessage, "sending packet to", + &query->addrinfo->sockaddr, + DNS_LOGCATEGORY_RESOLVER, + DNS_LOGMODULE_PACKETS, + ISC_LOG_DEBUG(11), + &dns_master_style_comment, + fctx->res->mctx); + + /* * We're now done with the query message. */ dns_message_reset(fctx->qmessage, DNS_MESSAGE_INTENTRENDER); @@ -7321,11 +7332,12 @@ resquery_response(isc_task_t *task, isc_event_t *event) { /* * Log the incoming packet. */ - dns_message_logfmtpacket(message, "received packet:\n", + dns_message_logfmtpacket(message, "received packet from", + &query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER, DNS_LOGMODULE_PACKETS, - &dns_master_style_comment, ISC_LOG_DEBUG(10), + &dns_master_style_comment, fctx->res->mctx); /* * Process receive opt record. @@ -7379,18 +7391,13 @@ resquery_response(isc_task_t *task, isc_event_t *event) { message->rcode == dns_rcode_refused || message->rcode == dns_rcode_yxdomain) && bad_edns(fctx, &query->addrinfo->sockaddr)) { - if (isc_log_wouldlog(dns_lctx, ISC_LOG_DEBUG(3))) { - char buf[4096], addrbuf[ISC_SOCKADDR_FORMATSIZE]; - isc_sockaddr_format(&query->addrinfo->sockaddr, - addrbuf, sizeof(addrbuf)); - snprintf(buf, sizeof(buf), - "received packet from %s (bad edns):\n", - addrbuf); - dns_message_logpacket(message, buf, + dns_message_logpacket(message, + "received packet (bad edns) from", + &query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER, DNS_LOGMODULE_RESOLVER, - ISC_LOG_DEBUG(3), fctx->res->mctx); - } + ISC_LOG_DEBUG(3), + fctx->res->mctx); dns_adb_changeflags(fctx->adb, query->addrinfo, DNS_FETCHOPT_NOEDNS0, DNS_FETCHOPT_NOEDNS0); @@ -7410,18 +7417,12 @@ resquery_response(isc_task_t *task, isc_event_t *event) { * should be safe to do for any rcode we limit it to NOERROR * and NXDOMAIN. */ - if (isc_log_wouldlog(dns_lctx, ISC_LOG_DEBUG(3))) { - char buf[4096], addrbuf[ISC_SOCKADDR_FORMATSIZE]; - isc_sockaddr_format(&query->addrinfo->sockaddr, - addrbuf, sizeof(addrbuf)); - snprintf(buf, sizeof(buf), - "received packet from %s (no opt):\n", - addrbuf); - dns_message_logpacket(message, buf, + dns_message_logpacket(message, "received packet (no opt) from", + &query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER, DNS_LOGMODULE_RESOLVER, - ISC_LOG_DEBUG(3), fctx->res->mctx); - } + ISC_LOG_DEBUG(3), + fctx->res->mctx); dns_adb_changeflags(fctx->adb, query->addrinfo, DNS_FETCHOPT_NOEDNS0, DNS_FETCHOPT_NOEDNS0); diff --git a/lib/dns/xfrin.c b/lib/dns/xfrin.c index 744f878..21ea0a3 100644 --- a/lib/dns/xfrin.c +++ b/lib/dns/xfrin.c @@ -1234,7 +1234,8 @@ xfrin_recv_done(isc_task_t *task, isc_event_t *ev) { DNS_MESSAGEPARSE_PRESERVEORDER); if (result == ISC_R_SUCCESS) - dns_message_logpacket(msg, "received message:\n", + dns_message_logpacket(msg, "received message from", + &tcpmsg->address, DNS_LOGCATEGORY_XFER_IN, DNS_LOGMODULE_XFER_IN, ISC_LOG_DEBUG(10), xfr->mctx); -- 2.1.0.rc1.8.gb4fa8f0