Bug #4449
closedwith high load, paging_concludes() may crash due to NULL vsub
100%
Description
During Abis load tests, initiating 200 calls almost concurrently via MNCC causes osmo-msc to crash with
#0 0x00007f70a6c98ac0 in ?? () #1 0x00005597c1d90ce0 in paging_concludes (vsub=vsub@entry=0x0, msc_a=msc_a@entry=0x0) at /home/user/src/osmo-msc/src/libmsc/paging.c:140 #2 0x00005597c1d90f17 in paging_expired (vsub=vsub@entry=0x0) at /home/user/src/osmo-msc/src/libmsc/paging.c:184 #3 0x00005597c1d81a50 in evaluate_acceptance_outcome (fi=<optimized out>, conn_accepted=conn_accepted@entry=false) at /home/user/src/osmo-msc/src/libmsc/msc_a.c:147 #4 0x00005597c1d822ff in msc_a_fsm_validate_l3 (fi=<optimized out>, event=<optimized out>, data=<optimized out>) at /home/user/src/osmo-msc/src/libmsc/msc_a.c:208 #5 0x00007f70a6c9daa9 in ?? () #6 0x0000000000000000 in ?? ()
Files
Updated by neels about 4 years ago
- File osmo-msc.log osmo-msc.log added
attached log file leading up to the crash.
A fix to avoid the segfault is easy: https://gerrit.osmocom.org/c/osmo-msc/+/17441
todo: figure out how a Paging Response for a NULL vsub is possible by reading attached log.
My guess is that this happens whenever a Paging Response contains an unknown identity(!)
Updated by neels about 4 years ago
It is after all not any invalid identity, but a repeated Paging Response for a known identity:
interesting log lines:
cat osmo-msc.log | sed $'s,\x1b\\[[0-9;]*[a-zA-Z],,g' | grep -n -C 10 '0x06B5315F\|IMSI-001010000000105'
13243-20200309195517892 DMSC DEBUG msc_a[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: Allocated (fsm.c:461) 13244-20200309195517892 DMSC DEBUG msc_a[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm[0x556c8c270d10] (fsm.c:491) 13245-20200309195517892 DMSC DEBUG msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_VALIDATE_L3 (X1, 5s) (msc_a.c:1140) 13246-20200309195517892 DMSC DEBUG msc_i(unknown:GERAN-A-91:NONE)[0x556c8c275a10]{READY}: Received Event MSC_EV_FROM_RAN_COMPLETE_LAYER_3 (ran_peer.c:392) 13247-20200309195517892 DMSC DEBUG msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_FROM_I_COMPLETE_LAYER_3 (msc_i.c:103) 13248-20200309195517892 DREF INFO msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: + msc_a_ran_dec: now used by 1 (msc_a_ran_dec) (msc_a.c:183) 13249-20200309195517892 DBSSAP DEBUG msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP: COMPLETE LAYER 3 (ran_msg_a.c:809) 13250-20200309195517892 DBSSAP DEBUG msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP Complete Layer 3 Information (msc_a.c:1642) 13251-20200309195517892 DBSSAP DEBUG msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: Complete Layer 3: Codec List (BSS Supported): GSM#3 (msc_a.c:1472) 13252-20200309195517892 DRLL DEBUG msc_a(unknown:GERAN-A-91:NONE)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: Dispatching 04.08 message: MM GSM48_MT_MM_LOC_UPD_REQUEST (msc_a.c:1261) 13253:20200309195517892 DMM DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: LOCATION UPDATING REQUEST: MI=IMSI-001010000000105 LU-type=NORMAL (gsm_04_08.c:347) 13254:20200309195517892 DMM DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: USIM: old LAI: 001-001-0 (gsm_04_08.c:390) 13255:20200309195517892 DREF DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: + mm_rx_loc_upd_req: now used by 2 (msc_a_ran_dec,mm_rx_loc_upd_req) (gsm_04_08.c:392) 13256:20200309195517892 DREF DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: + lu: now used by 3 (msc_a_ran_dec,mm_rx_loc_upd_req,lu) (gsm_04_08.c:393) 13257:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: Allocated (fsm.c:461) 13258:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: is child of msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260] (fsm.c:491) 13259:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth) (vlr_lu_fsm.c:1523) 13260:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA (vlr_lu_fsm.c:1529) 13261-20200309195517892 DSGS INFO SGs-UE(num:91)[0x556c8c27a970]{SGs-NULL}: Allocated (fsm.c:461) 13262-20200309195517892 DSGS INFO SGs-UE(num:91)[0x556c8c27a970]{SGs-NULL}: State change to SGs-NULL (no timeout) (vlr_sgs_fsm.c:381) 13263-20200309195517892 DREF INFO VLR subscr unknown + _lu_fsm_associate_vsub: now used by 1 (_lu_fsm_associate_vsub) (vlr_lu_fsm.c:1026) 13264-20200309195517892 DVLR DEBUG set IMSI on subscriber; IMSI=001010000000105 id=1010000000105 (vlr.c:435) 13265-20200309195517892 DVLR INFO New subscr, IMSI: 001010000000105 (vlr.c:386) 13266:20200309195517892 DREF DEBUG VLR subscr IMSI-001010000000105 + active-conn: now used by 2 (_lu_fsm_associate_vsub,active-conn) (msub.c:378) 13267:20200309195517892 DMSC DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_COMPLETE_LAYER_3_OK (gsm_04_08.c:1411) 13268:20200309195517892 DMSC DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_AUTH_CIPH (keeping X1, 4.999s remaining) (msc_a.c:203) 13269:20200309195517892 DREF DEBUG VLR subscr IMSI-001010000000105 - _lu_fsm_associate_vsub: now used by 1 (active-conn) (vlr_lu_fsm.c:1040) 13270-20200309195517892 DSGS INFO SGs-UE(num:91)[0x556c8c27a970]{SGs-NULL}: Received Event RX_LU_FROM_A_Iu_Gs (vlr_lu_fsm.c:1090) 13271-20200309195517892 DSGS INFO SGs-UE(num:91)[0x556c8c27a970]{SGs-NULL}: State change to SGs-NULL (no timeout) (vlr_sgs_fsm.c:55) 13272:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: vlr_loc_upd_node1_pre() (vlr_lu_fsm.c:924) 13273:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: vlr_loc_upd_node1() (vlr_lu_fsm.c:901) 13274:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth() (vlr_lu_fsm.c:855) 13275:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph() (vlr_lu_fsm.c:822) 13276:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: vlr_loc_upd_node_4() (vlr_lu_fsm.c:783) 13277:20200309195517892 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) (vlr_lu_fsm.c:792) 13278:20200309195517892 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_INIT}: Allocated (fsm.c:461) 13279:20200309195517892 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c24f4e0] (fsm.c:491) 13280:20200309195517892 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START (vlr_lu_fsm.c:176) 13281:20200309195517892 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) (vlr_lu_fsm.c:87) 13282:20200309195517892 DREF DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: - mm_rx_loc_upd_req: now used by 2 (msc_a_ran_dec,lu) (gsm_04_08.c:432) 13283:20200309195517892 DREF DEBUG msc_a(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: - msc_a_ran_dec: now used by 1 (lu) (msc_a.c:185) 13284-20200309195517895 DLGSUP DEBUG No explicit GSUP Message Class, trying to guess from message type OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gsup_client_mux.c:38) 13285-20200309195517895 DREF DEBUG VLR subscr IMSI-001010000000134 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx) (vlr.c:1069) 13286-20200309195517895 DVLR DEBUG IMSI:001010000000134 has MSISDN:90134 (vlr.c:787) 13287-20200309195517895 DVLR NOTICE SUBSCR(IMSI-001010000000134:MSISDN-90134) VLR: update for IMSI=001010000000134 (MSISDN=90134) (gsm_04_08.c:1388) 13288-20200309195517895 DREF DEBUG VLR subscr IMSI-001010000000134:MSISDN-90134 - vlr_gsup_rx: now used by 1 (active-conn) (vlr.c:1115) 13289-20200309195517902 DLGSUP DEBUG No explicit GSUP Message Class, trying to guess from message type OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gsup_client_mux.c:38) 13290-20200309195517902 DREF DEBUG VLR subscr IMSI-001010000000120 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx) (vlr.c:1069) 13291-20200309195517902 DVLR DEBUG IMSI:001010000000120 has MSISDN:90120 (vlr.c:787) 13292-20200309195517902 DVLR NOTICE SUBSCR(IMSI-001010000000120:MSISDN-90120) VLR: update for IMSI=001010000000120 (MSISDN=90120) (gsm_04_08.c:1388) 13293-20200309195517902 DREF DEBUG VLR subscr IMSI-001010000000120:MSISDN-90120 - vlr_gsup_rx: now used by 1 (active-conn) (vlr.c:1115) 13294-20200309195517909 DLGSUP DEBUG No explicit GSUP Message Class, trying to guess from message type OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gsup_client_mux.c:38) 13295-20200309195517909 DREF DEBUG VLR subscr IMSI-001010000000127 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx) (vlr.c:1069) 13296-20200309195517909 DVLR DEBUG IMSI:001010000000127 has MSISDN:90127 (vlr.c:787) 13297-20200309195517909 DVLR NOTICE SUBSCR(IMSI-001010000000127:MSISDN-90127) VLR: update for IMSI=001010000000127 (MSISDN=90127) (gsm_04_08.c:1388) 13298-20200309195517909 DREF DEBUG VLR subscr IMSI-001010000000127:MSISDN-90127 - vlr_gsup_rx: now used by 1 (active-conn) (vlr.c:1115) 13299-20200309195517916 DLGSUP DEBUG No explicit GSUP Message Class, trying to guess from message type OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gsup_client_mux.c:38) 13300:20200309195517916 DREF DEBUG VLR subscr IMSI-001010000000105 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx) (vlr.c:1069) 13301-20200309195517916 DVLR DEBUG IMSI:001010000000105 has MSISDN:90105 (vlr.c:787) 13302:20200309195517916 DVLR NOTICE SUBSCR(IMSI-001010000000105:MSISDN-90105) VLR: update for IMSI=001010000000105 (MSISDN=90105) (gsm_04_08.c:1388) 13303:20200309195517916 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105 - vlr_gsup_rx: now used by 1 (active-conn) (vlr.c:1115) 13304-20200309195517916 DLGSUP DEBUG No explicit GSUP Message Class, trying to guess from message type OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gsup_client_mux.c:38) 13305-20200309195517916 DREF DEBUG VLR subscr IMSI-001010000000134:MSISDN-90134 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx) (vlr.c:1069) 13306-20200309195517916 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000134:MSISDN-90134:GERAN-A-88:LU)[0x556c8c264700]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES (vlr.c:888) 13307-20200309195517916 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000134:GERAN-A-88:LU)[0x556c8c23a5f0]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK (vlr_lu_fsm.c:1211) 13308-20200309195517916 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000134:GERAN-A-88:LU)[0x556c8c23a5f0]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) (vlr_lu_fsm.c:109) 13309-20200309195517916 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000134:GERAN-A-88:LU)[0x556c8c23a5f0]{UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (vlr_lu_fsm.c:110) 13310-20200309195517916 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000134:GERAN-A-88:LU)[0x556c8c23a5f0]{UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(IMSI-001010000000134:MSISDN-90134:GERAN-A-88:LU)[0x556c8c264700] (vlr_lu_fsm.c:110) 13311-20200309195517916 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000134:GERAN-A-88:LU)[0x556c8c23a5f0]{UPD_HLR_VLR_S_DONE}: Freeing instance (vlr_lu_fsm.c:110) 13312-20200309195517916 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000134:GERAN-A-88:LU)[0x556c8c23a5f0]{UPD_HLR_VLR_S_DONE}: Deallocated (fsm.c:573) 13313-20200309195517916 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000134:MSISDN-90134:GERAN-A-88:LU)[0x556c8c264700]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL (vlr_lu_fsm.c:110) -- 13370-20200309195517917 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000127:MSISDN-90127:GERAN-A-90:LU)[0x556c8c26caa0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() (vlr_lu_fsm.c:427) 13371-20200309195517917 DVLR NOTICE SUBSCR(IMSI-001010000000127:MSISDN-90127:TMSInew-0x09DDABF8) VLR: update for IMSI=001010000000127 (MSISDN=90127) (gsm_04_08.c:1388) 13372-20200309195517917 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000127:MSISDN-90127:GERAN-A-90:LU)[0x556c8c26caa0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (T3250, 12s) (vlr_lu_fsm.c:435) 13373-20200309195517917 DMM DEBUG -> IMSI-001010000000127:MSISDN-90127:TMSInew-0x09DDABF8 LOCATION UPDATE ACCEPT (TMSI = 0x09ddabf8) (gsm_04_08.c:153) 13374-20200309195517917 DBSSAP DEBUG msc_a(IMSI-001010000000127:MSISDN-90127:TMSInew-0x09DDABF8:GERAN-A-90:LU)[0x556c8c24f9e0]{MSC_A_ST_AUTH_CIPH}: Sending DTAP: MM GSM48_MT_MM_LOC_UPD_ACCEPT (msc_a.c:1709) 13375-20200309195517917 DBSSAP DEBUG msc_a(IMSI-001010000000127:MSISDN-90127:TMSInew-0x09DDABF8:GERAN-A-90:LU)[0x556c8c24f9e0]{MSC_A_ST_AUTH_CIPH}: RAN encode: BSSMAP: DTAP (ran_msg_a.c:1201) 13376-20200309195517917 DMSC DEBUG msc_i(IMSI-001010000000127:MSISDN-90127:TMSInew-0x09DDABF8:GERAN-A-90:LU)[0x556c8c23d5d0]{READY}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST (msc_a.c:1715) 13377-20200309195517917 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CO (ran_conn.c:119) 13378-20200309195517917 DREF DEBUG VLR subscr IMSI-001010000000127:MSISDN-90127:TMSInew-0x09DDABF8 - vlr_gsup_rx: now used by 1 (active-conn) (vlr.c:1115) 13379-20200309195517957 DLGSUP DEBUG No explicit GSUP Message Class, trying to guess from message type OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gsup_client_mux.c:38) 13380:20200309195517957 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx) (vlr.c:1069) 13381:20200309195517957 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES (vlr.c:888) 13382:20200309195517957 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK (vlr_lu_fsm.c:1211) 13383:20200309195517957 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) (vlr_lu_fsm.c:109) 13384:20200309195517957 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (vlr_lu_fsm.c:110) 13385:20200309195517957 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c24f4e0] (vlr_lu_fsm.c:110) 13386:20200309195517957 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_DONE}: Freeing instance (vlr_lu_fsm.c:110) 13387:20200309195517957 DVLR DEBUG upd_hlr_vlr_fsm(IMSI-001010000000105:GERAN-A-91:LU)[0x556c8c268910]{UPD_HLR_VLR_S_DONE}: Deallocated (fsm.c:573) 13388:20200309195517957 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL (vlr_lu_fsm.c:110) 13389:20200309195517957 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) (vlr_lu_fsm.c:1219) 13390:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_INIT}: Allocated (fsm.c:461) 13391:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c24f4e0] (fsm.c:491) 13392:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START (vlr_lu_fsm.c:765) 13393:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) (vlr_lu_fsm.c:411) 13394:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL (vlr_lu_fsm.c:418) 13395:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() (vlr_lu_fsm.c:427) 13396:20200309195517957 DVLR NOTICE SUBSCR(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F) VLR: update for IMSI=001010000000105 (MSISDN=90105) (gsm_04_08.c:1388) 13397:20200309195517957 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (T3250, 12s) (vlr_lu_fsm.c:435) 13398:20200309195517957 DMM DEBUG -> IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F LOCATION UPDATE ACCEPT (TMSI = 0x06b5315f) (gsm_04_08.c:153) 13399:20200309195517957 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: Sending DTAP: MM GSM48_MT_MM_LOC_UPD_ACCEPT (msc_a.c:1709) 13400:20200309195517957 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: RAN encode: BSSMAP: DTAP (ran_msg_a.c:1201) 13401:20200309195517957 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST (msc_a.c:1715) 13402-20200309195517957 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CO (ran_conn.c:119) 13403:20200309195517957 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F - vlr_gsup_rx: now used by 1 (active-conn) (vlr.c:1115) 13404-20200309195517960 DBSSAP DEBUG (GERAN-A-92 from RI=SSN_PC,PC=0.23.3,SSN=BSSAP) sccp_ran_sap_up(N-CONNECT.indication) (sccp_ran.c:84) 13405-20200309195517960 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO_INITIAL (ran_peer.c:596) 13406-20200309195517960 DMSC DEBUG msub_fsm[0x556c8c256290]{active}: Allocated (fsm.c:461) 13407-20200309195517960 DMSC DEBUG msc_i[0x556c8c23ad00]{READY}: Allocated (fsm.c:461) 13408-20200309195517960 DMSC DEBUG msc_i[0x556c8c23ad00]{READY}: is child of msub_fsm[0x556c8c256290] (fsm.c:491) 13409-20200309195517960 DMSC DEBUG msc_a[0x556c8c23ae30]{MSC_A_ST_VALIDATE_L3}: Allocated (fsm.c:461) 13410-20200309195517960 DMSC DEBUG msc_a[0x556c8c23ae30]{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm[0x556c8c256290] (fsm.c:491) 13411-20200309195517960 DMSC DEBUG msc_a(unknown:GERAN-A-92:NONE)[0x556c8c23ae30]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_VALIDATE_L3 (X1, 5s) (msc_a.c:1140) 13412-20200309195517960 DMSC DEBUG msc_i(unknown:GERAN-A-92:NONE)[0x556c8c23ad00]{READY}: Received Event MSC_EV_FROM_RAN_COMPLETE_LAYER_3 (ran_peer.c:392) 13413-20200309195517960 DMSC DEBUG msc_a(unknown:GERAN-A-92:NONE)[0x556c8c23ae30]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_FROM_I_COMPLETE_LAYER_3 (msc_i.c:103) -- 14140-20200309195518327 DBSSAP DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Closing GERAN-A-89 (ran_conn.c:142) 14141-20200309195518327 DMSC DEBUG NULL{fi=NULL}: Deallocating no-RAN-peer-89 (ran_conn.c:155) 14142-20200309195518327 DMSC DEBUG msc_i(IMSI-001010000000120:MSISDN-90120:TMSI-0x72C073C0:GERAN-A-89:LU)[0x556c8c238750]{READY}: Freeing instance (msub.c:112) 14143-20200309195518327 DMSC DEBUG msc_i(IMSI-001010000000120:MSISDN-90120:TMSI-0x72C073C0:GERAN-A-89:LU)[0x556c8c238750]{READY}: Deallocated (fsm.c:573) 14144-20200309195518327 DMSC DEBUG msub(IMSI-001010000000120:MSISDN-90120:TMSI-0x72C073C0) Free (msub.c:118) 14145-20200309195518327 DREF DEBUG VLR subscr IMSI-001010000000120:MSISDN-90120:TMSI-0x72C073C0 - active-conn: now used by 1 (attached) (msub.c:374) 14146-20200309195518327 DMSC DEBUG msub_fsm[0x556c8c233190]{terminating}: Freeing instance (msub.c:112) 14147-20200309195518327 DMSC DEBUG msub_fsm[0x556c8c233190]{terminating}: Deallocated (fsm.c:573) 14148-20200309195518363 DBSSAP DEBUG (GERAN-A-91) sccp_ran_sap_up(N-DATA.indication) (sccp_ran.c:108) 14149-20200309195518363 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO (ran_peer.c:596) 14150:20200309195518363 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Received Event MSC_EV_FROM_RAN_UP_L2 (ran_peer.c:412) 14151:20200309195518363 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_FROM_I_PROCESS_ACCESS_SIGNALLING_REQUEST (msc_i.c:85) 14152:20200309195518363 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: + msc_a_ran_dec: now used by 2 (lu,msc_a_ran_dec) (msc_a.c:183) 14153:20200309195518363 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: RAN decode: BSSAP DTAP (msc_a.c:1642) 14154:20200309195518363 DRLL DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: Dispatching 04.08 message: MM GSM48_MT_MM_TMSI_REALL_COMPL (msc_a.c:1261) 14155:20200309195518363 DMM DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: TMSI Reallocation Completed (gsm_04_08.c:1094) 14156:20200309195518363 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSInew-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK (vlr.c:1187) 14157:20200309195518363 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK (vlr_lu_fsm.c:1257) 14158:20200309195518363 DVLR NOTICE SUBSCR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F) VLR: update for IMSI=001010000000105 (MSISDN=90105) (gsm_04_08.c:1388) 14159:20200309195518363 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + attached: now used by 2 (active-conn,attached) (vlr_lu_fsm.c:363) 14160:20200309195518363 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) (vlr_lu_fsm.c:353) 14161:20200309195518363 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS (vlr_lu_fsm.c:381) 14162:20200309195518363 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) (vlr_lu_fsm.c:773) 14163:20200309195518363 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0] (vlr_lu_fsm.c:773) 14164:20200309195518363 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_DONE}: Freeing instance (vlr_lu_fsm.c:773) 14165:20200309195518363 DVLR DEBUG lu_compl_vlr_fsm(IMSI-001010000000105:MSISDN-90105:GERAN-A-91:LU)[0x556c8c272a20]{LU_COMPL_VLR_S_DONE}: Deallocated (fsm.c:573) 14166:20200309195518363 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) (vlr_lu_fsm.c:741) 14167:20200309195518363 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_AUTHENTICATED (vlr_lu_fsm.c:733) 14168:20200309195518363 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTH_CIPH}: State change to MSC_A_ST_AUTHENTICATED (keeping X1, 4.529s remaining) (msc_a.c:358) 14169:20200309195518364 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTHENTICATED}: - lu: now used by 1 (msc_a_ran_dec) (msc_a.c:154) 14170:20200309195518364 DREF INFO msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTHENTICATED}: - msc_a_ran_dec: now used by 0 (-) (msc_a.c:185) 14171:20200309195518364 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTHENTICATED}: Received Event MSC_A_EV_UNUSED (msc_a.c:1127) 14172:20200309195518364 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_AUTHENTICATED}: State change to MSC_A_ST_RELEASING (X2, 30s) (msc_a.c:507) 14173:20200309195518364 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: Releasing: msc_a use is 0 (-) (msc_a.c:817) 14174:20200309195518364 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + msc_a_fsm_releasing_onenter: now used by 3 (active-conn,attached,msc_a_fsm_releasing_onenter) (msc_a.c:820) 14175:20200309195518364 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + vlr_subscr_cancel_attach_fsm: now used by 4 (active-conn,attached,msc_a_fsm_releasing_onenter,vlr_subscr_cancel_attach_fsm) (vlr.c:293) 14176:20200309195518364 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F - vlr_subscr_cancel_attach_fsm: now used by 3 (active-conn,attached,msc_a_fsm_releasing_onenter) (vlr.c:298) 14177:20200309195518364 DREF INFO msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: + wait-Clear-Complete: now used by 1 (wait-Clear-Complete) (msc_a.c:856) 14178:20200309195518364 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: RAN encode: BSSMAP: CLEAR_COMMAND (ran_msg_a.c:1201) 14179:20200309195518364 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST (msc_a.c:857) 14180-20200309195518364 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CO (ran_conn.c:119) 14181:20200309195518364 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F - msc_a_fsm_releasing_onenter: now used by 2 (active-conn,attached) (msc_a.c:866) 14182-20200309195518365 DBSSAP DEBUG (GERAN-A-91) sccp_ran_sap_up(N-DATA.indication) (sccp_ran.c:108) 14183-20200309195518365 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO (ran_peer.c:596) 14184:20200309195518365 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Received Event MSC_EV_FROM_RAN_UP_L2 (ran_peer.c:412) 14185:20200309195518365 DBSSAP DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: RAN decode: BSSMAP: CLEAR COMPLETE (ran_msg_a.c:809) 14186:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: Received Event MSC_A_EV_FROM_I_PROCESS_ACCESS_SIGNALLING_REQUEST (msc_i.c:85) 14187:20200309195518365 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: + msc_a_ran_dec: now used by 2 (wait-Clear-Complete,msc_a_ran_dec) (msc_a.c:183) 14188:20200309195518365 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: RAN decode: BSSMAP: CLEAR COMPLETE (ran_msg_a.c:809) 14189:20200309195518365 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: RAN decode: BSSMAP Clear Complete (msc_a.c:1642) 14190:20200309195518365 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: - wait-Clear-Complete: now used by 1 (msc_a_ran_dec) (msc_a.c:1494) 14191:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASING}: State change to MSC_A_ST_RELEASED (X2, 30s) (msc_a.c:1495) 14192:20200309195518365 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: Released: msc_a use is 1 (msc_a_ran_dec) (msc_a.c:907) 14193:20200309195518365 DREF INFO msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: - msc_a_ran_dec: now used by 0 (-) (msc_a.c:185) 14194:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: Received Event MSC_A_EV_UNUSED (msc_a.c:1127) 14195:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (msc_a.c:915) 14196:20200309195518365 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) (msc_a.c:915) 14197:20200309195518365 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_DONE}: Removing from parent msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260] (msc_a.c:915) 14198:20200309195518365 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT (vlr_lu_fsm.c:1448) 14199:20200309195518365 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_DONE}: Freeing instance (msc_a.c:915) 14200:20200309195518365 DVLR DEBUG vlr_lu_fsm(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c24f4e0]{VLR_ULA_S_DONE}: Deallocated (fsm.c:573) 14201:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: Removing from parent msub_fsm[0x556c8c270d10] (msc_a.c:915) 14202:20200309195518365 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: max total use count was 3 (msc_a.c:927) 14203:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: Freeing instance (msc_a.c:915) 14204:20200309195518365 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c26d260]{MSC_A_ST_RELEASED}: Deallocated (fsm.c:573) 14205-20200309195518365 DMSC DEBUG msub_fsm[0x556c8c270d10]{active}: Received Event MSUB_EV_ROLE_TERMINATED (msc_a.c:915) 14206:20200309195518365 DMSC DEBUG msub(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F) MSC-A terminated (msub.c:260) 14207:20200309195518365 DMSC DEBUG msub(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F) 1 MSC-I still active (msub.c:78) 14208-20200309195518365 DMSC DEBUG msub_fsm[0x556c8c270d10]{active}: State change to terminating (no timeout) (msub.c:90) 14209-20200309195518365 DMSC DEBUG msub_fsm[0x556c8c270d10]{terminating}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (msub.c:112) 14210:20200309195518365 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Terminating (cause = OSMO_FSM_TERM_PARENT) (msub.c:112) 14211:20200309195518365 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Removing from parent msub_fsm[0x556c8c270d10] (msub.c:112) 14212-20200309195518365 DBSSAP DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Closing GERAN-A-91 (ran_conn.c:142) 14213-20200309195518365 DMSC DEBUG NULL{fi=NULL}: Deallocating no-RAN-peer-91 (ran_conn.c:155) 14214:20200309195518365 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Freeing instance (msub.c:112) 14215:20200309195518365 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-91:LU)[0x556c8c275a10]{READY}: Deallocated (fsm.c:573) 14216:20200309195518365 DMSC DEBUG msub(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F) Free (msub.c:118) 14217:20200309195518365 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F - active-conn: now used by 1 (attached) (msub.c:374) 14218-20200309195518365 DMSC DEBUG msub_fsm[0x556c8c270d10]{terminating}: Freeing instance (msub.c:112) 14219-20200309195518365 DMSC DEBUG msub_fsm[0x556c8c270d10]{terminating}: Deallocated (fsm.c:573) 14220-20200309195518577 DBSSAP DEBUG (GERAN-A-93) sccp_ran_sap_up(N-DATA.indication) (sccp_ran.c:108) 14221-20200309195518577 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO (ran_peer.c:596) 14222-20200309195518577 DMSC DEBUG msc_i(IMSI-001010000000135:MSISDN-90135:TMSInew-0x0E5C696B:GERAN-A-93:LU)[0x556c8c23ae30]{READY}: Received Event MSC_EV_FROM_RAN_UP_L2 (ran_peer.c:412) 14223-20200309195518577 DMSC DEBUG msc_a(IMSI-001010000000135:MSISDN-90135:TMSInew-0x0E5C696B:GERAN-A-93:LU)[0x556c8c23ad00]{MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_FROM_I_PROCESS_ACCESS_SIGNALLING_REQUEST (msc_i.c:85) 14224-20200309195518577 DREF DEBUG msc_a(IMSI-001010000000135:MSISDN-90135:TMSInew-0x0E5C696B:GERAN-A-93:LU)[0x556c8c23ad00]{MSC_A_ST_AUTH_CIPH}: + msc_a_ran_dec: now used by 2 (lu,msc_a_ran_dec) (msc_a.c:183) 14225-20200309195518577 DBSSAP DEBUG msc_a(IMSI-001010000000135:MSISDN-90135:TMSInew-0x0E5C696B:GERAN-A-93:LU)[0x556c8c23ad00]{MSC_A_ST_AUTH_CIPH}: RAN decode: BSSAP DTAP (msc_a.c:1642) 14226-20200309195518577 DRLL DEBUG msc_a(IMSI-001010000000135:MSISDN-90135:TMSInew-0x0E5C696B:GERAN-A-93:LU)[0x556c8c23ad00]{MSC_A_ST_AUTH_CIPH}: Dispatching 04.08 message: MM GSM48_MT_MM_TMSI_REALL_COMPL (msc_a.c:1261) 14227-20200309195518577 DMM DEBUG msc_a(IMSI-001010000000135:MSISDN-90135:TMSInew-0x0E5C696B:GERAN-A-93:LU)[0x556c8c23ad00]{MSC_A_ST_AUTH_CIPH}: TMSI Reallocation Completed (gsm_04_08.c:1094) -- 29594-20200309195614868 DREF DEBUG VLR subscr IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF + CC: now used by 3 (attached,mncc_tx_to_gsm_cc,CC) (transaction.c:155) 29595-20200309195614868 DCC DEBUG trans(CC:NULL IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF callref-0x67 tid-255) New transaction (transaction.c:158) 29596-20200309195614868 DMNCC DEBUG trans(CC:NULL IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF callref-0x67 tid-255) rx MNCC_SETUP_REQ (gsm_04_08_cc.c:2219) 29597-20200309195614868 DPAG DEBUG Paging: IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF for MNCC: establish call: Starting paging (paging.c:101) 29598-20200309195614868 DPAG DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Paging for IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF on LAC:15 (ran_peer.c:690) 29599-20200309195614868 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CL (ran_peer.c:692) 29600-20200309195614868 DREF DEBUG VLR subscr IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF + Paging: now used by 4 (attached,mncc_tx_to_gsm_cc,CC,Paging) (paging.c:111) 29601-20200309195614868 DREF DEBUG VLR subscr IMSI-001010000000103:MSISDN-90103:TMSI-0xAC763BDF - mncc_tx_to_gsm_cc: now used by 3 (attached,CC,Paging) (gsm_04_08_cc.c:2232) 29602-20200309195614879 DCC ERROR trans(NULL NULL callref-0x0 tid-0) rx MNCC_SETUP_REQ for unknown subscriber number '90104' (gsm_04_08_cc.c:2147) 29603-20200309195614879 DMNCC DEBUG trans(NULL NULL callref-0x0 tid-0) tx MNCC_REL_IND (gsm_04_08_cc.c:238) 29604:20200309195614894 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + mncc_tx_to_gsm_cc: now used by 2 (attached,mncc_tx_to_gsm_cc) (gsm_04_08_cc.c:2144) 29605:20200309195614894 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + CC: now used by 3 (attached,mncc_tx_to_gsm_cc,CC) (transaction.c:155) 29606:20200309195614894 DCC DEBUG trans(CC:NULL IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F callref-0x69 tid-255) New transaction (transaction.c:158) 29607:20200309195614894 DMNCC DEBUG trans(CC:NULL IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F callref-0x69 tid-255) rx MNCC_SETUP_REQ (gsm_04_08_cc.c:2219) 29608:20200309195614894 DPAG DEBUG Paging: IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F for MNCC: establish call: Starting paging (paging.c:101) 29609:20200309195614894 DPAG DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Paging for IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F on LAC:15 (ran_peer.c:690) 29610-20200309195614894 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CL (ran_peer.c:692) 29611:20200309195614894 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + Paging: now used by 4 (attached,mncc_tx_to_gsm_cc,CC,Paging) (paging.c:111) 29612:20200309195614894 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F - mncc_tx_to_gsm_cc: now used by 3 (attached,CC,Paging) (gsm_04_08_cc.c:2232) 29613-20200309195614906 DREF DEBUG VLR subscr IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 + mncc_tx_to_gsm_cc: now used by 2 (attached,mncc_tx_to_gsm_cc) (gsm_04_08_cc.c:2144) 29614-20200309195614906 DREF DEBUG VLR subscr IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 + CC: now used by 3 (attached,mncc_tx_to_gsm_cc,CC) (transaction.c:155) 29615-20200309195614906 DCC DEBUG trans(CC:NULL IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 callref-0x6a tid-255) New transaction (transaction.c:158) 29616-20200309195614906 DMNCC DEBUG trans(CC:NULL IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 callref-0x6a tid-255) rx MNCC_SETUP_REQ (gsm_04_08_cc.c:2219) 29617-20200309195614906 DPAG DEBUG Paging: IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 for MNCC: establish call: Starting paging (paging.c:101) 29618-20200309195614906 DPAG DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Paging for IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 on LAC:16 (ran_peer.c:690) 29619-20200309195614906 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CL (ran_peer.c:692) 29620-20200309195614906 DREF DEBUG VLR subscr IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 + Paging: now used by 4 (attached,mncc_tx_to_gsm_cc,CC,Paging) (paging.c:111) 29621-20200309195614906 DREF DEBUG VLR subscr IMSI-001010000000106:MSISDN-90106:TMSI-0x7D71B521 - mncc_tx_to_gsm_cc: now used by 3 (attached,CC,Paging) (gsm_04_08_cc.c:2232) 29622-20200309195614918 DREF DEBUG VLR subscr IMSI-001010000000107:MSISDN-90107:TMSI-0x65100E08 + mncc_tx_to_gsm_cc: now used by 2 (attached,mncc_tx_to_gsm_cc) (gsm_04_08_cc.c:2144) -- 68389-20200309195622320 DMSC DEBUG msc_a[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Allocated (fsm.c:461) 68390-20200309195622320 DMSC DEBUG msc_a[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm[0x556c8ca0f740] (fsm.c:491) 68391-20200309195622320 DMSC DEBUG msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_VALIDATE_L3 (X1, 5s) (msc_a.c:1140) 68392-20200309195622320 DMSC DEBUG msc_i(unknown:GERAN-A-338:NONE)[0x556c8c81b480]{READY}: Received Event MSC_EV_FROM_RAN_COMPLETE_LAYER_3 (ran_peer.c:392) 68393-20200309195622320 DMSC DEBUG msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_FROM_I_COMPLETE_LAYER_3 (msc_i.c:103) 68394-20200309195622320 DREF INFO msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: + msc_a_ran_dec: now used by 1 (msc_a_ran_dec) (msc_a.c:183) 68395-20200309195622320 DBSSAP DEBUG msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP: COMPLETE LAYER 3 (ran_msg_a.c:809) 68396-20200309195622320 DBSSAP DEBUG msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP Complete Layer 3 Information (msc_a.c:1642) 68397-20200309195622320 DBSSAP DEBUG msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Complete Layer 3: Codec List (BSS Supported): GSM#3 (msc_a.c:1472) 68398-20200309195622320 DRLL DEBUG msc_a(unknown:GERAN-A-338:NONE)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Dispatching 04.08 message: RR GSM48_MT_RR_PAG_RESP (msc_a.c:1261) 68399:20200309195622320 DRR DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Rx PAGING RESPONSE (gsm_04_08.c:1168) 68400:20200309195622320 DREF DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: + paging-response: now used by 2 (msc_a_ran_dec,paging-response) (gsm_04_08.c:1170) 68401:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: Allocated (fsm.c:461) 68402:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: is child of msc_a(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0] (fsm.c:491) 68403:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth) (vlr_access_req_fsm.c:675) 68404:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START (vlr_access_req_fsm.c:699) 68405:20200309195622320 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + proc_arq_vlr_fn_init: now used by 4 (attached,CC,Paging,proc_arq_vlr_fn_init) (vlr_access_req_fsm.c:365) 68406:20200309195622320 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + active-conn: now used by 5 (attached,CC,Paging,proc_arq_vlr_fn_init,active-conn) (msub.c:378) 68407:20200309195622320 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_COMPLETE_LAYER_3_OK (gsm_04_08.c:1411) 68408:20200309195622320 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_AUTH_CIPH (keeping X1, 4.999s remaining) (msc_a.c:203) 68409:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() (vlr_access_req_fsm.c:333) 68410:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2() (vlr_access_req_fsm.c:284) 68411:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph() (vlr_access_req_fsm.c:250) 68412:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr() (vlr_access_req_fsm.c:222) 68413:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres() (vlr_access_req_fsm.c:207) 68414:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace() (vlr_access_req_fsm.c:191) 68415:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei() (vlr_access_req_fsm.c:169) 68416:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED) (vlr_access_req_fsm.c:182) 68417:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_INIT}: State change to PR_ARQ_S_DONE (no timeout) (vlr_access_req_fsm.c:103) 68418:20200309195622320 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_DONE}: Process Access Request result: PASSED (vlr_access_req_fsm.c:112) 68419:20200309195622320 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_AUTHENTICATED (vlr_access_req_fsm.c:153) 68420:20200309195622320 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_AUTH_CIPH}: State change to MSC_A_ST_AUTHENTICATED (keeping X1, 4.999s remaining) (msc_a.c:358) 68421:20200309195622320 DPAG DEBUG Paging: IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F for MNCC: establish call: Paging Response action (success) (paging.c:148) 68422:20200309195622320 DPAG DEBUG Paging: IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F for MNCC: establish call: Removing Paging Request (paging.c:126) 68423:20200309195622320 DCC DEBUG trans(CC:NULL IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F callref-0x69 tid-255) Paging succeeded (gsm_04_08_cc.c:319) 68424:20200309195622320 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_AUTHENTICATED}: + cc: now used by 3 (msc_a_ran_dec,paging-response,cc) (gsm_04_08_cc.c:321) 68425:20200309195622320 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_AUTHENTICATED}: Received Event MSC_A_EV_TRANSACTION_ACCEPTED (gsm_04_08_cc.c:324) 68426:20200309195622320 DMSC DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_AUTHENTICATED}: State change to MSC_A_ST_COMMUNICATING (no timeout) (msc_a.c:501) 68427:20200309195622320 DCC DEBUG trans(CC:NULL IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP callref-0x69 tid-0) codecs: RAN={AMR:octet-align=1#112,GSM-EFR#110,GSM#3,GSM-HR-08#111} cell={GSM#3} remote=:0{GSM#3,GSM-HR-08#111,GSM-EFR#110,AMR:octet-align=1#112} result=:0{GSM#3} (gsm_04_08_cc.c:715) 68428:20200309195622320 DCC DEBUG trans(CC:NULL IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP callref-0x69 tid-0) new state NULL -> CALL_PRESENT (gsm_04_08_cc.c:194) 68429:20200309195622320 DCC DEBUG trans(CC:CALL_PRESENT IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP callref-0x69 tid-0) starting timer T303 with 30 seconds (gsm_04_08_cc.c:489) 68430:20200309195622320 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_COMMUNICATING}: Sending DTAP: CC GSM48_MT_CC_SETUP (msc_a.c:1709) 68431:20200309195622320 DBSSAP DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_COMMUNICATING}: RAN encode: BSSMAP: DTAP (ran_msg_a.c:1201) 68432:20200309195622320 DMSC DEBUG msc_i(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b480]{READY}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST (msc_a.c:1715) 68433-20200309195622320 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_DOWN_CO (ran_conn.c:119) 68434:20200309195622320 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F - Paging: now used by 4 (attached,CC,proc_arq_vlr_fn_init,active-conn) (paging.c:168) 68435:20200309195622320 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_COMMUNICATING}: - paging-response: now used by 2 (msc_a_ran_dec,cc) (paging.c:174) 68436:20200309195622322 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F - proc_arq_vlr_fn_init: now used by 3 (attached,CC,active-conn) (vlr_access_req_fsm.c:383) 68437:20200309195622322 DREF DEBUG msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_COMMUNICATING}: - msc_a_ran_dec: now used by 1 (cc) (msc_a.c:185) 68438-20200309195622322 DBSSAP DEBUG (GERAN-A-325) sccp_ran_sap_up(N-DATA.indication) (sccp_ran.c:108) 68439-20200309195622322 DRR DEBUG ran_peer(GERAN-A:RI-SSN_PC:PC-0-23-3:SSN-BSSAP)[0x556c8c22e740]{READY}: Received Event RAN_PEER_EV_MSG_UP_CO (ran_peer.c:596) 68440-20200309195622322 DMSC DEBUG msc_i(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP)[0x556c8c940e70]{READY}: Received Event MSC_EV_FROM_RAN_UP_L2 (ran_peer.c:412) 68441-20200309195622322 DBSSAP DEBUG msc_i(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP)[0x556c8c940e70]{READY}: RAN decode: BSSMAP: ASSIGNMENT COMPL (ran_msg_a.c:809) 68442-20200309195622322 DMSC DEBUG msc_a(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP)[0x556c8c940fa0]{MSC_A_ST_COMMUNICATING}: Received Event MSC_A_EV_FROM_I_PROCESS_ACCESS_SIGNALLING_REQUEST (msc_i.c:85) 68443-20200309195622322 DREF DEBUG msc_a(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP)[0x556c8c940fa0]{MSC_A_ST_COMMUNICATING}: + msc_a_ran_dec: now used by 2 (cc,msc_a_ran_dec) (msc_a.c:183) 68444-20200309195622322 DBSSAP DEBUG msc_a(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP)[0x556c8c940fa0]{MSC_A_ST_COMMUNICATING}: RAN decode: BSSMAP: ASSIGNMENT COMPL (ran_msg_a.c:809) 68445-20200309195622322 DBSSAP DEBUG msc_a(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP)[0x556c8c940fa0]{MSC_A_ST_COMMUNICATING}: RAN decode: BSSMAP Assignment Complete (msc_a.c:1642) 68446-20200309195622322 DCC DEBUG rtp_stream(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP:trans-0:call-154:RTP_TO_RAN:CI-1D4F3B58:no-remote-port:local-172-18-23-2-23530)[0x556c8c8a29f0]{ESTABLISHING}: no change: codecs already set to GSM#3 (rtp_stream.c:410) 68447-20200309195622322 DCC DEBUG rtp_stream(IMSI-001010000000154:MSISDN-90154:TMSI-0xB7DBEBFD:GERAN-A-325:PAGING_RESP:trans-0:call-154:RTP_TO_RAN:CI-1D4F3B58:no-remote-port:local-172-18-23-2-23530)[0x556c8c8a29f0]{ESTABLISHING}: setting remote addr to 172.18.23.3:20538 (rtp_stream.c:451) -- 69007-20200309195622567 DMSC DEBUG msc_a[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Allocated (fsm.c:461) 69008-20200309195622567 DMSC DEBUG msc_a[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm[0x556c8c82f090] (fsm.c:491) 69009-20200309195622567 DMSC DEBUG msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: State change to MSC_A_ST_VALIDATE_L3 (X1, 5s) (msc_a.c:1140) 69010-20200309195622567 DMSC DEBUG msc_i(unknown:GERAN-A-340:NONE)[0x556c8c82f1c0]{READY}: Received Event MSC_EV_FROM_RAN_COMPLETE_LAYER_3 (ran_peer.c:392) 69011-20200309195622567 DMSC DEBUG msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_FROM_I_COMPLETE_LAYER_3 (msc_i.c:103) 69012-20200309195622567 DREF INFO msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: + msc_a_ran_dec: now used by 1 (msc_a_ran_dec) (msc_a.c:183) 69013-20200309195622567 DBSSAP DEBUG msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP: COMPLETE LAYER 3 (ran_msg_a.c:809) 69014-20200309195622567 DBSSAP DEBUG msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: RAN decode: BSSMAP Complete Layer 3 Information (msc_a.c:1642) 69015-20200309195622567 DBSSAP DEBUG msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Complete Layer 3: Codec List (BSS Supported): GSM#3 (msc_a.c:1472) 69016-20200309195622567 DRLL DEBUG msc_a(unknown:GERAN-A-340:NONE)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Dispatching 04.08 message: RR GSM48_MT_RR_PAG_RESP (msc_a.c:1261) 69017:20200309195622567 DRR DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Rx PAGING RESPONSE (gsm_04_08.c:1168) 69018:20200309195622567 DREF DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: + paging-response: now used by 2 (msc_a_ran_dec,paging-response) (gsm_04_08.c:1170) 69019:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: Allocated (fsm.c:461) 69020:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: is child of msc_a(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40be0] (fsm.c:491) 69021:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth) (vlr_access_req_fsm.c:675) 69022:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START (vlr_access_req_fsm.c:699) 69023:20200309195622567 DREF DEBUG VLR subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F + proc_arq_vlr_fn_init: now used by 4 (attached,CC,active-conn,proc_arq_vlr_fn_init) (vlr_access_req_fsm.c:365) 69024:20200309195622567 DVLR ERROR Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: Another proc_arq_fsm is already associated with subscr IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F, terminating the other FSM. (vlr_access_req_fsm.c:374) 69025:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_DONE}: proc_arq_fsm_done(NETWORK_FAILURE) (vlr_access_req_fsm.c:376) 69026:20200309195622567 DVLR ERROR Process_Access_Request_VLR(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b6e0]{PR_ARQ_S_DONE}: transition to state PR_ARQ_S_DONE not permitted! (vlr_access_req_fsm.c:103) 69027:20200309195622567 DBSSAP ERROR msc_a(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Cannot associate with VLR subscr, another connection is already active at IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP (msub.c:360) 69028:20200309195622567 DBSSAP ERROR msc_a(IMSI-001010000000105:MSISDN-90105:TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_COMMUNICATING}: Attempt to associate a second subscriber connection at TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP (msub.c:362) 69029:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: proc_arq_fsm_done(NETWORK_FAILURE) (vlr_access_req_fsm.c:380) 69030:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_INIT}: State change to PR_ARQ_S_DONE (no timeout) (vlr_access_req_fsm.c:103) 69031:20200309195622567 DVLR DEBUG Process_Access_Request_VLR(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40d10]{PR_ARQ_S_DONE}: Process Access Request result: NETWORK_FAILURE (vlr_access_req_fsm.c:112) 69032:20200309195622567 DMSC DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_CN_CLOSE (vlr_access_req_fsm.c:153)
What happens:
first Paging response:
68399:20200309195622320 DRR DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-338:PAGING_RESP)[0x556c8c81b5b0]{MSC_A_ST_VALIDATE_L3}: Rx PAGING RESPONSE (gsm_04_08.c:1168)
~300ms later another one for the same subscriber:
69017:20200309195622567 DRR DEBUG msc_a(TMSI-0x06B5315F:GERAN-A-340:PAGING_RESP)[0x556c8ca40be0]{MSC_A_ST_VALIDATE_L3}: Rx PAGING RESPONSE (gsm_04_08.c:1168)
But the first conn has already been established.
Hence the second conn does not get associated to the vsub and is concluded unsuccessfully -- with a NULL subscriber.
Updated by neels about 4 years ago
- Status changed from New to In Progress
- % Done changed from 0 to 90
Updated by neels almost 4 years ago
- Status changed from In Progress to Resolved
- % Done changed from 90 to 100
merged