Bug #3860
closedSMS memory leak
100%
Description
I've just sent a bunch of SMS from LTE-attached phones via SGs, and they were also delivered via SGs to LTE-attached phones. So the SMS were successfully submitted + delivered.
However, the OsmoMSC talloc report shows them still as allocated:
sms contains 24624 bytes in 39 blocks (ref 0) 0x561671d0d0c0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e70d00 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e70a10 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e70720 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e70430 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e70140 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6fe50 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6e980 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6d080 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e681c0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6d3e0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6b560 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6e330 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6e690 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6cb90 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6e040 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6b270 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6bb60 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e69f60 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6a450 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e68ba0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e688b0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e69380 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e69090 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e69c00 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e6aec0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e69910 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e67040 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e652e0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e66430 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e65fd0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e65ce0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e64ff0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e647a0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e613a0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e61da0 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e60760 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e5eb90 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0x561671e5db20
I'm not sure if this happens with all SMS (even on GSM or UMTS), or if it only happens in case of SGs.
Updated by fixeria about 5 years ago
Hi,
I'm not sure if this happens with all SMS (even on GSM or UMTS), or if it only happens in case of SGs.
AFAIR, if 'sms_over_gsup' mode is enabled, OsmoMSC neither does this transitional transcoding to/from
'gsm_sms' structure, nor store anything in its internal SMSC DB.
I think the source of this memleak can be narrowed down be setting a break-point to sms_alloc(),
since this is the only function doing such allocation:
return talloc_zero(tall_gsms_ctx, struct gsm_sms);
so then it would be good to see the call stack.
Hope this is helpful.
Updated by dexter about 5 years ago
(fixeria I assume you did MO sms by falling back to 2G, and sending the SMS from there via SGs)
I managed to reproduce the problem with MSC_Tests.TC_lu_and_mo_sms as well, so this seems not to be SGs related. This is also logical since the SGs related code only passes along dtap messages without caring what exactly is in them.
(Note: When using MSC_Tests.TC_sgsap_mo_sms to reproduce this, uncomment f_sgsap_bssmap_screening() to get a cleaner trace.)
When running the test I see a call to sms_alloc() at the very end of the procedure. The allocation is done by db.c:sms_from_result().
(gdb) bt full #0 sms_from_result (result=0x5555557eba10, net=<optimized out>) at db.c:744 sms = <optimized out> text = <optimized out> daddr = <optimized out> saddr = <optimized out> user_data = <optimized out> validity_timestamp = <optimized out> #1 0x0000555555569f7b in db_sms_get_next_unsent_rr_msisdn (net=net@entry=0x55555582b580, last_msisdn=last_msisdn@entry=0x55555590aff8 "", max_failed=max_failed@entry=9) at db.c:914 result = 0x5555557eba10 sms = <optimized out> q_last_msisdn = 0x5555557d2950 "@\376\220UUU" #2 0x000055555557fc6c in smsq_take_next_sms (net=0x55555582b580, last_msisdn=last_msisdn@entry=0x55555590aff8 "", last_msisdn_buflen=last_msisdn_buflen@entry=16) at sms_queue.c:217 sms = <optimized out> wrapped = <optimized out> sanity = <optimized out> started_with_msisdn = "\000\000\000\000\377\177\000\000\220,\221UUU\000" #3 0x000055555557fde6 in sms_submit_pending (_data=0x55555590af30) at sms_queue.c:258 pending = <optimized out> sms = <optimized out> smsq = 0x55555590af30 attempts = 20 initialized = 0 first_sub = 0 attempted = 0 rounds = 0 #4 0x00007ffff7318616 in osmo_timers_update () at timer.c:257 current_time = {tv_sec = 1553609043, tv_usec = 845832} node = <optimized out> timer_eviction_list = {next = 0x7fffffffdf20, prev = 0x7fffffffdf20} this = 0x55555590af80 work = <optimized out> #5 0x00007ffff7318d96 in osmo_select_main (polling=<optimized out>) at select.c:260 readset = {__fds_bits = {0 <repeats 16 times>}} writeset = {__fds_bits = {0 <repeats 16 times>}} exceptset = {__fds_bits = {0 <repeats 16 times>}} rc = <optimized out> no_time = {tv_sec = 0, tv_usec = 0} #6 0x0000555555561109 in main (argc=1, argv=<optimized out>) at msc_main.c:716 rc = <optimized out>
Here is the log from the test, with some printfs to track the alloc/free
<0011> sgs_server.c:185 SGs socket bound to r=NULL<->l=0.0.0.0:29118 Tue Mar 26 15:08:54 2019 DLSS7 <001e> osmo_ss7.c:1326 0: ASP Restart for server not implemented yet! WARNING: 'cs7-instance-iu' without effect: built without Iu support Tue Mar 26 15:08:54 2019 DMNCC <0004> mncc_sock.c:320 MNCC socket at /home/owner/mncc_sock Tue Mar 26 15:08:54 2019 DLGLOBAL <0012> telnet_interface.c:104 Available via telnet 127.0.0.1 4254 Tue Mar 26 15:08:54 2019 DSMPP <000c> smpp_smsc.c:1012 SMPP at 0.0.0.0 2775 Tue Mar 26 15:08:54 2019 DLCTRL <0019> control_if.c:911 CTRL at 127.0.0.1 4255 Tue Mar 26 15:08:54 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:08:54 2019 DLMGCP <0022> mgcp_client.c:716 MGCP client: using endpoint domain '@mgw' Tue Mar 26 15:08:54 2019 DLMGCP <0022> mgcp_client.c:791 MGCP GW connection: r=127.0.0.1:2427<->l=127.0.0.1:2727 Tue Mar 26 15:08:54 2019 DLSCCP <001f> sccp_user.c:397 OsmoMSC-A: Using SS7 instance 0, pc:0.23.1 Tue Mar 26 15:08:54 2019 DLSCCP <001f> sccp_user.c:415 OsmoMSC-A: Using AS instance as-clnt-OsmoMSC-A Tue Mar 26 15:08:54 2019 DLSCCP <001f> sccp_user.c:420 OsmoMSC-A: Creating default route Tue Mar 26 15:08:54 2019 DLSCCP <001f> sccp_user.c:476 OsmoMSC-A: Using ASP instance asp-clnt-OsmoMSC-A Tue Mar 26 15:08:54 2019 DLSS7 <001e> osmo_ss7.c:471 0: Creating SCCP instance Tue Mar 26 15:08:54 2019 DBSSAP <0010> a_iface.c:674 Initalizing SCCP connection to stp... Tue Mar 26 15:08:55 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:08:56 2019 DLM3UA <0021> m3ua.c:634 asp-asp-clnt-OsmoMSC-A: Received NOTIFY Type State Change:AS Inactive () Tue Mar 26 15:08:56 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:08:56 2019 DLSS7 <001e> xua_default_lm_fsm.c:353 xua_default_lm(asp-clnt-OsmoMSC-A)[0x5633ae8a5000]{ACTIVE}: Ignoring primitive M-ASP_ACTIVE.confirm Tue Mar 26 15:08:56 2019 DLM3UA <0021> m3ua.c:634 asp-asp-clnt-OsmoMSC-A: Received NOTIFY Type State Change:AS Active () Tue Mar 26 15:08:57 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:08:58 2019 DLCTRL <0019> control_if.c:554 accept()ed new CTRL connection from (r=127.0.0.1:46217<->l=127.0.0.1:4255) Tue Mar 26 15:08:58 2019 DMNCC <0004> mncc_sock.c:275 MNCC Socket has connection with external call control application Tue Mar 26 15:08:58 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:08:58 2019 DLINP <0014> input/ipa.c:128 127.0.0.1:4222 connection done Tue Mar 26 15:08:58 2019 DLINP <0014> input/ipaccess.c:705 received ID get from 0/0/0 Tue Mar 26 15:08:58 2019 DSMPP <000c> smpp_smsc.c:748 [] smpp_pdu_rx(00 00 00 32 00 00 00 09 00 00 00 00 00 00 00 01 6d 73 63 5f 74 65 73 74 65 72 00 6f 73 6d 6f 63 6f 6d 31 00 4d 53 43 5f 54 65 73 74 73 00 34 00 00 00 ) Tue Mar 26 15:08:58 2019 DSMPP <000c> smpp_smsc.c:544 [msc_tester] Rx BIND Trx (Version 34) Tue Mar 26 15:08:58 2019 DLCTRL <0019> control_if.c:554 accept()ed new CTRL connection from (r=127.0.0.1:33499<->l=127.0.0.1:4255) Tue Mar 26 15:08:59 2019 DBSSAP <0010> a_iface.c:140 The calling BSC (RI=SSN_PC,PC=0.24.1,SSN=BSSAP) is unknown to this MSC ... Tue Mar 26 15:08:59 2019 DBSSAP <0010> a_iface.c:490 Adding new BSC connection for BSC RI=SSN_PC,PC=0.24.1,SSN=BSSAP... Tue Mar 26 15:08:59 2019 DBSSAP <0010> a_iface_bssap.c:112 Rx BSSMAP RESET from BSC RI=SSN_PC,PC=0.24.1,SSN=BSSAP, sending RESET ACK Tue Mar 26 15:08:59 2019 DMM <0002> fsm.c:320 RAN_conn[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: Allocated Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: Updated ID Tue Mar 26 15:08:59 2019 DMM <0002> gsm_04_08.c:382 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: LOCATION UPDATING REQUEST: MI=IMSI-262420000000042 LU-type=IMSI-ATTACH Tue Mar 26 15:08:59 2019 DMM <0002> gsm_04_08.c:427 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: LU/new-LAC: 39321/23 Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:320 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: Allocated Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:350 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: is child of RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:1490 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: rev=R99 net=GERAN (no Auth) Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:1496 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA Tue Mar 26 15:08:59 2019 DSGS <0011> fsm.c:320 SGs-UE(num:0)[0x5633ae8aabf0]{SGs-NULL}: Allocated Tue Mar 26 15:08:59 2019 DSGS <0011> vlr_sgs_fsm.c:359 SGs-UE(num:0)[0x5633ae8aabf0]{SGs-NULL}: state_chg to SGs-NULL Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:434 set IMSI on subscriber; IMSI=262420000000042 id=262420000000042 Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:387 New subscr, IMSI: 262420000000042 Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: Updated ID Tue Mar 26 15:08:59 2019 DSGS <0011> vlr_lu_fsm.c:1065 SGs-UE(num:0)[0x5633ae8aabf0]{SGs-NULL}: Received Event RX_LU_FROM_A_Iu_Gs Tue Mar 26 15:08:59 2019 DSGS <0011> vlr_sgs_fsm.c:72 SGs-UE(num:0)[0x5633ae8aabf0]{SGs-NULL}: state_chg to SGs-NULL Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:909 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: vlr_loc_upd_node1() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:863 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:830 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:791 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: vlr_loc_upd_node_4() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:800 vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:320 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_INIT}: Allocated Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:350 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ac5f0] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:176 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:188 GSUP tx: 04010862420200000040f2280102 Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:87 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:568 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3 Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:118 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:906 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:151 RAN_conn(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:1080 GSUP rx 20: 10010862420200000040f2080706942103000024 Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:788 IMSI:262420000000042 has MSISDN:491230000042 Tue Mar 26 15:08:59 2019 DVLR <000e> gsm_04_08.c:1772 SUBSCR(IMSI-262420000000042:MSISDN-491230000042) VLR: update for IMSI=262420000000042 (MSISDN=491230000042, used=2) Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: Updated ID Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:188 GSUP tx: 12010862420200000040f2 Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:1080 GSUP rx 11: 06010862420200000040f2 Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:889 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:1197 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:109 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:110 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:110 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8ac5f0] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:110 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_DONE}: Freeing instance Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:402 upd_hlr_vlr_fsm(IMSI-262420000000042:GERAN-A-0:LU)[0x5633ae8acf70]{UPD_HLR_VLR_S_DONE}: Deallocated Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:110 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:1205 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:320 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_INIT}: Allocated Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:350 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8ac5f0] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:773 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:418 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:425 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:434 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() Tue Mar 26 15:08:59 2019 DVLR <000e> gsm_04_08.c:1772 SUBSCR(IMSI-262420000000042:MSISDN-491230000042:TMSInew-0x0EB03F3A) VLR: update for IMSI=262420000000042 (MSISDN=491230000042, used=2) Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSInew-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: Updated ID Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:443 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF Tue Mar 26 15:08:59 2019 DMM <0002> gsm_04_08.c:298 -> IMSI-262420000000042:MSISDN-491230000042:TMSInew-0x0EB03F3A LOCATION UPDATE ACCEPT (TMSI = 0x0eb03f3a) Tue Mar 26 15:08:59 2019 DMM <0002> gsm_04_08.c:1126 TMSI Reallocation Completed. Subscriber: IMSI-262420000000042:MSISDN-491230000042:TMSInew-0x0EB03F3A Tue Mar 26 15:08:59 2019 DVLR <000e> vlr.c:1226 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSInew-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:1240 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK Tue Mar 26 15:08:59 2019 DVLR <000e> gsm_04_08.c:1772 SUBSCR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A) VLR: update for IMSI=262420000000042 (MSISDN=491230000042, used=1) Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: Updated ID Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:353 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:388 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:781 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:781 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:781 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_DONE}: Freeing instance Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:402 lu_compl_vlr_fsm(IMSI-262420000000042:MSISDN-491230000042:GERAN-A-0:LU)[0x5633ae8acef0]{LU_COMPL_VLR_S_DONE}: Deallocated Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:749 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE Tue Mar 26 15:08:59 2019 DMM <0002> vlr_lu_fsm.c:741 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED Tue Mar 26 15:08:59 2019 DSMPP <000c> smpp_smsc.c:653 [msc_tester] Tx ALERT_NOTIFICATION (491230000042/3/1): Available Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:146 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:276 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:297 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:906 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:408 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:415 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) Tue Mar 26 15:08:59 2019 DVLR <000e> ran_conn.c:415 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) Tue Mar 26 15:08:59 2019 DVLR <000e> ran_conn.c:415 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_DONE}: Removing from parent RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_lu_fsm.c:1415 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT Tue Mar 26 15:08:59 2019 DVLR <000e> ran_conn.c:415 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_DONE}: Freeing instance Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:402 vlr_lu_fsm(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ac5f0]{VLR_ULA_S_DONE}: Deallocated Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:415 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_RELEASED}: Freeing instance Tue Mar 26 15:08:59 2019 DMM <0002> fsm.c:402 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-0:LU)[0x5633ae8ad0b0]{RAN_CONN_S_RELEASED}: Deallocated Tue Mar 26 15:08:59 2019 DMM <0002> fsm.c:320 RAN_conn[0x5633ae8ac440]{RAN_CONN_S_NEW}: Allocated Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_NEW}: Updated ID Tue Mar 26 15:08:59 2019 DMM <0002> gsm_04_08.c:780 RAN_conn(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_NEW}: Rx CM SERVICE REQUEST cm_service_type=0x04 Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:320 Process_Access_Request_VLR(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: Allocated Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:350 Process_Access_Request_VLR(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: is child of RAN_conn(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440] Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:679 Process_Access_Request_VLR(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: rev=R99 net=GERAN (no Auth) Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:703 Process_Access_Request_VLR(TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:735 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_NEW}: Updated ID Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:330 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:281 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:247 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:219 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:204 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:188 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:166 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei() Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:179 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED) Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:102 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE Tue Mar 26 15:08:59 2019 DVLR <000e> vlr_access_req_fsm.c:111 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_DONE}: Process Access Request result: PASSED Tue Mar 26 15:08:59 2019 DMM <0002> msc_ifaces.c:101 -> CM SERVICE ACCEPT IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A Tue Mar 26 15:08:59 2019 DMM <0002> vlr_access_req_fsm.c:150 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_NEW}: Received Event RAN_CONN_E_ACCEPTED Tue Mar 26 15:08:59 2019 DSMPP <000c> smpp_smsc.c:653 [msc_tester] Tx ALERT_NOTIFICATION (491230000042/3/1): Available Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:123 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_ACCEPTED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:239 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:568 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMPLETE_LAYER_3 Tue Mar 26 15:08:59 2019 DCC <0001> transaction.c:118 (ti 08 sub IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A callref 40000001) New transaction Tue Mar 26 15:08:59 2019 DMM <0002> gsm_04_08.c:1353 IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A: rx msg SMS:0x01: received_cm_service_request changes to false Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:641 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:289 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING ========================================> NOW SMS ALLOC from gsm340_rx_tpdu() ================================================== SMS ALLOC! Tue Mar 26 15:08:59 2019 DSMPP <000c> smpp_smsc.c:282 Looking up route for (0/0/12345) ================================================== SMS FREE! Tue Mar 26 15:08:59 2019 DLSMS <0018> gsm0411_smc.c:339 SMC(0) cannot release yet current state: WAIT_CP_ACK Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:641 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:906 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:317 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:906 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:408 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:415 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) Tue Mar 26 15:08:59 2019 DVLR <000e> ran_conn.c:415 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) Tue Mar 26 15:08:59 2019 DVLR <000e> ran_conn.c:415 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_DONE}: Removing from parent RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440] Tue Mar 26 15:08:59 2019 DVLR <000e> ran_conn.c:415 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_DONE}: Freeing instance Tue Mar 26 15:08:59 2019 DVLR <000e> fsm.c:402 Process_Access_Request_VLR(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ad9a0]{PR_ARQ_S_DONE}: Deallocated Tue Mar 26 15:08:59 2019 DMM <0002> ran_conn.c:415 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_RELEASED}: Freeing instance Tue Mar 26 15:08:59 2019 DMM <0002> fsm.c:402 RAN_conn(IMSI-262420000000042:MSISDN-491230000042:TMSI-0x0EB03F3A:GERAN-A-1:CM_SERVICE_REQ)[0x5633ae8ac440]{RAN_CONN_S_RELEASED}: Deallocated Tue Mar 26 15:08:59 2019 DLCTRL <0019> control_if.c:188 close()d CTRL connection (r=127.0.0.1:46217<->l=127.0.0.1:4255) Tue Mar 26 15:08:59 2019 DMNCC <0004> mncc_sock.c:85 MNCC Socket has LOST connection Tue Mar 26 15:08:59 2019 DCC <0001> gsm_04_08.c:232 Clearing all currently active transactions!!! Tue Mar 26 15:08:59 2019 DLINP <0014> input/ipa.c:65 127.0.0.1:4222 connection closed with server Tue Mar 26 15:08:59 2019 DLCTRL <0019> control_if.c:188 close()d CTRL connection (r=127.0.0.1:33499<->l=127.0.0.1:4255) ========================================> NOW SMS ALLOC from sms_from_result() ================================================== SMS ALLOC! Tue Mar 26 15:09:00 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:01 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:02 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:03 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:04 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:05 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:06 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:07 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:08 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:09 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222 Tue Mar 26 15:09:10 2019 DLGSUP <001c> gsup_client.c:73 GSUP connecting to 127.0.0.1:4222
To me this look like a problem with the smsqueue. It somehow wants to move on with the next SMS and then it stops or fails somehow. It is definitely suspicious.
Updated by fixeria about 5 years ago
- Status changed from New to In Progress
- Priority changed from Normal to High
- % Done changed from 0 to 90
Ok, I managed to reproduce this memleak with both:
- MSC_Tests.TC_lu_and_mo_sms,
- MSC_Tests.TC_lu_and_mt_sms.
My initial assumption was that our TTCN-3 test cases basically disconnect too quick, leaving some MT SMS (e.g. delivery report) undelivered, so they are getting stored in the database. This assumption was confirmed when I restarted OsmoMSC, and got the following surprise:
OsmoMSC# show talloc-context application full tree 0xc65b80 full talloc report on 'osmo_msc' (total 15690 bytes in 87 blocks) sms contains 648 bytes in 2 blocks (ref 0) 0xc65b80 struct gsm_sms contains 648 bytes in 1 blocks (ref 0) 0xdb08f0
the corresponding back-trace is:
#0 sms_alloc () at gsm_04_11.c:67 #1 0x000000000040f2a5 in sms_from_result (result=result@entry=0x7e8b20, net=0x6f7f00) at db.c:744 #2 0x0000000000410783 in db_sms_get_next_unsent_rr_msisdn (net=net@entry=0x6f7f00, last_msisdn=last_msisdn@entry=0x7d3578 "", max_failed=max_failed@entry=0x9) at db.c:911 #3 0x00000000004261d5 in smsq_take_next_sms (net=0x6f7f00, last_msisdn=last_msisdn@entry=0x7d3578 "", last_msisdn_buflen=last_msisdn_buflen@entry=0x10) at sms_queue.c:217 #4 0x00000000004262f6 in sms_submit_pending (_data=0x7d34b0) at sms_queue.c:258 #5 0x0000000000426c45 in sms_queue_start (network=0x6f7f00, max_pending=max_pending@entry=0x14) at sms_queue.c:393 #6 0x0000000000407ade in main (argc=argc@entry=0x3, argv=argv@entry=0x7fffffffdc28) at msc_main.c:679 #7 0x00007ffff60b4f45 in __libc_start_main (main=0x407500 <main>, argc=0x3, argv=0x7fffffffdc28, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffdc18) at libc-start.c:287 #8 0x0000000000407d8b in _start ()
The problem is that subscriber, to whom this message belongs to, is not connected to the network anymore!
I started to read the source code of sms_queue.c, and found the root of this memleak:
struct gsm_sms *smsq_take_next_sms(struct gsm_network *net, char *last_msisdn, size_t last_msisdn_buflen) { struct gsm_sms *sms; int wrapped = 0; int sanity = 100; char started_with_msisdn[last_msisdn_buflen]; OSMO_STRLCPY_ARRAY(started_with_msisdn, last_msisdn); while (wrapped < 2 && (--sanity)) { /* If we wrapped around and passed the first msisdn, we're * through the entire SMS DB; end it. */ if (wrapped && strcmp(last_msisdn, started_with_msisdn) >= 0) break; sms = db_sms_get_next_unsent_rr_msisdn(net, last_msisdn, 9); if (!sms) { last_msisdn[0] = '\0'; wrapped++; continue; } /* Whatever happens, next time around service another recipient */ osmo_strlcpy(last_msisdn, sms->dst.addr, last_msisdn_buflen); /* Is the subscriber attached? If not, go to next SMS */ if (!sms->receiver || !sms->receiver->lu_complete) /*!!! Memleak is HERE !!!*/ continue; return sms; } DEBUGP(DLSMS, "SMS queue: no SMS to be sent\n"); return NULL; }
So, if subscriber is not attached, this function doesn't free() 'gsm_sms' struct.
After adding talloc_free(), there is no memleak anymore ;) Writing the commit message now...
Updated by fixeria about 5 years ago
- Status changed from In Progress to Feedback
Please see https://gerrit.osmocom.org/#/c/osmo-msc/+/13450/
I don't see any SMS-related memleaks after applying this patch. However, it still needs to be investigated, why this SMS message has invalid delivery address, and is it really MT delivery report or something else:
DLSMS DEBUG <0018> sms_queue.c:232 Subscriber unknown is not attached, skipping SMS 1
Updated by fixeria almost 5 years ago
- Status changed from Feedback to Resolved
- % Done changed from 90 to 100
- Resolution set to fixed
However, it still needs to be investigated, why this SMS message has invalid delivery address, and is it really MT delivery report or something else:
DLSMS DEBUG <0018> sms_queue.c:232 Subscriber unknown is not attached, skipping SMS 1
As it turns out, the MSC_Tests.TC_lu_and_mo_sms basically sends a MO SMS to a non-attached subscriber 12345.
So, we probably need to clear the SMSC's database after the test case execution.
The fix has been merged, so closing this ticket.