RSL_Emulation: logging tweaks

Change-Id: I8ca105d1d5280cff9b88ce5a2bb9c98a3f1e7527

library/GSUP_Emulation.ttcn

@@ -138,7 +138,7 @@ runs on GSUP_Emulation_CT {
 		if (GsupImsiTable[i].imsi == "") {
 			GsupImsiTable[i].comp_ref := comp_ref;
 			GsupImsiTable[i].imsi := imsi;
-			log("Added IMSI table entry ", i, comp_ref, imsi);
+			log("GsupImsiTable: Added IMSI table entry ", i, comp_ref, imsi);
 			return;
 		}
 	}
@@ -149,7 +149,7 @@ private function f_imsi_table_del(charstring imsi)
 runs on GSUP_Emulation_CT {
 	for (var integer i := 0; i < sizeof(GsupImsiTable); i := i+1) {
 		if (GsupImsiTable[i].imsi == imsi) {
-			log("Deleted GSUP IMSI table entry ", i,
+			log("GsupImsiTable: Deleted GSUP IMSI table entry ", i,
 			    GsupImsiTable[i].comp_ref, imsi);
 			GsupImsiTable[i].imsi := "";
 			GsupImsiTable[i].comp_ref := null;

library/MGCP_Emulation.ttcn

@@ -251,6 +251,7 @@ runs on MGCP_Emulation_CT {
 }
 
 private function f_forward_to_client(MGCP_RecvFrom mrf, MGCP_ConnHdlr vc_conn) runs on MGCP_Emulation_CT {
+	log("MGCP_Emulation_CT -> ", vc_conn, ": ", mrf);
 	if (g_pars.multi_conn_mode) {
 		MGCP_CLIENT_MULTI.send(mrf) to vc_conn;
 	} else {
@@ -290,6 +291,7 @@ function main(MGCPOps ops, MGCP_conn_parameters p, charstring id) runs on MGCP_E
 		alt {
 		/* MGCP from client */
 		[not p.multi_conn_mode] MGCP_CLIENT.receive(MgcpResponse:?) -> value resp sender vc_conn {
+			log("MGCP_Emulation_CT: ", vc_conn, " -> MGCP_CLIENT: ", resp);
 			msg := {
 				response := resp
 			};
@@ -425,6 +427,9 @@ runs on MGCP_Emulation_CT return MGCP_ConnHdlr {
 	var template MgcpCommand mgcpcmd;
 	var integer i;
 
+	log("MGCP_Emulation_CT: rx ", cmd);
+	log("MGCP_Emulation_CT: MgcpExpectTable: ", MgcpExpectTable);
+
 	for (i := 0; i < sizeof(MgcpExpectTable); i := i+1) {
 		if (not ispresent(MgcpExpectTable[i].crit)) {
 			continue;

library/MNCC_Emulation.ttcn

@@ -171,7 +171,8 @@ runs on MNCC_Emulation_CT {
 		if (MnccCallTable[i].mncc_call_id == -1) {
 			MnccCallTable[i].comp_ref := comp_ref;
 			MnccCallTable[i].mncc_call_id := mncc_call_id;
-			log("Added conn table entry ", i, comp_ref, mncc_call_id);
+			log("Added conn table entry i ", i, " comp_ref ", comp_ref, " mncc_call_id ", mncc_call_id);
+			log("AA MnccCallTable ", MnccCallTable);
 			return;
 		}
 	}
@@ -186,6 +187,7 @@ runs on MNCC_Emulation_CT {
 			    MnccCallTable[i].comp_ref, mncc_call_id);
 			MnccCallTable[i].mncc_call_id := -1;
 			MnccCallTable[i].comp_ref := null;
+			log("AA MnccCallTable ", MnccCallTable);
 			return
 		}
 	}
@@ -280,6 +282,8 @@ runs on MNCC_Emulation_CT {
 	f_expect_table_init();
 	f_call_table_init();
 
+	log("YYY starting MNCC_Emulation_CT g_mncc_ud_id ", g_mncc_ud_id);
+
 	while (true) {
 		var MNCC_send_data sd;
 		var MNCC_Conn_Req creq;
@@ -289,9 +293,12 @@ runs on MNCC_Emulation_CT {
 		var charstring dest_nr;
 		var uint32_t mncc_call_id;
 
+		log("YY MNCC_Emulation_CT g_mncc_ud_id ", g_mncc_ud_id);
+
 		alt {
 		/* MNCC -> Client: UNIT-DATA (connectionless SCCP) from a BSC */
 		[] MNCC.receive(t_SD_MNCC_MSGT(g_mncc_ud_id, MNCC_SOCKET_HELLO)) -> value sd {
+			log("MNCC.receive ", sd);
 			/* Connectionless Procedures like HELLO */
 			var template MNCC_PDU resp;
 			resp := ops.unitdata_cb.apply(sd.data);
@@ -302,9 +309,11 @@ runs on MNCC_Emulation_CT {
 
 		/* MNCC -> Client: Release Indication / confirmation */
 		[] MNCC.receive(t_SD_MNCC_MSGT(g_mncc_ud_id, (MNCC_REL_IND, MNCC_REL_CNF))) -> value sd {
+			log("MNCC.receive ", sd);
 			var uint32_t call_id := f_mncc_get_call_id(sd.data);
 			/* forward to respective client */
 			vc_conn := f_comp_by_call_id(call_id);
+			log("MNCC.receive sends to ", vc_conn);
 			MNCC_CLIENT.send(sd.data) to vc_conn;
 			/* remove from call table */
 			f_call_table_del(call_id);
@@ -312,14 +321,17 @@ runs on MNCC_Emulation_CT {
 
 		/* MNCC -> Client: call related messages */
 		[] MNCC.receive(t_SD_MNCC_MSGT(g_mncc_ud_id, ?)) -> value sd {
+			log("MNCC.receive ", sd);
 			var uint32_t call_id := f_mncc_get_call_id(sd.data);
 
 			if (f_call_id_known(call_id)) {
 				vc_conn := f_comp_by_call_id(call_id);
+				log("MNCC.receive sends to ", vc_conn);
 				MNCC_CLIENT.send(sd.data) to vc_conn;
 			} else {
 				/* TODO: Only accept this for SETUP.req? */
 				vc_conn := ops.create_cb.apply(sd.data, id)
+				log("MNCC.receive sends to ", vc_conn);
 				/* store mapping between client components and SCCP connectionId */
 				f_call_table_add(vc_conn, call_id);
 				/* handle user payload */
@@ -329,6 +341,7 @@ runs on MNCC_Emulation_CT {
 
 		/* Client -> MNCC Socket: RELEASE.ind or RELEASE.cnf: forward + drop call table entry */
 		[] MNCC_CLIENT.receive(MNCC_PDU:{msg_type := (MNCC_REL_IND, MNCC_REL_CNF), u:=?}) -> value mncc sender vc_conn {
+			log("MNCC_CLIENT.receive ", mncc);
 			var integer call_id := f_call_id_by_comp(vc_conn);
 			/* forward to MNCC socket */
 			MNCC.send(t_SD_MNCC(g_mncc_ud_id, mncc));
@@ -338,6 +351,7 @@ runs on MNCC_Emulation_CT {
 
 		/* Client -> MNCC Socket: Normal message */
 		[] MNCC_CLIENT.receive(MNCC_PDU:?) -> value mncc sender vc_conn {
+			log("MNCC_CLIENT.receive ", mncc);
 			if (mncc.msg_type == MNCC_SETUP_REQ and not role_server) {
 				/* ConnHdlr -> MNCC Server: SETUP.req: add to call table */
 				f_call_table_add(vc_conn, f_mncc_get_call_id(mncc));
@@ -350,6 +364,7 @@ runs on MNCC_Emulation_CT {
 			}
 
 		[] MNCC_CLIENT.receive(MNCC_PDU:?) -> value mncc sender vc_conn {
+			log("MNCC_CLIENT.receive ", mncc);
 			/* forward to MNCC socket */
 			MNCC.send(t_SD_MNCC(g_mncc_ud_id, mncc));
 			}
@@ -357,6 +372,7 @@ runs on MNCC_Emulation_CT {
 
 		/* Client -> us: procedure call to register expect */
 		[] MNCC_PROC.getcall(MNCCEM_register:{?,?}) -> param(dest_nr, vc_hdlr) {
+			log("ZZZZZ register ", dest_nr, " --> ", vc_hdlr);
 			f_create_expect(dest_nr, vc_hdlr);
 			MNCC_PROC.reply(MNCCEM_register:{dest_nr, vc_hdlr}) to vc_hdlr;
 			}
@@ -439,6 +455,7 @@ runs on MNCC_Emulation_CT {
 			MnccExpectTable[i].dest_number := dest_number;
 			MnccExpectTable[i].vc_conn := hdlr;
 			log("Created MnccExpect[", i, "] for ", dest_number, " to be handled at ", hdlr);
+			log(MnccExpectTable);
 			return;
 		}
 	}

library/Osmocom_CTRL_Functions.ttcn

@@ -34,13 +34,16 @@ module Osmocom_CTRL_Functions {
 		timer T := 2.0;
 		var CtrlMessage rx;
 		var CtrlId id := f_gen_rand_id();
+		log("CTRL request: ", id, variable);
 		pt.send(ts_CtrlMsgGet(id, variable));
 		T.start;
 		alt {
 		[] pt.receive(tr_CtrlMsgGetRepl(id, variable)) -> value rx {
+			log("CTRL responds: ", rx);
 			}
 		[] pt.receive(tr_CtrlMsgTrap) { repeat; }
 		[] pt.receive(tr_CtrlMsgError) -> value rx {
+			log("CTRL responds: ", rx);
 			setverdict(fail, "Error in CTRL GET ", variable, ": ", rx.err.reason);
 			mtc.stop;
 			}
@@ -57,12 +60,16 @@ module Osmocom_CTRL_Functions {
 		timer T := 2.0;
 		var CtrlMessage rx;
 		var CtrlId id := f_gen_rand_id();
+		log("CTRL request: ", id, variable, val);
 		pt.send(ts_CtrlMsgSet(id, variable, val));
 		T.start;
 		alt {
-		[] pt.receive(tr_CtrlMsgSetRepl(id, variable, val)) { }
+		[] pt.receive(tr_CtrlMsgSetRepl(id, variable, val)) -> value rx {
+			log("CTRL responds: ", rx);
+			}
 		[] pt.receive(tr_CtrlMsgTrap) { repeat; }
 		[] pt.receive(tr_CtrlMsgError) -> value rx {
+			log("CTRL responds: ", rx);
 			setverdict(fail, "Error in CTRL SET ", variable, ": ", rx.err.reason);
 			mtc.stop;
 			}
@@ -144,7 +151,7 @@ module Osmocom_CTRL_Functions {
 		var charstring ctrl_resp;
 		ctrl_resp := f_ctrl_get(pt, variable);
 		if (not match(ctrl_resp, exp)) {
-			setverdict(fail, "Unexpected " & variable & ":" & ctrl_resp);
+			setverdict(fail, "Unexpected " & variable & ": '" & ctrl_resp & "'");
 			mtc.stop;
 		}
 	}

library/RSL_Emulation.ttcn

@@ -124,10 +124,12 @@ private function f_rx_or_fail(template RSL_Message exp_rx, RSL_DCHAN_PT rsl_pt :
 			return rx_rsl;
 		}
 		[] rsl_pt.receive {
+			log("Error: expected: ", exp_rx);
 			setverdict(fail, "Unexpected RSL message on DCHAN");
 			mtc.stop;
 		}
 		[] T.timeout {
+			log("Error: timeout, but expected: ", exp_rx);
 			setverdict(fail, "Timeout waiting for RSL on DCHAN");
 			mtc.stop;
 		}
@@ -217,6 +219,8 @@ private function f_cid_by_chan_nr(uint8_t trx_nr, RslChannelNr chan_nr)
 runs on RSL_Emulation_CT return integer {
 	var integer i;
 	for (i := 0; i < sizeof(ConnectionTable); i := i+1) {
+		log("Checking Dchan handler for trx_nr=", trx_nr, " chan_nr=", chan_nr, ": [",i,"] = ",
+		    ConnectionTable[i]);
 		if (ispresent(ConnectionTable[i].chan_nr) and
 		    ConnectionTable[i].chan_nr == chan_nr and ConnectionTable[i].trx_nr == trx_nr) {
 			return i;
@@ -270,6 +274,7 @@ runs on RSL_Emulation_CT {
 				ConnectionTable[i].ra_fn := omit;
 			}
 			ConnectionTable[i].comp_ref := comp_ref;
+			log("Created Dchan handler [", i, "] = ", ConnectionTable[i]);
 			return;
 		}
 	}
@@ -287,6 +292,7 @@ runs on RSL_Emulation_CT {
 			ConnectionTable[i].trx_nr := trx_nr;
 			ConnectionTable[i].chan_nr := chan_nr;
 			ConnectionTable[i].comp_ref := comp_ref;
+			log("Created Dchan handler [", i, "] = ", ConnectionTable[i]);
 			return;
 		}
 	}
@@ -305,6 +311,7 @@ runs on RSL_Emulation_CT return integer {
 		if (ConnectionTable[i].stream_id == stream_id and
 		    ConnectionTable[i].chan_nr == chan_nr and
 		    ConnectionTable[i].comp_ref == comp_ref) {
+			log("Clearing Dchan handler [", i, "] = ", ConnectionTable[i]);
 			f_cid_clear(i);
 		}
 	}
@@ -352,6 +359,7 @@ runs on RSL_Emulation_CT return RSL_Message {
 			return LastActTable[i].chan_act;
 		}
 	}
+	log("LastActTable: ", LastActTable);
 	testcase.stop("No LastActTable entry found for TRX ", trx_nr, " ", chan_nr);
 }
 
@@ -555,6 +563,7 @@ function main(boolean bts_role := true) runs on RSL_Emulation_CT {
 				/* TODO: add timer to time-out ConnectionTable entries which
 				 * never get followed-up to */
 				CLIENT_PT.send(rx_rsl.rsl) to ConnectionTable[cid].comp_ref;
+				log("Modified Dchan handler [", cid, "] = ", ConnectionTable[cid]);
 			} else if (ischosen(rr.payload.imm_ass_rej)) {
 				for (i := 0; i < sizeof(rr.payload.imm_ass_rej.payload); i := i + 1) {
 					ra := bit2oct(rr.payload.imm_ass_rej.payload[i].req_ref.ra);

library/SMPP_Emulation.ttcn

@@ -363,6 +363,7 @@ private function f_create_expect(charstring dest_number, SMPP_ConnHdlr hdlr)
 runs on SMPP_Emulation_CT {
 	for (var integer i := 0; i < sizeof(ExpectTable); i := i+1) {
 		if (ExpectTable[i].dst_addr == dest_number) {
+			log("SMPP ExpectTable[", i, "]: Replacing entry for ", dest_number, " -> ", hdlr);
 			ExpectTable[i] := {
 				dst_ton := omit,
 				dst_npi := omit,
@@ -374,6 +375,7 @@ runs on SMPP_Emulation_CT {
 	}
 	for (var integer i := 0; i < sizeof(ExpectTable); i := i+1) {
 		if (ExpectTable[i].vc_conn == null) {
+			log("SMPP ExpectTable[", i, "]: Adding entry for ", dest_number, " -> ", hdlr);
 			ExpectTable[i] := {
 				dst_ton := omit,
 				dst_npi := omit,

msc/BSC_ConnectionHandler.ttcn

@@ -463,6 +463,7 @@ var GSUP_IE auth_tuple;
 function f_mm_auth() runs on BSC_ConnHdlr
 {
 	if (g_pars.net.expect_auth) {
+		log("XX f_mm_auth");
 		as_GSUP_SAI();
 		if (g_pars.use_umts_aka) {
 			BSSAP.receive(tr_PDU_DTAP_MT(tr_ML3_MT_MM_AUTH_REQ_3G(g_pars.vec.rand, g_pars.vec.autn)));

msc/MSC_Tests.ttcn

@@ -5717,6 +5717,7 @@ testcase TC_ho_inter_bsc_unknown_cell() runs on MTC_CT {
 private altstep as_mgcp_ack_all_mdcx(CallParameters cpars) runs on BSC_ConnHdlr {
 	var MgcpCommand mgcp_cmd;
 	[] MGCP.receive(tr_MDCX) -> value mgcp_cmd {
+			log("XXXX ", mgcp_cmd);
 			var charstring conn_id;
 			f_mgcp_find_param_entry(mgcp_cmd.params, "I", conn_id);
 			var SDP_Message sdp := valueof(ts_SDP(cpars.mgw_conn_2.mgw_rtp_ip, cpars.mgw_conn_2.mgw_rtp_ip,
@@ -6652,8 +6653,11 @@ friend function f_tc_call_re_establishment_1(charstring id, BSC_ConnHdlrPars par
   runs on BSC_ConnHdlr {
 	f_init_handler(pars, t_guard := 30.0);
 
+	log("XX f_perform_lu");
 	f_perform_lu();
 
+	log("XX f_perform_lu done");
+
 	var CallParameters cpars := valueof(t_CallParams('12345'H, 0));
 	f_mo_call_establish(cpars);
 	f_sleep(3.0);