Logging enhancements.

docs/man/nng_log.3.adoc

@@ -55,6 +55,9 @@ The severity can be one of the following values:
 The message itself is handled according to the logging facility set up with xref:nng_mg_set_logger.3.adoc[`nng_log_set_logger`].
 Message delivery is best effort, and messages may be suppressed based on the priority set with xref:nng_log_set_level.3.adoc[`nng_log_set_level`].
 
+Note that in order to get log messages, a suitable logger must be set using `nng_log_set_logger`.
+The default logger, `nng_null_logger` simply discards logged content.
+
 == SEE ALSO
 
 xref:nng_log_set_facility.3.adoc[nng_log_set_facility(3)],

docs/man/nng_log_set_logger.adoc

@@ -36,6 +36,7 @@ Only a single logger may be registered at a time.
 If needed, the logger should make copies of either _msgid_ or _msg_, as those may not be valid once the logger function returns.
 
 The `nng_null_logger` function is an implementation of `nng_logger` that simply discards the content.
+This is the default logger, so logging is disabled by default.
 
 The `nng_stderr_logger` function is an implementation that logs messages to the standard error stream.
 It will attempt to colorize messages by the severity, if the standard error is a terminal device.

src/core/dialer.c

@@ -388,6 +388,9 @@ dialer_connect_cb(void *arg)
 	case NNG_ECONNREFUSED:
 	case NNG_ETIMEDOUT:
 	default:
+		nng_log_warn("NNG-CONN-FAIL", "Failed connecting to %s: %s",
+		    d->d_url->u_rawurl, nng_strerror(rv));
+
 		nni_dialer_bump_error(d, rv);
 		if (user_aio == NULL) {
 			nni_dialer_timer_start(d);
@@ -410,7 +413,7 @@ dialer_connect_start(nni_dialer *d)
 int
 nni_dialer_start(nni_dialer *d, unsigned flags)
 {
-	int      rv = 0;
+	int      rv  = 0;
 	nni_aio *aio = NULL;
 
 	if (nni_atomic_flag_test_and_set(&d->d_started)) {

src/core/init.c

@@ -9,6 +9,7 @@
 //
 
 #include "core/nng_impl.h"
+#include "nng/nng.h"
 
 #include <stdbool.h>
 #include <stdio.h>
@@ -44,14 +45,21 @@
 	nni_sp_tran_sys_init();
 
 	nni_inited = true;
+	nng_log_notice(
+	    "NNG-INIT", "NNG library version %s initialized", nng_version());
 
 	return (0);
 }
 
 int
 nni_init(void)
 {
-	return (nni_plat_init(nni_init_helper));
+	int rv;
+	if ((rv = nni_plat_init(nni_init_helper)) != 0) {
+		nng_log_err("NNG-INIT",
+		    "NNG library initialization failed: %s", nng_strerror(rv));
+	}
+	return (rv);
 }
 
 // accessing the list of parameters
@@ -60,7 +68,7 @@
 	nng_init_parameter param;
 	uint64_t           value;
 #ifdef NNG_TEST_LIB
-	uint64_t           effective;
+	uint64_t effective;
 #endif
 } nni_init_param;
 
@@ -114,7 +122,7 @@
 		}
 	}
 	if ((item = NNI_ALLOC_STRUCT(item)) != NULL) {
-		item->param = p;
+		item->param     = p;
 		item->effective = value;
 		nni_list_append(&nni_init_params, item);
 	}
@@ -134,11 +142,10 @@
 			return (item->effective);
 		}
 	}
-	return ((uint64_t)-1);
+	return ((uint64_t) -1);
 }
 #endif
 
-
 static void
 nni_init_params_fini(void)
 {

src/core/listener.c

@@ -10,6 +10,7 @@
 //
 
 #include "core/nng_impl.h"
+#include "core/strs.h"
 #include "sockimpl.h"
 
 #include <stdio.h>
@@ -21,7 +22,7 @@
 static void listener_accept_cb(void *);
 static void listener_timer_cb(void *);
 
-static nni_id_map listeners = NNI_ID_MAP_INITIALIZER(1, 0x7fffffff, 0);
+static nni_id_map listeners    = NNI_ID_MAP_INITIALIZER(1, 0x7fffffff, 0);
 static nni_mtx    listeners_lk = NNI_MTX_INITIALIZER;
 
 uint32_t
@@ -223,12 +224,12 @@
 		nni_url_free(url);
 		return (NNG_ENOMEM);
 	}
-	l->l_url     = url;
-	l->l_closed  = false;
-	l->l_data    = NULL;
-	l->l_ref     = 1;
-	l->l_sock    = s;
-	l->l_tran    = tran;
+	l->l_url    = url;
+	l->l_closed = false;
+	l->l_data   = NULL;
+	l->l_ref    = 1;
+	l->l_sock   = s;
+	l->l_tran   = tran;
 	nni_atomic_flag_reset(&l->l_started);
 
 	// Make a copy of the endpoint operations.  This allows us to
@@ -363,6 +364,8 @@
 	case NNG_ECONNRESET:   // remote condition, no cool down
 	case NNG_ETIMEDOUT:    // No need to sleep, we timed out already.
 	case NNG_EPEERAUTH:    // peer validation failure
+		nng_log_warn("NNG-ACCEPT-FAIL", "Failed accepting on %s: %s",
+		    l->l_url->u_rawurl, nng_strerror(rv));
 		nni_listener_bump_error(l, rv);
 		listener_accept_start(l);
 		break;
@@ -400,6 +403,8 @@
 	}
 
 	if ((rv = l->l_ops.l_bind(l->l_data)) != 0) {
+		nng_log_warn("NNG-BIND-FAIL", "Failed binding to %s: %s",
+		    l->l_url->u_rawurl, nng_strerror(rv));
 		nni_listener_bump_error(l, rv);
 		nni_atomic_flag_reset(&l->l_started);
 		return (rv);

src/core/log.c

@@ -58,17 +58,29 @@
 }
 
 void
-nng_stderr_logger(nng_log_level level, nng_log_facility facility,
-    const char *msgid, const char *msg)
+stderr_logger(nng_log_level level, nng_log_facility facility,
+    const char *msgid, const char *msg, bool timechk)
 {
 	const char *sgr, *sgr0;
 	// Initial implementation.
-	bool        colors = false;
-	const char *level_str;
-	time_t      now;
-	char        when[64];
+	bool             colors = false;
+	const char      *level_str;
+	char             when[64];
+	struct tm       *tm;
+	static struct tm last_log = { 0 };
+	time_t           now;
+	uint64_t         sec;
+	uint32_t         nsec;
+
 	NNI_ARG_UNUSED(facility);
 
+	if (nni_time_get(&sec, &nsec) != 0) {
+		// default to the epoch if we can't get a clock for some reason
+		sec  = 0;
+		nsec = 0;
+	}
+	now = (time_t) sec;
+
 #ifdef NNG_PLATFORM_WINDOWS
 	// NB: We are blithely assuming the user has a modern console.
 	colors = _isatty(_fileno(stderr));
@@ -79,7 +91,6 @@
 	colors = isatty(fileno(stderr)) && (getenv("TERM") != NULL) &&
 	    (getenv("TERM")[0] != 0);
 #else
-	now    = 0;
 	colors = false;
 #endif
 
@@ -92,15 +103,13 @@
 	    (getenv("NO_COLOR") != NULL)) {
 		colors = false;
 	}
-	now = time(NULL);
 #ifdef NNG_HAVE_LOCALTIME_R
-	struct tm tm;
+	struct tm tm_buf;
 	// No timezone offset, not strictly ISO8601 compliant
-	strftime(when, sizeof(when), "%Y-%m-%d %T", localtime_r(&now, &tm));
+	tm = localtime_r(&now, &tm_buf);
 #else
-	strftime(when, sizeof(when), "%Y-%m-%d %T", localtime(&now));
+	tm = localtime(&now);
 #endif
-
 	switch (level) {
 	case NNG_LOG_ERR:
 		sgr       = "\x1b[31m"; // red
@@ -139,8 +148,30 @@
 		sgr0 = "";
 	}
 
-	(void) fprintf(stderr, "%s[%-6s]: %s: %s%s%s%s\n", sgr, level_str,
-	    when, msgid ? msgid : "", msgid ? ": " : "", msg, sgr0);
+	if (timechk &&
+	    ((last_log.tm_mday != tm->tm_mday) ||
+	        (last_log.tm_mon != tm->tm_mon) ||
+	        (last_log.tm_year != tm->tm_year))) {
+		char new_day[64];
+		strftime(new_day, sizeof(new_day),
+		    "Date changed to %Y-%m-%d, TZ is %z", tm);
+		stderr_logger(
+		    NNG_LOG_DEBUG, facility, "NNG-DATE", new_day, false);
+		last_log = *tm;
+	}
+
+	strftime(when, sizeof(when), "%H:%M:%S", tm);
+	// we print with millisecond resolution
+	(void) fprintf(stderr, "%s[%-6s]: %s.%03d: %s%s%s%s\n", sgr, level_str,
+	    when, nsec / 1000000, msgid ? msgid : "", msgid ? ": " : "", msg,
+	    sgr0);
+}
+
+void
+nng_stderr_logger(nng_log_level level, nng_log_facility facility,
+    const char *msgid, const char *msg)
+{
+	stderr_logger(level, facility, msgid, msg, true);
 }
 
 void

src/core/platform.h

@@ -234,8 +234,8 @@ extern bool nni_atomic_cas(nni_atomic_int *, int, int);
 
 // atomic pointers.  We only support a few operations.
 typedef struct nni_atomic_ptr nni_atomic_ptr;
-extern void nni_atomic_set_ptr(nni_atomic_ptr *, void *);
-extern void *nni_atomic_get_ptr(nni_atomic_ptr *);
+extern void                   nni_atomic_set_ptr(nni_atomic_ptr *, void *);
+extern void                  *nni_atomic_get_ptr(nni_atomic_ptr *);
 
 //
 // Clock Support
@@ -249,6 +249,9 @@ extern void *nni_atomic_get_ptr(nni_atomic_ptr *);
 // option of using negative values for other purposes in the future.)
 extern nni_time nni_clock(void);
 
+// Get the real time, in seconds and nanoseconds
+extern int nni_time_get(uint64_t *seconds, uint32_t *nanoseconds);
+
 // nni_msleep sleeps for the specified number of milliseconds (at least).
 extern void nni_msleep(nni_duration);
 
@@ -445,7 +448,7 @@ extern int nni_plat_udp_sockname(nni_plat_udp *, nni_sockaddr *);
 // in APIs to transport file descriptors, or across a fork/exec boundary (so
 // that child processes may use these with socket to inherit a socket that is
 // connected to the parent.)
-extern int nni_socket_pair(int [2]);
+extern int nni_socket_pair(int[2]);
 
 //
 // File/Store Support

src/core/socket.c

@@ -940,7 +940,7 @@
 nni_sock_add_dialer(nni_sock *s, nni_dialer *d)
 {
 	nni_sockopt *sopt;
-	int rv;
+	int          rv;
 
 	// grab a hold on the dialer for the socket
 	if ((rv = nni_dialer_hold(d)) != 0) {
@@ -955,7 +955,7 @@
 	}
 
 	NNI_LIST_FOREACH (&s->s_options, sopt) {
 		int rv;
 		rv = nni_dialer_setopt(
 		    d, sopt->name, sopt->data, sopt->sz, sopt->typ);
 		if ((rv != 0) && (rv != NNG_ENOTSUP)) {
@@ -1522,6 +1522,8 @@
 		nni_stat_inc(&d->st_reject, 1);
 		nni_stat_inc(&s->st_rejects, 1);
 #endif
+		nng_log_debug("NNG-PIPEREJECT",
+		    "Pipe closed by pipe callback before added to socket");
 		nni_pipe_rele(p);
 		return;
 	}

src/platform/posix/CMakeLists.txt

@@ -63,6 +63,7 @@ if (NNG_PLATFORM_POSIX)
     nng_check_sym(atomic_flag_test_and_set stdatomic.h NNG_HAVE_STDATOMIC)
     nng_check_sym(socketpair sys/socket.h NNG_HAVE_SOCKETPAIR)
     nng_check_sym(AF_INET6 netinet/in.h NNG_HAVE_INET6)
+    nng_check_sym(timespec_get time.h NNG_HAVE_TIMESPEC_GET)
 
     nng_sources(
             posix_impl.h