changeset 28:660126bd5f59

themwi-mncc: fix one bug, add debug syslog output
author Mychaela Falconia <falcon@freecalypso.org>
date Tue, 28 Jun 2022 21:47:04 -0800
parents c6572f4c31d2
children dffcae9bc8a3
files libutil/Makefile libutil/mncc_debug.c mncc/call_setup.c mncc/extsock.c mncc/gsm_call.c mncc/intswitch.c mncc/mncc_recv.c mncc/mtsock.c
diffstat 8 files changed, 194 insertions(+), 17 deletions(-) [+]
line wrap: on
line diff
--- a/libutil/Makefile	Tue Jun 28 19:21:51 2022 -0800
+++ b/libutil/Makefile	Tue Jun 28 21:47:04 2022 -0800
@@ -1,7 +1,7 @@
 CC=	gcc
 CFLAGS=	-O2
-OBJS=	extdigits.o imsi_entry.o mncc_utils.o nanp_valid.o numstring.o \
-	sockinit.o
+OBJS=	extdigits.o imsi_entry.o mncc_debug.o mncc_utils.o nanp_valid.o \
+	numstring.o sockinit.o
 LIB=	libutil.a
 
 all:	${LIB}
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/libutil/mncc_debug.c	Tue Jun 28 21:47:04 2022 -0800
@@ -0,0 +1,109 @@
+/* MNCC debug functions */
+
+#include <sys/types.h>
+#include <sys/socket.h>
+#include <stdio.h>
+#include <stdint.h>
+#include "../include/mncc.h"
+
+char *
+mncc_msg_name(msgtype)
+{
+	static char buf[32];
+
+	switch (msgtype) {
+	case MNCC_SETUP_REQ:
+		return "MNCC_SETUP_REQ";
+	case MNCC_SETUP_IND:
+		return "MNCC_SETUP_IND";
+	case MNCC_SETUP_RSP:
+		return "MNCC_SETUP_RSP";
+	case MNCC_SETUP_CNF:
+		return "MNCC_SETUP_CNF";
+	case MNCC_SETUP_COMPL_REQ:
+		return "MNCC_SETUP_COMPL_REQ";
+	case MNCC_SETUP_COMPL_IND:
+		return "MNCC_SETUP_COMPL_IND";
+	case MNCC_CALL_CONF_IND:
+		return "MNCC_CALL_CONF_IND";
+	case MNCC_CALL_PROC_REQ:
+		return "MNCC_CALL_PROC_REQ";
+	case MNCC_PROGRESS_REQ:
+		return "MNCC_PROGRESS_REQ";
+	case MNCC_ALERT_REQ:
+		return "MNCC_ALERT_REQ";
+	case MNCC_ALERT_IND:
+		return "MNCC_ALERT_IND";
+	case MNCC_NOTIFY_REQ:
+		return "MNCC_NOTIFY_REQ";
+	case MNCC_NOTIFY_IND:
+		return "MNCC_NOTIFY_IND";
+	case MNCC_DISC_REQ:
+		return "MNCC_DISC_REQ";
+	case MNCC_DISC_IND:
+		return "MNCC_DISC_IND";
+	case MNCC_REL_REQ:
+		return "MNCC_REL_REQ";
+	case MNCC_REL_IND:
+		return "MNCC_REL_IND";
+	case MNCC_REL_CNF:
+		return "MNCC_REL_CNF";
+	case MNCC_FACILITY_REQ:
+		return "MNCC_FACILITY_REQ";
+	case MNCC_FACILITY_IND:
+		return "MNCC_FACILITY_IND";
+	case MNCC_START_DTMF_IND:
+		return "MNCC_START_DTMF_IND";
+	case MNCC_START_DTMF_RSP:
+		return "MNCC_START_DTMF_RSP";
+	case MNCC_START_DTMF_REJ:
+		return "MNCC_START_DTMF_REJ";
+	case MNCC_STOP_DTMF_IND:
+		return "MNCC_STOP_DTMF_IND";
+	case MNCC_STOP_DTMF_RSP:
+		return "MNCC_STOP_DTMF_RSP";
+	case MNCC_MODIFY_REQ:
+		return "MNCC_MODIFY_REQ";
+	case MNCC_MODIFY_IND:
+		return "MNCC_MODIFY_IND";
+	case MNCC_MODIFY_RSP:
+		return "MNCC_MODIFY_RSP";
+	case MNCC_MODIFY_CNF:
+		return "MNCC_MODIFY_CNF";
+	case MNCC_MODIFY_REJ:
+		return "MNCC_MODIFY_REJ";
+	case MNCC_HOLD_IND:
+		return "MNCC_HOLD_IND";
+	case MNCC_HOLD_CNF:
+		return "MNCC_HOLD_CNF";
+	case MNCC_HOLD_REJ:
+		return "MNCC_HOLD_REJ";
+	case MNCC_RETRIEVE_IND:
+		return "MNCC_RETRIEVE_IND";
+	case MNCC_RETRIEVE_CNF:
+		return "MNCC_RETRIEVE_CNF";
+	case MNCC_RETRIEVE_REJ:
+		return "MNCC_RETRIEVE_REJ";
+	case MNCC_USERINFO_REQ:
+		return "MNCC_USERINFO_REQ";
+	case MNCC_USERINFO_IND:
+		return "MNCC_USERINFO_IND";
+	case MNCC_REJ_REQ:
+		return "MNCC_REJ_REQ";
+	case MNCC_REJ_IND:
+		return "MNCC_REJ_IND";
+	case MNCC_BRIDGE:
+		return "MNCC_BRIDGE";
+	case MNCC_RTP_CREATE:
+		return "MNCC_RTP_CREATE";
+	case MNCC_RTP_CONNECT:
+		return "MNCC_RTP_CONNECT";
+	case MNCC_RTP_FREE:
+		return "MNCC_RTP_FREE";
+	case MNCC_SOCKET_HELLO:
+		return "MNCC_SOCKET_HELLO";
+	default:
+		sprintf(buf, "MNCC msgtype 0x%x", msgtype);
+		return buf;
+	}
+}
--- a/mncc/call_setup.c	Tue Jun 28 19:21:51 2022 -0800
+++ b/mncc/call_setup.c	Tue Jun 28 21:47:04 2022 -0800
@@ -66,12 +66,16 @@
 	else
 		msg->fields &= ~MNCC_F_CALLING;
 	if (!(msg->fields & MNCC_F_CALLED)) {
+		syslog(LOG_ERR, "rejecting MO call 0x%x: no called number",
+			msg->callref);
 		reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_INVAL_MAND_INF);
 		return;
 	}
 	call = create_gsm_call(msg->callref);
 	if (!call) {
+		syslog(LOG_ERR, "rejecting MO call 0x%x: no memory for call",
+			msg->callref);
 		reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_RESOURCE_UNAVAIL);
 		return;
@@ -91,6 +95,9 @@
 			break;
 		res = lookup_short_dial_number(msg->called.number, nanp);
 		if (!res) {
+			syslog(LOG_ERR,
+				"rejecting MO call 0x%x: invalid short number",
+				msg->callref);
 			reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 					GSM48_CC_CAUSE_UNASSIGNED_NR);
 			call->gc_flag = 1;
@@ -117,6 +124,9 @@
 		    msg->called.plan != GSM48_NPI_NATIONAL)
 			break;
 		if (!is_nanp_valid_prefix(msg->called.number)) {
+			syslog(LOG_ERR,
+				"rejecting MO call 0x%x: invalid NANP number",
+				msg->callref);
 			reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 					GSM48_CC_CAUSE_INV_NR_FORMAT);
 			call->gc_flag = 1;
@@ -139,6 +149,9 @@
 		if (msg->called.number[0] != '1')
 			break;
 		if (!is_nanp_valid_prefix(msg->called.number+1)) {
+			syslog(LOG_ERR,
+				"rejecting MO call 0x%x: invalid NANP number",
+				msg->callref);
 			reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 					GSM48_CC_CAUSE_INV_NR_FORMAT);
 			call->gc_flag = 1;
@@ -155,6 +168,8 @@
 		is_local = 1;
 	/* weed out attempts to call yourself */
 	if (is_local && !strcmp(msg->calling.number, msg->called.number)) {
+		syslog(LOG_ERR, "rejecting MO call 0x%x: call to self",
+			msg->callref);
 		reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_INCOMPAT_DEST);
 		call->gc_flag = 1;
@@ -166,6 +181,8 @@
 		return;
 	}
 	/* outbound calls remain to be implemented */
+	syslog(LOG_ERR, "rejecting MO call 0x%x: outbound not implemented",
+		msg->callref);
 	reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 			GSM48_CC_CAUSE_NO_ROUTE);
 	call->gc_flag = 1;
@@ -193,18 +210,23 @@
 	struct gsm_call *call;
 
 	if (!(msg->fields & MNCC_F_CALLED) && !msg->imsi[0]) {
+		syslog(LOG_ERR, "rejecting ext MT: no called number");
 		reject_mt_call(conn, msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_INVAL_MAND_INF);
 		return;
 	}
 	call = create_new_mt_call();
 	if (!call) {
+		syslog(LOG_ERR, "rejecting ext MT: no memory for call");
 		reject_mt_call(conn, msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_RESOURCE_UNAVAIL);
 		return;
 	}
 	call->socket = conn;
 	call->socket_ref = msg->callref;
+	conn->ncalls++;
+	syslog(LOG_DEBUG, "mapped socket callref 0x%x to GSM callref 0x%x",
+		msg->callref, call->callref);
 	/* forward to GSM MNCC interface */
 	msg->callref = call->callref;
 	send_mncc_to_gsm(msg, sizeof(struct gsm_mncc));
--- a/mncc/extsock.c	Tue Jun 28 19:21:51 2022 -0800
+++ b/mncc/extsock.c	Tue Jun 28 21:47:04 2022 -0800
@@ -17,6 +17,8 @@
 #include "struct.h"
 #include "gsm_call.h"
 
+extern char *mncc_msg_name();
+
 void
 extsock_dec_refcount(conn)
 	struct socket_conn *conn;
@@ -52,6 +54,9 @@
 		if (call->gc_flag)
 			continue;
 		if (call->socket == conn) {
+			syslog(LOG_WARNING,
+	"clearing broken socket call: GSM callref 0x%x, socket ref 0x%x",
+				call->callref, call->socket_ref);
 			send_rel_on_broken_socket(call);
 			extsock_dec_refcount(conn);
 			call->gc_flag = 1;
@@ -85,6 +90,8 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx MNCC_SETUP_REQ from socket, callref=0x%x",
+		msg->callref);
 	call = find_socket_call(conn, msg->callref);
 	if (call) {
 		syslog(LOG_ERR,
@@ -109,6 +116,8 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx %s from socket, callref=0x%x",
+		mncc_msg_name(msg->msg_type), msg->callref);
 	call = find_socket_call(conn, msg->callref);
 	if (!call) {
 		syslog(LOG_ERR,
@@ -138,6 +147,8 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx %s from socket, callref=0x%x",
+		mncc_msg_name(msg->msg_type), msg->callref);
 	call = find_socket_call(conn, msg->callref);
 	if (!call) {
 		syslog(LOG_ERR,
@@ -160,8 +171,11 @@
 
 	rc = recv(conn->fd, &msg, sizeof msg, 0);
 	if (rc < 4) {
-		if (conn->ncalls)
+		if (conn->ncalls) {
+			syslog(LOG_ERR, "ext socket broken with calls present");
 			broken_socket_clear_calls(conn);
+		} else
+			syslog(LOG_INFO, "normal closing of ext socket");
 		close(conn->fd);
 		conn->fd = -1;
 		return;
--- a/mncc/gsm_call.c	Tue Jun 28 19:21:51 2022 -0800
+++ b/mncc/gsm_call.c	Tue Jun 28 21:47:04 2022 -0800
@@ -83,6 +83,7 @@
 		if (!find_gsm_callref(callref))
 			break;
 	}
+	syslog(LOG_DEBUG, "creating new MT callref 0x%x", callref);
 	return create_gsm_call(callref);
 }
 
--- a/mncc/intswitch.c	Tue Jun 28 19:21:51 2022 -0800
+++ b/mncc/intswitch.c	Tue Jun 28 21:47:04 2022 -0800
@@ -16,6 +16,8 @@
 #include "struct.h"
 #include "gsm_call.h"
 
+extern char *mncc_msg_name();
+
 void
 internal_switch_mo_setup(call, msg)
 	struct gsm_call *call;
@@ -25,6 +27,8 @@
 	struct gsm_mncc callproc;
 
 	if (!(msg->fields & MNCC_F_BEARER_CAP)) {
+		syslog(LOG_ERR, "rejecting intsw call 0x%x: no bearer cap",
+			msg->callref);
 		reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_INVAL_MAND_INF);
 		call->gc_flag = 1;
@@ -33,6 +37,8 @@
 	/* same speech-only restriction as in OsmoMSC's mncc_builtin */
 	if (msg->bearer_cap.transfer != GSM48_BCAP_ITCAP_SPEECH ||
 	    msg->bearer_cap.mode != GSM48_BCAP_TMOD_CIRCUIT) {
+		syslog(LOG_ERR, "rejecting intsw call 0x%x: bad bearer cap",
+			msg->callref);
 		reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_BEARER_CA_UNAVAIL);
 		call->gc_flag = 1;
@@ -40,11 +46,15 @@
 	}
 	mt = create_new_mt_call();
 	if (!mt) {
+		syslog(LOG_ERR,
+			"rejecting intsw call 0x%x: no memory for MT call",
+			msg->callref);
 		reject_mo_call(msg->callref, GSM48_CAUSE_LOC_PRN_S_LU,
 				GSM48_CC_CAUSE_RESOURCE_UNAVAIL);
 		call->gc_flag = 1;
 		return;
 	}
+	syslog(LOG_DEBUG, "intsw: MO=0x%x MT=0x%x", call->callref, mt->callref);
 	call->other_leg = mt;
 	mt->other_leg = call;
 	/* send call proceeding */
@@ -73,8 +83,12 @@
 	ack.callref = call->callref;
 	send_mncc_to_gsm(&ack, sizeof(struct gsm_mncc));
 	/* do we have the far end? */
-	if (!call->other_leg)
+	if (!call->other_leg) {
+		syslog(LOG_ERR, "intsw: missing other leg for MNCC_SETUP_CNF");
 		return;
+	}
+	syslog(LOG_DEBUG, "MNCC_SETUP_CNF from 0x%x to 0x%x", call->callref,
+		call->other_leg->callref);
 	msg->msg_type = MNCC_SETUP_RSP;
 	msg->callref = call->other_leg->callref;
 	send_mncc_to_gsm(msg, sizeof(struct gsm_mncc));
@@ -93,6 +107,7 @@
 	uint32_t new_msg_type;
 {
 	if (!call->other_leg) {
+		syslog(LOG_ERR, "intsw: missing other leg for msg forwarding");
 		/* drop it like OsmoMSC's mncc_builtin does */
 		return;
 	}
@@ -113,8 +128,12 @@
 	send_mncc_to_gsm(msg, sizeof(struct gsm_mncc));
 	/* disconnect on far end */
 	remote = call->other_leg;
-	if (!remote)
+	if (!remote) {
+		syslog(LOG_ERR, "intsw: missing other leg for MNCC_DISC_IND");
 		return;
+	}
+	syslog(LOG_DEBUG, "MNCC_DISC_IND from 0x%x to 0x%x", call->callref,
+		remote->callref);
 	msg->msg_type = MNCC_DISC_REQ;
 	msg->callref = remote->callref;
 	send_mncc_to_gsm(msg, sizeof(struct gsm_mncc));
@@ -137,6 +156,8 @@
 	/* if no remote, nothing more to do */
 	if (!remote)
 		return;
+	syslog(LOG_DEBUG, "release with remote: from 0x%x to 0x%x",
+		call->callref, remote->callref);
 	/* send them a release request */
 	msg->msg_type = MNCC_REL_REQ;
 	msg->callref = remote->callref;
@@ -206,8 +227,7 @@
 		call->gc_flag = 1;
 		return;
 	default:
-		syslog(LOG_ERR,
-			"MNCC message type 0x%x unhandled for internal switch",
-			msg->msg_type);
+		syslog(LOG_ERR, "%s unhandled for internal switch",
+			mncc_msg_name(msg->msg_type));
 	}
 }
--- a/mncc/mncc_recv.c	Tue Jun 28 19:21:51 2022 -0800
+++ b/mncc/mncc_recv.c	Tue Jun 28 21:47:04 2022 -0800
@@ -13,6 +13,8 @@
 #include "struct.h"
 #include "gsm_call.h"
 
+extern char *mncc_msg_name();
+
 static void
 report_runt(msg)
 	union mncc_msg *msg;
@@ -32,6 +34,8 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx MNCC_SETUP_IND from GSM, callref=0x%x",
+		msg->callref);
 	call = find_gsm_callref(msg->callref);
 	if (call) {
 		syslog(LOG_ERR, "duplicate MNCC_SETUP_IND for callref 0x%x",
@@ -54,11 +58,12 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx %s from GSM, callref=0x%x",
+		mncc_msg_name(msg->msg_type), msg->callref);
 	call = find_gsm_callref(msg->callref);
 	if (!call) {
-		syslog(LOG_ERR,
-			"MNCC message type 0x%x: callref 0x%x not found",
-			msg->msg_type, msg->callref);
+		syslog(LOG_ERR, "%s from GSM: callref 0x%x not found",
+			mncc_msg_name(msg->msg_type), msg->callref);
 		/* drop it like OsmoMSC's mncc_builtin does */
 		return;
 	}
@@ -82,17 +87,21 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx %s from GSM, callref=0x%x",
+		mncc_msg_name(msg->msg_type), msg->callref);
 	call = find_gsm_callref(msg->callref);
 	if (!call) {
-		syslog(LOG_ERR,
-			"MNCC message type 0x%x: callref 0x%x not found",
-			msg->msg_type, msg->callref);
+		syslog(LOG_ERR, "%s from GSM: callref 0x%x not found",
+			mncc_msg_name(msg->msg_type), msg->callref);
 		/* drop it like OsmoMSC's mncc_builtin does */
 		return;
 	}
 	/* dispatch according to internal switch or socket */
 	if (call->socket) {
 		mncc_signal_to_socket(call, msg);
+		syslog(LOG_DEBUG,
+		"clearing socket call: GSM callref 0x%x, socket ref 0x%x",
+			call->callref, call->socket_ref);
 		extsock_dec_refcount(call->socket);
 		call->gc_flag = 1;
 	} else
@@ -110,11 +119,12 @@
 		report_runt(msg);
 		return;
 	}
+	syslog(LOG_DEBUG, "Rx %s from GSM, callref=0x%x",
+		mncc_msg_name(msg->msg_type), msg->callref);
 	call = find_gsm_callref(msg->callref);
 	if (!call) {
-		syslog(LOG_ERR,
-			"MNCC message type 0x%x: callref 0x%x not found",
-			msg->msg_type, msg->callref);
+		syslog(LOG_ERR, "%s from GSM: callref 0x%x not found",
+			mncc_msg_name(msg->msg_type), msg->callref);
 		/* drop it like OsmoMSC's mncc_builtin does */
 		return;
 	}
--- a/mncc/mtsock.c	Tue Jun 28 19:21:51 2022 -0800
+++ b/mncc/mtsock.c	Tue Jun 28 21:47:04 2022 -0800
@@ -68,6 +68,7 @@
 		close(fd);
 		return;
 	}
+	syslog(LOG_INFO, "new MT call socket connection");
 	bzero(conn, sizeof(struct socket_conn));
 	conn->fd = fd;
 	conn->next = mtcall_socket_head;