- Merge #892: Add cachedb hit stat. Introduces 'num.query.cachedb' as

a new statistical counter.

cachedb/cachedb.c

@@ -111,6 +111,15 @@ testframe_init(struct module_env* env, struct cachedb_env* cachedb_env)
 		log_err("out of memory");
 		return 0;
 	}
+	/* Register an EDNS option (65534) to bypass the worker cache lookup
+	 * for testing */
+	if(!edns_register_option(LDNS_EDNS_UNBOUND_CACHEDB_TESTFRAME_TEST,
+		1 /* bypass cache */,
+		0 /* no aggregation */, env)) {
+		log_err("testframe_init, could not register test opcode");
+		free(d);
+		return 0;
+	}
 	lock_basic_init(&d->lock);
 	lock_protect(&d->lock, d, sizeof(*d));
 	return 1;
@@ -228,7 +237,7 @@ cachedb_apply_cfg(struct cachedb_env* cachedb_env, struct config_file* cfg)
 	return 1;
 }
 
-int 
+int
 cachedb_init(struct module_env* env, int id)
 {
 	struct cachedb_env* cachedb_env = (struct cachedb_env*)calloc(1,
@@ -267,19 +276,16 @@ cachedb_init(struct module_env* env, int id)
 	return 1;
 }
 
-void 
+void
 cachedb_deinit(struct module_env* env, int id)
 {
 	struct cachedb_env* cachedb_env;
 	if(!env || !env->modinfo[id])
 		return;
 	cachedb_env = (struct cachedb_env*)env->modinfo[id];
-	/* free contents */
-	/* TODO */
 	if(cachedb_env->enabled) {
 		(*cachedb_env->backend->deinit)(env, cachedb_env);
 	}
-
 	free(cachedb_env);
 	env->modinfo[id] = NULL;
 }
@@ -630,11 +636,15 @@ cachedb_extcache_store(struct module_qstate* qstate, struct cachedb_env* ie)
  * See if unbound's internal cache can answer the query
  */
 static int
-cachedb_intcache_lookup(struct module_qstate* qstate)
+cachedb_intcache_lookup(struct module_qstate* qstate, struct cachedb_env* cde)
 {
 	uint8_t* dpname=NULL;
 	size_t dpnamelen=0;
 	struct dns_msg* msg;
+	/* for testframe bypass this lookup */
+	if(cde->backend == &testframe_backend) {
+		return 0;
+	}
 	if(iter_stub_fwd_no_cache(qstate, &qstate->qinfo,
 		&dpname, &dpnamelen))
 		return 0; /* no cache for these queries */
@@ -693,6 +703,7 @@ cachedb_handle_query(struct module_qstate* qstate,
 	struct cachedb_qstate* ATTR_UNUSED(iq),
 	struct cachedb_env* ie, int id)
 {
+	qstate->is_cachedb_answer = 0;
 	/* check if we are enabled, and skip if so */
 	if(!ie->enabled) {
 		/* pass request to next module */
@@ -709,7 +720,7 @@ cachedb_handle_query(struct module_qstate* qstate,
 
 	/* lookup inside unbound's internal cache.
 	 * This does not look for expired entries. */
-	if(cachedb_intcache_lookup(qstate)) {
+	if(cachedb_intcache_lookup(qstate, ie)) {
 		if(verbosity >= VERB_ALGO) {
 			if(qstate->return_msg->rep)
 				log_dns_msg("cachedb internal cache lookup",
@@ -746,6 +757,7 @@ cachedb_handle_query(struct module_qstate* qstate,
 				qstate->ext_state[id] = module_wait_module;
 				return;
 		}
+		qstate->is_cachedb_answer = 1;
 		/* we are done with the query */
 		qstate->ext_state[id] = module_finished;
 		return;
@@ -768,6 +780,7 @@ static void
 cachedb_handle_response(struct module_qstate* qstate,
 	struct cachedb_qstate* ATTR_UNUSED(iq), struct cachedb_env* ie, int id)
 {
+	qstate->is_cachedb_answer = 0;
 	/* check if we are not enabled or instructed to not cache, and skip */
 	if(!ie->enabled || qstate->no_cache_store) {
 		/* we are done with the query */

daemon/remote.c

@@ -1064,6 +1064,10 @@ print_ext(RES* ssl, struct ub_stats_info* s, int inhibit_zero)
 	if(!ssl_printf(ssl, "num.query.subnet_cache"SQ"%lu\n",
 		(unsigned long)s->svr.num_query_subnet_cache)) return 0;
 #endif /* CLIENT_SUBNET */
+#ifdef USE_CACHEDB
+	if(!ssl_printf(ssl, "num.query.cachedb"SQ"%lu\n",
+		(unsigned long)s->svr.num_query_cachedb)) return 0;
+#endif /* USE_CACHEDB */
 	return 1;
 }
 

daemon/stats.c

@@ -356,6 +356,11 @@ server_stats_compile(struct worker* worker, struct ub_stats_info* s, int reset)
 	s->svr.num_query_subnet = 0;
 	s->svr.num_query_subnet_cache = 0;
 #endif
+#ifdef USE_CACHEDB
+	s->svr.num_query_cachedb = (long long)worker->env.mesh->ans_cachedb;
+#else
+	s->svr.num_query_cachedb = 0;
+#endif
 
 	/* get tcp accept usage */
 	s->svr.tcp_accept_usage = 0;
@@ -476,6 +481,9 @@ void server_stats_add(struct ub_stats_info* total, struct ub_stats_info* a)
 		total->svr.unwanted_replies += a->svr.unwanted_replies;
 		total->svr.unwanted_queries += a->svr.unwanted_queries;
 		total->svr.tcp_accept_usage += a->svr.tcp_accept_usage;
+#ifdef USE_CACHEDB
+		total->svr.num_query_cachedb += a->svr.num_query_cachedb;
+#endif
 		for(i=0; i<UB_STATS_QTYPE_NUM; i++)
 			total->svr.qtype[i] += a->svr.qtype[i];
 		for(i=0; i<UB_STATS_QCLASS_NUM; i++)

doc/Changelog

@@ -1,3 +1,7 @@
+27 June 2023: George
+	- Merge #892: Add cachedb hit stat. Introduces 'num.query.cachedb' as
+	  a new statistical counter.
+
 22 June 2023: Wouter
 	- Merge #903: contrib: add yocto compatible init script.
 

doc/unbound-control.8.in

@@ -718,7 +718,12 @@ Number of queries that got an answer that contained EDNS client subnet data.
 .I num.query.subnet_cache
 Number of queries answered from the edns client subnet cache.  These are
 counted as cachemiss by the main counters, but hit the client subnet
-specific cache, after getting processed by the edns client subnet module.
+specific cache after getting processed by the edns client subnet module.
+.TP
+.I num.query.cachedb
+Number of queries answered from the external cache of cachedb.
+These are counted as cachemiss by the main counters, but hit the cachedb
+external cache after getting processed by the cachedb module.
 .TP
 .I num.rpz.action.<rpz_action>
 Number of queries answered using configured RPZ policy, per RPZ action type.

libunbound/unbound.h

@@ -827,6 +827,8 @@ struct ub_server_stats {
 	/** number of queries answered from edns-subnet specific data, and
 	 * the answer was from the edns-subnet cache. */
 	long long num_query_subnet_cache;
+	/** number of queries served from cachedb */
+	long long num_query_cachedb;
 	/** number of bytes in the stream wait buffers */
 	long long mem_stream_wait;
 	/** number of bytes in the HTTP2 query buffers */

services/mesh.c

@@ -206,6 +206,7 @@ mesh_create(struct module_stack* stack, struct module_env* env)
 	mesh->stats_jostled = 0;
 	mesh->stats_dropped = 0;
 	mesh->ans_expired = 0;
+	mesh->ans_cachedb = 0;
 	mesh->max_reply_states = env->cfg->num_queries_per_thread;
 	mesh->max_forever_states = (mesh->max_reply_states+1)/2;
 #ifndef S_SPLINT_S
@@ -1424,6 +1425,7 @@ void mesh_query_done(struct mesh_state* mstate)
 	struct reply_info* rep = (mstate->s.return_msg?
 		mstate->s.return_msg->rep:NULL);
 	struct timeval tv = {0, 0};
+	int i = 0;
 	/* No need for the serve expired timer anymore; we are going to reply. */
 	if(mstate->s.serve_expired_data) {
 		comm_timer_delete(mstate->s.serve_expired_data->timer);
@@ -1443,6 +1445,7 @@ void mesh_query_done(struct mesh_state* mstate)
 		}
 	}
 	for(r = mstate->reply_list; r; r = r->next) {
+		i++;
 		tv = r->start_time;
 
 		/* if a response-ip address block has been stored the
@@ -1454,16 +1457,6 @@ void mesh_query_done(struct mesh_state* mstate)
 				mstate->s.qinfo.qclass, r->local_alias,
 				&r->query_reply.client_addr,
 				r->query_reply.client_addrlen);
-			if(mstate->s.env->cfg->stat_extended &&
-				mstate->s.respip_action_info->rpz_used) {
-				if(mstate->s.respip_action_info->rpz_disabled)
-					mstate->s.env->mesh->rpz_action[RPZ_DISABLED_ACTION]++;
-				if(mstate->s.respip_action_info->rpz_cname_override)
-					mstate->s.env->mesh->rpz_action[RPZ_CNAME_OVERRIDE_ACTION]++;
-				else
-					mstate->s.env->mesh->rpz_action[respip_action_to_rpz_action(
-						mstate->s.respip_action_info->action)]++;
-			}
 		}
 
 		/* if this query is determined to be dropped during the
@@ -1494,6 +1487,27 @@ void mesh_query_done(struct mesh_state* mstate)
 			prev_buffer = r_buffer;
 		}
 	}
+	/* Account for each reply sent. */
+	if(i > 0 && mstate->s.respip_action_info &&
+		mstate->s.respip_action_info->addrinfo &&
+		mstate->s.env->cfg->stat_extended &&
+		mstate->s.respip_action_info->rpz_used) {
+		if(mstate->s.respip_action_info->rpz_disabled)
+			mstate->s.env->mesh->rpz_action[RPZ_DISABLED_ACTION] += i;
+		if(mstate->s.respip_action_info->rpz_cname_override)
+			mstate->s.env->mesh->rpz_action[RPZ_CNAME_OVERRIDE_ACTION] += i;
+		else
+			mstate->s.env->mesh->rpz_action[respip_action_to_rpz_action(
+				mstate->s.respip_action_info->action)] += i;
+	}
+	if(!mstate->s.is_drop && i > 0) {
+		if(mstate->s.env->cfg->stat_extended
+			&& mstate->s.is_cachedb_answer) {
+			mstate->s.env->mesh->ans_cachedb += i;
+		}
+	}
+
+	/* Mesh area accounting */
 	if(mstate->reply_list) {
 		mstate->reply_list = NULL;
 		if(!mstate->reply_list && !mstate->cb_list) {
@@ -1506,6 +1520,7 @@ void mesh_query_done(struct mesh_state* mstate)
 			mstate->s.env->mesh->num_detached_states++;
 	}
 	mstate->replies_sent = 1;
+
 	while((c = mstate->cb_list) != NULL) {
 		/* take this cb off the list; so that the list can be
 		 * changed, eg. by adds from the callback routine */
@@ -1889,6 +1904,7 @@ mesh_stats_clear(struct mesh_area* mesh)
 	mesh->ans_secure = 0;
 	mesh->ans_bogus = 0;
 	mesh->ans_expired = 0;
+	mesh->ans_cachedb = 0;
 	memset(&mesh->ans_rcode[0], 0, sizeof(size_t)*UB_STATS_RCODE_NUM);
 	memset(&mesh->rpz_action[0], 0, sizeof(size_t)*UB_STATS_RPZ_ACTION_NUM);
 	mesh->ans_nodata = 0;
@@ -2025,6 +2041,7 @@ mesh_serve_expired_callback(void* arg)
 	struct timeval tv = {0, 0};
 	int must_validate = (!(qstate->query_flags&BIT_CD)
 		|| qstate->env->cfg->ignore_cd) && qstate->env->need_to_validate;
+	int i = 0;
 	if(!qstate->serve_expired_data) return;
 	verbose(VERB_ALGO, "Serve expired: Trying to reply with expired data");
 	comm_timer_delete(qstate->serve_expired_data->timer);
@@ -2096,6 +2113,7 @@ mesh_serve_expired_callback(void* arg)
 		log_dns_msg("Serve expired lookup", &qstate->qinfo, msg->rep);
 
 	for(r = mstate->reply_list; r; r = r->next) {
+		i++;
 		tv = r->start_time;
 
 		/* If address info is returned, it means the action should be an
@@ -2105,16 +2123,6 @@ mesh_serve_expired_callback(void* arg)
 				qstate->qinfo.qtype, qstate->qinfo.qclass,
 				r->local_alias, &r->query_reply.client_addr,
 				r->query_reply.client_addrlen);
-
-			if(qstate->env->cfg->stat_extended && actinfo.rpz_used) {
-				if(actinfo.rpz_disabled)
-					qstate->env->mesh->rpz_action[RPZ_DISABLED_ACTION]++;
-				if(actinfo.rpz_cname_override)
-					qstate->env->mesh->rpz_action[RPZ_CNAME_OVERRIDE_ACTION]++;
-				else
-					qstate->env->mesh->rpz_action[
-						respip_action_to_rpz_action(actinfo.action)]++;
-			}
 		}
 
 		/* Add EDE Stale Answer (RCF8914). Ignore global ede as this is
@@ -2134,11 +2142,23 @@ mesh_serve_expired_callback(void* arg)
 			tcp_req_info_remove_mesh_state(r->query_reply.c->tcp_req_info, mstate);
 		prev = r;
 		prev_buffer = r_buffer;
-
-		/* Account for each reply sent. */
-		mesh->ans_expired++;
-
 	}
+	/* Account for each reply sent. */
+	if(i > 0) {
+		mesh->ans_expired += i;
+		if(actinfo.addrinfo && qstate->env->cfg->stat_extended &&
+			actinfo.rpz_used) {
+			if(actinfo.rpz_disabled)
+				qstate->env->mesh->rpz_action[RPZ_DISABLED_ACTION] += i;
+			if(actinfo.rpz_cname_override)
+				qstate->env->mesh->rpz_action[RPZ_CNAME_OVERRIDE_ACTION] += i;
+			else
+				qstate->env->mesh->rpz_action[
+					respip_action_to_rpz_action(actinfo.action)] += i;
+		}
+	}
+
+	/* Mesh area accounting */
 	if(mstate->reply_list) {
 		mstate->reply_list = NULL;
 		if(!mstate->reply_list && !mstate->cb_list) {
@@ -2149,6 +2169,7 @@ mesh_serve_expired_callback(void* arg)
 			}
 		}
 	}
+
 	while((c = mstate->cb_list) != NULL) {
 		/* take this cb off the list; so that the list can be
 		 * changed, eg. by adds from the callback routine */

services/mesh.h

@@ -114,6 +114,8 @@ struct mesh_area {
 	size_t stats_dropped;
 	/** stats, number of expired replies sent */
 	size_t ans_expired;
+	/** stats, number of cached replies from cachedb */
+	size_t ans_cachedb;
 	/** number of replies sent */
 	size_t replies_sent;
 	/** sum of waiting times for the replies */

sldns/rrdef.h

@@ -436,7 +436,8 @@ enum sldns_enum_edns_option
 	LDNS_EDNS_KEEPALIVE = 11, /* draft-ietf-dnsop-edns-tcp-keepalive*/
 	LDNS_EDNS_PADDING = 12, /* RFC7830 */
 	LDNS_EDNS_EDE = 15, /* RFC8914 */
-	LDNS_EDNS_CLIENT_TAG = 16 /* draft-bellis-dnsop-edns-tags-01 */
+	LDNS_EDNS_CLIENT_TAG = 16, /* draft-bellis-dnsop-edns-tags-01 */
+	LDNS_EDNS_UNBOUND_CACHEDB_TESTFRAME_TEST = 65534
 };
 typedef enum sldns_enum_edns_option sldns_edns_option;
 

smallapp/unbound-control.c

@@ -407,6 +407,9 @@ static void print_extended(struct ub_stats_info* s, int inhibit_zero)
 	PR_UL("num.query.subnet", s->svr.num_query_subnet);
 	PR_UL("num.query.subnet_cache", s->svr.num_query_subnet_cache);
 #endif
+#ifdef USE_CACHEDB
+	PR_UL("num.query.cachedb", s->svr.num_query_cachedb);
+#endif
 }
 
 /** print statistics out of memory structures */

testdata/stat_values.tdir/stat_values.pre

@@ -5,6 +5,13 @@
 [ -f .tpkg.var.test ] && source .tpkg.var.test
 
 . ../common.sh
+
+PRE="../.."
+if grep "define USE_CACHEDB 1" $PRE/config.h; then
+    USE_CACHEDB=1
+    echo "USE_CACHEDB=1" >> .tpkg.var.test
+fi
+
 get_random_port 4
 UNBOUND_PORT=$RND_PORT
 FWD_PORT=$(($RND_PORT + 1))
@@ -29,8 +36,8 @@ echo "FWD_EXPIRED_PID=$FWD_EXPIRED_PID" >> .tpkg.var.test
 
 # make config file
 sed -e 's/@PORT\@/'$UNBOUND_PORT'/' -e 's/@TOPORT\@/'$FWD_PORT'/' -e 's/@EXPIREDPORT\@/'$FWD_EXPIRED_PORT'/' -e 's/@CONTROL_PORT\@/'$CONTROL_PORT'/' < stat_values.conf > ub.conf
+sed -e 's/@PORT\@/'$UNBOUND_PORT'/' -e 's/@TOPORT\@/'$FWD_PORT'/' -e 's/@EXPIREDPORT\@/'$FWD_EXPIRED_PORT'/' -e 's/@CONTROL_PORT\@/'$CONTROL_PORT'/' < stat_values_cachedb.conf > ub_cachedb.conf
 # start unbound in the background
-PRE="../.."
 $PRE/unbound -d -c ub.conf >unbound.log 2>&1 &
 UNBOUND_PID=$!
 echo "UNBOUND_PID=$UNBOUND_PID" >> .tpkg.var.test

testdata/stat_values.tdir/stat_values.test

@@ -95,7 +95,7 @@ check_expected_stats () {
 	else
 		echo "! bad expected stats:"
         cat $FILTERED_STATS_FILE
-		exit 1
+		end 1
 	fi
 }
 
@@ -109,7 +109,7 @@ check_rest_stats () {
 	fi
 	if grep -v "=0$" $REST_STATS_FILE; then
 		echo "! bad rest stats"
-		exit 1
+		end 1
 	else
 		echo "OK"
 	fi
@@ -414,4 +414,98 @@ rrset.cache.count=3
 infra.cache.count=2"
 
 
+if test x$USE_CACHEDB = "x1"; then
+
+# Bring the cachedb configured Unbound up
+kill_pid $UNBOUND_PID  # kill current Unbound
+$PRE/unbound -d -c ub_cachedb.conf >unbound.log 2>&1 &
+UNBOUND_PID=$!
+echo "UNBOUND_PID=$UNBOUND_PID" >> .tpkg.var.test
+wait_unbound_up unbound.log
+
+echo
+echo "[ Check cachedb cache miss. ]"
+echo "> dig www.example.com."
+dig @127.0.0.1 +ednsopt=65534 -p $UNBOUND_PORT www.example.com. | tee outfile
+echo "> check answer"
+if grep "10.20.30.40" outfile; then
+	echo "OK"
+else
+	end 1
+fi
+check_stats "\
+total.num.queries=1
+total.num.cachemiss=1
+total.num.cachehits=0
+total.num.recursivereplies=1
+num.query.type.A=1
+num.query.class.IN=1
+num.query.opcode.QUERY=1
+num.query.flags.RD=1
+num.query.flags.AD=1
+num.query.edns.present=1
+num.query.udpout=1
+num.query.cachedb=0
+msg.cache.count=1
+rrset.cache.count=1
+infra.cache.count=1
+num.answer.rcode.NOERROR=1"
+
+echo
+echo "[ Check cachedb cache hit. ]"
+echo "> dig www.example.com."
+dig @127.0.0.1 +ednsopt=65534 -p $UNBOUND_PORT www.example.com. | tee outfile
+echo "> check answer"
+if grep "10.20.30.40" outfile; then
+	echo "OK"
+else
+	end 1
+fi
+check_stats "\
+total.num.queries=1
+total.num.cachemiss=1
+total.num.cachehits=0
+total.num.recursivereplies=1
+num.query.type.A=1
+num.query.class.IN=1
+num.query.opcode.QUERY=1
+num.query.flags.RD=1
+num.query.flags.AD=1
+num.query.edns.present=1
+num.query.udpout=0
+num.query.cachedb=1
+msg.cache.count=1
+rrset.cache.count=1
+infra.cache.count=1
+num.answer.rcode.NOERROR=1"
+
+echo
+echo "[ Check cachedb cache hit with stat reset ]"
+echo "> dig www.example.com."
+dig @127.0.0.1 +ednsopt=65534 -p $UNBOUND_PORT www.example.com. | tee outfile
+echo "> check answer"
+if grep "10.20.30.40" outfile; then
+	echo "OK"
+else
+	end 1
+fi
+check_stats "\
+total.num.queries=1
+total.num.cachemiss=1
+total.num.cachehits=0
+total.num.recursivereplies=1
+num.query.type.A=1
+num.query.class.IN=1
+num.query.opcode.QUERY=1
+num.query.flags.RD=1
+num.query.flags.AD=1
+num.query.edns.present=1
+num.query.cachedb=1
+msg.cache.count=1
+rrset.cache.count=1
+infra.cache.count=1
+num.answer.rcode.NOERROR=1"
+
+fi  # USE_CACHEDB
+
 end 0

testdata/stat_values.tdir/stat_values.testns

@@ -21,3 +21,13 @@ SECTION QUESTION
 SECTION ANSWER
 1ttl	1 IN	A 1.1.1.1
 ENTRY_END
+
+ENTRY_BEGIN
+MATCH opcode qtype qname
+REPLY QR AA NOERROR
+ADJUST copy_id
+SECTION QUESTION
+0ttl	IN	A
+SECTION ANSWER
+0ttl	0 IN	A 0.0.0.1
+ENTRY_END

testdata/stat_values.tdir/stat_values_cachedb.conf

@@ -0,0 +1,36 @@
+server:
+	verbosity: 5
+	module-config: "cachedb iterator"
+	serve-expired: yes
+	num-threads: 1
+	interface: 127.0.0.1
+	port: @PORT@
+	use-syslog: no
+	directory: ""
+	pidfile: "unbound.pid"
+	chroot: ""
+	username: ""
+	do-not-query-localhost: no
+	extended-statistics: yes
+	identity: "stat_values"
+	outbound-msg-retry: 0
+	root-key-sentinel: no
+	trust-anchor-signaling: no
+
+	local-zone: local.zone static
+	local-data: "www.local.zone A 192.0.2.1"
+remote-control:
+	control-enable: yes
+	control-interface: 127.0.0.1
+	# control-interface: ::1
+	control-port: @CONTROL_PORT@
+	server-key-file: "unbound_server.key"
+	server-cert-file: "unbound_server.pem"
+	control-key-file: "unbound_control.key"
+	control-cert-file: "unbound_control.pem"
+forward-zone:
+	name: "."
+	forward-addr: "127.0.0.1@@TOPORT@"
+forward-zone:
+	name: "expired."
+	forward-addr: "127.0.0.1@@EXPIREDPORT@"

util/module.h

@@ -677,6 +677,8 @@ struct module_qstate {
 	 * those servers. By comparing expiry time with qstarttime for type NS.
 	 */
 	time_t qstarttime;
+	/** whether a message from cachedb will be used for the reply */
+	int is_cachedb_answer;
 
 	/**
 	 * Attributes of clients that share the qstate that may affect IP-based