mir/bind
2
0
Fork 0
mirror of https://gitlab.isc.org/isc-projects/bind9 synced 2025-09-02 23:55:27 +00:00
Code Issues Releases Wiki Activity

Log type with stale answer log messages

Browse Source 
Add more information about which query type is dealing with serve-stale.
Update the expected log messages in the serve-stale system test.
This commit is contained in:
Mark Andrews
2022-10-28 09:00:45 +11:00
committed by Michał Kępień
parent e8ef7f644d
commit bce1cf6c62
2 changed files with 28 additions and 24 deletions
Download Patch File Download Diff File Expand all files Collapse all files

26
bin/tests/system/serve-stale/tests.sh
View File

@@ -1720,7 +1720,7 @@ t2=`$PERL -e 'print time()'`
n=$((n+1)) n=$((n+1))
echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 1.8) ($n)" echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 1.8) ($n)"
ret=0 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 "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 "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 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1
@@ -1764,7 +1764,7 @@ status=$((status+ret))
n=$((n+1)) n=$((n+1))
echo_i "check not in cache longttl.example TXT times out (stale-answer-client-timeout 1.8) ($n)" echo_i "check not in cache longttl.example TXT times out (stale-answer-client-timeout 1.8) ($n)"
ret=0 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 "timed out" dig.out.test$n > /dev/null || ret=1
grep ";; no servers could be reached" 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 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)" echo_i "check stale nodata.example TXT comes from cache (stale-answer-client-timeout 0) ($n)"
nextpart ns3/named.run > /dev/null nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 nodata.example TXT > dig.out.test$n $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 "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 "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 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)" echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 0) ($n)"
nextpart ns3/named.run > /dev/null nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$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 "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 "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 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)" echo_i "check stale cname1.stale.test A comes from cache (stale-answer-client-timeout 0) ($n)"
nextpart ns3/named.run > /dev/null nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 cname1.stale.test A > dig.out.test$n $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 "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 "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 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)" echo_i "check stale cname2.stale.test A comes from cache (stale-answer-client-timeout 0) ($n)"
nextpart ns3/named.run > /dev/null nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 cname2.stale.test A > dig.out.test$n $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 "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 "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 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)" 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 nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$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 "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 "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 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)" 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 nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$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 "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 "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 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)" 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 nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n $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 "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 "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 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)" 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 nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n $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 "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 "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 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1
@@ -2197,7 +2197,7 @@ n=$((n+1))
ret=0 ret=0
echo_i "check stale data.example TXT comes from cache (stale-answer-client-timeout 0 stale-refresh-time 4) ($n)" 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 $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 "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 "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 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)" echo_i "check stale data.example TXT comes from cache (fetch-limits) ($n)"
nextpart ns3/named.run > /dev/null nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n $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 "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 "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 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)" echo_i "check stale data.example TXT comes from cache again (fetch-limits) ($n)"
nextpart ns3/named.run > /dev/null nextpart ns3/named.run > /dev/null
$DIG -p ${PORT} @10.53.0.3 data.example TXT > dig.out.test$n $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 "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 "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 grep "ANSWER: 1," dig.out.test$n > /dev/null || ret=1

26
lib/ns/query.c
View File

@@ -5878,6 +5878,7 @@ query_lookup(query_ctx_t *qctx) {
dns_clientinfo_t ci; dns_clientinfo_t ci;
dns_name_t *rpzqname = NULL; dns_name_t *rpzqname = NULL;
char namebuf[DNS_NAME_FORMATSIZE]; char namebuf[DNS_NAME_FORMATSIZE];
char typebuf[DNS_RDATATYPE_FORMATSIZE];
unsigned int dboptions; unsigned int dboptions;
dns_ttl_t stale_refresh = 0; dns_ttl_t stale_refresh = 0;
bool dbfind_stale = false; bool dbfind_stale = false;
@@ -5992,6 +5993,7 @@ query_lookup(query_ctx_t *qctx) {
if (dbfind_stale || stale_refresh_window || stale_timeout) { if (dbfind_stale || stale_refresh_window || stale_timeout) {
dns_name_format(qctx->client->query.qname, namebuf, dns_name_format(qctx->client->query.qname, namebuf,
sizeof(namebuf)); sizeof(namebuf));
dns_rdatatype_format(qctx->qtype, typebuf, sizeof(typebuf));
inc_stats(qctx->client, ns_statscounter_trystale); inc_stats(qctx->client, ns_statscounter_trystale);
@@ -6015,10 +6017,10 @@ query_lookup(query_ctx_t *qctx) {
} }
if (dbfind_stale) { if (dbfind_stale) {
isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE, isc_log_write(
NS_LOGMODULE_QUERY, ISC_LOG_INFO, ns_lctx, NS_LOGCATEGORY_SERVE_STALE, NS_LOGMODULE_QUERY,
"%s resolver failure, stale answer %s", namebuf, ISC_LOG_INFO, "%s %s resolver failure, stale answer %s",
stale_found ? "used" : "unavailable"); namebuf, typebuf, stale_found ? "used" : "unavailable");
if (stale_found) { if (stale_found) {
ns_client_extendederror(qctx->client, ede, ns_client_extendederror(qctx->client, ede,
"resolver failure"); "resolver failure");
@@ -6037,9 +6039,10 @@ query_lookup(query_ctx_t *qctx) {
*/ */
isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE, isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE,
NS_LOGMODULE_QUERY, ISC_LOG_INFO, NS_LOGMODULE_QUERY, ISC_LOG_INFO,
"%s query within stale refresh time, stale " "%s %s query within stale refresh time, stale "
"answer %s", "answer %s",
namebuf, stale_found ? "used" : "unavailable"); namebuf, typebuf,
stale_found ? "used" : "unavailable");
if (stale_found) { if (stale_found) {
ns_client_extendederror( ns_client_extendederror(
@@ -6082,9 +6085,10 @@ query_lookup(query_ctx_t *qctx) {
isc_log_write( isc_log_write(
ns_lctx, NS_LOGCATEGORY_SERVE_STALE, ns_lctx, NS_LOGCATEGORY_SERVE_STALE,
NS_LOGMODULE_QUERY, ISC_LOG_INFO, NS_LOGMODULE_QUERY, ISC_LOG_INFO,
"%s stale answer used, an attempt to " "%s %s stale answer used, an attempt "
"refresh the RRset will still be made", "to refresh the RRset will still be "
namebuf); "made",
namebuf, typebuf);
qctx->refresh_rrset = STALE(qctx->rdataset); qctx->refresh_rrset = STALE(qctx->rdataset);
ns_client_extendederror( ns_client_extendederror(
qctx->client, ede, qctx->client, ede,
@@ -6098,8 +6102,8 @@ query_lookup(query_ctx_t *qctx) {
*/ */
isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE, isc_log_write(ns_lctx, NS_LOGCATEGORY_SERVE_STALE,
NS_LOGMODULE_QUERY, ISC_LOG_INFO, NS_LOGMODULE_QUERY, ISC_LOG_INFO,
"%s client timeout, stale answer %s", "%s %s client timeout, stale answer %s",
namebuf, namebuf, typebuf,
stale_found ? "used" : "unavailable"); stale_found ? "used" : "unavailable");
if (stale_found) { if (stale_found) {
ns_client_extendederror(qctx->client, ede, ns_client_extendederror(qctx->client, ede,