stream: Refactor sctp_recvmsg_wrapper() logging

*Move the helper function to stream.c and pass a logging prefix string
so that it can be used by both client and server.
* Adapt log level based on message type.
* Rework logging code to log everything in one line

Change-Id: I0ed84cc2effb71b6ef1f6efb3f8b663c602a5a31

3 files changed, 85 insertions, 73 deletions

diff --git a/include/osmocom/netif/stream_private.h b/include/osmocom/netif/stream_private.h
index 8f83a25..c593527 100644
--- a/include/osmocom/netif/stream_private.h
+++ b/include/osmocom/netif/stream_private.h
@@ -33,5 +33,6 @@ enum osmo_stream_mode {
 
 int stream_sctp_sock_activate_events(int fd);
 int stream_setsockopt_nodelay(int fd, int proto, int on);
+int stream_sctp_recvmsg_wrapper(int fd, struct msgb *msg, const char *log_pfx);
 
 /*! @} */
diff --git a/src/stream.c b/src/stream.c
index 5674c4b..26e745c 100644
--- a/src/stream.c
+++ b/src/stream.c
@@ -208,5 +208,84 @@ int stream_setsockopt_nodelay(int fd, int proto, int on)
 	return rc;
 }
 
+#ifdef HAVE_LIBSCTP
+#define LOGPFX(pfx, level, fmt, args...) \
+	LOGP(DLINP, level, "%s " fmt, pfx, ## args)
+int stream_sctp_recvmsg_wrapper(int fd, struct msgb *msg, const char *log_pfx)
+{
+	struct sctp_sndrcvinfo sinfo;
+	int flags = 0;
+	int ret;
+	uint8_t *data = msg->tail;
+
+	ret = sctp_recvmsg(fd, data, msgb_tailroom(msg), NULL, NULL, &sinfo, &flags);
+	msgb_sctp_msg_flags(msg) = 0;
+	msgb_sctp_ppid(msg) = ntohl(sinfo.sinfo_ppid);
+	msgb_sctp_stream(msg) = sinfo.sinfo_stream;
+
+	if (flags & MSG_NOTIFICATION) {
+		char buf[512];
+		struct osmo_strbuf sb = { .buf = buf, .len = sizeof(buf) };
+		int logl = LOGL_INFO;
+		union sctp_notification *notif = (union sctp_notification *)data;
+
+		OSMO_STRBUF_PRINTF(sb, "%s NOTIFICATION %s flags=0x%x", log_pfx,
+				   osmo_sctp_sn_type_str(notif->sn_header.sn_type), notif->sn_header.sn_flags);
+		msgb_put(msg, sizeof(union sctp_notification));
+		msgb_sctp_msg_flags(msg) = OSMO_STREAM_SCTP_MSG_FLAGS_NOTIFICATION;
+		ret = -EAGAIN;
+
+		switch (notif->sn_header.sn_type) {
+		case SCTP_ASSOC_CHANGE:
+			OSMO_STRBUF_PRINTF(sb, " %s", osmo_sctp_assoc_chg_str(notif->sn_assoc_change.sac_state));
+			switch (notif->sn_assoc_change.sac_state) {
+			case SCTP_COMM_UP:
+				break;
+			case SCTP_COMM_LOST:
+				OSMO_STRBUF_PRINTF(sb, " (err: %s)",
+						   osmo_sctp_sn_error_str(notif->sn_assoc_change.sac_error));
+				/* Handle this like a regular disconnect */
+				ret = 0;
+				break;
+			case SCTP_RESTART:
+			case SCTP_SHUTDOWN_COMP:
+				logl = LOGL_NOTICE;
+				break;
+			case SCTP_CANT_STR_ASSOC:
+				break;
+			}
+			break;
+		case SCTP_SEND_FAILED:
+			logl = LOGL_ERROR;
+			break;
+		case SCTP_PEER_ADDR_CHANGE:
+			{
+			char addr_str[INET6_ADDRSTRLEN + 10];
+			struct sockaddr_storage sa = notif->sn_paddr_change.spc_aaddr;
+			osmo_sockaddr_to_str_buf(addr_str, sizeof(addr_str),
+						 (const struct osmo_sockaddr *)&sa);
+			OSMO_STRBUF_PRINTF(sb, " %s %s err=%s",
+					   osmo_sctp_paddr_chg_str(notif->sn_paddr_change.spc_state), addr_str,
+					   (notif->sn_paddr_change.spc_state == SCTP_ADDR_UNREACHABLE) ?
+						osmo_sctp_sn_error_str(notif->sn_paddr_change.spc_error) : "None");
+			}
+			break;
+		case SCTP_SHUTDOWN_EVENT:
+			logl = LOGL_NOTICE;
+			/* RFC6458 3.1.4: Any attempt to send more data will cause sendmsg()
+			 * to return with an ESHUTDOWN error. */
+			break;
+		case SCTP_REMOTE_ERROR:
+			logl = LOGL_NOTICE;
+			OSMO_STRBUF_PRINTF(sb, " %s", osmo_sctp_op_error_str(ntohs(notif->sn_remote_error.sre_error)));
+			break;
+		}
+		LOGP(DLINP, logl, "%s\n", buf);
+		return ret;
+	}
+	return ret;
+}
+#endif
+
 
 /*! @} */
diff --git a/src/stream_srv.c b/src/stream_srv.c
index 3625ffd..17925af 100644
--- a/src/stream_srv.c
+++ b/src/stream_srv.c
@@ -830,78 +830,6 @@ void osmo_stream_srv_send(struct osmo_stream_srv *conn, struct msgb *msg)
 	}
 }
 
-#ifdef HAVE_LIBSCTP
-static int _sctp_recvmsg_wrapper(int fd, struct msgb *msg)
-{
-	struct sctp_sndrcvinfo sinfo;
-	int flags = 0;
-	int ret;
-	uint8_t *data = msg->tail;
-
-	ret = sctp_recvmsg(fd, data, msgb_tailroom(msg),
-			NULL, NULL, &sinfo, &flags);
-	msgb_sctp_msg_flags(msg) = 0;
-	msgb_sctp_ppid(msg) = ntohl(sinfo.sinfo_ppid);
-	msgb_sctp_stream(msg) = sinfo.sinfo_stream;
-	if (flags & MSG_NOTIFICATION) {
-		union sctp_notification *notif = (union sctp_notification *)data;
-		LOGP(DLINP, LOGL_DEBUG, "NOTIFICATION %u flags=0x%x\n", notif->sn_header.sn_type, notif->sn_header.sn_flags);
-		msgb_put(msg, sizeof(union sctp_notification));
-		msgb_sctp_msg_flags(msg) = OSMO_STREAM_SCTP_MSG_FLAGS_NOTIFICATION;
-		switch (notif->sn_header.sn_type) {
-		case SCTP_ASSOC_CHANGE:
-			LOGP(DLINP, LOGL_DEBUG, "===> ASSOC CHANGE:");
-			switch (notif->sn_assoc_change.sac_state) {
-			case SCTP_COMM_UP:
-				LOGPC(DLINP, LOGL_DEBUG, " UP\n");
-				break;
-			case SCTP_COMM_LOST:
-				LOGPC(DLINP, LOGL_DEBUG, " COMM_LOST (err: %s)\n",
-				      osmo_sctp_sn_error_str(notif->sn_assoc_change.sac_error));
-				/* Handle this like a regular disconnect */
-				return 0;
-			case SCTP_RESTART:
-				LOGPC(DLINP, LOGL_DEBUG, " RESTART\n");
-				break;
-			case SCTP_SHUTDOWN_COMP:
-				LOGPC(DLINP, LOGL_DEBUG, " SHUTDOWN COMP\n");
-				break;
-			case SCTP_CANT_STR_ASSOC:
-				LOGPC(DLINP, LOGL_DEBUG, " CANT STR ASSOC\n");
-				break;
-			}
-			break;
-		case SCTP_SEND_FAILED:
-			LOGP(DLINP, LOGL_DEBUG, "===> SEND FAILED\n");
-			break;
-		case SCTP_PEER_ADDR_CHANGE:
-			{
-			char addr_str[INET6_ADDRSTRLEN + 10];
-			struct sockaddr_storage sa = notif->sn_paddr_change.spc_aaddr;
-			osmo_sockaddr_to_str_buf(addr_str, sizeof(addr_str),
-						 (const struct osmo_sockaddr *)&sa);
-			LOGP(DLINP, LOGL_DEBUG, "===> PEER ADDR CHANGE: %s %s err=%s\n",
-			     addr_str, osmo_sctp_paddr_chg_str(notif->sn_paddr_change.spc_state),
-			     (notif->sn_paddr_change.spc_state == SCTP_ADDR_UNREACHABLE) ?
-				osmo_sctp_sn_error_str(notif->sn_paddr_change.spc_error) : "None");
-			}
-			break;
-		case SCTP_SHUTDOWN_EVENT:
-			LOGP(DLINP, LOGL_DEBUG, "===> SHUTDOWN EVT\n");
-			/* RFC6458 3.1.4: Any attempt to send more data will cause sendmsg()
-			 * to return with an ESHUTDOWN error. */
-			break;
-		case SCTP_REMOTE_ERROR:
-			LOGP(DLINP, LOGL_DEBUG, "===> REMOTE ERROR: %s\n",
-			     osmo_sctp_op_error_str(ntohs(notif->sn_remote_error.sre_error)));
-			break;
-		}
-		return -EAGAIN;
-	}
-	return ret;
-}
-#endif
-
 /*! \brief Receive data via Osmocom stream server
  *  \param[in] conn Stream Server from which to receive
  *  \param msg pre-allocate message buffer to which received data is appended
@@ -933,8 +861,12 @@ int osmo_stream_srv_recv(struct osmo_stream_srv *conn, struct msgb *msg)
 		switch (conn->srv->proto) {
 #ifdef HAVE_LIBSCTP
 		case IPPROTO_SCTP:
-			ret = _sctp_recvmsg_wrapper(conn->ofd.fd, msg);
+		{
+			char log_pfx[128];
+			snprintf(log_pfx, sizeof(log_pfx), "SRV(%s,%s)", conn->name ? : "", conn->sockname);
+			ret = stream_sctp_recvmsg_wrapper(conn->ofd.fd, msg, log_pfx);
 			break;
+		}
 #endif
 		case IPPROTO_TCP:
 		default: