msc_vlr_test_call.c: add MNCC logging

Change-Id: I03b25c134553c620d3fa9d23a67ad39414546861
This commit is contained in:
Neels Hofmeyr 2019-10-21 05:53:58 +02:00
parent e0f906c42c
commit 07351d8f78
2 changed files with 41 additions and 5 deletions

View File

@ -25,11 +25,13 @@
#include <osmocom/msc/gsm_04_08.h>
static void mncc_sends_to_cc(uint32_t msg_type, struct gsm_mncc *mncc)
{
mncc->msg_type = msg_type;
mncc_tx_to_cc(net, mncc);
}
#define mncc_sends_to_cc(MSG_TYPE, MNCC) do { \
(MNCC)->msg_type = MSG_TYPE; \
log("MSC <-- MNCC: callref 0x%x: %s\n%s", (MNCC)->callref, \
get_mncc_name((MNCC)->msg_type), \
(MNCC)->sdp); \
mncc_tx_to_cc(net, MNCC); \
} while(0)
/*
static void on_call_release_mncc_sends_to_cc(uint32_t msg_type, struct gsm_mncc *mncc)

View File

@ -297,6 +297,8 @@ DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN
MSC --> MNCC: callref 0x80000001: MNCC_SETUP_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
- MNCC replies with MNCC_RTP_CREATE, causing MGW endpoint CRCX to RAN
MSC <-- MNCC: callref 0x80000001: MNCC_RTP_CREATE
DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) rx MNCC_RTP_CREATE
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Starting call assignment
DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){ESTABLISHING}: Allocated
@ -328,6 +330,8 @@ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVIC
DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) tx MNCC_RTP_CREATE
MSC --> MNCC: callref 0x80000001: MNCC_RTP_CREATE
- MNCC says that's fine
MSC <-- MNCC: callref 0x80000001: MNCC_CALL_PROC_REQ
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
@ -341,6 +345,8 @@ DMSC dummy_msc_i(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_S
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Assignment for this trans already started earlier
- Total time passed: 1.000023 s
- The other call leg got established (not shown here), MNCC tells us so
MSC <-- MNCC: callref 0x80000001: MNCC_ALERT_REQ
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
@ -351,6 +357,8 @@ DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE
- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_ALERTING: 8301
- DTAP matches expected message
DMSC dummy_msc_i(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){0}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST
MSC <-- MNCC: callref 0x80000001: MNCC_SETUP_RSP
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
@ -390,6 +398,8 @@ DCC trans(CC:ACTIVE IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:C
DMNCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000001 tid-8) tx MNCC_DISC_IND
MSC --> MNCC: callref 0x80000001: MNCC_DISC_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
MSC <-- MNCC: callref 0x80000001: MNCC_REL_REQ
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
@ -661,6 +671,8 @@ DREF VLR subscr IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 - standard_lu:
- after a while, MNCC asks us to setup a call, causing Paging
MSC <-- MNCC: callref 0x423: MNCC_SETUP_REQ
DREF VLR subscr IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 + mncc_tx_to_gsm_cc: now used by 2 (attached,mncc_tx_to_gsm_cc)
DREF VLR subscr IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 + CC: now used by 3 (attached,mncc_tx_to_gsm_cc,CC)
DCC trans(CC:NULL IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 callref-0x423 tid-255) New transaction
@ -779,6 +791,8 @@ DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x030201
MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
- MNCC sends MNCC_RTP_CREATE
MSC <-- MNCC: callref 0x423: MNCC_RTP_CREATE
DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) rx MNCC_RTP_CREATE
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: Assignment for this trans already started earlier
- MGW acknowledges the CRCX to RAN, triggering Assignment
@ -827,6 +841,8 @@ DCC trans(CC:CALL_RECEIVED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTR
DMNCC trans(CC:CONNECT_REQUEST IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) tx MNCC_SETUP_CNF
MSC --> MNCC: callref 0x423: MNCC_SETUP_CNF
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
MSC <-- MNCC: callref 0x423: MNCC_SETUP_COMPL_REQ
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
@ -853,6 +869,8 @@ DCC trans(CC:ACTIVE IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:P
DMNCC trans(CC:DISCONNECT_IND IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) tx MNCC_DISC_IND
MSC --> MNCC: callref 0x423: MNCC_DISC_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
MSC <-- MNCC: callref 0x423: MNCC_REL_REQ
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
@ -1124,6 +1142,8 @@ DREF VLR subscr IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 - standard_lu:
- after a while, MNCC asks us to setup a call, causing Paging
MSC <-- MNCC: callref 0x423: MNCC_SETUP_REQ
DREF VLR subscr IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 + mncc_tx_to_gsm_cc: now used by 2 (attached,mncc_tx_to_gsm_cc)
DREF VLR subscr IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 + CC: now used by 3 (attached,mncc_tx_to_gsm_cc,CC)
DCC trans(CC:NULL IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100 callref-0x423 tid-255) New transaction
@ -1242,6 +1262,8 @@ DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x030201
MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
- MNCC sends MNCC_RTP_CREATE
MSC <-- MNCC: callref 0x423: MNCC_RTP_CREATE
DMNCC trans(CC:MO_TERM_CALL_CONF IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP callref-0x423 tid-0) rx MNCC_RTP_CREATE
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:PAGING_RESP){MSC_A_ST_COMMUNICATING}: Assignment for this trans already started earlier
- MGW acknowledges the CRCX to RAN, triggering Assignment
@ -1645,6 +1667,8 @@ DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN
MSC --> MNCC: callref 0x80000002: MNCC_SETUP_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
- MNCC replies with MNCC_RTP_CREATE, causing MGW endpoint CRCX to RAN
MSC <-- MNCC: callref 0x80000002: MNCC_RTP_CREATE
DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) rx MNCC_RTP_CREATE
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Starting call assignment
DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){ESTABLISHING}: Allocated
@ -1676,6 +1700,8 @@ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVIC
DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000002 tid-8) tx MNCC_RTP_CREATE
MSC --> MNCC: callref 0x80000002: MNCC_RTP_CREATE
- MNCC says that's fine
MSC <-- MNCC: callref 0x80000002: MNCC_CALL_PROC_REQ
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
@ -1688,6 +1714,8 @@ DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE
DMSC dummy_msc_i(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){0}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Assignment for this trans already started earlier
- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
MSC <-- MNCC: callref 0x80000002: MNCC_REL_REQ
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
@ -2067,6 +2095,8 @@ DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN
MSC --> MNCC: callref 0x80000003: MNCC_SETUP_IND
DREF msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: - rx_from_ms: now used by 1 (cc)
- MNCC replies with MNCC_RTP_CREATE, causing MGW endpoint CRCX to RAN
MSC <-- MNCC: callref 0x80000003: MNCC_RTP_CREATE
DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) rx MNCC_RTP_CREATE
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Starting call assignment
DCC call_leg(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){ESTABLISHING}: Allocated
@ -2098,6 +2128,8 @@ DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVIC
DMNCC trans(CC:INITIATED IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ callref-0x80000003 tid-8) tx MNCC_RTP_CREATE
MSC --> MNCC: callref 0x80000003: MNCC_RTP_CREATE
- MNCC says that's fine
MSC <-- MNCC: callref 0x80000003: MNCC_CALL_PROC_REQ
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
@ -2110,6 +2142,8 @@ DMSC msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE
DMSC dummy_msc_i(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){0}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST
DIUCS msc_a(IMSI-901700000010650:MSISDN-42342:TMSI-0x03020100:UTRAN-Iu:CM_SERVICE_REQ){MSC_A_ST_COMMUNICATING}: Assignment for this trans already started earlier
- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
MSC <-- MNCC: callref 0x80000003: MNCC_REL_REQ
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