Move from debugging to logging for

- upstream_stats & stub system

src/context.c

@@ -187,18 +187,19 @@ _getdns_strdup2(const struct mem_funcs *mfs, const getdns_bindata *s)
    Add code to open the trust store using wincrypt API and add
    the root certs into openssl trust store */
 static int 
-add_WIN_cacerts_to_openssl_store(SSL_CTX* tls_ctx)
+add_WIN_cacerts_to_openssl_store(getdns_context *ctxt, SSL_CTX* tls_ctx)
 {
 	HCERTSTORE      hSystemStore;
 	PCCERT_CONTEXT  pTargetCert = NULL;
 	
-	DEBUG_STUB("%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__,
+	_getdns_log(&ctxt->log, GETDNS_LOG_SYS_STUB, GETDNS_LOG_DEBUG
-		"Adding Windows certificates from system root store to CA store");
+	    , "%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__
+	    , "Adding Windows certificates from system root store to CA store")
+	    ;
 
 	/* load just once per context lifetime for this version of getdns
 	   TODO: dynamically update CA trust changes as they are available */
-	if (!tls_ctx)
+	assert(tls_ctx);
-		return 0;
 
 	/* Call wincrypt's CertOpenStore to open the CA root store. */
 
@@ -211,19 +212,27 @@ add_WIN_cacerts_to_openssl_store(SSL_CTX* tls_ctx)
 		1 << 16,
 		L"root")) == 0)
 	{
+		_getdns_log(&ctxt->log, GETDNS_LOG_SYS_STUB, GETDNS_LOG_ERR
+		    , "%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__
+		    , "Could not CertOpenStore()");
 		return 0;
 	}
 
 	X509_STORE* store = SSL_CTX_get_cert_store(tls_ctx);
-	if (!store)
+	if (!store) {
+		_getdns_log(&ctxt->log, GETDNS_LOG_SYS_STUB, GETDNS_LOG_ERR
+		    , "%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__
+		    , "Could not SSL_CTX_get_cert_store()");
 		return 0;
+	}
 
 	/* failure if the CA store is empty or the call fails */
 	if ((pTargetCert = CertEnumCertificatesInStore(
-		hSystemStore, pTargetCert)) == 0) {
+	    hSystemStore, pTargetCert)) == 0) {
-		DEBUG_STUB("%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__,
+		_getdns_log(&ctxt->log, GETDNS_LOG_SYS_STUB, GETDNS_LOG_NOTICE
-			"CA certificate store for Windows is empty.");
+		    , "%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__
-			return 0;
+		    , "CA certificate store for Windows is empty.");
+		return 0;
 	}
 	/* iterate over the windows cert store and add to openssl store */
 	do 
@@ -233,9 +242,13 @@ add_WIN_cacerts_to_openssl_store(SSL_CTX* tls_ctx)
 			pTargetCert->cbCertEncoded);
 		if (!cert1) {
 			/* return error if a cert fails */
-			DEBUG_STUB("%s %-35s: %s %d:%s\n", STUB_DEBUG_SETUP_TLS, __FUNC__,
+			_getdns_log(&ctxt->log
-				"Unable to parse certificate in memory",
+			    , GETDNS_LOG_SYS_STUB, GETDNS_LOG_ERR,
-				ERR_get_error(), ERR_error_string(ERR_get_error(), NULL));
+			    , "%s %-35s: %s %d:%s\n"
+			    , STUB_DEBUG_SETUP_TLS, __FUNC__
+			    , "Unable to parse certificate in memory"
+			    , ERR_get_error()
+			    , ERR_error_string(ERR_get_error(), NULL));
 			return 0;
 		}
 		else {
@@ -247,9 +260,16 @@ add_WIN_cacerts_to_openssl_store(SSL_CTX* tls_ctx)
 				* certificate is already in the store.  */ 
 				if(ERR_GET_LIB(error) != ERR_LIB_X509 ||
 				   ERR_GET_REASON(error) != X509_R_CERT_ALREADY_IN_HASH_TABLE) {
-					DEBUG_STUB("%s %-35s: %s %d:%s\n", STUB_DEBUG_SETUP_TLS, __FUNC__,
+					_getdns_log(&ctxt->log
-					    "Error adding certificate", ERR_get_error(),
+					    , GETDNS_LOG_SYS_STUB
-					     ERR_error_string(ERR_get_error(), NULL));
+					    , GETDNS_LOG_ERR
+					    , "%s %-35s: %s %d:%s\n"
+					    , STUB_DEBUG_SETUP_TLS, __FUNC__
+					    , "Error adding certificate"
+					    , ERR_get_error()
+					    , ERR_error_string( ERR_get_error()
+					                      , NULL)
+					    );
 					X509_free(cert1);
 					return 0;
 				}
@@ -264,12 +284,18 @@ add_WIN_cacerts_to_openssl_store(SSL_CTX* tls_ctx)
 		CertFreeCertificateContext(pTargetCert);
 	if (hSystemStore)
 	{
-		if (!CertCloseStore(
+		if (!CertCloseStore(hSystemStore, 0)) {
-			hSystemStore, 0))
+			_getdns_log(&ctxt->log
+			    , GETDNS_LOG_SYS_STUB, GETDNS_LOG_ERR
+			    , "%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__
+			    , "Could not CertCloseStore()");
 			return 0;
+		}
 	}
-	DEBUG_STUB("%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__,
+	_getdns_log(&ctxt->log, GETDNS_LOG_SYS_STUB, GETDNS_LOG_INFO
-		"Completed adding Windows certificates to CA store successfully");
+	    , "%s %-35s: %s\n", STUB_DEBUG_SETUP_TLS, __FUNC__
+	    , "Completed adding Windows certificates to CA store successfully")
+	    ;
 	return 1;
 }
 #endif
@@ -698,26 +724,6 @@ upstreams_create(getdns_context *context, size_t size)
 }
 
 
-#if defined(USE_DANESSL) && defined(STUB_DEBUG) && STUB_DEBUG
-static void _stub_debug_print_openssl_errors(void)
-{
-    unsigned long err;
-    char buffer[1024];
-    const char *file;
-    const char *data;
-    int line;
-    int flags;
-
-    while ((err = ERR_get_error_line_data(&file, &line, &data, &flags)) != 0) {
-        ERR_error_string_n(err, buffer, sizeof(buffer));
-        if (flags & ERR_TXT_STRING)
-            DEBUG_STUB("DEBUG OpenSSL Error: %s:%s:%d:%s\n", buffer, file, line, data);
-        else
-            DEBUG_STUB("DEBUG OpenSSL Error: %s:%s:%d\n", buffer, file, line);
-    }
-}
-#endif
-
 void
 _getdns_upstreams_dereference(getdns_upstreams *upstreams)
 {
@@ -760,9 +766,6 @@ _getdns_upstreams_dereference(getdns_upstreams *upstreams)
 		if (upstream->tls_obj != NULL) {
 			SSL_shutdown(upstream->tls_obj);
 #ifdef USE_DANESSL
-# if defined(STUB_DEBUG) && STUB_DEBUG
-			_stub_debug_print_openssl_errors();
-# endif
 			DANESSL_cleanup(upstream->tls_obj);
 #endif
 			SSL_free(upstream->tls_obj);
@@ -789,22 +792,6 @@ _getdns_upstreams_dereference(getdns_upstreams *upstreams)
 	GETDNS_FREE(upstreams->mf, upstreams);
 }
 
-void _getdns_upstream_log(getdns_upstream *upstream, uint64_t system,
-    getdns_loglevel_type level, const char *fmt, ...)
-{
-	va_list args;
-
-	if (!upstream || !upstream->upstreams || !upstream->upstreams->log.func
-	    || !(upstream->upstreams->log.system & system)
-	    || level > upstream->upstreams->log.level)
-		return;
-
-	va_start(args, fmt);
-	upstream->upstreams->log.func(
-	    upstream->upstreams->log.userarg, system, level, fmt, args);
-	va_end(args);
-}
-
 static void
 upstream_backoff(getdns_upstream *upstream) {
 	upstream->conn_state = GETDNS_CONN_BACKOFF;
@@ -881,9 +868,6 @@ _getdns_upstream_reset(getdns_upstream *upstream)
 	if (upstream->tls_obj != NULL) {
 		SSL_shutdown(upstream->tls_obj);
 #ifdef USE_DANESSL
-# if defined(STUB_DEBUG) && STUB_DEBUG
-		_stub_debug_print_openssl_errors();
-# endif
 		DANESSL_cleanup(upstream->tls_obj);
 #endif
 		SSL_free(upstream->tls_obj);
@@ -1941,20 +1925,6 @@ getdns_context_set_logfunc(getdns_context *context, void *userarg,
 	return GETDNS_RETURN_GOOD;
 }
 
-void _getdns_context_log(getdns_context *context, uint64_t system,
-    getdns_loglevel_type level, const char *fmt, ...)
-{
-	va_list args;
-
-	if (!context || !context->log.func || !(context->log.system & system)
-	    || level > context->log.level)
-		return;
-
-	va_start(args, fmt);
-	context->log.func(context->log.userarg, system, level, fmt, args);
-	va_end(args);
-}
-
 #ifdef HAVE_LIBUNBOUND
 /*
  * Helpers to set options on the unbound ctx
@@ -3692,8 +3662,11 @@ getdns_return_t
 _getdns_context_prepare_for_resolution(getdns_context *context)
 {
 	getdns_return_t r;
+#if defined(HAVE_SSL_CTX_DANE_ENABLE) || defined(USE_DANESSL)
+	int osr;
+#endif
 
-	RETURN_IF_NULL(context, GETDNS_RETURN_INVALID_PARAMETER);
+	assert(context);
 	if (context->destroying)
 		return GETDNS_RETURN_BAD_CONTEXT;
 
@@ -3777,29 +3750,23 @@ _getdns_context_prepare_for_resolution(getdns_context *context)
 #  ifndef USE_WINSOCK
 			else if (!SSL_CTX_set_default_verify_paths(context->tls_ctx)) {
 #  else
-			else if (!add_WIN_cacerts_to_openssl_store(context->tls_ctx)) {
+			else if (!add_WIN_cacerts_to_openssl_store(context, context->tls_ctx)) {
 #  endif /* USE_WINSOCK */
 				if (context->tls_auth_min == GETDNS_AUTHENTICATION_REQUIRED) 
 					return GETDNS_RETURN_BAD_CONTEXT;
 			}
 #  if defined(HAVE_SSL_CTX_DANE_ENABLE)
-#   if defined(STUB_DEBUG) && STUB_DEBUG
+			osr = SSL_CTX_dane_enable(context->tls_ctx);
-			int osr =
+			_getdns_log(&context->log
-#   else
+			    , GETDNS_LOG_SYS_STUB, GETDNS_LOG_DEBUG
-			(void)
+			    , "%s %-35s: DEBUG: SSL_CTX_dane_enable() -> %d\n"
-#   endif
+			    , STUB_DEBUG_SETUP_TLS, __FUNC__, osr);
-				SSL_CTX_dane_enable(context->tls_ctx);
-			DEBUG_STUB("%s %-35s: DEBUG: SSL_CTX_dane_enable() -> %d\n"
-			          , STUB_DEBUG_SETUP_TLS, __FUNC__, osr);
 #  elif defined(USE_DANESSL)
-#   if defined(STUB_DEBUG) && STUB_DEBUG
+			osr = DANESSL_CTX_init(context->tls_ctx);
-			int osr =
+			_getdns_log(&context->log
-#   else
+			    , GETDNS_LOG_SYS_STUB, GETDNS_LOG_DEBUG
-			(void)
+			    , "%s %-35s: DEBUG: DANESSL_CTX_init() returned "
-#   endif
+			      "%d\n", STUB_DEBUG_SETUP_TLS, __FUNC__, osr);
-				DANESSL_CTX_init(context->tls_ctx);
-			DEBUG_STUB("%s %-35s: DEBUG: DANESSL_CTX_init() -> %d\n"
-			          , STUB_DEBUG_SETUP_TLS, __FUNC__, osr);
 #  endif
 #else /* HAVE_TLS_v1_2 */
 			if (tls_only_is_in_transports_list(context) == 1)

src/context.h

@@ -127,7 +127,7 @@ const getdns_tsig_info *_getdns_get_tsig_info(getdns_tsig_algo tsig_alg);
 
 /* for doing public key pinning of TLS-capable upstreams: */
 typedef struct sha256_pin {
-	char pin[SHA256_DIGEST_LENGTH];
+	uint8_t pin[SHA256_DIGEST_LENGTH];
 	struct sha256_pin *next;
 } sha256_pin_t;
 
@@ -502,11 +502,38 @@ struct getdns_context {
 #endif /* HAVE_MDNS_SUPPORT */
 }; /* getdns_context */
 
-void _getdns_upstream_log(getdns_upstream *upstream, uint64_t system,
+static inline int _getdns_check_log(const getdns_log_config *log,
-    getdns_loglevel_type level, const char *fmt, ...);
+    uint64_t system, getdns_loglevel_type level)
+{ assert(log)
+; return log->func && (log->system & system) && level <= log->level; }
 
-void _getdns_context_log(getdns_context *context, uint64_t system,
+static inline void _getdns_log(const getdns_log_config *log,
-    getdns_loglevel_type level, const char *fmt, ...);
+    uint64_t system, getdns_loglevel_type level, const char *fmt, ...)
+{
+	va_list args;
+
+	if (!_getdns_check_log(log, system, level))
+		return;
+
+	va_start(args, fmt);
+	log->func(log->userarg, system, level, fmt, args);
+	va_end(args);
+}
+
+static inline void _getdns_upstream_log(const getdns_upstream *up,
+    uint64_t system, getdns_loglevel_type level, const char *fmt, ...)
+{
+	va_list args;
+
+	if (!up || !up->upstreams
+	||  !_getdns_check_log(&up->upstreams->log, system, level))
+		return;
+
+	va_start(args, fmt);
+	up->upstreams->log.func(
+	    up->upstreams->log.userarg, system, level, fmt, args);
+	va_end(args);
+}
 
 
 /** internal functions **/

src/dnssec.c

@@ -3481,7 +3481,7 @@ void _getdns_ta_notify_dnsreqs(getdns_context *context)
 			getdns_network_req *netreq, **netreq_p;
 			int r = GETDNS_RETURN_GOOD;
 
-			 (void) _getdns_context_prepare_for_resolution(context);
+			(void) _getdns_context_prepare_for_resolution(context);
 
 			*dnsreq_p = dnsreq->ta_notify;
 			for ( netreq_p = dnsreq->netreqs

src/getdns/getdns_extra.h.in

@@ -557,8 +557,11 @@ typedef enum getdns_loglevel_type {
 #define GETDNS_LOG_INFO_TEXT    "Informational message"
 #define GETDNS_LOG_DEBUG_TEXT   "Debug-level message"
 
-#define GETDNS_LOG_UPSTREAM_STATS 4096
+#define GETDNS_LOG_UPSTREAM_STATS 0x1000
 #define GETDNS_LOG_UPSTREAM_STATS_TEXT "Log messages about upstream statistics"
+#define GETDNS_LOG_SYS_STUB       0x2000
+#define GETDNS_LOG_SYS_STUB_TEXT "Log messages involving non upstream specific stub matters"
+
 
 typedef void (*getdns_logfunc_type) (void *userarg, uint64_t log_systems,
     getdns_loglevel_type, const char *, va_list ap);

src/pubkey-pinning.c

@@ -55,6 +55,7 @@
 #include <string.h>
 #include "context.h"
 #include "util-internal.h"
+#include "gldns/parseutil.h"
 
 #if OPENSSL_VERSION_NUMBER < 0x10100000 || defined(HAVE_LIBRESSL)
 #define X509_STORE_CTX_get0_untrusted(store) store->untrusted
@@ -378,19 +379,19 @@ _getdns_associate_upstream_with_SSL(SSL *ssl,
 }
 
 getdns_return_t
-_getdns_verify_pinset_match(const sha256_pin_t *pinset,
+_getdns_verify_pinset_match(const getdns_upstream *upstream,
-			    X509_STORE_CTX *store)
+    const sha256_pin_t *pinset, X509_STORE_CTX *store)
 {
-	getdns_return_t ret = GETDNS_RETURN_GENERIC_ERROR;
 	X509 *x, *prev = NULL;
+	char x_name_spc[1024], *x_name, prev_name_spc[1024];
 	int i, len;
 	unsigned char raw[4096];
 	unsigned char *next;
 	unsigned char buf[sizeof(pinset->pin)];
 	const sha256_pin_t *p;
 
-	if (pinset == NULL || store == NULL)
+	assert(pinset);
-		return GETDNS_RETURN_GENERIC_ERROR;
+	assert(store);
 
 	/* start at the base of the chain (the end-entity cert) and
 	 * make sure that some valid element of the chain does match
@@ -407,29 +408,74 @@ _getdns_verify_pinset_match(const sha256_pin_t *pinset,
 
 	/* TODO: how do we handle raw public keys? */
 
-	for (i = 0; i < sk_X509_num(X509_STORE_CTX_get0_untrusted(store)); i++, prev = x) {
+	for ( i = 0
-
+	    ; i < sk_X509_num(X509_STORE_CTX_get0_untrusted(store))
+	    ; i++, prev = x) {
 		x = sk_X509_value(X509_STORE_CTX_get0_untrusted(store), i);
-#if defined(STUB_DEBUG) && STUB_DEBUG
+		x_name = NULL;
-		DEBUG_STUB("%s %-35s: Name of cert: %d ",
+
-		           STUB_DEBUG_SETUP_TLS, __FUNC__, i);
+		if (upstream->upstreams
-		X509_NAME_print_ex_fp(stderr, X509_get_subject_name(x), 1, XN_FLAG_ONELINE);
+		&& _getdns_check_log(&upstream->upstreams->log,
-		fprintf(stderr, "\n");
+		    GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG)) {
-#endif
+
+			x_name = X509_NAME_oneline( X509_get_subject_name(x)
+			                          , x_name_spc
+			                          , sizeof(x_name_spc));
+			_getdns_upstream_log( upstream
+			    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG
+			    , "%-40s : Verifying pinsets with cert: %d %s\n"
+			    , upstream->addr_str, i, x_name);
+		}
 		if (i > 0) {
-		/* we ensure that "prev" is signed by "x" */
+			/* we ensure that "prev" is signed by "x" */
 			EVP_PKEY *pkey = X509_get_pubkey(x);
 			int verified;
+
 			if (!pkey) {
-				DEBUG_STUB("%s %-35s: Could not get pubkey from cert %d (%p)\n",
+				if (!upstream->upstreams
-					   STUB_DEBUG_SETUP_TLS, __FUNC__, i, (void*)x);
+				||  !_getdns_check_log(
+				      &upstream->upstreams->log
+				    , GETDNS_LOG_UPSTREAM_STATS
+				    , GETDNS_LOG_ERR
+				    ))
+					return GETDNS_RETURN_GENERIC_ERROR;
+
+				if (!x_name)
+					x_name = X509_NAME_oneline(
+					      X509_get_subject_name(x)
+					    , x_name_spc, sizeof(x_name_spc));
+				_getdns_upstream_log( upstream
+				    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_ERR
+				    , "%-40s : Could not get pubkey from cert "
+				      "cert: %d %s\n"
+				    , upstream->addr_str, i, x_name);
 				return GETDNS_RETURN_GENERIC_ERROR;
 			}
 			verified = X509_verify(prev, pkey);
 			EVP_PKEY_free(pkey);
 			if (!verified) {
-				DEBUG_STUB("%s %-35s: cert %d (%p) was not signed by cert %d\n",
+				if (!upstream->upstreams
-					   STUB_DEBUG_SETUP_TLS, __FUNC__, i-1, (void*)prev, i);
+				||  !_getdns_check_log(
+				      &upstream->upstreams->log
+				    , GETDNS_LOG_UPSTREAM_STATS
+				    , GETDNS_LOG_ERR
+				    ))
+					return GETDNS_RETURN_GENERIC_ERROR;
+
+				if (!x_name)
+					x_name = X509_NAME_oneline(
+					      X509_get_subject_name(x)
+					    , x_name_spc, sizeof(x_name_spc));
+				_getdns_upstream_log( upstream
+				    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_ERR
+				    , "%-40s : Cert: %d %swas not signed "
+				      "by cert %d %s\n", upstream->addr_str
+				    , i - 1
+				    , X509_NAME_oneline(
+				            X509_get_subject_name(prev)
+					  , prev_name_spc
+				          , sizeof(prev_name_spc) )
+				    , i, x_name);
 				return GETDNS_RETURN_GENERIC_ERROR;
 			}
 		}
@@ -437,31 +483,85 @@ _getdns_verify_pinset_match(const sha256_pin_t *pinset,
 		/* digest the cert with sha256 */
 		len = i2d_X509_PUBKEY(X509_get_X509_PUBKEY(x), NULL);
 		if (len > (int)sizeof(raw)) {
-			DEBUG_STUB("%s %-35s: Pubkey %d is larger than %"PRIsz" octets\n",
+			if (!upstream->upstreams
-			           STUB_DEBUG_SETUP_TLS, __FUNC__, i, sizeof(raw));
+			||  !_getdns_check_log( &upstream->upstreams->log
+			                      , GETDNS_LOG_UPSTREAM_STATS
+			                      , GETDNS_LOG_WARNING ))
+				continue;
+
+			if (!x_name)
+				x_name = X509_NAME_oneline(
+				      X509_get_subject_name(x)
+				    , x_name_spc, sizeof(x_name_spc));
+			_getdns_upstream_log( upstream
+			    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_WARNING
+			    , "%-40s : Skipping cert %d %s, because pubkey is "
+			      "larger than buffer size (%"PRIsz" octets)\n"
+			    , upstream->addr_str, i, x_name, sizeof(raw));
 			continue;
 		}
 		next = raw;
 		i2d_X509_PUBKEY(X509_get_X509_PUBKEY(x), &next);
 		if (next - raw != len) {
-			DEBUG_STUB("%s %-35s: Pubkey %d claimed it needed %d octets, really needed %"PRIsz"\n",
+			if (!upstream->upstreams
-			           STUB_DEBUG_SETUP_TLS, __FUNC__, i, len, next - raw);
+			||  !_getdns_check_log( &upstream->upstreams->log
+			                      , GETDNS_LOG_UPSTREAM_STATS
+			                      , GETDNS_LOG_WARNING ))
+				continue;
+
+			if (!x_name)
+				x_name = X509_NAME_oneline(
+				      X509_get_subject_name(x)
+				    , x_name_spc, sizeof(x_name_spc));
+			_getdns_upstream_log( upstream
+			    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_WARNING
+			    , "%-40s : Skipping cert %d %s, because pubkey si"
+			      "ze %"PRIsz" differs from earlier reported %d\n"
+			    , upstream->addr_str, i, x_name, next - raw, len);
 			continue;
 		}
 		SHA256(raw, len, buf);
 
 		/* compare it */
-		for (p = pinset; p; p = p->next)
+		for (p = pinset; p; p = p->next) {
-			if (0 == memcmp(buf, p->pin, sizeof(p->pin))) {
+			char pin_str[1024];
-				DEBUG_STUB("%s %-35s: Pubkey %d matched pin %p (%"PRIsz")\n",
-					   STUB_DEBUG_SETUP_TLS, __FUNC__, i, (void*)p, sizeof(p->pin));
-				return GETDNS_RETURN_GOOD;
-			} else
-				DEBUG_STUB("%s %-35s: Pubkey %d did not match pin %p\n",
-					   STUB_DEBUG_SETUP_TLS, __FUNC__, i, (void*)p);
-	}
 			
-	return ret;
+			if (x_name) /* only when debugging */
+				gldns_b64_ntop( p->pin , sizeof(p->pin)
+				              , pin_str, sizeof(pin_str) );
+
+			if (0 == memcmp(buf, p->pin, sizeof(p->pin))) {
+				if (!upstream->upstreams
+				||  !_getdns_check_log(
+				      &upstream->upstreams->log
+				    , GETDNS_LOG_UPSTREAM_STATS
+				    , GETDNS_LOG_INFO))
+					return GETDNS_RETURN_GOOD;
+
+				if (!x_name) {
+					x_name = X509_NAME_oneline(
+					      X509_get_subject_name(x)
+					    , x_name_spc, sizeof(x_name_spc));
+					gldns_b64_ntop( p->pin , sizeof(p->pin)
+					              , pin_str
+						      , sizeof(pin_str) );
+				}
+				_getdns_upstream_log( upstream
+				    , GETDNS_LOG_UPSTREAM_STATS
+				    , GETDNS_LOG_INFO
+				    , "%-40s : Pubkey of cert %d %s matched "
+				      "pin %s\n", upstream->addr_str
+				    , i, x_name, pin_str);
+				return GETDNS_RETURN_GOOD;
+			}
+			_getdns_upstream_log( upstream
+			    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG
+			    , "%-40s : Pubkey of cert %d %s did not match"
+			      " pin %s\n", upstream->addr_str
+			    , i, x_name, pin_str);
+		}
+	}
+	return GETDNS_RETURN_GENERIC_ERROR;
 }
 
 /* pubkey-pinning.c */

src/pubkey-pinning.h

@@ -61,8 +61,8 @@ _getdns_associate_upstream_with_SSL(SSL *ssl,
 				    getdns_upstream *upstream);
 
 getdns_return_t
-_getdns_verify_pinset_match(const sha256_pin_t *pinset,
+_getdns_verify_pinset_match(const getdns_upstream *upstream,
-			    X509_STORE_CTX *store);
+    const sha256_pin_t *pinset, X509_STORE_CTX *store);
 
 #endif
 /* pubkey-pinning.h */

src/stub.c

@@ -887,7 +887,8 @@ tls_verify_callback(int preverify_ok, X509_STORE_CTX *ctx)
 
 	/* Deal with the pinset validation */
 	if (upstream->tls_pubkey_pinset)
-		pinset_ret = _getdns_verify_pinset_match(upstream->tls_pubkey_pinset, ctx);
+		pinset_ret = _getdns_verify_pinset_match(
+		    upstream, upstream->tls_pubkey_pinset, ctx);
 
 	if (pinset_ret != GETDNS_RETURN_GOOD) {
 		DEBUG_STUB("%s %-35s: FD:  %d, WARNING: Pinset validation failure!\n",
@@ -2402,9 +2403,9 @@ upstream_find_for_netreq(getdns_network_req *netreq)
 		return fd;
 	}
 	/* Handle better, will give generic error*/
-	DEBUG_STUB("%s %-35s: MSG: %p No valid upstream! \n", STUB_DEBUG_SCHEDULE, __FUNC__, (void*)netreq);
+	_getdns_log(&netreq->owner->context->log
-	_getdns_context_log(netreq->owner->context, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_ERR,
+	    , GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_ERR
-	    "   *FAILURE* no valid transports or upstreams available!\n");
+	    , "   *FAILURE* no valid transports or upstreams available!\n");
 	return -1;
 }