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.

6 files changed, 68 insertions, 40 deletions

diff --git a/src/sp/transport/ipc/ipc.c b/src/sp/transport/ipc/ipc.c
index fc817d1a..61c25da3 100644
--- a/src/sp/transport/ipc/ipc.c
+++ b/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;
 		}
diff --git a/src/sp/transport/ipc/ipc_test.c b/src/sp/transport/ipc/ipc_test.c
index b39aa937..3936a750 100644
--- a/src/sp/transport/ipc/ipc_test.c
+++ b/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 },
-};
\ No newline at end of file
+};
diff --git a/src/sp/transport/tcp/tcp.c b/src/sp/transport/tcp/tcp.c
index dfc3d20c..5aead15d 100644
--- a/src/sp/transport/tcp/tcp.c
+++ b/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,20 @@ 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";
+			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;
 		}
diff --git a/src/sp/transport/tcp/tcp_test.c b/src/sp/transport/tcp/tcp_test.c
index 16c70d7d..005fd2b0 100644
--- a/src/sp/transport/tcp/tcp_test.c
+++ b/src/sp/transport/tcp/tcp_test.c
@@ -1,5 +1,5 @@
 //
-// Copyright 2020 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>
 // Copyright 2018 Cody Piersall <cody.piersall@gmail.com>
@@ -10,7 +10,6 @@
 // found online at https://opensource.org/licenses/MIT.
 //
 
-
 #include <nuts.h>
 
 // TCP tests.
@@ -75,7 +74,7 @@ test_tcp_port_zero_bind(void)
 	nng_socket   s2;
 	nng_sockaddr sa;
 	nng_listener l;
-	char *       addr;
+	char        *addr;
 
 	NUTS_OPEN(s1);
 	NUTS_OPEN(s2);
@@ -96,7 +95,7 @@ void
 test_tcp_bad_local_interface(void)
 {
 	nng_socket s1;
-	int rv;
+	int        rv;
 
 	NUTS_OPEN(s1);
 	rv = nng_dial(s1, "tcp://bogus1;127.0.0.1:80", NULL, 0),
@@ -122,12 +121,9 @@ test_tcp_malformed_address(void)
 	nng_socket s1;
 
 	NUTS_OPEN(s1);
-	NUTS_FAIL(
-	    nng_dial(s1, "tcp://127.0.0.1", NULL, 0), NNG_EADDRINVAL);
-	NUTS_FAIL(
-	    nng_dial(s1, "tcp://127.0.0.1.32", NULL, 0), NNG_EADDRINVAL);
-	NUTS_FAIL(
-	    nng_dial(s1, "tcp://127.0.x.1.32", NULL, 0), NNG_EADDRINVAL);
+	NUTS_FAIL(nng_dial(s1, "tcp://127.0.0.1", NULL, 0), NNG_EADDRINVAL);
+	NUTS_FAIL(nng_dial(s1, "tcp://127.0.0.1.32", NULL, 0), NNG_EADDRINVAL);
+	NUTS_FAIL(nng_dial(s1, "tcp://127.0.x.1.32", NULL, 0), NNG_EADDRINVAL);
 	NUTS_FAIL(
 	    nng_listen(s1, "tcp://127.0.0.1.32", NULL, 0), NNG_EADDRINVAL);
 	NUTS_FAIL(
@@ -143,7 +139,7 @@ test_tcp_no_delay_option(void)
 	nng_listener l;
 	bool         v;
 	int          x;
-	char         *addr;
+	char        *addr;
 
 	NUTS_ADDR(addr, "tcp");
 
@@ -161,8 +157,7 @@ test_tcp_no_delay_option(void)
 	NUTS_FAIL(
 	    nng_dialer_get_int(d, NNG_OPT_TCP_NODELAY, &x), NNG_EBADTYPE);
 	x = 0;
-	NUTS_FAIL(
-	    nng_dialer_set_int(d, NNG_OPT_TCP_NODELAY, x), NNG_EBADTYPE);
+	NUTS_FAIL(nng_dialer_set_int(d, NNG_OPT_TCP_NODELAY, x), NNG_EBADTYPE);
 	// This assumes sizeof (bool) != sizeof (int)
 	if (sizeof(bool) != sizeof(int)) {
 		NUTS_FAIL(
@@ -205,7 +200,7 @@ test_tcp_keep_alive_option(void)
 	nng_listener l;
 	bool         v;
 	int          x;
-	char         *addr;
+	char        *addr;
 
 	NUTS_ADDR(addr, "tcp");
 	NUTS_OPEN(s);
@@ -258,7 +253,7 @@ test_tcp_recv_max(void)
 	nng_socket   s1;
 	nng_listener l;
 	size_t       sz;
-	char         *addr;
+	char        *addr;
 
 	NUTS_ADDR(addr, "tcp");
 
@@ -296,4 +291,4 @@ NUTS_TESTS = {
 	{ "tcp keep alive option", test_tcp_keep_alive_option },
 	{ "tcp recv max", test_tcp_recv_max },
 	{ NULL, NULL },
-};
\ No newline at end of file
+};
diff --git a/src/sp/transport/tls/tls.c b/src/sp/transport/tls/tls.c
index 4412fa03..30a95725 100644
--- a/src/sp/transport/tls/tls.c
+++ b/src/sp/transport/tls/tls.c
@@ -377,9 +377,20 @@ tlstran_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";
+			if ((rv = nng_stream_get_addr(
+			         p->tls, 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 TLS",
-			    (unsigned long) len);
+			    "Oversize message of %lu bytes (> %lu) "
+			    "on socket<%u> pipe<%u> from TLS %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;
 		}
diff --git a/src/sp/transport/ws/ws_test.c b/src/sp/transport/ws/ws_test.c
index b5e72b79..9115338f 100644
--- a/src/sp/transport/ws/ws_test.c
+++ b/src/sp/transport/ws/ws_test.c
@@ -144,7 +144,7 @@ test_ws_recv_max(void)
 	nng_socket   s1;
 	nng_listener l;
 	size_t       sz;
-	char *       addr;
+	char        *addr;
 
 	memset(msg, 0, sizeof(msg)); // required to silence valgrind
 
@@ -177,4 +177,4 @@ TEST_LIST = {
 	{ "ws empty host", test_empty_host },
 	{ "ws recv max", test_ws_recv_max },
 	{ NULL, NULL },
-};
\ No newline at end of file
+};