Bug #4449: with high load, paging_concludes() may crash due to NULL vsub - OsmoMSC - Open Source Mobile Communications

Custom queries

all-by-project

Actions

Copy link

Bug #4449

closed

with high load, paging_concludes() may crash due to NULL vsub

Added by neels about 4 years ago. Updated almost 4 years ago.

Status:

Resolved

Priority:

Normal

Assignee:

neels

Category:

Target version:

Start date:

03/09/2020

Due date:

% Done:

100%

Resolution:

Spec Reference:

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

osmo-msc.log

15 MB

neels, 03/09/2020 07:57 PM

History
Notes
Property changes

Actions

Copy link

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(!)

Actions

Copy link

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.

Actions

Copy link