Actions
Bug #3860
closedSMS memory leak
Added by laforge about 5 years ago. Updated about 5 years ago.
Start date:
03/25/2019
Due date:
% Done:
100%
Resolution:
fixed
Spec Reference:
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 about 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.
Actions
