From 95fc05c45468d023f302dc0d1ea8ab1a2f1d1c84 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20=C5=A0pa=C4=8Dek?= Date: Fri, 5 Aug 2022 14:03:30 +0200 Subject: [PATCH 1/4] Log reason why recursion is not available Log which ACL caused RA=0 condition. Expected performance impact is negligible. --- lib/ns/client.c | 64 ++++++++++++++++++++++++++++++++++++------------- 1 file changed, 48 insertions(+), 16 deletions(-) diff --git a/lib/ns/client.c b/lib/ns/client.c index 6c491afa59..70e091a45b 100644 --- a/lib/ns/client.c +++ b/lib/ns/client.c @@ -1713,6 +1713,24 @@ ns__client_request(isc_nmhandle_t *handle, isc_result_t eresult, #ifdef HAVE_DNSTAP dns_dtmsgtype_t dtmsgtype; #endif /* ifdef HAVE_DNSTAP */ + static const char *ra_reasons[] = { + "ACLs not processed yet", + "no resolver in view", + "recursion not enabled for view", + "allow-recursion did not match", + "allow-query-cache did not match", + "allow-recursion-on did not match", + "allow-query-cache-on did not match", + }; + enum refusal_reasons { + INVALID, + NO_RESOLVER, + RECURSION_DISABLED, + ALLOW_RECURSION, + ALLOW_QUERY_CACHE, + ALLOW_RECURSION_ON, + ALLOW_QUERY_CACHE_ON + } ra_refusal_reason = INVALID; if (eresult != ISC_R_SUCCESS) { return; @@ -2152,28 +2170,42 @@ ns__client_request(isc_nmhandle_t *handle, isc_result_t eresult, * cache there is no point in setting RA. */ ra = false; - if (client->view->resolver != NULL && client->view->recursion && - ns_client_checkaclsilent(client, NULL, client->view->recursionacl, - true) == ISC_R_SUCCESS && - ns_client_checkaclsilent(client, NULL, client->view->cacheacl, - true) == ISC_R_SUCCESS && - ns_client_checkaclsilent(client, &client->destaddr, - client->view->recursiononacl, - true) == ISC_R_SUCCESS && - ns_client_checkaclsilent(client, &client->destaddr, - client->view->cacheonacl, - true) == ISC_R_SUCCESS) - { - ra = true; - } - if (ra) { + /* must be initialized before ns_client_log uses it as index */ + if (client->view->resolver == NULL) { + ra_refusal_reason = NO_RESOLVER; + } else if (!client->view->recursion) { + ra_refusal_reason = RECURSION_DISABLED; + } else if (ns_client_checkaclsilent(client, NULL, + client->view->recursionacl, + true) != ISC_R_SUCCESS) + { + ra_refusal_reason = ALLOW_RECURSION; + } else if (ns_client_checkaclsilent(client, NULL, + client->view->cacheacl, + true) != ISC_R_SUCCESS) + { + ra_refusal_reason = ALLOW_QUERY_CACHE; + } else if (ns_client_checkaclsilent(client, &client->destaddr, + client->view->recursiononacl, + true) != ISC_R_SUCCESS) + { + ra_refusal_reason = ALLOW_RECURSION_ON; + } else if (ns_client_checkaclsilent(client, &client->destaddr, + client->view->cacheonacl, + true) != ISC_R_SUCCESS) + { + ra_refusal_reason = ALLOW_QUERY_CACHE_ON; + } else { + ra = true; client->attributes |= NS_CLIENTATTR_RA; } ns_client_log(client, DNS_LOGCATEGORY_SECURITY, NS_LOGMODULE_CLIENT, ISC_LOG_DEBUG(3), - ra ? "recursion available" : "recursion not available"); + ra ? "recursion available" + : "recursion not available (%s)", + ra_reasons[ra_refusal_reason]); /* * Adjust maximum UDP response size for this client. From fdf74566432a67761bf940224e6145ea435f5edf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20=C5=A0pa=C4=8Dek?= Date: Fri, 5 Aug 2022 15:21:35 +0200 Subject: [PATCH 2/4] Log reason why cache peek is not available Log which ACL caused RD=0 query into cache to be refused. Expected performance impact is negligible. --- lib/ns/query.c | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/lib/ns/query.c b/lib/ns/query.c index beeae0e653..46ef30e515 100644 --- a/lib/ns/query.c +++ b/lib/ns/query.c @@ -844,6 +844,15 @@ query_checkcacheaccess(ns_client_t *client, const dns_name_t *name, isc_result_t result; if ((client->query.attributes & NS_QUERYATTR_CACHEACLOKVALID) == 0) { + enum refusal_reasons { + ALLOW_QUERY_CACHE, + ALLOW_QUERY_CACHE_ON + }; + static const char *acl_desc[] = { + "allow-query-cache did not match", + "allow-query-cache-on did not match", + }; + /* * The view's cache ACLs have not yet been evaluated. * Do it now. Both allow-query-cache and @@ -852,9 +861,11 @@ query_checkcacheaccess(ns_client_t *client, const dns_name_t *name, bool log = ((options & DNS_GETDB_NOLOG) == 0); char msg[NS_CLIENT_ACLMSGSIZE("query (cache)")]; + enum refusal_reasons refusal_reason = ALLOW_QUERY_CACHE; result = ns_client_checkaclsilent(client, NULL, client->view->cacheacl, true); if (result == ISC_R_SUCCESS) { + refusal_reason = ALLOW_QUERY_CACHE_ON; result = ns_client_checkaclsilent( client, &client->destaddr, client->view->cacheonacl, true); @@ -890,7 +901,8 @@ query_checkcacheaccess(ns_client_t *client, const dns_name_t *name, sizeof(msg)); ns_client_log(client, DNS_LOGCATEGORY_SECURITY, NS_LOGMODULE_QUERY, ISC_LOG_INFO, - "%s denied", msg); + "%s denied (%s)", msg, + acl_desc[refusal_reason]); } } From 67c3a3439bddf25b72793b04aeb2e0618c8c9be7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20=C5=A0pa=C4=8Dek?= Date: Wed, 14 Sep 2022 12:32:41 +0200 Subject: [PATCH 3/4] CHANGES note for [GL !6669] --- CHANGES | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGES b/CHANGES index 68770f4101..e83f11d7b6 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,5 @@ +5970. [func] Log the reason why a query was refused. [GL !6669] + 5969. [bug] DNSSEC signing statistics failed to identify the algorithm involved. The key names have been changed to be the algorithm number followed by "+" followed From a2bbe578bf9f1c0a8726a50baca4f6ee38a5565b Mon Sep 17 00:00:00 2001 From: Evan Hunt Date: Wed, 14 Sep 2022 12:49:20 -0700 Subject: [PATCH 4/4] Add tests for the new log messages with refusal reason Update the allow-query test to check for the new log messages. --- bin/tests/system/allow-query/tests.sh | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/bin/tests/system/allow-query/tests.sh b/bin/tests/system/allow-query/tests.sh index 97a0859637..74a372e79f 100644 --- a/bin/tests/system/allow-query/tests.sh +++ b/bin/tests/system/allow-query/tests.sh @@ -95,6 +95,7 @@ $DIG $DIGOPTS @10.53.0.2 -b 10.53.0.2 a.normal.example a > dig.out.ns2.$n || ret grep 'status: REFUSED' dig.out.ns2.$n > /dev/null || ret=1 grep 'EDE: 18 (Prohibited)' dig.out.ns2.$n > /dev/null || ret=1 grep '^a.normal.example' dig.out.ns2.$n > /dev/null && ret=1 +nextpart ns2/named.run | grep 'recursion not enabled for view' > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -636,11 +637,13 @@ status=`expr $status + $ret` n=`expr $n + 1` echo_i "test $n: default allow-recursion configuration" ret=0 +nextpart ns3/named.run > /dev/null $DIG -p ${PORT} @10.53.0.3 -b 127.0.0.1 a.normal.example a > dig.out.ns3.1.$n grep 'status: NOERROR' dig.out.ns3.1.$n > /dev/null || ret=1 $DIG -p ${PORT} @10.53.0.3 -b 10.53.0.1 a.normal.example a > dig.out.ns3.2.$n grep 'status: REFUSED' dig.out.ns3.2.$n > /dev/null || ret=1 grep 'EDE: 18 (Prohibited)' dig.out.ns3.2.$n > /dev/null || ret=1 +nextpart ns3/named.run | grep 'allow-recursion did not match' > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -653,6 +656,7 @@ grep 'status: NOERROR' dig.out.ns3.1.$n > /dev/null || ret=1 $DIG -p ${PORT} @10.53.0.3 -b 10.53.0.1 ns . > dig.out.ns3.2.$n grep 'status: REFUSED' dig.out.ns3.2.$n > /dev/null || ret=1 grep 'EDE: 18 (Prohibited)' dig.out.ns3.2.$n > /dev/null || ret=1 +nextpart ns3/named.run | grep 'allow-recursion did not match' > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -671,6 +675,7 @@ grep 'ANSWER: 1' dig.out.ns3.1.$n > /dev/null || ret=1 $DIG -p ${PORT} @10.53.0.3 b.normal.example a > dig.out.ns3.2.$n grep 'recursion requested but not available' dig.out.ns3.2.$n > /dev/null || ret=1 grep 'ANSWER: 0' dig.out.ns3.2.$n > /dev/null || ret=1 +nextpart ns3/named.run | grep 'allow-recursion-on did not match' > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -697,6 +702,7 @@ $DIG -p ${PORT} @10.53.1.2 d.normal.example a > dig.out.ns3.4.$n grep 'recursion requested but not available' dig.out.ns3.4.$n > /dev/null || ret=1 grep 'status: REFUSED' dig.out.ns3.4.$n > /dev/null || ret=1 grep 'EDE: 18 (Prohibited)' dig.out.ns3.4.$n > /dev/null || ret=1 +nextpart ns3/named.run | grep 'allow-recursion-on did not match' > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -723,6 +729,7 @@ $DIG -p ${PORT} @10.53.1.2 f.normal.example a > dig.out.ns3.4.$n grep 'recursion requested but not available' dig.out.ns3.4.$n > /dev/null || ret=1 grep 'status: REFUSED' dig.out.ns3.4.$n > /dev/null || ret=1 grep 'EDE: 18 (Prohibited)' dig.out.ns3.4.$n > /dev/null || ret=1 +nextpart ns3/named.run | grep 'allow-recursion-on did not match' > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret`