From 58f408839ca49c580b9972fe6f2092a9c53f5eda Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Wed, 8 Mar 2023 04:04:27 +0100 Subject: [PATCH] tweak MNCC logging, add RTP info Omit "in state FOO", because LOG_TRANS() already logs the state. Most MNCC "rx" logging was duplicated. Log "rx" only once. If there is RTP information passed with the MNCC message, log it: - if there is SDP, log the SDP information. - if there is no SDP, log the legacy MNCC RTP fields, if any. One motivation to do this is to get RTP information in ladder diagrams generated by msc_log_to_ladder.py without the need to add udtrace MNCC logging to osmo-msc; and also to get RTP info for internal MNCC, where udtrace doesn't apply, because no unix domain socket is involved in internal MNCC operation. Change-Id: I4b916cb482ed441b508c6295de211a21c49cd5c1 --- src/libmsc/gsm_04_08_cc.c | 86 +++++++++++++++++++++++------ tests/msc_vlr/msc_vlr_test_call.err | 20 ++----- 2 files changed, 73 insertions(+), 33 deletions(-) diff --git a/src/libmsc/gsm_04_08_cc.c b/src/libmsc/gsm_04_08_cc.c index 771ddbc1b..5715429ac 100644 --- a/src/libmsc/gsm_04_08_cc.c +++ b/src/libmsc/gsm_04_08_cc.c @@ -55,6 +55,7 @@ #include #include #include +#include #include #include @@ -228,15 +229,70 @@ static void gsm48_stop_cc_timer(struct gsm_trans *trans) } } +/* Log the MNCC tx and rx events. + * Depending on msg_type, also log whether RTP information is passed on. + * (This is particularly interesting for the doc/sequence_charts/msc_log_to_ladder.py) + */ +static void log_mncc_rx_tx(struct gsm_trans *trans, const char *rx_tx, const union mncc_msg *mncc) +{ + const char *sdp = NULL; + struct sdp_msg sdp_msg = {}; + struct osmo_sockaddr addr = {}; + + if (!log_check_level(DMNCC, LOGL_DEBUG)) + return; + + switch (mncc->msg_type) { + case MNCC_RTP_CREATE: + case MNCC_RTP_CONNECT: + addr = (struct osmo_sockaddr){ .u.sas = mncc->rtp.addr }; + sdp = mncc->rtp.sdp; + break; + + case MNCC_SETUP_IND: + case MNCC_SETUP_REQ: + case MNCC_SETUP_COMPL_IND: + case MNCC_SETUP_COMPL_REQ: + case MNCC_SETUP_RSP: + case MNCC_SETUP_CNF: + case MNCC_CALL_CONF_IND: + case MNCC_CALL_PROC_REQ: + case MNCC_ALERT_IND: + case MNCC_ALERT_REQ: + sdp = mncc->signal.sdp; + break; + + default: + break; + } + + if (sdp && sdp[0] && (sdp_msg_from_sdp_str(&sdp_msg, sdp) == 0)) { + LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "%s %s (RTP=%s)\n", + rx_tx, + get_mncc_name(mncc->msg_type), + sdp_msg_to_str(&sdp_msg)); + return; + } + + if (osmo_sockaddr_is_any(&addr) == 0) { + LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "%s %s (RTP=%s)\n", + rx_tx, + get_mncc_name(mncc->msg_type), + osmo_sockaddr_to_str_c(OTC_SELECT, &addr)); + return; + } + + LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "%s %s\n", rx_tx, get_mncc_name(mncc->msg_type)); +} + static int mncc_recvmsg(struct gsm_network *net, struct gsm_trans *trans, int msg_type, struct gsm_mncc *mncc) { struct msgb *msg; unsigned char *data; - LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "tx %s\n", get_mncc_name(msg_type)); - mncc->msg_type = msg_type; + log_mncc_rx_tx(trans, "tx", (union mncc_msg *)mncc); msg = msgb_alloc(sizeof(struct gsm_mncc), "MNCC"); if (!msg) @@ -1677,24 +1733,24 @@ static void mncc_recv_rtp_err(struct gsm_network *net, struct gsm_trans *trans, mncc_recv_rtp(net, trans, callref, cmd, NULL, 0, 0); } -static int tch_rtp_create(struct gsm_network *net, uint32_t callref) +static int tch_rtp_create(struct gsm_network *net, const struct gsm_mncc_rtp *rtp) { struct gsm_trans *trans; /* Find callref */ - trans = trans_find_by_callref(net, callref); + trans = trans_find_by_callref(net, rtp->callref); if (!trans) { LOG_TRANS_CAT(trans, DMNCC, LOGL_ERROR, "RTP create for non-existing trans\n"); - mncc_recv_rtp_err(net, trans, callref, MNCC_RTP_CREATE); + mncc_recv_rtp_err(net, trans, rtp->callref, MNCC_RTP_CREATE); return -EIO; } log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); if (!trans->msc_a) { LOG_TRANS_CAT(trans, DMNCC, LOGL_NOTICE, "RTP create for trans without conn\n"); - mncc_recv_rtp_err(net, trans, callref, MNCC_RTP_CREATE); + mncc_recv_rtp_err(net, trans, rtp->callref, MNCC_RTP_CREATE); return 0; } - LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "rx %s\n", get_mncc_name(MNCC_RTP_CREATE)); + log_mncc_rx_tx(trans, "rx", (const union mncc_msg *)rtp); /* Assign call (if not done yet) */ return msc_a_try_call_assignment(trans); @@ -1751,7 +1807,6 @@ static int tch_rtp_connect(struct gsm_network *net, const struct gsm_mncc_rtp *r struct call_leg *cl; struct rtp_stream *rtps; struct osmo_sockaddr_str rtp_addr; - char ipbuf[INET6_ADDRSTRLEN]; /* FIXME: in *rtp we should get the codec information of the remote * leg. We will have to populate trans->conn->rtp.codec_cn with a @@ -1777,9 +1832,7 @@ static int tch_rtp_connect(struct gsm_network *net, const struct gsm_mncc_rtp *r return -EIO; } - LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "rx %s %s:%u\n", get_mncc_name(rtp->msg_type), - osmo_sockaddr_ntop((const struct sockaddr*)&rtp->addr, ipbuf), - osmo_sockaddr_port((const struct sockaddr*)&rtp->addr)); + log_mncc_rx_tx(trans, "rx", (const union mncc_msg *)rtp); cl = trans->msc_a->cc.call_leg; rtps = cl ? cl->rtp[RTP_TO_CN] : NULL; @@ -1874,7 +1927,7 @@ static int mncc_tx_to_gsm_cc(struct gsm_network *net, const union mncc_msg *msg) disconnect_bridge(net, &msg->bridge, -rc); return rc; case MNCC_RTP_CREATE: - return tch_rtp_create(net, msg->rtp.callref); + return tch_rtp_create(net, &msg->rtp); case MNCC_RTP_CONNECT: return tch_rtp_connect(net, &msg->rtp); case MNCC_RTP_FREE: @@ -1981,7 +2034,7 @@ static int mncc_tx_to_gsm_cc(struct gsm_network *net, const union mncc_msg *msg) if (!msc_a) { /* This condition will return before the common logging of the received MNCC message below, so * log it now. */ - LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "rx %s\n", get_mncc_name(msg->msg_type)); + log_mncc_rx_tx(trans, "rx", msg); /* store setup information until paging succeeds */ memcpy(&trans->cc.msg, data, sizeof(struct gsm_mncc)); @@ -2008,7 +2061,7 @@ static int mncc_tx_to_gsm_cc(struct gsm_network *net, const union mncc_msg *msg) log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); } - LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "rx %s\n", get_mncc_name(msg->msg_type)); + log_mncc_rx_tx(trans, "rx", msg); gsm48_start_guard_timer(trans); trans->cc.mncc_initiated = true; @@ -2021,7 +2074,7 @@ static int mncc_tx_to_gsm_cc(struct gsm_network *net, const union mncc_msg *msg) struct gsm_mncc rel = { .callref = data->callref, }; - LOG_TRANS(trans, LOGL_DEBUG, "rx %s in paging state\n", get_mncc_name(msg->msg_type)); + LOG_TRANS(trans, LOGL_DEBUG, "still paging\n"); mncc_set_cause(&rel, GSM48_CAUSE_LOC_PRN_S_LU, GSM48_CC_CAUSE_NORM_CALL_CLEAR); if (msg->msg_type == MNCC_REL_REQ) @@ -2031,9 +2084,6 @@ static int mncc_tx_to_gsm_cc(struct gsm_network *net, const union mncc_msg *msg) trans->callref = 0; trans_free(trans); return rc; - } else { - LOG_TRANS(trans, LOGL_DEBUG, "rx %s in state %s\n", - get_mncc_name(msg->msg_type), gsm48_cc_state_name(trans->cc.state)); } /* Find function for current state and message */ diff --git a/tests/msc_vlr/msc_vlr_test_call.err b/tests/msc_vlr/msc_vlr_test_call.err index c25c08389..e972219b8 100644 --- a/tests/msc_vlr/msc_vlr_test_call.err +++ b/tests/msc_vlr/msc_vlr_test_call.err @@ -325,7 +325,7 @@ DCC rtp_stream(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SER DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){ESTABLISHING}: Received Event CALL_LEG_EV_RTP_STREAM_ADDR_AVAILABLE DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Received Event MSC_EV_CALL_LEG_RTP_LOCAL_ADDR_AVAILABLE DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: MGW endpoint's RTP address available for the CI RTP_TO_CN: 10.23.23.1:23 (osmux=no:-2) -DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) tx MNCC_RTP_CREATE +DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) tx MNCC_RTP_CREATE (RTP=10.23.23.1:23) MSC --> MNCC: callref 0x80000001: MNCC_RTP_CREATE - MNCC says that's fine MSC <-- MNCC: callref 0x80000001: MNCC_CALL_PROC_REQ @@ -333,7 +333,6 @@ DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_CALL_PROC_REQ DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) stopping pending guard timer DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) starting guard timer with 180 seconds -DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_CALL_PROC_REQ in state INITIATED DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) new state INITIATED -> MO_CALL_PROC DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_CALL_PROC DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: RAN encode: DTAP on UTRAN-Iu @@ -348,7 +347,6 @@ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVIC DMNCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_ALERT_REQ DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) stopping pending guard timer DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) starting guard timer with 180 seconds -DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_ALERT_REQ in state MO_CALL_PROC DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) new state MO_CALL_PROC -> CALL_DELIVERED DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_ALERTING DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: RAN encode: DTAP on UTRAN-Iu @@ -360,7 +358,6 @@ DMSC dummy_msc_i(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_S DMNCC trans(CC:CALL_DELIVERED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_SETUP_RSP DCC trans(CC:CALL_DELIVERED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) stopping pending guard timer DCC trans(CC:CALL_DELIVERED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) starting guard timer with 180 seconds -DCC trans(CC:CALL_DELIVERED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_SETUP_RSP in state CALL_DELIVERED DCC trans(CC:CALL_DELIVERED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) starting timer T313 with 30 seconds DCC trans(CC:CALL_DELIVERED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) new state CALL_DELIVERED -> CONNECT_IND DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_CONNECT @@ -400,7 +397,6 @@ DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE DMNCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_REL_REQ DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) starting guard timer with 180 seconds -DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_REL_REQ in state DISCONNECT_IND DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) starting timer T308 with 10 seconds DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) new state DISCONNECT_IND -> RELEASE_REQ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_RELEASE @@ -813,7 +809,7 @@ DCC rtp_stream(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){ESTABLISHING}: Received Event CALL_LEG_EV_RTP_STREAM_ADDR_AVAILABLE DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: Received Event MSC_EV_CALL_LEG_RTP_LOCAL_ADDR_AVAILABLE DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: MGW endpoint's RTP address available for the CI RTP_TO_CN: 10.23.23.1:23 (osmux=no:-2) -DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) tx MNCC_RTP_CREATE +DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) tx MNCC_RTP_CREATE (RTP=10.23.23.1:23) MSC --> MNCC: callref 0x423: MNCC_RTP_CREATE - Total time passed: 1.000023 s MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_ALERTING @@ -842,7 +838,6 @@ DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RES DMNCC trans(CC:CONNECT_REQUEST IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) rx MNCC_SETUP_COMPL_REQ DCC trans(CC:CONNECT_REQUEST IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) starting guard timer with 180 seconds -DCC trans(CC:CONNECT_REQUEST IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) rx MNCC_SETUP_COMPL_REQ in state CONNECT_REQUEST DCC trans(CC:CONNECT_REQUEST IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) new state CONNECT_REQUEST -> ACTIVE DCC trans(CC:ACTIVE IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) stopping pending guard timer DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_CONNECT_ACK @@ -870,7 +865,6 @@ DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RES DMNCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) rx MNCC_REL_REQ DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) starting guard timer with 180 seconds -DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) rx MNCC_REL_REQ in state DISCONNECT_IND DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) starting timer T308 with 10 seconds DCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) new state DISCONNECT_IND -> RELEASE_REQ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_RELEASE @@ -1283,7 +1277,7 @@ DCC rtp_stream(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){ESTABLISHING}: Received Event CALL_LEG_EV_RTP_STREAM_ADDR_AVAILABLE DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: Received Event MSC_EV_CALL_LEG_RTP_LOCAL_ADDR_AVAILABLE DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: MGW endpoint's RTP address available for the CI RTP_TO_CN: 10.23.23.1:23 (osmux=no:-2) -DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) tx MNCC_RTP_CREATE +DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) tx MNCC_RTP_CREATE (RTP=10.23.23.1:23) MSC --> MNCC: callref 0x423: MNCC_RTP_CREATE - Total time passed: 1.000023 s MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_ALERTING @@ -1692,7 +1686,7 @@ DCC rtp_stream(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SER DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){ESTABLISHING}: Received Event CALL_LEG_EV_RTP_STREAM_ADDR_AVAILABLE DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Received Event MSC_EV_CALL_LEG_RTP_LOCAL_ADDR_AVAILABLE DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: MGW endpoint's RTP address available for the CI RTP_TO_CN: 10.23.23.1:23 (osmux=no:-2) -DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) tx MNCC_RTP_CREATE +DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) tx MNCC_RTP_CREATE (RTP=10.23.23.1:23) MSC --> MNCC: callref 0x80000002: MNCC_RTP_CREATE - MNCC says that's fine MSC <-- MNCC: callref 0x80000002: MNCC_CALL_PROC_REQ @@ -1700,7 +1694,6 @@ DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) rx MNCC_CALL_PROC_REQ DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) stopping pending guard timer DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) starting guard timer with 180 seconds -DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) rx MNCC_CALL_PROC_REQ in state INITIATED DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) new state INITIATED -> MO_CALL_PROC DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_CALL_PROC DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: RAN encode: DTAP on UTRAN-Iu @@ -1714,7 +1707,6 @@ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVIC DMNCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) rx MNCC_REL_REQ DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) stopping pending guard timer DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) starting guard timer with 180 seconds -DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) rx MNCC_REL_REQ in state MO_CALL_PROC DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) starting timer T308 with 10 seconds DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) new state MO_CALL_PROC -> RELEASE_REQ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_RELEASE @@ -2120,7 +2112,7 @@ DCC rtp_stream(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SER DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){ESTABLISHING}: Received Event CALL_LEG_EV_RTP_STREAM_ADDR_AVAILABLE DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Received Event MSC_EV_CALL_LEG_RTP_LOCAL_ADDR_AVAILABLE DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: MGW endpoint's RTP address available for the CI RTP_TO_CN: 10.23.23.1:23 (osmux=no:-2) -DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) tx MNCC_RTP_CREATE +DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) tx MNCC_RTP_CREATE (RTP=10.23.23.1:23) MSC --> MNCC: callref 0x80000003: MNCC_RTP_CREATE - MNCC says that's fine MSC <-- MNCC: callref 0x80000003: MNCC_CALL_PROC_REQ @@ -2128,7 +2120,6 @@ DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) rx MNCC_CALL_PROC_REQ DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) stopping pending guard timer DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) starting guard timer with 180 seconds -DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) rx MNCC_CALL_PROC_REQ in state INITIATED DCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) new state INITIATED -> MO_CALL_PROC DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_CALL_PROC DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: RAN encode: DTAP on UTRAN-Iu @@ -2142,7 +2133,6 @@ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVIC DMNCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) rx MNCC_REL_REQ DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) stopping pending guard timer DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) starting guard timer with 180 seconds -DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) rx MNCC_REL_REQ in state MO_CALL_PROC DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) starting timer T308 with 10 seconds DCC trans(CC:MO_CALL_PROC IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) new state MO_CALL_PROC -> RELEASE_REQ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_RELEASE