subscr_conn: introduce usage tokens for ref error tracking
When hunting a conn use count bug, it was very hard to figure out who's (not)
using the conn. To ease tracking down this bug and future bugs, explicitly name
what a conn is being reserved for, and track in a bit mask.
Show in the DREF logs what uses and un-uses a conn. See the test expectation
updates, which nicely show how that clarifies the state of the conn in the
logs.
On errors, log them, but don't fail hard: if one conn use/un-use fails, we
don't want to crash the entire MSC before we have to.
Change-Id: I259aa0eec41efebb4c8221275219433eafaa549b
diff --git a/tests/msc_vlr/msc_vlr_test_rest.err b/tests/msc_vlr/msc_vlr_test_rest.err
index 493c35b..ce27bf1 100644
--- a/tests/msc_vlr/msc_vlr_test_rest.err
+++ b/tests/msc_vlr/msc_vlr_test_rest.err
@@ -4,7 +4,7 @@
- freshly allocated conn
msc_subscr_conn_is_accepted() == false
- conn_fsm present, in state NEW
-DREF unknown: MSC conn use + 1 == 1
+DREF unknown: MSC conn use + fsm == 1 (0x4)
DMM Subscr_Conn(test){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(test){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(test){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
@@ -29,7 +29,7 @@
DMM Subscr_Conn(test){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DMM msc_subscr_conn_close(vsub=unknown, cause=2): no conn fsm, releasing directly without release event.
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF unknown: MSC conn use - 1 == 0
+DREF unknown: MSC conn use - fsm == 0 (0x0)
DRLL subscr unknown: Freeing subscriber connection
DREF VLR subscr unknown usage decreases to: 0
DREF freeing VLR subscr unknown
@@ -46,10 +46,10 @@
- CM Service Request without a prior Location Updating
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
new conn
-DREF unknown: MSC conn use + 1 == 1
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
-DREF unknown: MSC conn use + 1 == 2
+DREF unknown: MSC conn use + fsm == 2 (0x5)
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
@@ -72,10 +72,10 @@
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
DMM msc_subscr_conn_close(vsub=unknown, cause=2): no conn fsm, releasing directly without release event.
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF unknown: MSC conn use - 1 == 1
+DREF unknown: MSC conn use - fsm == 1 (0x1)
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
-DREF unknown: MSC conn use - 1 == 0
+DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
DRLL Freeing subscriber connection with NULL subscriber
bssap_clear_sent == 1
- conn was released
@@ -89,9 +89,9 @@
- Location Update request causes a GSUP LU request to HLR
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
new conn
-DREF unknown: MSC conn use + 1 == 1
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
-DREF unknown: MSC conn use + 1 == 2
+DREF unknown: MSC conn use + fsm == 2 (0x5)
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
@@ -118,7 +118,7 @@
GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
-DREF IMSI:901700000004620: MSC conn use - 1 == 1
+DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
lu_result_sent == 0
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
@@ -191,7 +191,7 @@
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF MSISDN:46071: MSC conn use - 1 == 0
+DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 2
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
@@ -207,9 +207,9 @@
- Location Update request causes a GSUP LU request to HLR
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
new conn
-DREF unknown: MSC conn use + 1 == 1
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
-DREF unknown: MSC conn use + 1 == 2
+DREF unknown: MSC conn use + fsm == 2 (0x5)
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
@@ -234,7 +234,7 @@
GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
-DREF MSISDN:46071: MSC conn use - 1 == 1
+DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
lu_result_sent == 0
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
@@ -306,7 +306,7 @@
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF MSISDN:46071: MSC conn use - 1 == 0
+DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 2
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
@@ -321,7 +321,7 @@
- subscriber detaches
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
new conn
-DREF unknown: MSC conn use + 1 == 1
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
DREF VLR subscr MSISDN:46071 usage increases to: 2
@@ -331,7 +331,7 @@
DREF freeing VLR subscr MSISDN:46071
DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF unknown: MSC conn use - 1 == 0
+DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
DRLL Freeing subscriber connection with NULL subscriber
bssap_clear_sent == 1
llist_count(&net->subscr_conns) == 0
@@ -344,9 +344,9 @@
- Location Update request with unknown TMSI sends ID Request for IMSI
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
new conn
-DREF unknown: MSC conn use + 1 == 1
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
-DREF unknown: MSC conn use + 1 == 2
+DREF unknown: MSC conn use + fsm == 2 (0x5)
DMM Subscr_Conn(591536962){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(591536962){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(591536962){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
@@ -366,7 +366,7 @@
- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051801
- DTAP matches expected message
DMM TMSI:0x23422342: bump: conn still being established (SUBSCR_CONN_S_NEW)
-DREF TMSI:0x23422342: MSC conn use - 1 == 1
+DREF TMSI:0x23422342: MSC conn use - compl_l3 == 1 (0x4)
lu_result_sent == 0
msc_subscr_conn_is_accepted() == false
requests shall be thwarted
@@ -380,7 +380,7 @@
DRLL subscr TMSI:0x23422342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
- MS tells us the IMSI, causes a GSUP LU request to HLR
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
-DREF TMSI:0x23422342: MSC conn use + 1 == 2
+DREF TMSI:0x23422342: MSC conn use + dtap == 2 (0x6)
DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
DMM IDENTITY RESPONSE: MI(IMSI)=901700000004620
DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
@@ -398,7 +398,7 @@
GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
DVLR upd_hlr_vlr_fsm(591536962){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
-DREF IMSI:901700000004620: MSC conn use - 1 == 1
+DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
lu_result_sent == 0
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
@@ -471,7 +471,7 @@
DVLR vlr_lu_fsm(591536962){VLR_ULA_S_DONE}: Deallocated
DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF MSISDN:46071: MSC conn use - 1 == 0
+DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 2
DMM Subscr_Conn(591536962){SUBSCR_CONN_S_RELEASED}: Freeing instance