]> git.ipfire.org Git - thirdparty/bind9.git/commitdiff
projects / thirdparty / bind9.git / commitdiff
? search:
summary | shortlog | log | commit | commitdiff | tree
raw | patch | inline | side by side (parent: e8ef7f6)
Log type with stale answer log messages
authorMark Andrews <marka@isc.org>
Thu, 27 Oct 2022 22:00:45 +0000 (09:00 +1100)
committerMichał Kępień <michal@isc.org>
Wed, 30 Nov 2022 13:32:58 +0000 (14:32 +0100)
Add more information about which query type is dealing with serve-stale.
Update the expected log messages in the serve-stale system test.

bin/tests/system/serve-stale/tests.sh patch | blob | blame | history
lib/ns/query.c patch | blob | blame | history

diff --git a/bin/tests/system/serve-stale/tests.sh b/bin/tests/system/serve-stale/tests.sh
index c3b167bd5d42a1a14f28fb0db04ab2a20cb8d184..b64fc5b48c7dd9c1a751e4746495b9d3b1e9a743 100755 (executable)
--- 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 e37a96de8ef567a4d4a8f43d72cf1e5865a7f9cc..ee89b62a17be8fb1b12958e33dbfab3de5ebaa41 100644 (file)
--- 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,
Mirror of https://gitlab.isc.org/isc-projects/bind9.git