Logging improvements (#1816)

* Add nng_str_sockaddr to get string representation of socket address.

* Added nng_log_get_level() is meant to allow users to obtain the
current level and avoid some possibly expensive operations just
to collect debugging information when debugging is not in effect.

We use a custom logger for NUTS, and this fits within the NUTS
test framework well, so that if -v is supplied we get more content.
All tests now get this by default.

9 files changed, 415 insertions, 15 deletions

diff --git a/src/core/CMakeLists.txt b/src/core/CMakeLists.txt
index 48b25265..90ef4023 100644
--- a/src/core/CMakeLists.txt
+++ b/src/core/CMakeLists.txt
@@ -57,6 +57,7 @@ nng_sources(
         protocol.h
         reap.c
         reap.h
+        sockaddr.c
         socket.c
         socket.h
         sockimpl.h
@@ -86,5 +87,6 @@ nng_test(log_test)
 nng_test(message_test)
 nng_test(reconnect_test)
 nng_test(sock_test)
+nng_test(sockaddr_test)
 nng_test(stats_test)
 nng_test(url_test)
diff --git a/src/core/dialer.c b/src/core/dialer.c
index ed8577dc..722a0868 100644
--- a/src/core/dialer.c
+++ b/src/core/dialer.c
@@ -1,5 +1,5 @@
 //
-// Copyright 2023 Staysail Systems, Inc. <info@staysail.tech>
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
 // Copyright 2018 Capitar IT Group BV <info@capitar.com>
 // Copyright 2018 Devolutions <info@devolutions.net>
 //
@@ -388,8 +388,10 @@ 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));
+		nng_log_warn("NNG-CONN-FAIL",
+		    "Failed connecting socket<%u> to %s: %s",
+		    nni_sock_id(d->d_sock), d->d_url->u_rawurl,
+		    nng_strerror(rv));
 
 		nni_dialer_bump_error(d, rv);
 		if (user_aio == NULL) {
@@ -441,6 +443,9 @@ nni_dialer_start(nni_dialer *d, unsigned flags)
 		nni_aio_free(aio);
 	}
 
+	nng_log_info("NNG-DIAL", "Starting dialer for socket<%u> on %s",
+	    nni_sock_id(d->d_sock), d->d_url->u_rawurl);
+
 	return (rv);
 }
 
diff --git a/src/core/listener.c b/src/core/listener.c
index a020079d..65fe5a9f 100644
--- a/src/core/listener.c
+++ b/src/core/listener.c
@@ -1,5 +1,5 @@
 //
-// Copyright 2023 Staysail Systems, Inc. <info@staysail.tech>
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
 // Copyright 2018 Capitar IT Group BV <info@capitar.com>
 // Copyright 2018 Devolutions <info@devolutions.net>
 //
@@ -11,6 +11,7 @@
 
 #include "core/nng_impl.h"
 #include "core/strs.h"
+#include "nng/nng.h"
 #include "sockimpl.h"
 
 #include <stdio.h>
@@ -364,8 +365,10 @@ listener_accept_cb(void *arg)
 	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));
+		nng_log_warn("NNG-ACCEPT-FAIL",
+		    "Failed accepting for socket<%u> on %s: %s",
+		    nni_sock_id(l->l_sock), l->l_url->u_rawurl,
+		    nng_strerror(rv));
 		nni_listener_bump_error(l, rv);
 		listener_accept_start(l);
 		break;
@@ -395,7 +398,9 @@ listener_accept_start(nni_listener *l)
 int
 nni_listener_start(nni_listener *l, int flags)
 {
-	int rv;
+	int    rv;
+	char  *url;
+	size_t sz;
 	NNI_ARG_UNUSED(flags);
 
 	if (nni_atomic_flag_test_and_set(&l->l_started)) {
@@ -403,12 +408,21 @@ nni_listener_start(nni_listener *l, int flags)
 	}
 
 	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));
+		nng_log_warn("NNG-BIND-FAIL",
+		    "Failed binding socket<%u> to %s: %s",
+		    nni_sock_id(l->l_sock), l->l_url->u_rawurl,
+		    nng_strerror(rv));
 		nni_listener_bump_error(l, rv);
 		nni_atomic_flag_reset(&l->l_started);
 		return (rv);
 	}
+	// collect the URL which may have changed (e.g. binding to port 0)
+	sz = sizeof(url);
+	(void) (nni_listener_getopt(
+	    l, NNG_OPT_URL, &url, &sz, NNI_TYPE_STRING));
+	nng_log_info("NNG-LISTEN", "Starting listener for socket<%u> on %s",
+	    nni_sock_id(l->l_sock), url);
+	nni_strfree(url);
 
 	listener_accept_start(l);
 
diff --git a/src/core/log.c b/src/core/log.c
index cef3169c..e415e159 100644
--- a/src/core/log.c
+++ b/src/core/log.c
@@ -37,6 +37,12 @@ nng_log_set_level(nng_log_level level)
 	log_level = level;
 }
 
+nng_log_level
+nng_log_get_level(void)
+{
+	return (log_level);
+}
+
 void
 nng_log_set_logger(nng_logger logger)
 {
@@ -54,7 +60,6 @@ nng_null_logger(nng_log_level level, nng_log_facility facility,
 	NNI_ARG_UNUSED(facility);
 	NNI_ARG_UNUSED(msgid);
 	NNI_ARG_UNUSED(msg);
-	return;
 }
 
 void
diff --git a/src/core/pipe.c b/src/core/pipe.c
index 10a1f35a..2fa8d017 100644
--- a/src/core/pipe.c
+++ b/src/core/pipe.c
@@ -1,5 +1,5 @@
 //
-// Copyright 2023 Staysail Systems, Inc. <info@staysail.tech>
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
 // Copyright 2018 Capitar IT Group BV <info@capitar.com>
 // Copyright 2018 Devolutions <info@devolutions.net>
 //
@@ -10,6 +10,7 @@
 //
 
 #include "core/nng_impl.h"
+#include "nng/nng.h"
 #include "sockimpl.h"
 
 #include <stdio.h>
@@ -409,3 +410,14 @@ nni_pipe_bump_error(nni_pipe *p, int err)
 		nni_listener_bump_error(p->p_listener, err);
 	}
 }
+
+char *
+nni_pipe_peer_addr(nni_pipe *p, char buf[NNG_MAXADDRSTRLEN])
+{
+	nng_sockaddr sa;
+	size_t       sz = sizeof(sa);
+	sa.s_family     = AF_UNSPEC;
+	nni_pipe_getopt(p, NNG_OPT_REMADDR, &sa, &sz, NNI_TYPE_SOCKADDR);
+	nng_str_sockaddr(&sa, buf, NNG_MAXADDRSTRLEN);
+	return (buf);
+}
diff --git a/src/core/pipe.h b/src/core/pipe.h
index 458a42d9..a1bc361e 100644
--- a/src/core/pipe.h
+++ b/src/core/pipe.h
@@ -1,5 +1,5 @@
 //
-// Copyright 2021 Staysail Systems, Inc. <info@staysail.tech>
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
 // Copyright 2018 Capitar IT Group BV <info@capitar.com>
 //
 // This software is supplied under the terms of the MIT License, a
@@ -17,6 +17,7 @@
 
 #include "core/defs.h"
 #include "core/thread.h"
+#include "nng/nng.h"
 #include "sp/transport.h"
 
 // AIO
@@ -61,4 +62,6 @@ extern void nni_pipe_bump_rx(nni_pipe *, size_t);
 extern void nni_pipe_bump_tx(nni_pipe *, size_t);
 extern void nni_pipe_bump_error(nni_pipe *, int);
 
+extern char *nni_pipe_peer_addr(nni_pipe *p, char buf[NNG_MAXADDRSTRLEN]);
+
 #endif // CORE_PIPE_H
diff --git a/src/core/sockaddr.c b/src/core/sockaddr.c
new file mode 100644
index 00000000..50fd4214
--- /dev/null
+++ b/src/core/sockaddr.c
@@ -0,0 +1,165 @@
+//
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
+//
+// This software is supplied under the terms of the MIT License, a
+// copy of which should be located in the distribution where this
+// file was obtained (LICENSE.txt).  A copy of the license may also be
+// found online at https://opensource.org/licenses/MIT.
+//
+
+#include "core/nng_impl.h"
+#include "nng/nng.h"
+
+#include <stdio.h>
+#include <string.h>
+
+static const char *
+str_sa_inproc(const nng_sockaddr_inproc *sa, char *buf, size_t bufsz)
+{
+	snprintf(buf, bufsz, "inproc[%s]", sa->sa_name);
+	return buf;
+}
+
+static const char *
+str_sa_inet(const nng_sockaddr_in *sa, char *buf, size_t bufsz)
+{
+	uint8_t *a_bytes = (uint8_t *) &sa->sa_addr;
+	uint8_t *p_bytes = (uint8_t *) &sa->sa_port;
+
+	snprintf(buf, bufsz, "%u.%u.%u.%u:%u", a_bytes[0], a_bytes[1],
+	    a_bytes[2], a_bytes[3],
+	    (((uint16_t) p_bytes[0]) << 8) + p_bytes[1]);
+	return (buf);
+}
+
+// emit an IPv6 address in "short form"
+static char *
+nni_inet_ntop(const uint8_t addr[16], char buf[46])
+{
+
+	const uint8_t v4map[12] = { 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0xff, 0xff };
+
+	if (memcmp(addr, v4map, 12) == 0) {
+		snprintf(buf, 46, "::ffff:%u.%u.%u.%u", addr[12], addr[13],
+		    addr[14], addr[15]);
+		return (buf);
+	}
+
+	uint8_t off    = 0; // offset of first set of elided zeros
+	uint8_t cnt    = 0; // how many elided zeros so far
+	uint8_t maxoff = 0; // offset of largest compressed region
+	uint8_t maxcnt = 0; // how many elided zeros at maxoff
+
+	// look for the largest compressible region
+	for (uint8_t i = 0; i < 16; i += 2) {
+		// is this word zero?
+		if ((addr[i] == 0) && (addr[i + 1] == 0)) {
+			cnt += 2;
+			// if this was the first zero word in region, record it
+			if (cnt == 2) {
+				off = i;
+			}
+			// possibly update the maximums
+			if (cnt > maxcnt) {
+				maxcnt = cnt;
+				maxoff = off;
+			}
+		} else {
+			cnt = 0;
+		}
+	}
+	if (maxcnt < 2) {
+		maxoff = 0xff; // too big for anything
+	}
+
+	int  idx = 0;
+	bool sep = false;
+	buf[0]   = 0;
+	for (uint8_t i = 0; i < 16; i += 2) {
+		// We have 46 bytes allocated, which is a "theoretical"
+		// maximum only.  In practice the worst case is really
+		// 8 groups of four digits with 7 colons, so 39 bytes plus
+		// the null is 40 bytes.  We only use the v4 mapped syntax
+		// when presented with ::ffff: - so 23 bytes for that syntax.
+		if (i == maxoff) {
+			NNI_ASSERT(idx <= 43);
+			strcat(buf + idx, "::");
+			idx += 2;
+			sep = false;
+		} else if (i < maxoff || i >= maxoff + maxcnt) {
+			// this takes at most six bytes -- four hax digits a
+			// colon, and a null
+			NNI_ASSERT(idx <= 40);
+			snprintf(buf + idx, 6, sep ? ":%x" : "%x",
+			    (((uint16_t) addr[i]) << 8) + addr[i + 1]);
+			idx += strlen(buf + idx);
+			sep = true;
+		}
+	}
+	return (buf);
+}
+
+static const char *
+str_sa_inet6(const nng_sockaddr_in6 *sa, char *buf, size_t bufsz)
+{
+	const uint8_t *p_bytes = (uint8_t *) &sa->sa_port;
+	char           istr[46];
+
+	if (sa->sa_scope) {
+		snprintf(buf, bufsz, "[%s%%%u]:%u",
+		    nni_inet_ntop(sa->sa_addr, istr), sa->sa_scope,
+		    (((uint16_t) (p_bytes[0])) << 8) + p_bytes[1]);
+	} else {
+		snprintf(buf, bufsz, "[%s]:%u",
+		    nni_inet_ntop(sa->sa_addr, istr),
+		    (((uint16_t) (p_bytes[0])) << 8) + p_bytes[1]);
+	}
+	return (buf);
+}
+
+static const char *
+str_sa_ipc(const nng_sockaddr_ipc *sa, char *buf, size_t bufsz)
+{
+	// does not deal well with embedded "{}" chars
+	snprintf(buf, bufsz, "%s", sa->sa_path);
+	return (buf);
+}
+
+static const char *
+str_sa_abstract(const nng_sockaddr_abstract *sa, char *buf, size_t bufsz)
+{
+	// does not deal well with embedded "{}" chars
+	snprintf(buf, bufsz, "abstract[%s]", sa->sa_name);
+	return (buf);
+}
+
+static const char *
+str_sa_zt(const nng_sockaddr_zt *sa, char *buf, size_t bufsz)
+{
+	snprintf(buf, bufsz, "ZT[%llx:%llx:%u]",
+	    (unsigned long long) sa->sa_nodeid,
+	    (unsigned long long) sa->sa_nwid, sa->sa_port);
+	return (buf);
+}
+
+const char *
+nng_str_sockaddr(const nng_sockaddr *sa, char *buf, size_t bufsz)
+{
+	switch (sa->s_family) {
+	case NNG_AF_INPROC:
+		return (str_sa_inproc(&sa->s_inproc, buf, bufsz));
+	case NNG_AF_INET:
+		return (str_sa_inet(&sa->s_in, buf, bufsz));
+	case NNG_AF_INET6:
+		return (str_sa_inet6(&sa->s_in6, buf, bufsz));
+	case NNG_AF_IPC:
+		return (str_sa_ipc(&sa->s_ipc, buf, bufsz));
+	case NNG_AF_ABSTRACT:
+		return (str_sa_abstract(&sa->s_abstract, buf, bufsz));
+	case NNG_AF_ZT:
+		return (str_sa_zt(&sa->s_zt, buf, bufsz));
+	case NNG_AF_UNSPEC:
+	default:
+		return ("unknown");
+	}
+}
diff --git a/src/core/sockaddr_test.c b/src/core/sockaddr_test.c
new file mode 100644
index 00000000..0e05fc79
--- /dev/null
+++ b/src/core/sockaddr_test.c
@@ -0,0 +1,176 @@
+//
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
+//
+// This software is supplied under the terms of the MIT License, a
+// copy of which should be located in the distribution where this
+// file was obtained (LICENSE.txt).  A copy of the license may also be
+// found online at https://opensource.org/licenses/MIT.
+//
+
+#include <stdio.h>
+#include <string.h>
+
+#include "nuts.h"
+#include <nng/nng.h>
+
+#ifndef _WIN32
+#include <arpa/inet.h> // for endianness functions
+#endif
+
+void
+test_sa_ipc(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_ipc.sa_family = NNG_AF_IPC;
+	snprintf(sa.s_ipc.sa_path, sizeof(sa.s_ipc.sa_path), "/tmp/something");
+	NUTS_ASSERT(strcmp(nng_str_sockaddr(&sa, addr, sizeof(addr)),
+	                "/tmp/something") == 0);
+}
+
+void
+test_sa_abstract(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_abstract.sa_family = NNG_AF_ABSTRACT;
+	snprintf((char *) sa.s_abstract.sa_name, sizeof(sa.s_abstract.sa_name),
+	    "something");
+	NUTS_ASSERT(strcmp(nng_str_sockaddr(&sa, addr, sizeof(addr)),
+	                "abstract[something]") == 0);
+}
+
+void
+test_sa_inproc(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_inproc.sa_family = NNG_AF_INPROC;
+	snprintf((char *) sa.s_inproc.sa_name, sizeof(sa.s_inproc.sa_name),
+	    "something");
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "inproc[something]") == 0);
+}
+
+void
+test_sa_inet(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_in.sa_family = NNG_AF_INET;
+	sa.s_in.sa_addr   = htonl(0x7F000001);
+	sa.s_in.sa_port   = htons(80);
+	NUTS_ASSERT(strcmp(nng_str_sockaddr(&sa, addr, sizeof(addr)),
+	                "127.0.0.1:80") == 0);
+}
+
+void
+test_sa_inet6(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_in.sa_family = NNG_AF_INET6;
+	memset(sa.s_in6.sa_addr, 0, sizeof(sa.s_in6.sa_addr));
+	sa.s_in6.sa_addr[15] = 1; // loopback
+	sa.s_in6.sa_scope    = 0;
+	sa.s_in6.sa_port     = htons(80);
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "[::1]:80") == 0);
+}
+
+void
+test_sa_inet6_v4_mapped(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_in.sa_family = NNG_AF_INET6;
+	memset(sa.s_in6.sa_addr, 0, sizeof(sa.s_in6.sa_addr));
+	sa.s_in6.sa_addr[10] = 0xff;
+	sa.s_in6.sa_addr[11] = 0xff;
+	sa.s_in6.sa_addr[12] = 192;
+	sa.s_in6.sa_addr[13] = 168;
+	sa.s_in6.sa_addr[14] = 1;
+	sa.s_in6.sa_addr[15] = 100;
+	sa.s_in6.sa_scope    = 0;
+	sa.s_in6.sa_port     = htons(80);
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "[::ffff:192.168.1.100]:80") == 0);
+}
+
+void
+test_sa_inet6_ll(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_in.sa_family = NNG_AF_INET6;
+	memset(sa.s_in6.sa_addr, 0, sizeof(sa.s_in6.sa_addr));
+	sa.s_in6.sa_addr[0]  = 0xfe;
+	sa.s_in6.sa_addr[1]  = 0x80;
+	sa.s_in6.sa_addr[15] = 4;
+	sa.s_in6.sa_scope    = 0;
+	sa.s_in6.sa_port     = htons(80);
+	sa.s_in6.sa_scope    = 2; // link local addresses have a non-zero scope
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "[fe80::4%2]:80") == 0);
+}
+
+void
+test_sa_inet6_zero(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_in6.sa_family = NNG_AF_INET6;
+	memset(sa.s_in6.sa_addr, 0, sizeof(sa.s_in6.sa_addr));
+	sa.s_in6.sa_port  = htons(80);
+	sa.s_in6.sa_scope = 0;
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "[::]:80") == 0);
+}
+
+void
+test_sa_inet6_net(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_in6.sa_family = NNG_AF_INET6;
+	memset(sa.s_in6.sa_addr, 0, sizeof(sa.s_in6.sa_addr));
+	sa.s_in6.sa_port    = htons(80);
+	sa.s_in6.sa_addr[0] = 0xfc;
+	sa.s_in6.sa_scope   = 0;
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "[fc00::]:80") == 0);
+}
+
+void
+test_sa_zt(void)
+{
+	nng_sockaddr sa;
+	char         addr[NNG_MAXADDRSTRLEN];
+	sa.s_zt.sa_family = NNG_AF_ZT;
+	sa.s_zt.sa_nodeid = 0xa;
+	sa.s_zt.sa_nwid   = 0xb;
+	sa.s_zt.sa_port   = 1 << 20;
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug(NULL, "address is %s", addr);
+	NUTS_ASSERT(strcmp(addr, "ZT[a:b:1048576]") == 0);
+}
+
+TEST_LIST = {
+	{ "nng_sockaddr_ipc", test_sa_ipc },
+	{ "nng_sockaddr_abstract", test_sa_abstract },
+	{ "nng_sockaddr_inproc", test_sa_inproc },
+	{ "nng_sockaddr_in", test_sa_inet },
+	{ "nng_sockaddr_in6", test_sa_inet6 },
+	{ "nng_sockaddr_in6 v4 mapped", test_sa_inet6_v4_mapped },
+	{ "nng_sockaddr_in6 link local", test_sa_inet6_ll },
+	{ "nng_sockaddr_in6 zero", test_sa_inet6_zero },
+	{ "nng_sockaddr_in6 subnet", test_sa_inet6_net },
+	{ "nng_sockaddr_zt", test_sa_zt },
+	{ NULL, NULL },
+};
diff --git a/src/core/socket.c b/src/core/socket.c
index 98999f6e..44612036 100644
--- a/src/core/socket.c
+++ b/src/core/socket.c
@@ -1,5 +1,5 @@
 //
-// Copyright 2023 Staysail Systems, Inc. <info@staysail.tech>
+// Copyright 2024 Staysail Systems, Inc. <info@staysail.tech>
 // Copyright 2018 Capitar IT Group BV <info@capitar.com>
 //
 // This software is supplied under the terms of the MIT License, a
@@ -9,7 +9,9 @@
 //
 
 #include "core/nng_impl.h"
+#include "core/pipe.h"
 #include "list.h"
+#include "nng/nng.h"
 #include "sockimpl.h"
 
 #include <stdio.h>
@@ -1522,8 +1524,12 @@ nni_dialer_add_pipe(nni_dialer *d, void *tpipe)
 		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");
+		if (nng_log_get_level() >= NNG_LOG_DEBUG) {
+			char addr[NNG_MAXADDRSTRLEN];
+			nng_log_debug("NNG-PIPEREJECT",
+			    "Pipe on socket<%u> from %s rejected by callback",
+			    nni_pipe_sock_id(p), nni_pipe_peer_addr(p, addr));
+		}
 		nni_pipe_rele(p);
 		return;
 	}
@@ -1543,6 +1549,12 @@ nni_dialer_add_pipe(nni_dialer *d, void *tpipe)
 	nni_stat_register(&p->st_root);
 #endif
 	nni_pipe_run_cb(p, NNG_PIPE_EV_ADD_POST);
+	if (nng_log_get_level() >= NNG_LOG_DEBUG) {
+		char addr[NNG_MAXADDRSTRLEN];
+		nng_log_debug("NNG-CONNECT",
+		    "Connected pipe<%u> on socket<%u> to %s", nni_pipe_id(p),
+		    nni_sock_id(s), nni_pipe_peer_addr(p, addr));
+	}
 	nni_pipe_rele(p);
 }
 
@@ -1653,6 +1665,12 @@ nni_listener_add_pipe(nni_listener *l, void *tpipe)
 	nni_stat_register(&p->st_root);
 #endif
 	nni_pipe_run_cb(p, NNG_PIPE_EV_ADD_POST);
+	if (nng_log_get_level() >= NNG_LOG_DEBUG) {
+		char addr[NNG_MAXADDRSTRLEN];
+		nng_log_debug("NNG-ACCEPT",
+		    "Accepted pipe<%u> on socket<%u> from %s", nni_pipe_id(p),
+		    nni_sock_id(s), nni_pipe_peer_addr(p, addr));
+	}
 	nni_pipe_rele(p);
 }