msc_vlr_test_call.c: add MNCC logging

Change-Id: I03b25c134553c620d3fa9d23a67ad39414546861

2 files changed, 41 insertions, 5 deletions

diff --git a/tests/msc_vlr/msc_vlr_test_call.c b/tests/msc_vlr/msc_vlr_test_call.c
index 392d38df6..dfa3141c6 100644
--- a/tests/msc_vlr/msc_vlr_test_call.c
+++ b/tests/msc_vlr/msc_vlr_test_call.c
@@ -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)
diff --git a/tests/msc_vlr/msc_vlr_test_call.err b/tests/msc_vlr/msc_vlr_test_call.err
index 7f9940bc5..07e10a5af 100644
--- a/tests/msc_vlr/msc_vlr_test_call.err
+++ b/tests/msc_vlr/msc_vlr_test_call.err
@@ -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