From 44bd3c439fc72756aa66604cb8be60364caa3271 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Thu, 4 Jun 2020 15:25:50 +0200 Subject: [PATCH] RSL_Emulation: logging tweaks Change-Id: I8ca105d1d5280cff9b88ce5a2bb9c98a3f1e7527 --- library/GSUP_Emulation.ttcn | 4 ++-- library/MGCP_Emulation.ttcn | 5 +++++ library/MNCC_Emulation.ttcn | 19 ++++++++++++++++++- library/Osmocom_CTRL_Functions.ttcn | 11 +++++++++-- library/RSL_Emulation.ttcn | 9 +++++++++ library/SMPP_Emulation.ttcn | 2 ++ msc/BSC_ConnectionHandler.ttcn | 1 + msc/MSC_Tests.ttcn | 4 ++++ 8 files changed, 50 insertions(+), 5 deletions(-) diff --git a/library/GSUP_Emulation.ttcn b/library/GSUP_Emulation.ttcn index 5e15d0699..15d408c98 100644 --- a/library/GSUP_Emulation.ttcn +++ b/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; diff --git a/library/MGCP_Emulation.ttcn b/library/MGCP_Emulation.ttcn index 9a92b9cb1..4c8bde7d9 100644 --- a/library/MGCP_Emulation.ttcn +++ b/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; diff --git a/library/MNCC_Emulation.ttcn b/library/MNCC_Emulation.ttcn index 85556c1f5..4b32cd42b 100644 --- a/library/MNCC_Emulation.ttcn +++ b/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; } } diff --git a/library/Osmocom_CTRL_Functions.ttcn b/library/Osmocom_CTRL_Functions.ttcn index 2c90de459..faba02c3c 100644 --- a/library/Osmocom_CTRL_Functions.ttcn +++ b/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; } } diff --git a/library/RSL_Emulation.ttcn b/library/RSL_Emulation.ttcn index effe83bc2..2145cc0dc 100644 --- a/library/RSL_Emulation.ttcn +++ b/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); diff --git a/library/SMPP_Emulation.ttcn b/library/SMPP_Emulation.ttcn index 6c808ebee..a5193b274 100644 --- a/library/SMPP_Emulation.ttcn +++ b/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, diff --git a/msc/BSC_ConnectionHandler.ttcn b/msc/BSC_ConnectionHandler.ttcn index c3426a444..439b341e0 100644 --- a/msc/BSC_ConnectionHandler.ttcn +++ b/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))); diff --git a/msc/MSC_Tests.ttcn b/msc/MSC_Tests.ttcn index 724455560..7f0a11d02 100644 --- a/msc/MSC_Tests.ttcn +++ b/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);