- Add that log-servfail prints an IP address and more information

about one of the last failures for that query.

doc/Changelog

@@ -1,3 +1,7 @@
+29 April 2021: Wouter
+	- Add that log-servfail prints an IP address and more information
+	  about one of the last failures for that query.
+
 28 April 2021: George
 	- Fix compiler warning for signed/unsigned comparison for
 	  max_reuse_tcp_queries.

ipsecmod/ipsecmod.c

@@ -419,6 +419,7 @@ ipsecmod_handle_query(struct module_qstate* qstate,
 			if(!qstate->env->cfg->ipsecmod_ignore_bogus &&
 				rrset_data->security == sec_status_bogus) {
 				log_err("ipsecmod: bogus IPSECKEY");
+				errinf(qstate, "ipsecmod: bogus IPSECKEY");
 				ipsecmod_error(qstate, id);
 				return;
 			}
@@ -426,6 +427,7 @@ ipsecmod_handle_query(struct module_qstate* qstate,
 			if(!call_hook(qstate, iq, ie) &&
 				qstate->env->cfg->ipsecmod_strict) {
 				log_err("ipsecmod: ipsecmod-hook failed");
+				errinf(qstate, "ipsecmod: ipsecmod-hook failed");
 				ipsecmod_error(qstate, id);
 				return;
 			}
@@ -497,6 +499,7 @@ ipsecmod_handle_response(struct module_qstate* qstate,
 			qstate->qinfo.qname_len, LDNS_RR_TYPE_IPSECKEY,
 			qstate->qinfo.qclass, 0)) {
 			log_err("ipsecmod: could not generate subquery.");
+			errinf(qstate, "ipsecmod: could not generate subquery.");
 			ipsecmod_error(qstate, id);
 		}
 		return;
@@ -520,6 +523,7 @@ ipsecmod_operate(struct module_qstate* qstate, enum module_ev event, int id,
 	if((event == module_event_new || event == module_event_pass) &&
 		iq == NULL) {
 		if(!ipsecmod_new(qstate, id)) {
+			errinf(qstate, "ipsecmod: could not ipsecmod_new");
 			ipsecmod_error(qstate, id);
 			return;
 		}
@@ -542,6 +546,7 @@ ipsecmod_operate(struct module_qstate* qstate, enum module_ev event, int id,
 	}
 	if(event == module_event_error) {
 		verbose(VERB_ALGO, "got called with event error, giving up");
+		errinf(qstate, "ipsecmod: got called with event error");
 		ipsecmod_error(qstate, id);
 		return;
 	}
@@ -552,6 +557,7 @@ ipsecmod_operate(struct module_qstate* qstate, enum module_ev event, int id,
 	}
 
 	log_err("ipsecmod: bad event %s", strmodulevent(event));
+	errinf(qstate, "ipsecmod: operate got bad event");
 	ipsecmod_error(qstate, id);
 	return;
 }

iterator/iterator.c

@@ -585,6 +585,60 @@ handle_cname_response(struct module_qstate* qstate, struct iter_qstate* iq,
 	return 1;
 }
 
+/** add response specific error information for log servfail */
+static void
+errinf_reply(struct module_qstate* qstate, struct iter_qstate* iq)
+{
+	if(qstate->env->cfg->val_log_level < 2 && !qstate->env->cfg->log_servfail)
+		return;
+	if((qstate->reply && qstate->reply->addrlen != 0) ||
+		(iq->fail_reply && iq->fail_reply->addrlen != 0)) {
+		char from[256], frm[512];
+		if(qstate->reply && qstate->reply->addrlen != 0)
+			addr_to_str(&qstate->reply->addr, qstate->reply->addrlen,
+				from, sizeof(from));
+		else
+			addr_to_str(&iq->fail_reply->addr, iq->fail_reply->addrlen,
+				from, sizeof(from));
+		snprintf(frm, sizeof(frm), "from %s", from);
+		errinf(qstate, frm);
+	}
+	if(iq->scrub_failures || iq->parse_failures) {
+		if(iq->scrub_failures)
+			errinf(qstate, "upstream response failed scrub");
+		if(iq->parse_failures)
+			errinf(qstate, "could not parse upstream response");
+	} else if(iq->response == NULL && iq->timeout_count != 0) {
+		errinf(qstate, "upstream server timeout");
+	} else if(iq->response == NULL) {
+		errinf(qstate, "no server to query");
+		if(iq->dp) {
+			if(iq->dp->target_list == NULL)
+				errinf(qstate, "no addresses for nameservers");
+			else	errinf(qstate, "nameserver addresses not usable");
+			if(iq->dp->nslist == NULL)
+				errinf(qstate, "have no nameserver names");
+			if(iq->dp->bogus)
+				errinf(qstate, "NS record was dnssec bogus");
+		}
+	}
+	if(iq->response && iq->response->rep) {
+		if(FLAGS_GET_RCODE(iq->response->rep->flags) != 0) {
+			char rcode[256], rc[32];
+			(void)sldns_wire2str_rcode_buf(
+				FLAGS_GET_RCODE(iq->response->rep->flags),
+				rc, sizeof(rc));
+			snprintf(rcode, sizeof(rcode), "got %s", rc);
+			errinf(qstate, rcode);
+		} else {
+			/* rcode NOERROR */
+			if(iq->response->rep->an_numrrsets == 0) {
+				errinf(qstate, "nodata answer");
+			}
+		}
+	}
+}
+
 /** see if last resort is possible - does config allow queries to parent */
 static int
 can_have_last_resort(struct module_env* env, uint8_t* nm, size_t nmlen,
@@ -1922,6 +1976,7 @@ processLastResort(struct module_qstate* qstate, struct iter_qstate* iq,
 		 * of a response. */
 		errinf(qstate, "all the configured stub or forward servers failed,");
 		errinf_dname(qstate, "at zone", iq->dp->name);
+		errinf_reply(qstate, iq);
 		verbose(VERB_QUERY, "configured stub or forward servers failed -- returning SERVFAIL");
 		return error_response_cache(qstate, id, LDNS_RCODE_SERVFAIL);
 	}
@@ -2068,6 +2123,7 @@ processLastResort(struct module_qstate* qstate, struct iter_qstate* iq,
 
 	errinf(qstate, "all servers for this domain failed,");
 	errinf_dname(qstate, "at zone", iq->dp->name);
+	errinf_reply(qstate, iq);
 	verbose(VERB_QUERY, "out of query targets -- returning SERVFAIL");
 	/* fail -- no more targets, no more hope of targets, no hope 
 	 * of a response. */
@@ -2959,6 +3015,8 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq,
 			qstate->env->detach_subs));
 		(*qstate->env->detach_subs)(qstate);
 		iq->num_target_queries = 0;
+		iq->response = NULL;
+		iq->fail_reply = NULL;
 		verbose(VERB_ALGO, "cleared outbound list for next round");
 		return next_state(iq, QUERYTARGETS_STATE);
 	} else if(type == RESPONSE_TYPE_CNAME) {
@@ -3722,6 +3780,7 @@ process_response(struct module_qstate* qstate, struct iter_qstate* iq,
 	}
 
 	/* parse message */
+	iq->fail_reply = qstate->reply;
 	prs = (struct msg_parse*)regional_alloc(qstate->env->scratch, 
 		sizeof(struct msg_parse));
 	if(!prs) {
@@ -3735,12 +3794,15 @@ process_response(struct module_qstate* qstate, struct iter_qstate* iq,
 	sldns_buffer_set_position(pkt, 0);
 	if(parse_packet(pkt, prs, qstate->env->scratch) != LDNS_RCODE_NOERROR) {
 		verbose(VERB_ALGO, "parse error on reply packet");
+		iq->parse_failures++;
 		goto handle_it;
 	}
 	/* edns is not examined, but removed from message to help cache */
 	if(parse_extract_edns(prs, &edns, qstate->env->scratch) !=
-		LDNS_RCODE_NOERROR)
+		LDNS_RCODE_NOERROR) {
+		iq->parse_failures++;
 		goto handle_it;
+	}
 
 	/* Copy the edns options we may got from the back end */
 	if(edns.opt_list) {
@@ -3774,6 +3836,7 @@ process_response(struct module_qstate* qstate, struct iter_qstate* iq,
 			iq->num_current_queries--;
 			verbose(VERB_DETAIL, "Capsforid: scrub failed, starting fallback with no response");
 		}
+		iq->scrub_failures++;
 		goto handle_it;
 	}
 

iterator/iterator.h

@@ -406,6 +406,12 @@ struct iter_qstate {
 	int auth_zone_response;
 	/** True if the auth_zones should not be consulted for the query */
 	int auth_zone_avoid;
+	/** true if there have been scrubbing failures of reply packets */
+	int scrub_failures;
+	/** true if there have been parse failures of reply packets */
+	int parse_failures;
+	/** a failure printout address for last received answer */
+	struct comm_reply* fail_reply;
 };
 
 /**

testcode/testbound.c

@@ -279,6 +279,7 @@ setup_config(FILE* in, int* lineno, int* pass_argc, char* pass_argv[])
 	fprintf(cfg, "		username: \"\"\n");
 	fprintf(cfg, "		pidfile: \"\"\n");
 	fprintf(cfg, "		val-log-level: 2\n");
+	fprintf(cfg, "		log-servfail: yes\n");
 	fprintf(cfg, "remote-control:	control-enable: no\n");
 	while(fgets(line, MAX_LINE_LEN-1, in)) {
 		parse = line;