More useful debugging information.

This includes socket<xxx> and pipe<xxx> identifying information,
and logged URLs and socket addresses. This should help especially
when debugging complex configurations/topologies.

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);
 }
 

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,20 +398,30 @@ 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)) {
 		return (NNG_ESTATE);
 	}
 
 	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);
 
 	listener_accept_start(l);
 

src/core/sockaddr.c

@@ -26,7 +26,7 @@ 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, "inet{%u.%u.%u.%u:%u}", a_bytes[0], a_bytes[1],
+	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);
@@ -98,12 +98,12 @@ str_sa_inet6(const nng_sockaddr_in6 *sa, char *buf, size_t bufsz)
 	char           istr[46];
 
 	if (sa->sa_scope) {
-		snprintf(buf, bufsz, "inet6{[%s]:%u%%%u}",
+		snprintf(buf, bufsz, "[%s]:%u%%%u",
 		    nni_inet_ntop(sa->sa_addr, istr),
 		    (((uint16_t) (p_bytes[0])) << 8) + p_bytes[1],
 		    sa->sa_scope);
 	} else {
-		snprintf(buf, bufsz, "inet6{[%s]:%u}",
+		snprintf(buf, bufsz, "[%s]:%u",
 		    nni_inet_ntop(sa->sa_addr, istr),
 		    (((uint16_t) (p_bytes[0])) << 8) + p_bytes[1]);
 	}
@@ -114,22 +114,22 @@ 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, "ipc{%s}", sa->sa_path);
+	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);
+	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}",
+	snprintf(buf, bufsz, "ZT:{%llx,%llx,%u}",
 	    (unsigned long long) sa->sa_nodeid,
 	    (unsigned long long) sa->sa_nwid, sa->sa_port);
 	return (buf);
@@ -153,6 +153,6 @@ nng_str_sockaddr(const nng_sockaddr *sa, char *buf, size_t bufsz)
 	    return (str_sa_zt(&sa->s_zt, buf, bufsz));
 	case NNG_AF_UNSPEC:
 	default:
-		return ("unknown{}");
+		return ("unknown");
 	}
 }

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
@@ -10,6 +10,7 @@
 
 #include "core/nng_impl.h"
 #include "list.h"
+#include "nng/nng.h"
 #include "sockimpl.h"
 
 #include <stdio.h>
@@ -1543,6 +1544,14 @@ 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);
+	nng_sockaddr sa;
+	char         addr[256] = "unknown";
+	size_t       sz        = sizeof(sa);
+	sa.s_family            = NNG_AF_UNSPEC;
+	nni_pipe_getopt(p, NNG_OPT_REMADDR, &sa, &sz, NNI_TYPE_SOCKADDR);
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug("NNG-CONNECT", "Connected pipe<%u> on socket<%u> to %s",
+	    nni_pipe_id(p), nni_sock_id(s), addr);
 	nni_pipe_rele(p);
 }
 
@@ -1653,6 +1662,14 @@ 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);
+	nng_sockaddr sa;
+	char         addr[256] = "unknown";
+	size_t       sz        = sizeof(sa);
+	sa.s_family            = NNG_AF_UNSPEC;
+	nni_pipe_getopt(p, NNG_OPT_REMADDR, &sa, &sz, NNI_TYPE_SOCKADDR);
+	nng_str_sockaddr(&sa, addr, sizeof(addr));
+	nng_log_debug("NNG-ACCEPT", "Accepted pipe<%u> on socket<%u> from %s",
+	    nni_pipe_id(p), nni_sock_id(s), addr);
 	nni_pipe_rele(p);
 }
 

src/sp/transport/ipc/ipc.c

@@ -382,9 +382,19 @@ ipc_pipe_recv_cb(void *arg)
 		// Make sure the message payload is not too big.  If it is
 		// the caller will shut down the pipe.
 		if ((len > p->rcv_max) && (p->rcv_max > 0)) {
+			uint64_t pid;
+			char     peer[64] = "";
+			if (nng_stream_get_uint64(
+			        p->conn, NNG_OPT_PEER_PID, &pid) == 0) {
+				snprintf(peer, sizeof(peer), " from PID %lu",
+				    (unsigned long) pid);
+			}
 			nng_log_warn("NNG-RCVMAX",
-			    "Rejected oversize message of %lu bytes on IPC",
-			    (unsigned long) len);
+			    "Oversize message of %lu bytes (> %lu) "
+			    "on socket<%u> pipe<%u> from IPC%s",
+			    (unsigned long) len, (unsigned long) p->rcv_max,
+			    nni_pipe_sock_id(p->pipe), nni_pipe_id(p->pipe),
+			    peer);
 			rv = NNG_EMSGSIZE;
 			goto error;
 		}

src/sp/transport/ipc/ipc_test.c

@@ -42,7 +42,7 @@ test_ipc_dialer_perms(void)
 {
 	nng_socket s;
 	nng_dialer d;
-	char *     addr;
+	char      *addr;
 
 	NUTS_ADDR(addr, "ipc");
 	NUTS_OPEN(s);
@@ -59,7 +59,7 @@ test_ipc_dialer_properties(void)
 	nng_dialer   d;
 	nng_sockaddr sa;
 	size_t       z;
-	char         *addr;
+	char        *addr;
 
 	NUTS_ADDR(addr, "ipc");
 	NUTS_OPEN(s);
@@ -84,10 +84,10 @@ test_ipc_listener_perms(void)
 {
 	nng_socket   s;
 	nng_listener l;
-	char         *addr;
+	char        *addr;
 
 #ifndef _WIN32
-	char *      path;
+	char       *path;
 	struct stat st;
 #endif
 
@@ -125,7 +125,7 @@ test_ipc_listener_properties(void)
 	nng_listener l;
 	nng_sockaddr sa;
 	size_t       z;
-	char         *addr;
+	char        *addr;
 
 	NUTS_ADDR(addr, "ipc");
 	NUTS_OPEN(s);
@@ -154,8 +154,9 @@ test_ipc_recv_max(void)
 	nng_socket   s1;
 	nng_listener l;
 	size_t       sz;
-	char         *addr;
+	char        *addr;
 
+	NUTS_ENABLE_LOG(NNG_LOG_INFO);
 	NUTS_ADDR(addr, "ipc");
 	NUTS_OPEN(s0);
 	NUTS_PASS(nng_socket_set_ms(s0, NNG_OPT_RECVTIMEO, 100));
@@ -184,12 +185,12 @@ test_abstract_sockets(void)
 #ifdef NNG_HAVE_ABSTRACT_SOCKETS
 	nng_socket   s1;
 	nng_socket   s2;
-	char         *addr;
+	char        *addr;
 	nng_pipe     p1;
 	nng_pipe     p2;
 	nng_sockaddr sa1;
 	nng_sockaddr sa2;
-	char *       prefix = "abstract://";
+	char        *prefix = "abstract://";
 
 	NUTS_ADDR(addr, "abstract");
 	NUTS_OPEN(s1);
@@ -341,7 +342,7 @@ test_unix_alias(void)
 	char         rng[20];
 	nng_sockaddr sa1;
 	nng_sockaddr sa2;
-	nng_msg *    msg;
+	nng_msg     *msg;
 	nng_pipe     p;
 
 	// Presumes /tmp.
@@ -385,11 +386,11 @@ test_ipc_pipe_peer(void)
 #ifdef NNG_PLATFORM_POSIX
 	// this test verifies that closing a socket peer
 	// during negotiation is ok.
-	nng_socket   s0, s1;
-	nng_msg     *msg;
-	nng_pipe     p;
-	uint64_t     id;
-	char         *addr;
+	nng_socket s0, s1;
+	nng_msg   *msg;
+	nng_pipe   p;
+	uint64_t   id;
+	char      *addr;
 
 	NUTS_ADDR(addr, "ipc");
 	NUTS_OPEN(s0);
@@ -432,7 +433,6 @@ test_ipc_pipe_peer(void)
 #endif // NNG_PLATFORM_POSIX
 }
 
-
 TEST_LIST = {
 	{ "ipc path too long", test_path_too_long },
 	{ "ipc dialer perms", test_ipc_dialer_perms },
@@ -447,4 +447,4 @@ TEST_LIST = {
 	{ "ipc unix alias", test_unix_alias },
 	{ "ipc peer id", test_ipc_pipe_peer },
 	{ NULL, NULL },
-};
+};

src/sp/transport/tcp/tcp.c

@@ -13,6 +13,7 @@
 #include <string.h>
 
 #include "core/nng_impl.h"
+#include "nng/nng.h"
 
 // TCP transport.   Platform specific TCP operations must be
 // supplied as well.
@@ -384,9 +385,21 @@ tcptran_pipe_recv_cb(void *arg)
 		// Make sure the message payload is not too big.  If it is
 		// the caller will shut down the pipe.
 		if ((len > p->rcvmax) && (p->rcvmax > 0)) {
+			nng_sockaddr_storage ss;
+			nng_sockaddr        *sa = (nng_sockaddr *) &ss;
+			char                 peername[64] = "unknown";
+			int                  rv;
+			if ((rv = nng_stream_get_addr(
+			         p->conn, NNG_OPT_REMADDR, sa)) == 0) {
+				(void) nng_str_sockaddr(
+				    sa, peername, sizeof(peername));
+			}
 			nng_log_warn("NNG-RCVMAX",
-			    "Rejected oversize message of %lu bytes on TCP",
-			    (unsigned long) len);
+			    "Oversize message of %lu bytes (> %lu) "
+			    "on socket<%u> pipe<%u> from TCP %s",
+			    (unsigned long) len, (unsigned long) p->rcvmax,
+			    nni_pipe_sock_id(p->npipe), nni_pipe_id(p->npipe),
+			    peername);
 			rv = NNG_EMSGSIZE;
 			goto recv_error;
 		}