Skip to content

Commit

Permalink
new: dev: Log both "from" and "to" socket in debug messages
Browse files Browse the repository at this point in the history 
Debug messages logging network traffic now include information about both sides of each communication channel rather than just one of them.

Closes #4345

Merge branch '4345-log-both-from-and-to-socket-in-debug-messages' into 'main'

See merge request isc-projects/bind9!8349
  • Loading branch information
@kempniu
kempniu committed Dec 31, 2024
2 parents 44d5dbe + dd2c509 commit 6230bc8
Show file tree
Hide file tree
Showing 6 changed files with 83 additions and 80 deletions.
4 changes: 2 additions & 2 deletions bin/tests/system/forward/tests.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -268,7 +268,7 @@ echo "//" | sendcmd 10.53.0.6
nextpart ns3/named.run >/dev/null
dig_with_opts txt.example7. txt @$f1 >dig.out.$n.f1 || ret=1
# The forwarder for the "example7" zone should only be queried once.
start_pattern="sending packet to 10\.53\.0\.6"
start_pattern="sending packet from [^ ]* to 10\.53\.0\.6"
retry_quiet 5 wait_for_log ns3/named.run "$start_pattern"
check_sent 1 ns3/named.run "$start_pattern" ";txt\.example7\.[[:space:]]*IN[[:space:]]*TXT$" || ret=1
if [ $ret != 0 ]; then echo_i "failed"; fi
Expand All @@ -280,7 +280,7 @@ ret=0
nextpart ns7/named.run >/dev/null
dig_with_opts +noadd +noauth txt.example1. txt @10.53.0.7 >dig.out.$n.f7 || ret=1
received_pattern="received packet from 10\.53\.0\.1"
start_pattern="sending packet to 10\.53\.0\.1"
start_pattern="sending packet from [^ ]* to 10\.53\.0\.1"
retry_quiet 5 wait_for_log ns7/named.run "$received_pattern" || ret=1
check_sent 1 ns7/named.run "$start_pattern" ";\.[[:space:]]*IN[[:space:]]*NS$" || ret=1
sent=$(grep -c "10.53.0.7#.* (.): query '\./NS/IN' approved" ns4/named.run || true)
Expand Down
2 changes: 1 addition & 1 deletion bin/tests/system/legacy/tests.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -241,7 +241,7 @@ status=$((status + ret))
n=$((n + 1))
echo_i "checking recursive lookup to edns 512 + no tcp server does not cause query loops ($n)"
ret=0
sent=$(grep -c -F "sending packet to 10.53.0.7" ns1/named.run)
sent=$(grep -c "sending packet from [^ ]* to 10\.53\.0\.7" ns1/named.run)
if [ $sent -ge 10 ]; then
echo_i "ns1 sent $sent queries to ns7, expected less than 10"
ret=1
Expand Down
43 changes: 22 additions & 21 deletions lib/dns/include/dns/message.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1396,34 +1396,35 @@ dns_message_gettimeadjust(dns_message_t *msg);
*/

void
dns_message_logpacket(dns_message_t *message, const char *description,
const isc_sockaddr_t *address, isc_logcategory_t category,
isc_logmodule_t module, int level, isc_mem_t *mctx);
dns_message_logpacketfrom(dns_message_t *message, const char *description,
const 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,
const isc_sockaddr_t *address,
isc_logcategory_t category, isc_logmodule_t module,
const dns_master_style_t *style, int level,
isc_mem_t *mctx);
dns_message_logpacketfromto(dns_message_t *message, const char *description,
const isc_sockaddr_t *from,
const isc_sockaddr_t *to,
isc_logcategory_t category, isc_logmodule_t module,
int level, isc_mem_t *mctx);
/*%<
* Log 'message' at the specified logging parameters.
* Log the provided DNS 'message' using the specified logging parameters,
* prepending it with the given 'description'.
*
* For dns_message_logpacket and dns_message_logfmtpacket expect the
* 'description' to end in a newline.
* For dns_message_logpacketfrom(), only the address of the sending socket must
* be provided (in the 'address' parameter).
*
* For dns_message_logpacket2 and dns_message_logfmtpacket2
* 'description' will be emitted at the start of the message followed
* by the formatted address and a newline.
* For dns_message_logpacketfromto(), the addresses of both the sending socket
* ('from') and the receiving socket ('to') must be provided.
*
* Requires:
* \li message be a valid.
* \li description to be non NULL.
* \li address to be non NULL.
* \li category to be valid.
* \li module to be valid.
* \li style to be valid.
* \li mctx to be a valid.
* \li 'message' be a valid DNS message.
* \li 'description' to be non-NULL.
* \li 'address' to be non-NULL (dns_message_logpacketfrom() only).
* \li 'from' and 'to' be non-NULL (dns_message_logpacketfromto() only).
* \li 'category' to be a valid logging category.
* \li 'module' to be a valid logging module.
* \li 'mctx' to be a valid memory context.
*/

isc_result_t
Expand Down
59 changes: 31 additions & 28 deletions lib/dns/message.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -216,9 +216,9 @@ msgblock_free(isc_mem_t *, dns_msgblock_t *, unsigned int);

static void
logfmtpacket(dns_message_t *message, const char *description,
const isc_sockaddr_t *address, isc_logcategory_t category,
isc_logmodule_t module, const dns_master_style_t *style, int level,
isc_mem_t *mctx);
const isc_sockaddr_t *from, const isc_sockaddr_t *to,
isc_logcategory_t category, isc_logmodule_t module,
const dns_master_style_t *style, int level, isc_mem_t *mctx);

/*
* Allocate a new dns_msgblock_t, and return a pointer to it. If no memory
Expand Down Expand Up @@ -4728,35 +4728,35 @@ dns_opcode_totext(dns_opcode_t opcode, isc_buffer_t *target) {
}

void
dns_message_logpacket(dns_message_t *message, const char *description,
const isc_sockaddr_t *address, isc_logcategory_t category,
isc_logmodule_t module, int level, isc_mem_t *mctx) {
dns_message_logpacketfrom(dns_message_t *message, const char *description,
const isc_sockaddr_t *address,
isc_logcategory_t category, isc_logmodule_t module,
int level, isc_mem_t *mctx) {
REQUIRE(address != NULL);

logfmtpacket(message, description, address, category, module,
logfmtpacket(message, description, address, NULL, category, module,
&dns_master_style_debug, level, mctx);
}

void
dns_message_logfmtpacket(dns_message_t *message, const char *description,
const isc_sockaddr_t *address,
isc_logcategory_t category, isc_logmodule_t module,
const dns_master_style_t *style, int level,
isc_mem_t *mctx) {
REQUIRE(address != NULL);

logfmtpacket(message, description, address, category, module, style,
level, mctx);
dns_message_logpacketfromto(dns_message_t *message, const char *description,
const isc_sockaddr_t *from,
const isc_sockaddr_t *to,
isc_logcategory_t category, isc_logmodule_t module,
int level, isc_mem_t *mctx) {
REQUIRE(from != NULL && to != NULL);

logfmtpacket(message, description, from, to, category, module,
&dns_master_style_comment, level, mctx);
}

static void
logfmtpacket(dns_message_t *message, const char *description,
const isc_sockaddr_t *address, isc_logcategory_t category,
isc_logmodule_t module, const dns_master_style_t *style, int level,
isc_mem_t *mctx) {
char addrbuf[ISC_SOCKADDR_FORMATSIZE] = { 0 };
const char *newline = "\n";
const char *space = " ";
const isc_sockaddr_t *from, const isc_sockaddr_t *to,
isc_logcategory_t category, isc_logmodule_t module,
const dns_master_style_t *style, int level, isc_mem_t *mctx) {
char frombuf[ISC_SOCKADDR_FORMATSIZE] = { 0 };
char tobuf[ISC_SOCKADDR_FORMATSIZE] = { 0 };
isc_buffer_t buffer;
char *buf = NULL;
int len = 1024;
Expand All @@ -4771,10 +4771,11 @@ logfmtpacket(dns_message_t *message, const char *description,
* to appear in the log after each message.
*/

if (address != NULL) {
isc_sockaddr_format(address, addrbuf, sizeof(addrbuf));
} else {
newline = space = "";
if (from != NULL) {
isc_sockaddr_format(from, frombuf, sizeof(frombuf));
}
if (to != NULL) {
isc_sockaddr_format(to, tobuf, sizeof(tobuf));
}

do {
Expand All @@ -4785,8 +4786,10 @@ logfmtpacket(dns_message_t *message, const char *description,
isc_mem_put(mctx, buf, len);
len += 1024;
} else if (result == ISC_R_SUCCESS) {
isc_log_write(category, module, level, "%s%s%s%s%.*s",
description, space, addrbuf, newline,
isc_log_write(category, module, level,
"%s%s%s%s%s\n%.*s", description,
(from != NULL ? " from " : ""), frombuf,
(to != NULL ? " to " : ""), tobuf,
(int)isc_buffer_usedlength(&buffer), buf);
}
} while (result == ISC_R_NOSPACE);
Expand Down
51 changes: 25 additions & 26 deletions lib/dns/resolver.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2340,8 +2340,8 @@ resquery_send(resquery_t *query) {
dns_ednsopt_t ednsopts[DNS_EDNSOPTIONS];
unsigned int ednsopt = 0;
uint16_t hint = 0, udpsize = 0; /* No EDNS */
#ifdef HAVE_DNSTAP
isc_sockaddr_t localaddr, *la = NULL;
#ifdef HAVE_DNSTAP
unsigned char zone[DNS_NAME_MAXWIRE];
dns_transport_type_t transport_type;
dns_dtmsgtype_t dtmsgtype;
Expand Down Expand Up @@ -2709,10 +2709,15 @@ 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,
&dns_master_style_comment, ISC_LOG_DEBUG(11), fctx->mctx);
result = dns_dispentry_getlocaladdress(query->dispentry, &localaddr);
if (result == ISC_R_SUCCESS) {
la = &localaddr;
}

dns_message_logpacketfromto(
fctx->qmessage, "sending packet", la,
&query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER,
DNS_LOGMODULE_PACKETS, ISC_LOG_DEBUG(11), fctx->mctx);

/*
* We're now done with the query message.
Expand All @@ -2737,11 +2742,6 @@ resquery_send(resquery_t *query) {
dtmsgtype = DNS_DTTYPE_RQ;
}

result = dns_dispentry_getlocaladdress(query->dispentry, &localaddr);
if (result == ISC_R_SUCCESS) {
la = &localaddr;
}

if (query->addrinfo->transport != NULL) {
transport_type =
dns_transport_get_type(query->addrinfo->transport);
Expand Down Expand Up @@ -8162,8 +8162,8 @@ rctx_edns(respctx_t *rctx) {
query->rmessage->rcode == dns_rcode_yxdomain) &&
bad_edns(fctx, &query->addrinfo->sockaddr))
{
dns_message_logpacket(
query->rmessage, "received packet (bad edns) from",
dns_message_logpacketfrom(
query->rmessage, "received packet (bad edns)",
&query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER,
DNS_LOGMODULE_RESOLVER, ISC_LOG_DEBUG(3), fctx->mctx);
dns_adb_changeflags(fctx->adb, query->addrinfo,
Expand All @@ -8188,8 +8188,8 @@ rctx_edns(respctx_t *rctx) {
* this should be safe to do for any rcode we limit it
* to NOERROR and NXDOMAIN.
*/
dns_message_logpacket(
query->rmessage, "received packet (no opt) from",
dns_message_logpacketfrom(
query->rmessage, "received packet (no opt)",
&query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER,
DNS_LOGMODULE_RESOLVER, ISC_LOG_DEBUG(3), fctx->mctx);
dns_adb_changeflags(fctx->adb, query->addrinfo,
Expand Down Expand Up @@ -9718,9 +9718,9 @@ rctx_done(respctx_t *rctx, isc_result_t result) {
static void
rctx_logpacket(respctx_t *rctx) {
fetchctx_t *fctx = rctx->fctx;
#ifdef HAVE_DNSTAP
isc_result_t result;
isc_sockaddr_t localaddr, *la = NULL;
#ifdef HAVE_DNSTAP
unsigned char zone[DNS_NAME_MAXWIRE];
dns_transport_type_t transport_type;
dns_dtmsgtype_t dtmsgtype;
Expand All @@ -9729,11 +9729,16 @@ rctx_logpacket(respctx_t *rctx) {
isc_buffer_t zb;
#endif /* HAVE_DNSTAP */

dns_message_logfmtpacket(
rctx->query->rmessage, "received packet from",
&rctx->query->addrinfo->sockaddr, DNS_LOGCATEGORY_RESOLVER,
DNS_LOGMODULE_PACKETS, &dns_master_style_comment,
ISC_LOG_DEBUG(10), fctx->mctx);
result = dns_dispentry_getlocaladdress(rctx->query->dispentry,
&localaddr);
if (result == ISC_R_SUCCESS) {
la = &localaddr;
}

dns_message_logpacketfromto(
rctx->query->rmessage, "received packet",
&rctx->query->addrinfo->sockaddr, la, DNS_LOGCATEGORY_RESOLVER,
DNS_LOGMODULE_PACKETS, ISC_LOG_DEBUG(10), fctx->mctx);

#ifdef HAVE_DNSTAP
/*
Expand All @@ -9755,12 +9760,6 @@ rctx_logpacket(respctx_t *rctx) {
dtmsgtype = DNS_DTTYPE_RR;
}

result = dns_dispentry_getlocaladdress(rctx->query->dispentry,
&localaddr);
if (result == ISC_R_SUCCESS) {
la = &localaddr;
}

if (rctx->query->addrinfo->transport != NULL) {
transport_type = dns_transport_get_type(
rctx->query->addrinfo->transport);
Expand Down
4 changes: 2 additions & 2 deletions lib/dns/xfrin.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1760,8 +1760,8 @@ xfrin_recv_done(isc_result_t result, isc_region_t *region, void *arg) {
result = dns_message_parse(msg, &buffer,
DNS_MESSAGEPARSE_PRESERVEORDER);
if (result == ISC_R_SUCCESS) {
dns_message_logpacket(
msg, "received message from", &xfr->primaryaddr,
dns_message_logpacketfrom(
msg, "received message", &xfr->primaryaddr,
DNS_LOGCATEGORY_XFER_IN, DNS_LOGMODULE_XFER_IN,
ISC_LOG_DEBUG(10), xfr->mctx);
} else {
Expand Down

0 comments on commit 6230bc8

Please sign in to comment.