Reintroduct timestamps and replace GETDNS_DAEMON: with STUBBY:

This commit is contained in:
Willem Toorop 2017-06-28 21:09:40 +02:00
parent 8235250fb6
commit 264135e799
4 changed files with 39 additions and 26 deletions

View File

@ -748,20 +748,20 @@ _getdns_upstream_shutdown(getdns_upstream *upstream)
if (upstream->tls_auth_state > upstream->best_tls_auth_state)
upstream->best_tls_auth_state = upstream->tls_auth_state;
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Conn closed : Transport=%s - Resp=%d,Timeouts=%d,Auth=%s,Keepalive(ms)=%d\n",
STUB_DEBUG_DAEMON, upstream->addr_str,
"%-40s : Conn closed : Transport=%s - Resp=%d,Timeouts=%d,Auth=%s,Keepalive(ms)=%d\n",
upstream->addr_str,
(upstream->transport == GETDNS_TRANSPORT_TLS ? "TLS" : "TCP"),
(int)upstream->responses_received, (int)upstream->responses_timeouts,
_getdns_auth_str(upstream->tls_auth_state), (int)upstream->keepalive_timeout);
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Upstream stats: Transport=%s - Resp=%d,Timeouts=%d,Best_auth=%s\n",
STUB_DEBUG_DAEMON, upstream->addr_str,
"%-40s : Upstream stats: Transport=%s - Resp=%d,Timeouts=%d,Best_auth=%s\n",
upstream->addr_str,
(upstream->transport == GETDNS_TRANSPORT_TLS ? "TLS" : "TCP"),
(int)upstream->total_responses, (int)upstream->total_timeouts,
_getdns_auth_str(upstream->best_tls_auth_state));
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Upstream stats: Transport=%s - Conns=%d,Conn_fails=%d,Conn_shutdowns=%d,Backoffs=%d\n",
STUB_DEBUG_DAEMON, upstream->addr_str,
"%-40s : Upstream stats: Transport=%s - Conns=%d,Conn_fails=%d,Conn_shutdowns=%d,Backoffs=%d\n",
upstream->addr_str,
(upstream->transport == GETDNS_TRANSPORT_TLS ? "TLS" : "TCP"),
(int)upstream->conn_completed, (int)upstream->conn_setup_failed,
(int)upstream->conn_shutdowns, (int)upstream->conn_backoffs);
@ -789,8 +789,8 @@ _getdns_upstream_shutdown(getdns_upstream *upstream)
upstream->conn_backoffs++;
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : !Backing off this upstream - Will retry as new upstream at %s",
STUB_DEBUG_DAEMON, upstream->addr_str,
"%-40s : !Backing off this upstream - Will retry as new upstream at %s",
upstream->addr_str,
asctime(gmtime(&upstream->conn_retry_time)));
}
// Reset per connection counters

View File

@ -44,7 +44,6 @@
#define STUB_DEBUG_READ "------- READ: "
#define STUB_DEBUG_WRITE "------- WRITE: "
#define STUB_DEBUG_CLEANUP "--- CLEANUP: "
#define STUB_DEBUG_DAEMON "GETDNS_DAEMON: "
#ifdef GETDNS_ON_WINDOWS
#define DEBUG_ON(...) do { \

View File

@ -609,8 +609,8 @@ stub_timeout_cb(void *userarg)
netreq->upstream->udp_timeouts++;
if (netreq->upstream->udp_timeouts % 100 == 0)
_getdns_upstream_log(netreq->upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Upstream stats: Transport=UDP - Resp=%d,Timeouts=%d\n",
STUB_DEBUG_DAEMON, netreq->upstream->addr_str,
"%-40s : Upstream stats: Transport=UDP - Resp=%d,Timeouts=%d\n",
netreq->upstream->addr_str,
(int)netreq->upstream->udp_responses, (int)netreq->upstream->udp_timeouts);
stub_next_upstream(netreq);
} else {
@ -909,8 +909,8 @@ tls_verify_callback(int preverify_ok, X509_STORE_CTX *ctx)
#endif
if (!preverify_ok && !upstream->tls_fallback_ok)
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Verify failed : Transport=TLS - *Failure* - (%d) \"%s\"\n",
STUB_DEBUG_DAEMON, upstream->addr_str, err,
"%-40s : Verify failed : Transport=TLS - *Failure* - (%d) \"%s\"\n",
upstream->addr_str, err,
X509_verify_cert_error_string(err));
/* First deal with the hostname authentication done by OpenSSL. */
@ -945,8 +945,8 @@ tls_verify_callback(int preverify_ok, X509_STORE_CTX *ctx)
STUB_DEBUG_SETUP_TLS, __FUNC__, upstream->fd);
else
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Conn failed : Transport=TLS - *Failure* - Pinset validation failure\n",
STUB_DEBUG_DAEMON, upstream->addr_str);
"%-40s : Conn failed : Transport=TLS - *Failure* - Pinset validation failure\n",
upstream->addr_str);
} else {
/* If we _only_ had a pinset and it is good then force succesful
authentication when the cert self-signed
@ -958,8 +958,8 @@ tls_verify_callback(int preverify_ok, X509_STORE_CTX *ctx)
DEBUG_STUB("%s %-35s: FD: %d, Allowing self-signed (%d) cert since pins match\n",
STUB_DEBUG_SETUP_TLS, __FUNC__, upstream->fd, err);
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Verify passed : Transport=TLS - Allowing self-signed cert since pins match\n",
STUB_DEBUG_DAEMON, upstream->addr_str);
"%-40s : Verify passed : Transport=TLS - Allowing self-signed cert since pins match\n",
upstream->addr_str);
}
}
@ -1473,8 +1473,8 @@ stub_udp_read_cb(void *userarg)
if (upstream->udp_responses == 1 ||
upstream->udp_responses % 100 == 0)
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Upstream stats: Transport=UDP - Resp=%d,Timeouts=%d\n",
STUB_DEBUG_DAEMON, upstream->addr_str,
"%-40s : Upstream stats: Transport=UDP - Resp=%d,Timeouts=%d\n",
upstream->addr_str,
(int)upstream->udp_responses, (int)upstream->udp_timeouts);
_getdns_check_dns_req_complete(dnsreq);
}
@ -1730,8 +1730,8 @@ upstream_write_cb(void *userarg)
/* Cleaning up after connection or auth check failure. Need to fallback. */
stub_cleanup(netreq);
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Conn closed : Transport=%s - *Failure*\n",
STUB_DEBUG_DAEMON, upstream->addr_str,
"%-40s : Conn closed : Transport=%s - *Failure*\n",
upstream->addr_str,
(upstream->transport == GETDNS_TRANSPORT_TLS ? "TLS" : "TCP"));
if (fallback_on_write(netreq) == STUB_TCP_ERROR) {
/* TODO: Need new state to report transport unavailable*/
@ -1885,8 +1885,8 @@ upstream_select_stateful(getdns_network_req *netreq, getdns_transport_list_t tra
upstreams->upstreams[i].conn_retry_time < now) {
upstreams->upstreams[i].conn_state = GETDNS_CONN_CLOSED;
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Re-instating upstream\n",
STUB_DEBUG_DAEMON, upstreams->upstreams[i].addr_str);
"%-40s : Re-instating upstream\n",
upstreams->upstreams[i].addr_str);
}
}
@ -2018,7 +2018,7 @@ upstream_connect(getdns_upstream *upstream, getdns_transport_list_t transport,
}
upstream->conn_state = GETDNS_CONN_SETUP;
_getdns_upstream_log(upstream, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s %-40s : Conn init : Transport=%s - Profile=%s\n", STUB_DEBUG_DAEMON,
"%-40s : Conn init : Transport=%s - Profile=%s\n",
upstream->addr_str, transport == GETDNS_TRANSPORT_TLS ? "TLS":"TCP",
dnsreq->context->tls_auth_min == GETDNS_AUTHENTICATION_NONE ? "Opportunistic":"Strict");
break;
@ -2087,8 +2087,7 @@ upstream_find_for_netreq(getdns_network_req *netreq)
/* Handle better, will give generic error*/
DEBUG_STUB("%s %-35s: MSG: %p No valid upstream! \n", STUB_DEBUG_SCHEDULE, __FUNC__, (void*)netreq);
_getdns_context_log(netreq->owner->context, GETDNS_LOG_UPSTREAM_STATS, GETDNS_LOG_DEBUG,
"%s *FAILURE* no valid transports or upstreams available!\n",
STUB_DEBUG_DAEMON);
"*FAILURE* no valid transports or upstreams available!\n");
return -1;
}

View File

@ -1622,7 +1622,22 @@ error:
static void stubby_log(void *userarg, uint64_t system,
getdns_loglevel_type level, const char *fmt, va_list ap)
{
struct timeval tv;
struct tm tm;
char buf[10];
#ifdef GETDNS_ON_WINDOWS
time_t tsec;
gettimeofday(&tv, NULL);
tsec = (time_t) tv.tv_sec;
gmtime_s(&tm, (const time_t *) &tsec);
#else
gettimeofday(&tv, NULL);
gmtime_r(&tv.tv_sec, &tm);
#endif
strftime(buf, 10, "%H:%M:%S", &tm);
(void)userarg; (void)system; (void)level;
(void) fprintf(stderr, "[%s.%.6d] STUBBY: ", buf, (int)tv.tv_usec);
(void) vfprintf(stderr, fmt, ap);
}