From: Mark Andrews Date: Thu, 27 Oct 2022 22:00:45 +0000 (+1100) Subject: Log type with stale answer log messages X-Git-Tag: v9.19.8~30^2~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=bce1cf6c62711741b0a293e519d1b2c41d685e64;p=thirdparty%2Fbind9.git Log type with stale answer log messages Add more information about which query type is dealing with serve-stale. Update the expected log messages in the serve-stale system test. --- diff --git a/bin/tests/system/serve-stale/tests.sh b/bin/tests/system/serve-stale/tests.sh index c3b167bd5d4..b64fc5b48c7 100755 --- a/bin/tests/system/serve-stale/tests.sh +++ b/bin/tests/system/serve-stale/tests.sh @@ -1720,7 +1720,7 @@ t2=`$PERL -e 'print time()'` n=$((n+1)) echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 1.8) ($n)" ret=0 -wait_for_log 5 "data.example client timeout, stale answer used" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT client timeout, stale answer used" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (client timeout)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -1764,7 +1764,7 @@ status=$((status+ret)) n=$((n+1)) echo_i "check not in cache longttl.example TXT times out (stale-answer-client-timeout 1.8) ($n)" ret=0 -wait_for_log 4 "longttl.example client timeout, stale answer unavailable" ns3/named.run || ret=1 +wait_for_log 4 "longttl.example TXT client timeout, stale answer unavailable" ns3/named.run || ret=1 grep "timed out" dig.out.test$n > /dev/null || ret=1 grep ";; no servers could be reached" dig.out.test$n > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi @@ -1880,7 +1880,7 @@ ret=0 echo_i "check stale nodata.example TXT comes from cache (stale-answer-client-timeout 0) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 nodata.example TXT > dig.out.test$n -wait_for_log 5 "nodata.example stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "nodata.example TXT stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 0," dig.out.test$n > /dev/null || ret=1 @@ -1893,7 +1893,7 @@ ret=0 echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 0) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -1969,7 +1969,7 @@ ret=0 echo_i "check stale cname1.stale.test A comes from cache (stale-answer-client-timeout 0) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 cname1.stale.test A > dig.out.test$n -wait_for_log 5 "cname1.stale.test stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "cname1.stale.test A stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 2," dig.out.test$n > /dev/null || ret=1 @@ -2008,7 +2008,7 @@ ret=0 echo_i "check stale cname2.stale.test A comes from cache (stale-answer-client-timeout 0) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 cname2.stale.test A > dig.out.test$n -wait_for_log 5 "cname2.stale.test stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "cname2.stale.test A stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 2," dig.out.test$n > /dev/null || ret=1 @@ -2085,7 +2085,7 @@ ret=0 echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 0 stale-refresh-time 4) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -2134,7 +2134,7 @@ ret=0 echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 0 stale-refresh-time 4) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -2155,7 +2155,7 @@ ret=0 echo_i "check stale data.example TXT comes from cache within stale-refresh-time (stale-answer-client-timeout 0 stale-refresh-time 4) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example query within stale refresh time" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT query within stale refresh time" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (query within stale refresh time window)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -2182,7 +2182,7 @@ ret=0 echo_i "check stale data.example TXT was not refreshed (stale-answer-client-timeout 0 stale-refresh-time 4) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example query within stale refresh time" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT query within stale refresh time" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (query within stale refresh time window)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -2197,7 +2197,7 @@ n=$((n+1)) ret=0 echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 0 stale-refresh-time 4) ($n)" $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT stale answer used, an attempt to refresh the RRset" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (stale data prioritized over lookup)" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -2305,7 +2305,7 @@ ret=0 echo_i "check stale data.example TXT comes from cache (fetch-limits) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example resolver failure, stale answer used" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT resolver failure, stale answer used" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (resolver failure" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 @@ -2319,7 +2319,7 @@ ret=0 echo_i "check stale data.example TXT comes from cache again (fetch-limits) ($n)" nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n -wait_for_log 5 "data.example resolver failure, stale answer used" ns3/named.run || ret=1 +wait_for_log 5 "data.example TXT resolver failure, stale answer used" ns3/named.run || ret=1 grep "status: NOERROR" dig.out.test$n > /dev/null || ret=1 grep "EDE: 3 (Stale Answer): (resolver failure" dig.out.test$n > /dev/null || ret=1 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1 diff --git a/lib/ns/query.c b/lib/ns/query.c index e37a96de8ef..ee89b62a17b 100644 --- a/lib/ns/query.c +++ b/lib/ns/query.c @@ -5878,6 +5878,7 @@ query_lookup(query_ctx_t *qctx) { dns_clientinfo_t ci; dns_name_t *rpzqname = NULL; char namebuf[DNS_NAME_FORMATSIZE]; + char typebuf[DNS_RDATATYPE_FORMATSIZE]; unsigned int dboptions; dns_ttl_t stale_refresh = 0; bool dbfind_stale = false; @@ -5992,6 +5993,7 @@ query_lookup(query_ctx_t *qctx) { if (dbfind_stale || stale_refresh_window || stale_timeout) { dns_name_format(qctx->client->query.qname, namebuf, sizeof(namebuf)); + dns_rdatatype_format(qctx->qtype, typebuf, sizeof(typebuf)); inc_stats(qctx->client, ns_statscounter_trystale); @@ -6015,10 +6017,10 @@ query_lookup(query_ctx_t *qctx) { } if (dbfind_stale) { - isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE, - NS_LOGMODULE_QUERY, ISC_LOG_INFO, - "%s resolver failure, stale answer %s", namebuf, - stale_found ? "used" : "unavailable"); + isc_log_write( + ns_lctx, NS_LOGCATEGORY_SERVE_STALE, NS_LOGMODULE_QUERY, + ISC_LOG_INFO, "%s %s resolver failure, stale answer %s", + namebuf, typebuf, stale_found ? "used" : "unavailable"); if (stale_found) { ns_client_extendederror(qctx->client, ede, "resolver failure"); @@ -6037,9 +6039,10 @@ query_lookup(query_ctx_t *qctx) { */ isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE, NS_LOGMODULE_QUERY, ISC_LOG_INFO, - "%s query within stale refresh time, stale " + "%s %s query within stale refresh time, stale " "answer %s", - namebuf, stale_found ? "used" : "unavailable"); + namebuf, typebuf, + stale_found ? "used" : "unavailable"); if (stale_found) { ns_client_extendederror( @@ -6082,9 +6085,10 @@ query_lookup(query_ctx_t *qctx) { isc_log_write( ns_lctx, NS_LOGCATEGORY_SERVE_STALE, NS_LOGMODULE_QUERY, ISC_LOG_INFO, - "%s stale answer used, an attempt to " - "refresh the RRset will still be made", - namebuf); + "%s %s stale answer used, an attempt " + "to refresh the RRset will still be " + "made", + namebuf, typebuf); qctx->refresh_rrset = STALE(qctx->rdataset); ns_client_extendederror( qctx->client, ede, @@ -6098,8 +6102,8 @@ query_lookup(query_ctx_t *qctx) { */ isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE, NS_LOGMODULE_QUERY, ISC_LOG_INFO, - "%s client timeout, stale answer %s", - namebuf, + "%s %s client timeout, stale answer %s", + namebuf, typebuf, stale_found ? "used" : "unavailable"); if (stale_found) { ns_client_extendederror(qctx->client, ede,