Merge remote-tracking branch 'nlnet/master'

* nlnet/master:
  - Fix NLnetLabs#1144: [FR] log timestamps in ISO8601 format with timezone.   This adds the option `log-time-iso: yes` that logs in ISO8601   format.
  Changelog entry for NLnetLabs#1143: - Merge NLnetLabs#1143: Fix cache update when serve expired is used. Expired   records are favored over resolution and validation failures when   serve-expired is used.
  Fix cache update when serve expired is used (NLnetLabs#1143)
  - More clear text for prefetch and minimal-responses in the   unbound.conf man page.
  - Attempt to further fix doh_downstream_buffer_size.tdir flakiness.

cachedb/cachedb.c

@@ -828,8 +828,6 @@ cachedb_handle_query(struct module_qstate* qstate,
 		/* In case we have expired data but there is a client timer for expired
 		 * answers, pass execution to next module in order to try updating the
 		 * data first.
-		 * TODO: this needs revisit. The expired data stored from cachedb has
-		 * 0 TTL which is picked up by iterator later when looking in the cache.
 		 */
 		if(qstate->env->cfg->serve_expired && msg_expired) {
 			qstate->return_msg = NULL;

daemon/remote.c

@@ -1953,6 +1953,8 @@ bogus_del_msg(struct lruhash_entry* e, void* arg)
 	struct reply_info* d = (struct reply_info*)e->data;
 	if(d->security == sec_status_bogus) {
 		d->ttl = inf->expired;
+		d->prefetch_ttl = inf->expired;
+		d->serve_expired_ttl = inf->expired;
 		inf->num_msgs++;
 #ifdef USE_CACHEDB
 		if(inf->remcachedb && inf->worker->env.cachedb_enabled)
@@ -2035,6 +2037,8 @@ negative_del_msg(struct lruhash_entry* e, void* arg)
 	 * or NOERROR rcode with ANCOUNT==0: a NODATA answer */
 	if(FLAGS_GET_RCODE(d->flags) != 0 || d->an_numrrsets == 0) {
 		d->ttl = inf->expired;
+		d->prefetch_ttl = inf->expired;
+		d->serve_expired_ttl = inf->expired;
 		inf->num_msgs++;
 #ifdef USE_CACHEDB
 		if(inf->remcachedb && inf->worker->env.cachedb_enabled)

daemon/worker.c

@@ -661,22 +661,18 @@ answer_from_cache(struct worker* worker, struct query_info* qinfo,
 	if(rep->ttl < timenow) {
 		/* Check if we need to serve expired now */
 		if(worker->env.cfg->serve_expired &&
-			!worker->env.cfg->serve_expired_client_timeout
+			/* if serve-expired-client-timeout is set, serve
+			 * an expired record without attempting recursion
+			 * if the serve_expired_norec_ttl is set for the record
+			 * as we know that recursion is currently failing. */
+			(!worker->env.cfg->serve_expired_client_timeout ||
+			 timenow < rep->serve_expired_norec_ttl)
 #ifdef USE_CACHEDB
 			&& !(worker->env.cachedb_enabled &&
 			  worker->env.cfg->cachedb_check_when_serve_expired)
 #endif
 			) {
-				if(worker->env.cfg->serve_expired_ttl &&
-					rep->serve_expired_ttl < timenow)
-					return 0;
-				/* Ignore expired failure answers */
-				if(FLAGS_GET_RCODE(rep->flags) !=
-					LDNS_RCODE_NOERROR &&
-					FLAGS_GET_RCODE(rep->flags) !=
-					LDNS_RCODE_NXDOMAIN &&
-					FLAGS_GET_RCODE(rep->flags) !=
-					LDNS_RCODE_YXDOMAIN)
+				if(!reply_info_can_answer_expired(rep, timenow))
 					return 0;
 				if(!rrset_array_lock(rep->ref, rep->rrset_count, 0))
 					return 0;

dns64/dns64.c

@@ -847,6 +847,7 @@ dns64_adjust_a(int id, struct module_qstate* super, struct module_qstate* qstate
 	 */
 	cp = construct_reply_info_base(super->region, rep->flags, rep->qdcount,
 		rep->ttl, rep->prefetch_ttl, rep->serve_expired_ttl,
+		rep->serve_expired_norec_ttl,
 		rep->an_numrrsets, rep->ns_numrrsets, rep->ar_numrrsets,
 		rep->rrset_count, rep->security, LDNS_EDE_NONE);
 	if(!cp)

doc/Changelog

@@ -1,3 +1,16 @@
+25 September 2024: Wouter
+	- Fix #1144: [FR] log timestamps in ISO8601 format with timezone.
+	  This adds the option `log-time-iso: yes` that logs in ISO8601
+	  format.
+
+24 September 2024: Yorgos
+	- Attempt to further fix doh_downstream_buffer_size.tdir flakiness.
+	- More clear text for prefetch and minimal-responses in the
+	  unbound.conf man page.
+	- Merge #1143: Fix cache update when serve expired is used. Expired
+	  records are favored over resolution and validation failures when
+	  serve-expired is used.
+
 23 September 2024: Wouter
 	- Fix dns64 with prefetch that the prefetch is stored in cache.
 

doc/example.conf.in

@@ -461,6 +461,10 @@ server:
 	# print UTC timestamp in ascii to logfile, default is epoch in seconds.
 	# log-time-ascii: no
 
+	# log timestamp in ISO8601 format if also log-time-ascii is enabled.
+	# (y-m-dTh:m:s.msec[+-]tzhours:tzminutes)
+	# log-time-iso: no
+
 	# print one line with time, IP, name, type, class for every query.
 	# log-queries: no
 

doc/unbound.conf.5.in

@@ -936,6 +936,10 @@ Sets logfile lines to use a timestamp in UTC ascii. Default is no, which
 prints the seconds since 1970 in brackets. No effect if using syslog, in
 that case syslog formats the timestamp printed into the log files.
 .TP
+.B log\-time\-iso:\fR <yes or no>
+Log time in ISO8601 format, if \fBlog\-time\-ascii:\fR yes is also set.
+Default is no.
+.TP
 .B log\-queries: \fI<yes or no>
 Prints one line per query to the log, with the log timestamp and IP address,
 name, type and class.  Default is no.  Note that it takes time to print these
@@ -1176,10 +1180,11 @@ IP6 ::1 and IP4 127.0.0.1/8. If no, then localhost can be used to send
 queries to. Default is yes.
 .TP
 .B prefetch: \fI<yes or no>
-If yes, message cache elements are prefetched before they expire to
-keep the cache up to date.  Default is no.  Turning it on gives about
-10 percent more traffic and load on the machine, but popular items do
-not expire from the cache.
+If yes, cache hits on message cache elements that are on their last 10 percent
+of their TTL value trigger a prefetch to keep the cache up to date.
+Default is no.
+Turning it on gives about 10 percent more traffic and load on the machine, but
+popular items do not expire from the cache.
 .TP
 .B prefetch\-key: \fI<yes or no>
 If yes, fetch the DNSKEYs earlier in the validation process, when a DS
@@ -1199,12 +1204,13 @@ from the query ID, for speed and thread safety).  Default is yes.
 .B minimal-responses: \fI<yes or no>
 If yes, Unbound does not insert authority/additional sections into response
 messages when those sections are not required.  This reduces response
-size significantly, and may avoid TCP fallback for some responses.
-This may cause a slight speedup.  The default is yes, even though the DNS
+size significantly, and may avoid TCP fallback for some responses which may
+cause a slight speedup.  The default is yes, even though the DNS
 protocol RFCs mandate these sections, and the additional content could
-be of use and save roundtrips for clients.  Because they are not used,
-and the saved roundtrips are easier saved with prefetch, whilst this is
-faster.
+save roundtrips for clients that use the additional content.
+However these sections are hardly used by clients.
+Enabling prefetch can benefit clients that need the additional content
+by trying to keep that content fresh in the cache.
 .TP
 .B disable-dnssec-lame-check: \fI<yes or no>
 If true, disables the DNSSEC lameness check in the iterator.  This check

iterator/iterator.c

@@ -322,16 +322,21 @@ error_response_cache(struct module_qstate* qstate, int id, int rcode)
 		qstate->qinfo.qname, qstate->qinfo.qname_len,
 		qstate->qinfo.qtype, qstate->qinfo.qclass,
 		qstate->query_flags, 0,
-		qstate->env->cfg->serve_expired_ttl_reset)) != NULL) {
+		qstate->env->cfg->serve_expired)) != NULL) {
 		struct reply_info* rep = (struct reply_info*)msg->entry.data;
-		if(qstate->env->cfg->serve_expired &&
-			qstate->env->cfg->serve_expired_ttl_reset && rep &&
-			*qstate->env->now + qstate->env->cfg->serve_expired_ttl
-			> rep->serve_expired_ttl) {
-			verbose(VERB_ALGO, "reset serve-expired-ttl for "
+		if(qstate->env->cfg->serve_expired && rep) {
+			if(qstate->env->cfg->serve_expired_ttl_reset &&
+				*qstate->env->now + qstate->env->cfg->serve_expired_ttl
+				> rep->serve_expired_ttl) {
+				verbose(VERB_ALGO, "reset serve-expired-ttl for "
+					"response in cache");
+				rep->serve_expired_ttl = *qstate->env->now +
+					qstate->env->cfg->serve_expired_ttl;
+			}
+			verbose(VERB_ALGO, "set serve-expired-norec-ttl for "
 				"response in cache");
-			rep->serve_expired_ttl = *qstate->env->now +
-				qstate->env->cfg->serve_expired_ttl;
+			rep->serve_expired_norec_ttl = NORR_TTL +
+				*qstate->env->now;
 		}
 		if(rep && (FLAGS_GET_RCODE(rep->flags) ==
 			LDNS_RCODE_NOERROR ||
@@ -4046,6 +4051,8 @@ processClassResponse(struct module_qstate* qstate, int id,
 			to->rep->prefetch_ttl = from->rep->prefetch_ttl;
 		if(from->rep->serve_expired_ttl < to->rep->serve_expired_ttl)
 			to->rep->serve_expired_ttl = from->rep->serve_expired_ttl;
+		if(from->rep->serve_expired_norec_ttl < to->rep->serve_expired_norec_ttl)
+			to->rep->serve_expired_norec_ttl = from->rep->serve_expired_norec_ttl;
 	}
 	/* are we done? */
 	foriq->num_current_queries --;

services/cache/dns.c

@@ -162,7 +162,7 @@ dns_cache_store_msg(struct module_env* env, struct query_info* qinfo,
 	size_t i;
 
 	/* store RRsets */
-        for(i=0; i<rep->rrset_count; i++) {
+	for(i=0; i<rep->rrset_count; i++) {
 		rep->ref[i].key = rep->rrsets[i];
 		rep->ref[i].id = rep->rrsets[i]->id;
 	}
@@ -197,6 +197,7 @@ dns_cache_store_msg(struct module_env* env, struct query_info* qinfo,
 	reply_info_sortref(rep);
 	if(!(e = query_info_entrysetup(qinfo, rep, hash))) {
 		log_err("store_msg: malloc failed");
+		reply_info_delete(rep, NULL);
 		return;
 	}
 	slabhash_insert(env->msg_cache, hash, &e->entry, rep, env->alloc);
@@ -607,22 +608,8 @@ tomsg(struct module_env* env, struct query_info* q, struct reply_info* r,
 	time_t now_control = now;
 	if(now > r->ttl) {
 		/* Check if we are allowed to serve expired */
-		if(allow_expired) {
-			if(env->cfg->serve_expired_ttl &&
-				r->serve_expired_ttl < now) {
-				return NULL;
-			}
-			/* Ignore expired failure answers */
-			if(FLAGS_GET_RCODE(r->flags) !=
-				LDNS_RCODE_NOERROR &&
-				FLAGS_GET_RCODE(r->flags) !=
-				LDNS_RCODE_NXDOMAIN &&
-				FLAGS_GET_RCODE(r->flags) !=
-				LDNS_RCODE_YXDOMAIN)
-				return 0;
-		} else {
+		if(!allow_expired || !reply_info_can_answer_expired(r, now))
 			return NULL;
-		}
 		/* Change the current time so we can pass the below TTL checks when
 		 * serving expired data. */
 		now_control = r->ttl - env->cfg->serve_expired_reply_ttl;
@@ -641,6 +628,7 @@ tomsg(struct module_env* env, struct query_info* q, struct reply_info* r,
 	else
 		msg->rep->prefetch_ttl = PREFETCH_TTL_CALC(msg->rep->ttl);
 	msg->rep->serve_expired_ttl = msg->rep->ttl + SERVE_EXPIRED_TTL;
+	msg->rep->serve_expired_norec_ttl = 0;
 	msg->rep->security = r->security;
 	msg->rep->an_numrrsets = r->an_numrrsets;
 	msg->rep->ns_numrrsets = r->ns_numrrsets;
@@ -724,6 +712,7 @@ rrset_msg(struct ub_packed_rrset_key* rrset, struct regional* region,
 	msg->rep->ttl = d->ttl - now;
 	msg->rep->prefetch_ttl = PREFETCH_TTL_CALC(msg->rep->ttl);
 	msg->rep->serve_expired_ttl = msg->rep->ttl + SERVE_EXPIRED_TTL;
+	msg->rep->serve_expired_norec_ttl = 0;
 	msg->rep->security = sec_status_unchecked;
 	msg->rep->an_numrrsets = 1;
 	msg->rep->ns_numrrsets = 0;
@@ -763,6 +752,7 @@ synth_dname_msg(struct ub_packed_rrset_key* rrset, struct regional* region,
 	msg->rep->ttl = d->ttl - now;
 	msg->rep->prefetch_ttl = PREFETCH_TTL_CALC(msg->rep->ttl);
 	msg->rep->serve_expired_ttl = msg->rep->ttl + SERVE_EXPIRED_TTL;
+	msg->rep->serve_expired_norec_ttl = 0;
 	msg->rep->security = sec_status_unchecked;
 	msg->rep->an_numrrsets = 1;
 	msg->rep->ns_numrrsets = 0;
@@ -1070,6 +1060,35 @@ dns_cache_store(struct module_env* env, struct query_info* msgqinf,
 	struct regional* region, uint32_t flags, time_t qstarttime)
 {
 	struct reply_info* rep = NULL;
+	if(SERVE_EXPIRED) {
+		/* We are serving expired records. Before caching, check if a
+		 * useful expired record exists. */
+		struct msgreply_entry* e = msg_cache_lookup(env,
+			msgqinf->qname, msgqinf->qname_len, msgqinf->qtype,
+			msgqinf->qclass, flags, 0, 0);
+		if(e) {
+			struct reply_info* cached = e->entry.data;
+			if(cached->ttl < *env->now
+				&& reply_info_could_use_expired(cached, *env->now)
+				/* If we are validating make sure only
+				 * validating modules can update such messages.
+				 * In that case don't cache it and let a
+				 * subsequent module handle the caching. For
+				 * example, the iterator should not replace an
+				 * expired secure answer with a fresh unchecked
+				 * one and let the validator manage caching. */
+				&& cached->security != sec_status_bogus
+				&& (env->need_to_validate &&
+				msgrep->security == sec_status_unchecked)) {
+				verbose(VERB_ALGO, "a validated expired entry "
+					"could be overwritten, skip caching "
+					"the new message at this stage");
+				lock_rw_unlock(&e->entry.lock);
+				return 1;
+			}
+			lock_rw_unlock(&e->entry.lock);
+		}
+	}
 	/* alloc, malloc properly (not in region, like msg is) */
 	rep = reply_info_copy(msgrep, env->alloc, NULL);
 	if(!rep)

services/cache/rrset.c

@@ -128,8 +128,8 @@ need_to_update_rrset(void* nd, void* cd, time_t timenow, int equal, int ns)
 {
 	struct packed_rrset_data* newd = (struct packed_rrset_data*)nd;
 	struct packed_rrset_data* cached = (struct packed_rrset_data*)cd;
-	/*	o if new data is expired, current data is better */
-	if( newd->ttl < timenow && cached->ttl >= timenow)
+	/*	o if new data is expired, cached data is better */
+	if( newd->ttl < timenow && timenow <= cached->ttl)
 		return 0;
 	/* 	o store if rrset has been validated 
 	 *  		everything better than bogus data 
@@ -140,9 +140,9 @@ need_to_update_rrset(void* nd, void* cd, time_t timenow, int equal, int ns)
 	if( cached->security == sec_status_bogus && 
 		newd->security != sec_status_bogus && !equal)
 		return 1;
-        /*      o if current RRset is more trustworthy - insert it */
+        /*      o if new RRset is more trustworthy - insert it */
         if( newd->trust > cached->trust ) {
-		/* if the cached rrset is bogus, and this one equal,
+		/* if the cached rrset is bogus, and new is equal,
 		 * do not update the TTL - let it expire. */
 		if(equal && cached->ttl >= timenow && 
 			cached->security == sec_status_bogus)
@@ -155,7 +155,7 @@ need_to_update_rrset(void* nd, void* cd, time_t timenow, int equal, int ns)
 	/*  o same trust, but different in data - insert it */
 	if( newd->trust == cached->trust && !equal ) {
 		/* if this is type NS, do not 'stick' to owner that changes
-		 * the NS RRset, but use the old TTL for the new data, and
+		 * the NS RRset, but use the cached TTL for the new data, and
 		 * update to fetch the latest data. ttl is not expired, because
 		 * that check was before this one. */
 		if(ns) {

services/mesh.c

@@ -311,7 +311,7 @@ int mesh_make_new_space(struct mesh_area* mesh, sldns_buffer* qbuf)
 
 struct dns_msg*
 mesh_serve_expired_lookup(struct module_qstate* qstate,
-	struct query_info* lookup_qinfo)
+	struct query_info* lookup_qinfo, int* is_expired)
 {
 	hashvalue_type h;
 	struct lruhash_entry* e;
@@ -321,13 +321,15 @@ mesh_serve_expired_lookup(struct module_qstate* qstate,
 	time_t timenow = *qstate->env->now;
 	int must_validate = (!(qstate->query_flags&BIT_CD)
 		|| qstate->env->cfg->ignore_cd) && qstate->env->need_to_validate;
+	*is_expired = 0;
 	/* Lookup cache */
 	h = query_info_hash(lookup_qinfo, qstate->query_flags);
 	e = slabhash_lookup(qstate->env->msg_cache, h, lookup_qinfo, 0);
 	if(!e) return NULL;
 
 	key = (struct msgreply_entry*)e->key;
 	data = (struct reply_info*)e->data;
+	if(data->ttl < timenow) *is_expired = 1;
 	msg = tomsg(qstate->env, &key->key, data, qstate->region, timenow,
 		qstate->env->cfg->serve_expired, qstate->env->scratch);
 	if(!msg)
@@ -2176,6 +2178,7 @@ mesh_serve_expired_callback(void* arg)
 	int must_validate = (!(qstate->query_flags&BIT_CD)
 		|| qstate->env->cfg->ignore_cd) && qstate->env->need_to_validate;
 	int i = 0;
+	int is_expired;
 	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);
@@ -2193,7 +2196,7 @@ mesh_serve_expired_callback(void* arg)
 		fptr_ok(fptr_whitelist_serve_expired_lookup(
 			qstate->serve_expired_data->get_cached_answer));
 		msg = (*qstate->serve_expired_data->get_cached_answer)(qstate,
-			lookup_qinfo);
+			lookup_qinfo, &is_expired);
 		if(!msg)
 			return;
 		/* Reset these in case we pass a second time from here. */
@@ -2285,8 +2288,10 @@ mesh_serve_expired_callback(void* arg)
 
 		/* Add EDE Stale Answer (RCF8914). Ignore global ede as this is
 		 * warning instead of an error */
-		if (r->edns.edns_present && qstate->env->cfg->ede_serve_expired &&
-			qstate->env->cfg->ede) {
+		if(r->edns.edns_present &&
+			qstate->env->cfg->ede_serve_expired &&
+			qstate->env->cfg->ede &&
+			is_expired) {
 			edns_opt_list_append_ede(&r->edns.opt_list_out,
 				mstate->s.region, LDNS_EDE_STALE_ANSWER, NULL);
 		}

services/mesh.h

@@ -673,11 +673,12 @@ void mesh_serve_expired_callback(void* arg);
  * the same behavior as when replying from cache.
  * @param qstate: the module qstate.
  * @param lookup_qinfo: the query info to look for in the cache.
+ * @param is_expired: set if the cached answer is expired.
  * @return dns_msg if a cached answer was found, otherwise NULL.
  */
 struct dns_msg*
 mesh_serve_expired_lookup(struct module_qstate* qstate,
-	struct query_info* lookup_qinfo);
+	struct query_info* lookup_qinfo, int* is_expired);
 
 /**
  * See if the mesh has space for more queries. You can allocate queries