Project

General

Profile

Actions

Bug #5572

open

segfault with osmo-BSC in osmo_mgcpc_ep_ci_request (rare)

Added by keith about 1 month ago. Updated about 22 hours ago.

Status:
In Progress
Priority:
High
Assignee:
Category:
RTP/Media
Target version:
-
Start date:
05/26/2022
Due date:
% Done:

50%

Spec Reference:

Description

The line that crashed was added in https://cgit.osmocom.org/osmo-mgw/commit/?id=3ff71284fa90e5c26963db860590054f41169970

We can run for a few days before hitting this.

I don't have much relevant lead-up log captured at this time, only a backtrace.
Last Log line on the console is:

DMSC ERROR osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn43820_subscr-IMSI-334020218960160-TMSI-0x6919a240)[0x555555aded00]{WAIT_CLEAR_CMD}: Event MT_DTAP not permitted  

Program received signal SIGSEGV, Segmentation fault.                                                                                                                             
0x00007ffff79ebd6d in osmo_mgcpc_ep_ci_request (ci=0x555555b2d570, verb=MGCP_VERB_DLCX, verb_info=0x0, notify=0x0, event_success=0, event_failure=0, notify_data=0x0)            
    at mgcp_client_endpoint_fsm.c:665                                                                                                                                            
665             LOG_CI_VERB(ci, LOGL_DEBUG, "notify=%s\n", osmo_fsm_inst_name(ci->notify.fi));                                                                                   
(gdb) bt
#0  0x00007ffff79ebd6d in osmo_mgcpc_ep_ci_request (ci=0x555555b2d570, verb=MGCP_VERB_DLCX, verb_info=0x0, notify=0x0, event_success=0, event_failure=0, notify_data=0x0)
    at mgcp_client_endpoint_fsm.c:665
#1  0x000055555559d52d in osmo_mgcpc_ep_ci_dlcx (ci=0x555555b2d570) at /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:42
#2  0x000055555559d802 in assignment_reset (conn=0x555555b367c0) at assignment_fsm.c:134
#3  0x00005555555c84ad in gscon_release_lchans (conn=0x555555b367c0, do_rr_release=true, cause_rr=GSM48_RR_CAUSE_NORMAL) at bsc_subscr_conn_fsm.c:260
#4  0x00005555555c824e in gscon_fsm_wait_sccp_rlsd_onenter (fi=0x555555aded00, prev_state=6) at bsc_subscr_conn_fsm.c:215
#5  0x00007ffff7ad09d4 in state_chg (fi=0x555555aded00, new_state=7, keep_timer=false, timeout_ms=60000, T=-4, file=0x5555556b8876 "bsc_subscr_conn_fsm.c", line=971)
    at fsm.c:694
#6  0x00007ffff7ad0a37 in _osmo_fsm_inst_state_chg (fi=0x555555aded00, new_state=7, timeout_secs=60, T=-4, file=0x5555556b8876 "bsc_subscr_conn_fsm.c", line=971) at fsm.c:743
#7  0x00007ffff7aebe4b in _osmo_tdef_fsm_inst_state_chg (fi=0x555555aded00, state=7, timeouts_array=0x55555571d300 <conn_fsm_timeouts>,
    tdefs=0x5555557281a0 <gsm_network_T_defs>, default_timeout=-1, file=0x5555556b8876 "bsc_subscr_conn_fsm.c", line=971) at tdef.c:357
#8  0x00005555555cc763 in gscon_fsm_allstate (fi=0x555555aded00, event=4, data=0x7fffffffcd1c) at bsc_subscr_conn_fsm.c:971
#9  0x00007ffff7ad133e in _osmo_fsm_inst_dispatch (fi=0x555555aded00, event=4, data=0x7fffffffcd1c, file=0x5555556e8c96 "osmo_bsc_bssap.c", line=438) at fsm.c:860
#10 0x000055555566f32b in bssmap_handle_clear_cmd (conn=0x555555b367c0, msg=0x555555b19d00, length=4) at osmo_bsc_bssap.c:438
#11 0x0000555555673a0e in bssmap_rcvmsg_dt1 (conn=0x555555b367c0, msg=0x555555b19d00, length=4) at osmo_bsc_bssap.c:1172
#12 0x0000555555674997 in bsc_handle_dt (conn=0x555555b367c0, msg=0x555555b19d00, len=6) at osmo_bsc_bssap.c:1360
#13 0x000055555567fb3a in handle_data_from_msc (conn=0x555555b367c0, msg=0x555555b19d00) at osmo_bsc_sigtran.c:141
#14 0x0000555555680598 in sccp_sap_up (oph=0x555555b19d88, _scu=0x555555a61ca0) at osmo_bsc_sigtran.c:256
#15 0x00007ffff7a1acd4 in sccp_user_prim_up (scu=0x555555a61ca0, prim=0x555555b19d88) at sccp_user.c:177
#16 0x00007ffff7a17da2 in scu_gen_encode_and_send (conn=0x555555b3e690, event=11, xua=0x555555b189f0, primitive=1, operation=PRIM_OP_INDICATION) at sccp_scoc.c:805
#17 0x00007ffff7a188ee in scoc_fsm_active (fi=0x555555aaf730, event=11, data=0x555555b189f0) at sccp_scoc.c:1124                                                                
#18 0x00007ffff7ad162d in _osmo_fsm_inst_dispatch (fi=0x555555aaf730, event=11, data=0x555555b189f0, file=0x7ffff7a3bc68 "sccp_scoc.c", line=1698) at fsm.c:872                 
#19 0x00007ffff7a19daa in sccp_scoc_rx_from_scrc (inst=0x555555a61b00, xua=0x555555b189f0) at sccp_scoc.c:1698                                                                  
#20 0x00007ffff7a150fd in scrc_rx_mtp_xfer_ind_xua (inst=0x555555a61b00, xua=0x555555b189f0) at sccp_scrc.c:479                                                                 
#21 0x00007ffff7a1ae48 in mtp_user_prim_cb (oph=0x555555af8cc8, ctx=0x555555a61b00) at sccp_user.c:202                                                                          
#22 0x00007ffff7a294a6 in deliver_to_mtp_user (osu=0x555555a61b48, xua=0x555555ad1120) at osmo_ss7_hmrt.c:95                                                                    
#23 0x00007ffff7a29673 in hmdt_message_for_distribution (inst=0x555555a2b3c0, xua=0x555555ad1120) at osmo_ss7_hmrt.c:134                                                        
#24 0x00007ffff7a2a0a7 in m3ua_hmdc_rx_from_l2 (inst=0x555555a2b3c0, xua=0x555555ad1120) at osmo_ss7_hmrt.c:278                                                                 
#25 0x00007ffff7a0b37f in m3ua_rx_xfer (asp=0x555555a602d0, xua=0x555555ad1120) at m3ua.c:577                                                                                   
#26 0x00007ffff7a0bb9b in m3ua_rx_msg (asp=0x555555a602d0, msg=0x555555adb750) at m3ua.c:732                                                                                    
#27 0x00007ffff7a27668 in xua_cli_read_cb (conn=0x555555a60bd0) at osmo_ss7.c:1950
#28 0x00007ffff7a96a3d in osmo_stream_cli_read (cli=0x555555a60bd0) at stream.c:327
#29 0x00007ffff7a9717f in osmo_stream_cli_fd_cb (ofd=0x555555a60bd0, what=1) at stream.c:446                                                                                    
#30 0x00007ffff7ac881c in poll_disp_fds (n_fd=12) at select.c:361
#31 0x00007ffff7ac8929 in _osmo_select_main (polling=0) at select.c:399
#32 0x00007ffff7ac8997 in osmo_select_main_ctx (polling=0) at select.c:455
#33 0x00005555555797f9 in main (argc=3, argv=0x7fffffffe4b8) at osmo_bsc_main.c:1043

(gdb) info locals
ep = 0x555555b2d350
fi = 0x555555b18960
cleared_ci = {ep = 0x555555b2d350, occupied = true, label = '\000' <repeats 63 times>, mgcp_client_fi = 0x0, pending = false, sent = false, verb = MGCP_VERB_DLCX, verb_info = {
    addr = '\000' <repeats 45 times>, port = 0, endpoint = '\000' <repeats 511 times>, call_id = 0, ptime = 0, codecs = {CODEC_PCMU_8000_1, CODEC_PCMU_8000_1,                  
      CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1}, codecs_len = 0,  
    ptmap = {{codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {              
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {                    
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}}, ptmap_len = 0, x_osmo_ign = 0, x_osmo_osmux_use = false, x_osmo_osmux_cid = 0,                
    conn_mode = MGCP_CONN_NONE, param_present = false, param = {amr_octet_aligned_present = false, amr_octet_aligned = false}}, notify = {entry = {next = 0x0, prev = 0x0},     
    fi = 0x0, success = 0, failure = 0, data = 0x0}, got_port_info = false, rtp_info = {addr = '\000' <repeats 45 times>, port = 0, endpoint = '\000' <repeats 511 times>,      
    call_id = 0, ptime = 0, codecs = {CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1,      
      CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1}, codecs_len = 0, ptmap = {{codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {            
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {                    
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}}, ptmap_len = 0,      
    x_osmo_ign = 0, x_osmo_osmux_use = false, x_osmo_osmux_cid = 0, conn_mode = MGCP_CONN_NONE, param_present = false, param = {amr_octet_aligned_present = false,              
      amr_octet_aligned = false}}, mgcp_ci_str = '\000' <repeats 32 times>}
(gdb) p ci
$1 = (struct osmo_mgcpc_ep_ci *) 0x555555b2d570
(gdb) p *ci
$2 = {ep = 0x555555b2d350, occupied = true, label = '\000' <repeats 63 times>, mgcp_client_fi = 0x0, pending = false, sent = false, verb = MGCP_VERB_DLCX, verb_info = {        
    addr = '\000' <repeats 45 times>, port = 0, endpoint = '\000' <repeats 511 times>, call_id = 0, ptime = 0, codecs = {CODEC_PCMU_8000_1, CODEC_PCMU_8000_1,                  
      CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1}, codecs_len = 0,  
    ptmap = {{codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {              
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {                    
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}}, ptmap_len = 0, x_osmo_ign = 0, x_osmo_osmux_use = false, x_osmo_osmux_cid = 0,                
    conn_mode = MGCP_CONN_NONE, param_present = false, param = {amr_octet_aligned_present = false, amr_octet_aligned = false}}, notify = {entry = {next = 0x0, prev = 0x0},     
    fi = 0x0, success = 0, failure = 0, data = 0x0}, got_port_info = false, rtp_info = {addr = '\000' <repeats 45 times>, port = 0, endpoint = '\000' <repeats 511 times>,      
    call_id = 0, ptime = 0, codecs = {CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1,      
      CODEC_PCMU_8000_1, CODEC_PCMU_8000_1, CODEC_PCMU_8000_1}, codecs_len = 0, ptmap = {{codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {            
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {                    
        codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}, {codec = CODEC_PCMU_8000_1, pt = 0}}, ptmap_len = 0,      
    x_osmo_ign = 0, x_osmo_osmux_use = false, x_osmo_osmux_cid = 0, conn_mode = MGCP_CONN_NONE, param_present = false, param = {amr_octet_aligned_present = false,              
      amr_octet_aligned = false}}, mgcp_ci_str = '\000' <repeats 32 times>}
(gdb) p ci->notify
$3 = {entry = {next = 0x0, prev = 0x0}, fi = 0x0, success = 0, failure = 0, data = 0x0}


Checklist

  • TTCN3 reproducer for "540 FAIL" case
  • fix crash in "540 FAIL" situations
  • implement clearing all configured E1 trunks via wildcard DLCX on osmo-bsc start
Actions #1

Updated by laforge about 1 month ago

  • Assignee set to dexter
Actions #2

Updated by dexter 30 days ago

Hello Keith,

i have checked this back. From the data I see here I can not see any obvious reason why it crashes. The ci->notify.fi is NULL, but osmo_fsm_inst_name() tolerates that. Then there are a couple of dereferences in LOG_CI_VERB and LOG_CI, but I cannot see how they could make the program crash. The ci struct is generated inside the function. We can be sure that all unpopulated members are 0x00.

Maybe it makes sense to build osmo-mgw with --enable-sanitize ?

Best regards.
Philipp

Actions #3

Updated by neels 29 days ago

  • Status changed from New to In Progress
  • Assignee changed from dexter to neels
  • % Done changed from 0 to 50

Most likely ci references an osmo_mgcpc_ep_ci that has already been deallocated.
This happens during a Clear Command from the MSC, so there might be a situation where
the ci is already deallocated but conn->assignment.created_ci_for_msc still points at where it was.

I think I also found the reason: gscon_forget_mgw_endpoint_ci() is supposed to clear all
references from conn to the ci, but it fails to clear conn->assignment.created_ci_for_msc.

This probably fixes the issue:
https://gerrit.osmocom.org/c/osmo-bsc/+/28210
but haven't run the patch through the ttcn3 BSC tests yet.

Actions #4

Updated by neels 29 days ago

  • Project changed from OsmoMGW to OsmoBSC

This is actually a bug in osmo-bsc, moving from OsmoMGW to OsmoBSC

Actions #5

Updated by keith 16 days ago

I'm still seeing this crash.

Backtrace from last night was the same:

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f49b9aa7d6d in osmo_mgcpc_ep_ci_request (ci=0x55dc7903b6d0, verb=MGCP_VERB_DLCX, verb_info=0x0, notify=0x0, event_success=0, event_failure=0, notify_data=0x0)
    at mgcp_client_endpoint_fsm.c:665
665        LOG_CI_VERB(ci, LOGL_DEBUG, "notify=%s\n", osmo_fsm_inst_name(ci->notify.fi));
(gdb) bt
#0  0x00007f49b9aa7d6d in osmo_mgcpc_ep_ci_request (ci=0x55dc7903b6d0, verb=MGCP_VERB_DLCX, verb_info=0x0, notify=0x0, event_success=0, event_failure=0, notify_data=0x0)
    at mgcp_client_endpoint_fsm.c:665
#1  0x000055dc7704d52d in osmo_mgcpc_ep_ci_dlcx (ci=0x55dc7903b6d0) at /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:42
#2  0x000055dc7704d803 in assignment_reset (conn=0x55dc78fe8ec0) at assignment_fsm.c:137
#3  0x000055dc770784ae in gscon_release_lchans (conn=0x55dc78fe8ec0, do_rr_release=true, cause_rr=GSM48_RR_CAUSE_NORMAL) at bsc_subscr_conn_fsm.c:260
#4  0x000055dc7707824f in gscon_fsm_wait_sccp_rlsd_onenter (fi=0x55dc79004680, prev_state=6) at bsc_subscr_conn_fsm.c:215
#5  0x00007f49b9b8c9d4 in state_chg (fi=0x55dc79004680, new_state=7, keep_timer=false, timeout_ms=60000, T=-4, file=0x55dc77168876 "bsc_subscr_conn_fsm.c", line=974)
    at fsm.c:694
#6  0x00007f49b9b8ca37 in _osmo_fsm_inst_state_chg (fi=0x55dc79004680, new_state=7, timeout_secs=60, T=-4, file=0x55dc77168876 "bsc_subscr_conn_fsm.c", line=974) at fsm.c:743
#7  0x00007f49b9ba7e4b in _osmo_tdef_fsm_inst_state_chg (fi=0x55dc79004680, state=7, timeouts_array=0x55dc771cd300 <conn_fsm_timeouts>, 
    tdefs=0x55dc771d81a0 <gsm_network_T_defs>, default_timeout=-1, file=0x55dc77168876 "bsc_subscr_conn_fsm.c", line=974) at tdef.c:357
#8  0x000055dc7707c784 in gscon_fsm_allstate (fi=0x55dc79004680, event=4, data=0x7ffec4a1a28c) at bsc_subscr_conn_fsm.c:974
#9  0x00007f49b9b8d33e in _osmo_fsm_inst_dispatch (fi=0x55dc79004680, event=4, data=0x7ffec4a1a28c, file=0x55dc77198c96 "osmo_bsc_bssap.c", line=438) at fsm.c:860

I don't know if it related, but since applying the above patch, I am now seeing "stuck" endpoints in the MGW - and it eventually runs out. see #5577

Actions #6

Updated by neels 15 days ago

  • Status changed from In Progress to Feedback
  • Assignee changed from neels to keith

Seems that my first guess at the failure cause was not accurate.
To resolve this, we need to know the overall situation around that crash:
ideally a pcap with OsmoBSC's gsmtap_log included, of all relevant events leading up to the crash.

If the BSC logs leading up to the crash are still available, those could also be sufficient,
"the longer the better".

The aim is to reproduce the failure with a ttcn3 test.

Actions #7

Updated by keith 5 days ago

Following the LOG_... macro rabbit hole,

LOG_CI_VERB(ci, ...)
 LOG_CI(ci, ...)
  LOG_MGCPC_EP(ci->ep, ...)
   LOGPFML(ep->fi, ...)
    LOGPFSMLSRC(fi, ...)

Then 

LOGPFSMSLSRC(fi, (fi) ? (fi)->fsm->log_subsys : DLGLOBAL, level, caller_file, caller_line, fmt, ## args)

But in the backtrace, in osmo_mgcpc_ep_ci_request() where we call the original LOG_CI_VERB

(gdb) p ci->ep->fi->fsm
$42 = (struct osmo_fsm *) 0x3536343436313032

And of course..
(gdb) p *ci->ep->fi->fsm
Cannot access memory at address 0x3536343436313032

So I guess that (fi)->fsm->log_subsys is causing the SIGSEGV?

Actions #8

Updated by keith 5 days ago

neels,
I'm looking at this particular backtrace for a occurrence of this crash:

#0  0x00007f20fef3e046 in osmo_mgcpc_ep_ci_request (ci=0x55ea60bb5b20, verb=MGCP_VERB_DLCX, verb_info=0x0, notify=0x0, event_success=0, event_failure=0, notify_data=0x0)
    at mgcp_client_endpoint_fsm.c:700
#1  0x000055ea5ee3952d in osmo_mgcpc_ep_ci_dlcx (ci=0x55ea60bb5b20) at /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:42
#2  0x000055ea5ee39803 in assignment_reset (conn=0x55ea60ba0c60) at assignment_fsm.c:137
#3  0x000055ea5ee5f702 in assignment_fsm_cleanup (fi=0x55ea60bac5b0, cause=OSMO_FSM_TERM_ERROR) at assignment_fsm.c:991
#4  0x00007f20ff02238f in _osmo_fsm_inst_term (fi=0x55ea60bac5b0, cause=OSMO_FSM_TERM_ERROR, data=0x0, file=0x55ea5ef5162e "assignment_fsm.c", line=163) at fsm.c:944
#5  0x000055ea5ee39fca in on_assignment_failure (conn=0x55ea60ba0c60) at assignment_fsm.c:163
#6  0x000055ea5ee5f6c3 in assignment_fsm_timer_cb (fi=0x55ea60bac5b0) at assignment_fsm.c:984
#7  0x00007f20ff01e3fe in fsm_tmr_cb (data=0x55ea60bac5b0) at fsm.c:320
#8  0x00007f20ff01782a in osmo_timers_update () at timer.c:269
#9  0x00007f20ff0188d6 in _osmo_select_main (polling=0) at select.c:394
#10 0x00007f20ff018997 in osmo_select_main_ctx (polling=0) at select.c:455
#11 0x000055ea5ee157f9 in main (argc=4, argv=0x7ffca9c84c38) at osmo_bsc_main.c:1043

In assignment_reset()

(gdb) p conn.assignment.fi
$121 = (struct osmo_fsm_inst *) 0x55ea60bac5b0
(gdb) p ci.ep.fi
$122 = (struct osmo_fsm_inst *) 0x55ea60bb5410

They are not the same. I'm not sure if what might be wanted there is something like

ci->ep->fi = conn->assignment.fi;

or whatever the correct dereferencing syntax would be.
If I'm not incorrect in understanding the macros, then the logging could dereference the ci->ep->fi->fsm and not crash.

I can't seem to try that out trivially due to dereferencing pointer to incomplete type ‘struct osmo_mgcpc_ep_ci’ , and whenever I start seeing that kind of thing I assume I'm probably on the wrong track.

Maybe this means something to you?

Actions #9

Updated by laforge 5 days ago

Neels is on sick leave for at least another week.

From what I can tell (obvious?):
  • we are firing a timer
  • the timer in question is the assignment_fsm in an assignment failure case
  • during cleanup we're simulating a DLCX towards the MGCP connection FSM
  • while processing that, there is no ci->mgcp_client_fi (NULL)
  • the first two crashes are in in line 665, the third crash in line 700 of mgcp_client_endpoint_fsm.c
  • it appears as if the ep->fi (endpoint fsm instance) is either NULL or pointing somewhere invalid
Misc:
  • the 'notify' part (and hence the "this was added by neels commit ...") is a dead end, as even in the line-665 crashes we see the notify=NULL argument, which a few lines later means that ci->notify.fi == NULL, and it's safe to call osmo_fsm_inst_name(NULL).

keith, the MGCP endpoing fsm instance has nothing to do with other FSM instances, so clearly you should not randomly assign one to the other :)

Actions #10

Updated by laforge 5 days ago

keith wrote in #note-8:

I can't seem to try that out trivially due to dereferencing pointer to incomplete type ‘struct osmo_mgcpc_ep_ci’ , and whenever I start seeing that kind of thing I assume I'm probably on the wrong track.

That message just means that they type information is not known to gdb, e.g. somehow libosmo-mgcp-client used has no[t all] debug symbols?

Actions #11

Updated by laforge 5 days ago

So in terms of talloc memory ownership,
  • the endpoint fsm instance (ep->fi) is allocated first
  • the 'ep' is allocated as a talloc child context to that fi' second
Furthermore, there are the following code paths to destroy an endpoint FSM:
  • osmo_mgcpc_ep_clear()
    • doesn't clear ep->fi pointer back to NULL, so somebody still holding an 'ep' reference might de-reference it but the memory might be reused already
    • called by subscr_conn_fsm:gscon_pre_term()
    • called by subscr_conn_fsm:gscon_fsm_wait_sccp_rlsd_onenter()
  • osmo_mgcpc_ep_fsm_check_state_chg_after_response()
    • calls osmo_fsm_inst_term() directly, not calling osmo_mgcpc_ep_clear() and hence not calling osmo_mgcpc_ep_cancel_notify(): separate bug?

In any case, any termination of the endpoint FSM will end up calling osmo_mgcpc_ep_fsm_pre_term which clears all the 'ci', so we would never end up in the above.

All in all, I'd say this looks almost more like memory corruption. Would be interesting to see it in an a asan-enabled build.

As neels states, the important bit would be to see the pcap + logs at the time of the crash, so we can try to create a TTCN3 test to reproduce it.

Actions #12

Updated by keith 3 days ago

Jun 25 14:08:39 huautla-bsc osmo-bsc[4529]: DAS ERROR assignment_fsm.c:984 assignment(msc0-conn29_subscr-IMSI-334020426871600-TMSI-0x2cce3b44_0-3-7-TCH_F-0)[0x61200002ae20]{WAIT_MGW_
Jun 25 14:08:39 huautla-bsc osmo-bsc[4529]: DAS ERROR assignment_fsm.c:162 assignment(msc0-conn29_subscr-IMSI-334020426871600-TMSI-0x2cce3b44_0-3-7-TCH_F-0)[0x61200002ae20]{WAIT_MGW_
Jun 25 14:08:39 huautla-bsc osmo-bsc[4529]: =================================================================
Jun 25 14:08:39 huautla-bsc osmo-bsc[4529]: ==4529==ERROR: AddressSanitizer: heap-use-after-free on address 0x62b000000480 at pc 0x7f0648264889 bp 0x7fffbb760c10 sp 0x7fffbb760c08
Jun 25 14:08:39 huautla-bsc osmo-bsc[4529]: READ of size 8 at 0x62b000000480 thread T0
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #0 0x7f0648264888 in osmo_mgcpc_ep_check_ci /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:149
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #1 0x7f064826e413 in osmo_mgcpc_ep_ci_request /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:623
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #2 0x55e57593a447 in osmo_mgcpc_ep_ci_dlcx /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:42
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #3 0x55e57593af0d in assignment_reset /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:137
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #4 0x55e5759ff3e1 in assignment_fsm_cleanup /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:991
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #5 0x7f064843438e in _osmo_fsm_inst_term /home/rhizomatica/src/libosmocore/src/fsm.c:944
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #6 0x55e57593d583 in on_assignment_failure /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:163
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #7 0x55e5759ff3a2 in assignment_fsm_timer_cb /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:984
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #8 0x7f06484303fd in fsm_tmr_cb /home/rhizomatica/src/libosmocore/src/fsm.c:320
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #9 0x7f0648429829 in osmo_timers_update /home/rhizomatica/src/libosmocore/src/timer.c:269
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #10 0x7f064842a8d5 in _osmo_select_main /home/rhizomatica/src/libosmocore/src/select.c:394
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #11 0x7f064842a996 in osmo_select_main_ctx /home/rhizomatica/src/libosmocore/src/select.c:455
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #12 0x55e575892e9a in main /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/osmo_bsc_main.c:1043
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #13 0x7f06474cf09a in __libc_start_main ../csu/libc-start.c:308
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #14 0x55e575889139 in _start (/usr/local/bin/osmo-bsc+0x92c139)
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: 0x62b000000480 is located 640 bytes inside of 26512-byte region [0x62b000000200,0x62b000006990)
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: freed by thread T0 here:
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #0 0x7f0648a06fb0 in __interceptor_free (/lib/x86_64-linux-gnu/libasan.so.5+0xe8fb0)
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #1 0x7f064840f5d2  (/lib/x86_64-linux-gnu/libtalloc.so.2+0xb5d2)
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: previously allocated by thread T0 here:
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #0 0x7f0648a07330 in __interceptor_malloc (/lib/x86_64-linux-gnu/libasan.so.5+0xe9330)
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:     #1 0x7f064840d140 in _talloc_zero (/lib/x86_64-linux-gnu/libtalloc.so.2+0x9140)
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: SUMMARY: AddressSanitizer: heap-use-after-free /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:149 in os
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: Shadow bytes around the buggy address:
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff8040: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff8050: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff8060: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff8070: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff8080: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: =>0x0c567fff8090:[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff80a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff80b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff80c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff80d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   0x0c567fff80e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: Shadow byte legend (one shadow byte represents 8 application bytes):
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Addressable:           00
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Partially addressable: 01 02 03 04 05 06 07
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Heap left redzone:       fa
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Freed heap region:       fd
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Stack left redzone:      f1
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Stack mid redzone:       f2
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Stack right redzone:     f3
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Stack after return:      f5
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Stack use after scope:   f8
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Global redzone:          f9
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Global init order:       f6
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Poisoned by user:        f7
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Container overflow:      fc
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Array cookie:            ac
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Intra object redzone:    bb
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   ASan internal:           fe
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Left alloca redzone:     ca
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]:   Right alloca redzone:    cb
Jun 25 14:08:40 huautla-bsc osmo-bsc[4529]: ==4529==ABORTING
Actions #13

Updated by laforge 3 days ago

Hi Keith,

thanks a lot. So we were right here, it is something talloc catches.

Unforunately the "freed by threads T0 here..." and "allocated by thread T0 here..." backtraces
only become useful if you use the ASAN_OPTIONS="fast_unwind_on_malloc=0" environment variable
when running the process as described in
https://osmocom.org/projects/cellular-infrastructure/wiki/Devtools#meaniungful-backtraces On Sat, Jun 25, 2022

I'm not sure if this is still required for anyone with more mgw knowledge than me to find out
what happens, but adding the enviornment on the next process restart seems like an easy thing to do,
so if you have the time...

Having the full backtrace at whcih point the first free happens should be very illustrative.

Regards,
Harald

Actions #14

Updated by keith 3 days ago

I'm able to reproduce this now, well, because currently my MGW is showing the following EP in use, however, they are not.

(I guess they never got deleted due to osmo-bsc crashing mid-transaction?)

E1 trunk 0 with 465 endpoints:
E1 trunk 0 endpoint ds/e1-0/s-9/su16-6@mgw:
   Availability: available
   CONN: (2a9/rtp, id:0xE2AA3C2C, ip:172.16.0.1, rtp:4562 rtcp:4563)

E1 trunk 0 endpoint ds/e1-0/s-12/su16-0@mgw:
   Availability: available
   CONN: (561/rtp, id:0xE5CE1778, ip:172.16.0.1, rtp:4978 rtcp:4979)

E1 trunk 0 endpoint ds/e1-0/s-12/su16-2@mgw:
   Availability: available
   CONN: (577/rtp, id:0xC4871B10, ip:172.16.0.1, rtp:4984 rtcp:4985)

E1 trunk 0 endpoint ds/e1-0/s-12/su16-4@mgw:
   Availability: available
   CONN: (521/rtp, id:0x40E1C425, ip:172.16.0.1, rtp:4944 rtcp:4945)

E1 trunk 0 endpoint ds/e1-0/s-12/su16-6@mgw:
   Availability: available
   CONN: (4a6/rtp, id:0xCF779C36, ip:172.16.0.1, rtp:4828 rtcp:4829)

As long as I do not either restart the MGW or use the vty command free-endpoint to release these, on the first attempt from osmo-bsc to use the first channel (with chan alloc descending) TRX3/TS7 (ds/e1-0/s-12/su16-6@mgw)

Jun 25 18:12:05 huautla-bsc osmo-bsc[21489]: DRSL INFO abis_rsl.c:1932 (bts=0) CHAN RQD: reason: call (re-)establishment (ra=0x4e, neci=0x01, chreq_reason=0x02)
Jun 25 18:12:05 huautla-bsc osmo-bsc[21489]: DRSL INFO abis_rsl.c:1932 (bts=0) CHAN RQD: reason: Location updating (ra=0x02, neci=0x01, chreq_reason=0x03)
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DRR DEBUG gsm_04_08_rr.c:623 -> ASSIGNMENT COMMAND tch_mode=0x01
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_pool.c:168 MGW pool is empty -- using (single) MGW mgw
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG fsm.c:456 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{UNUSED}: Allocated
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG fsm.c:486 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{UNUSED}: is child of SUBSCR_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000022ba0]
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP NOTICE mgcp_client_endpoint_fsm.c:667 Endpoint has FSM pointer: [0x7f02c145bc40]
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:715 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{UNUSED}: ds/e1-0/s-12/su16-6@mgw CI[0] to-MSC: CRCX 172.16.0.1:4232: Scheduling
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:718 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{UNUSED}: State change to WAIT_MGW_RESPONSE (X2427, 5s)
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:767 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: ds/e1-0/s-12/su16-6@mgw CI[0] to-MSC: CRCX 172.16.0.1:4232: Sending
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG fsm.c:456 MGCP_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000023920]{ST_CRCX}: Allocated
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG fsm.c:486 MGCP_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000023920]{ST_CRCX}: is child of mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:651 MGCP_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000023920]{ST_CRCX}: Received Event EV_CRCX
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:221 MGCP_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000023920]{ST_CRCX}: MGW/CRCX: creating connection on MGW endpoint:ds/e1-0/s-12/su16-6@mgw...
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client.c:1122 MGW(mgw) Queued 163 bytes for MGW
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:239 MGCP_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000023920]{ST_CRCX}: State change to ST_CRCX_RESP (T1, 4s)
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:923 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: ds/e1-0/s-12/su16-6@mgw Sent messages: 1
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client.c:748 MGW(mgw) Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=163 'CRCX 1 ds/e1-0/s-12/su16-6@mgw MGCP 1.0\r\nC'...
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client.c:685 MGW(mgw) MGCP client: Rx 540 1 FAIL
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP ERROR mgcp_client_fsm.c:281 MGCP_CONN(to-MSC)[0x612000023920]{ST_CRCX_RESP}: MGW/CRCX: response yields error: 540 FAIL
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x612000023920]{ST_CRCX_RESP}: Terminating (cause = OSMO_FSM_TERM_ERROR)
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x612000023920]{ST_CRCX_RESP}: Removing from parent mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x612000023920]{ST_CRCX_RESP}: Freeing instance
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG fsm.c:568 MGCP_CONN(to-MSC)[0x612000023920]{ST_CRCX_RESP}: Deallocated
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_fsm.c:282 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: Received Event MGW Response for CI #0
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:867 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: ds/e1-0/s-12/su16-6@mgw CI in use: 0, waiting for response: 0
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:872 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:872 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: Removing from parent SUBSCR_CONN(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x612000022ba0]
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG mgcp_client_endpoint_fsm.c:872 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: Freeing instance
Jun 25 18:12:06 huautla-bsc osmo-bsc[21489]: DLMGCP DEBUG fsm.c:568 mgw-endp(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac)[0x6120000237a0]{WAIT_MGW_RESPONSE}: Deallocated
Jun 25 18:12:07 huautla-bsc osmo-bsc[21489]: DRR DEBUG gsm_04_08_rr.c:329 Sending Channel Release: Chan: Number: 2 Type: 1 RR-Cause: 0x0 'Normal event'
Jun 25 18:12:08 huautla-bsc osmo-bsc[21489]: DCHAN ERROR lchan_fsm.c:1801 lchan(0-3-0-SDCCH8-0)[0x612000020920]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) lchan allocation failed in state WAIT_RLL_RTP_ESTABLISH: Timeout (rll_ready=no,voice_require=no,voice_ready=no)
Jun 25 18:12:08 huautla-bsc osmo-bsc[21489]: DRR DEBUG gsm_04_08_rr.c:329 Sending Channel Release: Chan: Number: 0 Type: 1 RR-Cause: 0x0 'Normal event'
Jun 25 18:12:09 huautla-bsc osmo-bsc[21489]: DRSL INFO abis_rsl.c:1932 (bts=0) CHAN RQD: reason: other (ra=0x19, neci=0x01, chreq_reason=0x04)
Jun 25 18:12:11 huautla-bsc osmo-bsc[21489]: DAS ERROR assignment_fsm.c:984 assignment(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac_0-3-7-TCH_F-0)[0x6120000234a0]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) Assignment failed in state WAIT_MGW_ENDPOINT_TO_MSC, cause EQUIPMENT FAILURE: Timeout
Jun 25 18:12:11 huautla-bsc osmo-bsc[21489]: DAS ERROR assignment_fsm.c:162 assignment(msc0-conn2_subscr-IMSI-334020152527508-TMSI-0x1dc03aac_0-3-7-TCH_F-0)[0x6120000234a0]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) Assignment failed
Jun 25 18:12:11 huautla-bsc osmo-bsc[21489]: =================================================================
Jun 25 18:12:11 huautla-bsc osmo-bsc[21489]: ==21489==ERROR: AddressSanitizer: heap-use-after-free on address 0x62b000000480 at pc 0x7f02c1397889 bp 0x7ffd03e5a1e0 sp 0x7ffd03e5a1d8
Jun 25 18:12:11 huautla-bsc osmo-bsc[21489]: READ of size 8 at 0x62b000000480 thread T0
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #0 0x7f02c1397888 in osmo_mgcpc_ep_check_ci /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:149
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #1 0x7f02c13a1413 in osmo_mgcpc_ep_ci_request /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:623
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #2 0x55b6c4d2c524 in osmo_mgcpc_ep_ci_dlcx /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:42
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #3 0x55b6c4d2cfea in assignment_reset /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:137
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #4 0x55b6c4df14be in assignment_fsm_cleanup /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:991
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #5 0x7f02c156738e in _osmo_fsm_inst_term /home/rhizomatica/src/libosmocore/src/fsm.c:944
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #6 0x55b6c4d2f660 in on_assignment_failure /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:163
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #7 0x55b6c4df147f in assignment_fsm_timer_cb /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:984
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #8 0x7f02c15633fd in fsm_tmr_cb /home/rhizomatica/src/libosmocore/src/fsm.c:320
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #9 0x7f02c155c829 in osmo_timers_update /home/rhizomatica/src/libosmocore/src/timer.c:269
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #10 0x7f02c155d8d5 in _osmo_select_main /home/rhizomatica/src/libosmocore/src/select.c:394
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #11 0x7f02c155d996 in osmo_select_main_ctx /home/rhizomatica/src/libosmocore/src/select.c:455
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #12 0x55b6c4c84f77 in main /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/osmo_bsc_main.c:1048
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #13 0x7f02c060209a in __libc_start_main ../csu/libc-start.c:308
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #14 0x55b6c4c7b139 in _start (/usr/local/bin/osmo-bsc+0x92c139)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: 0x62b000000480 is located 640 bytes inside of 26512-byte region [0x62b000000200,0x62b000006990)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: freed by thread T0 here:
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #0 0x7f02c1b39fb0 in __interceptor_free (/lib/x86_64-linux-gnu/libasan.so.5+0xe8fb0)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #1 0x7f02c15425d2  (/lib/x86_64-linux-gnu/libtalloc.so.2+0xb5d2)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #2 0x7f02c15451af in talloc_free_children (/lib/x86_64-linux-gnu/libtalloc.so.2+0xe1af)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #3 0x7f02c155d9b8 in osmo_select_main_ctx /home/rhizomatica/src/libosmocore/src/select.c:457
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #4 0x55b6c4c84f77 in main /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/osmo_bsc_main.c:1048
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #5 0x7f02c060209a in __libc_start_main ../csu/libc-start.c:308
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #6 0x55b6c4c7b139 in _start (/usr/local/bin/osmo-bsc+0x92c139)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: previously allocated by thread T0 here:
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #0 0x7f02c1b3a330 in __interceptor_malloc (/lib/x86_64-linux-gnu/libasan.so.5+0xe9330)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #1 0x7f02c1540140 in _talloc_zero (/lib/x86_64-linux-gnu/libtalloc.so.2+0x9140)
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #2 0x7f02c1398c59 in osmo_mgcpc_ep_alloc /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:309
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #3 0x55b6c4e10753 in gscon_ensure_mgw_endpoint /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/bsc_subscr_conn_fsm.c:675
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #4 0x55b6c4e14174 in gscon_connect_mgw_to_msc /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/bsc_subscr_conn_fsm.c:753
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #5 0x55b6c4dc2267 in assignment_fsm_wait_mgw_endpoint_to_msc_onenter /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:792
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #6 0x7f02c15659d3 in state_chg /home/rhizomatica/src/libosmocore/src/fsm.c:694
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #7 0x7f02c1565a36 in _osmo_fsm_inst_state_chg /home/rhizomatica/src/libosmocore/src/fsm.c:743
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #8 0x7f02c1580e4a in _osmo_tdef_fsm_inst_state_chg /home/rhizomatica/src/libosmocore/src/tdef.c:357
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #9 0x55b6c4dc0ad4 in assignment_fsm_post_lchan_established /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:774
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #10 0x55b6c4dc084e in assignment_fsm_wait_lchan_established_onenter /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:753
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #11 0x7f02c15659d3 in state_chg /home/rhizomatica/src/libosmocore/src/fsm.c:694
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #12 0x7f02c1565ad4 in _osmo_fsm_inst_state_chg_keep_timer /home/rhizomatica/src/libosmocore/src/fsm.c:774
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #13 0x7f02c1580ded in _osmo_tdef_fsm_inst_state_chg /home/rhizomatica/src/libosmocore/src/tdef.c:351
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #14 0x55b6c4db20a8 in assignment_fsm_wait_rr_ass_complete /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/assignment_fsm.c:726
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #15 0x7f02c156662c in _osmo_fsm_inst_dispatch /home/rhizomatica/src/libosmocore/src/fsm.c:872
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #16 0x55b6c4f07362 in dispatch_dtap /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/gsm_04_08_rr.c:1018
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #17 0x55b6c4f0ea68 in gsm0408_rcvmsg /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/gsm_04_08_rr.c:1098
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #18 0x55b6c4cfd15a in abis_rsl_rx_rll /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/abis_rsl.c:2531
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #19 0x55b6c4d1ecbc in abis_rsl_rcvmsg /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/abis_rsl.c:3116
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #20 0x55b6c4ee6b90 in bts_isdn_sign_link /home/rhizomatica/src/osmo-bsc/src/osmo-bsc/e1_config.c:145
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #21 0x7f02c14f4839 in e1inp_rx_ts /home/rhizomatica/src/libosmo-abis/src/e1_input.c:730
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #22 0x7f02c14f4ec7 in e1inp_dlsap_up /home/rhizomatica/src/libosmo-abis/src/e1_input.c:817
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #23 0x7f02c1506798 in send_dlsap input/lapd.c:667
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #24 0x7f02c15dcadd in send_dl_l3 /home/rhizomatica/src/libosmocore/src/gsm/lapd_core.c:404
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #25 0x7f02c15e229f in lapd_rx_i /home/rhizomatica/src/libosmocore/src/gsm/lapd_core.c:1613
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #26 0x7f02c15e2a8f in lapd_ph_data_ind /home/rhizomatica/src/libosmocore/src/gsm/lapd_core.c:1708
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #27 0x7f02c1505c55 in lapd_receive input/lapd.c:496
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #28 0x7f02c14f4b2c in e1inp_rx_ts_lapd /home/rhizomatica/src/libosmo-abis/src/e1_input.c:778
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:     #29 0x7f02c14fa97c in handle_ts_sign_read input/e1d.c:78
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: SUMMARY: AddressSanitizer: heap-use-after-free /home/rhizomatica/src/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:149 in osmo_mgcpc_ep_check_ci
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: Shadow bytes around the buggy address:
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff8040: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff8050: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff8060: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff8070: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff8080: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: =>0x0c567fff8090:[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff80a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff80b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff80c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff80d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   0x0c567fff80e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: Shadow byte legend (one shadow byte represents 8 application bytes):
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Addressable:           00
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Partially addressable: 01 02 03 04 05 06 07
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Heap left redzone:       fa
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Freed heap region:       fd
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Stack left redzone:      f1
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Stack mid redzone:       f2
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Stack right redzone:     f3
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Stack after return:      f5
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Stack use after scope:   f8
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Global redzone:          f9
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Global init order:       f6
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Poisoned by user:        f7
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Container overflow:      fc
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Array cookie:            ac
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Intra object redzone:    bb
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   ASan internal:           fe
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Left alloca redzone:     ca
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]:   Right alloca redzone:    cb
Jun 25 18:12:12 huautla-bsc osmo-bsc[21489]: ==21489==ABORTING
Jun 25 18:12:12 huautla-bsc systemd[1]: osmo-bsc-e1.service: Main process exited, code=exited, status=1/FAILURE

Actions #15

Updated by keith 3 days ago

This seems to be what your ttcn3 test would look like, no?

DLMGCP DEBUG mgcp_client.c:748 MGW(mgw) Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=163 'CRCX 1 ds/e1-0/s-12/su16-6@mgw MGCP 1.0\r\nC'...
DLMGCP DEBUG mgcp_client.c:685 MGW(mgw) MGCP client: Rx 540 1 FAIL
DLMGCP ERROR mgcp_client_fsm.c:281 MGCP_CONN(to-MSC)[0x612000026920]{ST_CRCX_RESP}: MGW/CRCX: response yields error: 540 FAIL
DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x612000026920]{ST_CRCX_RESP}: Terminating (cause = OSMO_FSM_TERM_ERROR)

Crashes every time the MGW returns 540

EDIT: of course, only crashes every time with an ASAN build, most of the time we get away with it.

Actions #16

Updated by keith 3 days ago

Just to confirm from the corefile backtrace, in case it is not totally evident from provided information:

AddressSanitizer: heap-use-after-free on address 0x62b000000480 at pc 0x7f5a6a651889 bp 0x7fff8cb99b60 sp 0x7fff8cb99b58

#6 0x00007f5a6a651889 in osmo_mgcpc_ep_check_ci (ci= 0x62b000000480 ) at mgcp_client_endpoint_fsm.c:149

I don't know what kind of pcap could help here, but if there's anything else I can provide, ask.

Actions #17

Updated by keith 2 days ago

A more complete log from RACH to crash, (with some LUR going on too) in case it helps:

Also, it's only happening with E1, maybe that gives a clue as to why we seem to be violating the hints in comments at mgcp_client_endpoint.c:260

/*! Allocate an osmo_mgcpc_ep FSM.
 * MGCP messages to set up the endpoint will be sent on the given mgcp_client, as soon as the first
 * osmo_mgcpc_ep_ci_request() is invoked.
 *
 * IMPORTANT: To avoid use-after-free problems, using this FSM requires use of deferred FSM deallocation using
 * osmo_fsm_set_dealloc_ctx(), e.g. using osmo_select_main_ctx(OTC_SELECT) with osmo_select_main_ctx() as main loop. */
DRSL INFO abis_rsl.c:1932 (bts=0) CHAN RQD: reason: call (re-)establishment (ra=0x4c, neci=0x01, chreq_reason=0x02)
DCHAN INFO lchan_select.c:320 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{UNUSED}: (type=SDCCH) Selected
DCHAN DEBUG abis_rsl.c:2226 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{UNUSED}: (type=SDCCH) MS: Channel Request: reason=CALL ra=0x4c ta=3
DCHAN DEBUG lchan_fsm.c:395 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{UNUSED}: Received Event LCHAN_EV_ACTIVATE
DCHAN DEBUG lchan_fsm.c:646 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{UNUSED}: State change to WAIT_TS_READY (X5, 5s)
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_TS_READY}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_TS_READY}: (type=SDCCH) MS Power level update (power class 0): 0 -> 3
DCHAN INFO lchan_fsm.c:755 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_TS_READY}: (type=SDCCH) Activation requested: ACTIVATE_FOR_MS_CHANNEL_REQUEST voice=no MGW-ci=none type=SDCCH tch-m
ode=SIGNALLING encr-alg=A5/0 ck=none
DTS DEBUG lchan_fsm.c:759 timeslot(0-3-0-SDCCH8)[0x612000013420]{IN_USE}: Received Event TS_EV_LCHAN_REQUESTED
DCHAN DEBUG timeslot_fsm.c:689 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_TS_READY}: Received Event LCHAN_EV_TS_READY
DCHAN DEBUG lchan_fsm.c:785 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_TS_READY}: State change to WAIT_ACTIV_ACK (X6, 5s)
DRSL DEBUG abis_rsl.c:613 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) Tx RSL Channel Activate with act_type=INITIAL
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx CHAN_ACTIV_ACK
DCHAN DEBUG abis_rsl.c:1554 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK
DCHAN INFO lchan_fsm.c:932 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx Activ ACK SIGNALLING
DCHAN DEBUG lchan_fsm.c:685 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_ACTIV_ACK}: (type=SDCCH) Tx RR Immediate Assignment
DCHAN DEBUG lchan_fsm.c:996 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_ACTIV_ACK}: State change to WAIT_RLL_RTP_ESTABLISH (T3101, 3s)
DCHAN DEBUG abis_rsl.c:2535 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) SAPI=0 ESTABLISH INDICATION
DCHAN DEBUG abis_rsl.c:2568 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND
DCHAN DEBUG lchan_fsm.c:1027 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) no voice stream required
DCHAN DEBUG lchan_fsm.c:1028 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RLL_RTP_ESTABLISH}: State change to ESTABLISHED (no timeout)
DREF INFO bsc_subscriber.c:172 subscr-TMSI-0x025ad5da: + bsc_compl_l3: now used by 1 (bsc_compl_l3)
DMSC DEBUG fsm.c:456 SUBSCR_CONN[0x612000023920]{INIT}: Allocated
DLCLS DEBUG fsm.c:456 LCLS[0x612000023aa0]{NO_LCLS}: Allocated
DLCLS DEBUG fsm.c:486 LCLS[0x612000023aa0]{NO_LCLS}: is child of SUBSCR_CONN[0x612000023920]
DREF DEBUG gsm_08_08.c:424 subscr-TMSI-0x025ad5da: + conn: now used by 2 (bsc_compl_l3,conn)
DREF DEBUG gsm_08_08.c:426 subscr-TMSI-0x025ad5da: - bsc_compl_l3: now used by 1 (conn)
DMSC DEBUG bsc_subscr_conn_fsm.c:848 SUBSCR_CONN[0x612000023920]{INIT}: setting primary lchan for this conn to lchan(0-3-0-SDCCH8-0)[0x612000018520]
DMSC DEBUG gsm_08_08.c:263 TMSI-0x025AD5DA NRI(10)=0x16b=363: No MSC found for this NRI, doing round-robin
DMSC DEBUG gsm_08_08.c:277 New subscriber TMSI-0x025AD5DA: MSC round-robin selects msc 0
DMSC INFO osmo_bsc_sigtran.c:297 Initializing resources for new SCCP connection to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP...
DRLL DEBUG gsm_data.c:979 MS Power class update: 0 -> 4
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 3 -> 5
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: (type=SDCCH) Tx MS POWER CONTROL (ms_power_lvl=5)
DMSC DEBUG gsm_08_08.c:527 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-TMSI-0x025ad5da)[0x612000023920]{INIT}: Received Event MO_COMPL_L3
DMSC DEBUG osmo_bsc_sigtran.c:340 Allocated new connection id: 5
DMSC INFO osmo_bsc_sigtran.c:344 Opening new SCCP connection (id=5) to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
DMSC DEBUG bsc_subscr_conn_fsm.c:411 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-TMSI-0x025ad5da)[0x612000023920]{INIT}: State change to WAIT_CC (X3210, 20s)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 88 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:233 N-CONNECT.cnf(5, )
DMSC DEBUG osmo_bsc_sigtran.c:236 SUBSCR_CONN(msc0-conn5_subscr-TMSI-0x025ad5da)[0x612000023920]{WAIT_CC}: Received Event MO-CONNECT.cfm
DMSC DEBUG bsc_subscr_conn_fsm.c:493 SUBSCR_CONN(msc0-conn5_subscr-TMSI-0x025ad5da)[0x612000023920]{WAIT_CC}: State change to ACTIVE (no timeout)
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(5, 00 0b 2f 08 08 39 43 30 30 00 71 27 99 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP COMMON ID
DMSC DEBUG osmo_bsc_bssap.c:1113 SUBSCR_CONN(msc0-conn5_subscr-TMSI-0x025ad5da)[0x612000023920]{ACTIVE}: Received Event COMMON_ID.ind
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(5, 01 00 0e 05 02 33 f4 70 01 12 17 05 f4 70 4a 98 90 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 00 0e 05 02 33 f4 70 01 12 17 05 f4 70 4a 98 90
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: RR/MM/CC CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{ACTIVE}: Received Event MT_DTAP
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334050154245996-TMSI-0x1b451a9a for ch. type 0 (attempt 9)
DCHAN DEBUG abis_rsl.c:2535 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) SAPI=0 ESTABLISH INDICATION
DCHAN DEBUG abis_rsl.c:2568 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND
DCHAN DEBUG lchan_fsm.c:1027 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) no voice stream required
DCHAN DEBUG lchan_fsm.c:1028 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{WAIT_RLL_RTP_ESTABLISH}: State change to ESTABLISHED (no timeout)
DREF INFO bsc_subscriber.c:172 subscr-TMSI-0xab55930e: + bsc_compl_l3: now used by 1 (bsc_compl_l3)
DMSC DEBUG fsm.c:456 SUBSCR_CONN[0x612000023da0]{INIT}: Allocated
DLCLS DEBUG fsm.c:456 LCLS[0x612000023f20]{NO_LCLS}: Allocated
DLCLS DEBUG fsm.c:486 LCLS[0x612000023f20]{NO_LCLS}: is child of SUBSCR_CONN[0x612000023da0]
DREF DEBUG gsm_08_08.c:424 subscr-TMSI-0xab55930e: + conn: now used by 2 (bsc_compl_l3,conn)
DREF DEBUG gsm_08_08.c:426 subscr-TMSI-0xab55930e: - bsc_compl_l3: now used by 1 (conn)
DMSC DEBUG bsc_subscr_conn_fsm.c:848 SUBSCR_CONN[0x612000023da0]{INIT}: setting primary lchan for this conn to lchan(0-3-0-SDCCH8-1)[0x6120000186a0]
DMSC DEBUG gsm_08_08.c:263 TMSI-0xAB55930E NRI(10)=0x156=342: No MSC found for this NRI, doing round-robin
DMSC DEBUG gsm_08_08.c:277 New subscriber TMSI-0xAB55930E: MSC round-robin selects msc 0
DMSC INFO osmo_bsc_sigtran.c:297 Initializing resources for new SCCP connection to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP...
DRLL DEBUG gsm_data.c:979 MS Power class update: 0 -> 4
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 3 -> 5
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Tx MS POWER CONTROL (ms_power_lvl=5)
DMSC DEBUG gsm_08_08.c:527 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-TMSI-0xab55930e)[0x612000023da0]{INIT}: Received Event MO_COMPL_L3
DMSC DEBUG osmo_bsc_sigtran.c:340 Allocated new connection id: 6
DMSC INFO osmo_bsc_sigtran.c:344 Opening new SCCP connection (id=6) to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
DMSC DEBUG bsc_subscr_conn_fsm.c:411 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-TMSI-0xab55930e)[0x612000023da0]{INIT}: State change to WAIT_CC (X3210, 20s)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 84 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:233 N-CONNECT.cnf(6, )
DMSC DEBUG osmo_bsc_sigtran.c:236 SUBSCR_CONN(msc0-conn6_subscr-TMSI-0xab55930e)[0x612000023da0]{WAIT_CC}: Received Event MO-CONNECT.cfm
DMSC DEBUG bsc_subscr_conn_fsm.c:493 SUBSCR_CONN(msc0-conn6_subscr-TMSI-0xab55930e)[0x612000023da0]{WAIT_CC}: State change to ACTIVE (no timeout)
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(6, 00 0b 2f 08 08 39 43 50 20 43 67 59 69 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP COMMON ID
DMSC DEBUG osmo_bsc_bssap.c:1113 SUBSCR_CONN(msc0-conn6_subscr-TMSI-0xab55930e)[0x612000023da0]{ACTIVE}: Received Event COMMON_ID.ind
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(6, 01 00 02 05 21 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 00 02 05 21
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: RR/MM/CC CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]{ACTIVE}: Received Event MT_DTAP
DRLL DEBUG chan_alloc.c:231 (bts=0) channel load average is 0.10%
DRLL DEBUG chan_alloc.c:244 (bts=0) T3122 wait indicator set to 10 seconds
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=0): meas_rep_count++=1 meas_rep_last_seen_nr=0
DLOOP INFO power_control.c:246 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=0,SDCCH) (subscr-IMSI-334030300177299-TMSI-0x025ad5da) Keeping MS power at control level 3 (37 dBm): ms-p
wr-lvl[curr 3, max 37], RSSI[curr -85, avg -85, thresh -78..-72] dBm
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=1 meas_rep_last_seen_nr=0
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=1,SDCCH) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Raising MS power control level 5 (33 dBm) => 3 (37
 dBm): ms-pwr-lvl[curr 5, max 37], RSSI[curr -93, avg -93, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 5 -> 5
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: (type=SDCCH) SAPI=0 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x00
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=5) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 80 02 05 5b )
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334020411955357-TMSI-0x52de2416 for ch. type 0 (attempt 4)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 44 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(5, 00 04 20 04 01 09 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP CLEAR COMMAND
DMSC DEBUG osmo_bsc_bssap.c:438 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{ACTIVE}: Received Event CLEAR_CMD
DMSC DEBUG bsc_subscr_conn_fsm.c:974 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{ACTIVE}: State change to WAIT_SCCP_RLSD (X4, 60s)
DMSC INFO osmo_bsc_sigtran.c:380 Tx MSC: BSSMAP: CLEAR COMPLETE
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=5) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 01 21 )
DCHAN DEBUG lchan_fsm.c:1896 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: lchan detaches from conn SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023
920]
DMSC DEBUG lchan_fsm.c:1899 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: lchan lchan(0-3-0-SDCCH8-0)[0x612000018520] detaches fro
m conn
DCHAN DEBUG lchan_fsm.c:1861 lchan(0-3-0-SDCCH8-0)[0x612000018520]{ESTABLISHED}: State change to WAIT_RLL_RTP_RELEASED (T3109, 5s)
DCHAN DEBUG lchan_fsm.c:1338 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RLL_RTP_RELEASED}: (type=SDCCH) SAPI[0] = 1
DRR DEBUG gsm_04_08_rr.c:329 Sending Channel Release: Chan: Number: 0 Type: 1 RR-Cause: 0x0 'Normal event'
DRSL DEBUG abis_rsl.c:853 (bts=0,trx=3,ts=0,ss=0) DEACTivate SACCH CMD
DCHAN DEBUG lchan_fsm.c:1368 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RLL_RTP_RELEASED}: State change to WAIT_BEFORE_RF_RELEASE (T3111, 2s)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 44 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:263 N-DISCONNECT.ind(5, , cause=768)
DMSC DEBUG osmo_bsc_sigtran.c:270 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: Received Event DISCONNET.ind
DMSC DEBUG bsc_subscr_conn_fsm.c:979 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DLCLS DEBUG bsc_subscr_conn_fsm.c:1078 LCLS[0x612000023aa0]{NO_LCLS}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DLCLS DEBUG bsc_subscr_conn_fsm.c:1078 LCLS[0x612000023aa0]{NO_LCLS}: Removing from parent SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]
DLCLS DEBUG bsc_subscr_conn_fsm.c:1078 LCLS[0x612000023aa0]{NO_LCLS}: Freeing instance
DLCLS DEBUG fsm.c:568 LCLS[0x612000023aa0]{NO_LCLS}: Deallocated
DMSC DEBUG bsc_subscr_conn_fsm.c:1078 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: FSM instance already terminating, not dispatch
ing event LCLS_FAIL
DMSC DEBUG bsc_subscr_conn_fsm.c:1082 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: Releasing all lchans (if any) because this con
n is terminating
DMSC DEBUG bsc_subscr_conn_fsm.c:1048 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: Putting bsc_subscr
DREF INFO bsc_subscr_conn_fsm.c:1049 subscr-IMSI-334030300177299-TMSI-0x025ad5da: - conn: now used by 0 (-)
DMSC DEBUG bsc_subscr_conn_fsm.c:979 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: Freeing instance
DMSC DEBUG fsm.c:568 SUBSCR_CONN(msc0-conn5_subscr-IMSI-334030300177299-TMSI-0x025ad5da)[0x612000023920]{WAIT_SCCP_RLSD}: Deallocated
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 40 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) SAPI=0 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x00
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=6) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 80 21 03 45 04 06 60 04 02 00 05 81 5e 07 81 96 16 10 34 56 f4 15 02
01 00 40 08 04 02 60 04 00 02 1f 00 )
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 76 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(6, 00 22 01 0b 07 01 0a a1 91 81 a5 05 7c 06 ac 10 00 01 1b e2 7d 09 83 ff 57 82 80 84 3f 07 81 7f 7f 31 00 80 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP ASSIGNMENT REQ
DMSC DEBUG osmo_bsc_bssap.c:734 Found matching audio type (pref=0): full rate SPEECH_V1 for channel_type = { ch_indctr=0x1, ch_rate_type=0xa, perm_spch=[ 21 11 01 25 05 ] }
DMSC DEBUG osmo_bsc_bssap.c:973 SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]{ACTIVE}: Received Event ASSIGNMENT_START
DMSC DEBUG bsc_subscr_conn_fsm.c:519 SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]{ACTIVE}: State change to ASSIGNMENT (no timeout)
DAS DEBUG fsm.c:456 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024220]{WAIT_LCHAN_ACTIVE}: Allocated
DAS DEBUG fsm.c:486 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024220]{WAIT_LCHAN_ACTIVE}: is child of SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596
-TMSI-0xab55930e)[0x612000023da0]
DAS DEBUG assignment_fsm.c:529 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024220]{WAIT_LCHAN_ACTIVE}: incrementing rate counter: assignment:attempted Ass
ignment attempts
DAS DEBUG assignment_fsm.c:529 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024220]{WAIT_LCHAN_ACTIVE}: incrementing rate counter: bts0 assignment:attempte
d_speech Assignment of speech lchan attempts
DRLL DEBUG lchan_select.c:299 (bts=0) lchan_select_by_type(TCH_F)
DRLL DEBUG lchan_select.c:233 (bts=0) lchan_avail_by_type(TCH_F)
DRLL DEBUG lchan_select.c:120 looking for lchan TCH/F: (bts=0,trx=3,ts=7,pchan=TCH/F,state=UNUSED) ss=0 interf=255=0dBm is available
DCHAN INFO lchan_select.c:320 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{UNUSED}: (type=TCH_F) Selected
DAS DEBUG assignment_fsm.c:613 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024220]{WAIT_LCHAN_ACTIVE}: (bts=0,trx=3,ts=7,ss=0) selected new lchan (bts=0,t
rx=3,ts=7,ss=0) for mode[0] = SPEECH_V1 channel_rate=2
DAS INFO assignment_fsm.c:643 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_LCHAN_ACTIVE}: (bts=0,trx=3,ts=7,ss=0) Starting Assig
nment: chan_mode=SPEECH_V1, chan_type=FR, aoip=yes MSC-rtp=172.16.0.1:7138 (osmux=no)
DAS DEBUG assignment_fsm.c:645 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_LCHAN_ACTIVE}: State change to WAIT_LCHAN_ACTIVE (T1
0, 6s)
DCHAN DEBUG lchan_fsm.c:395 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{UNUSED}: Received Event LCHAN_EV_ACTIVATE
DCHAN DEBUG lchan_fsm.c:646 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{UNUSED}: State change to WAIT_TS_READY (X5, 5s)
DCHAN DEBUG gsm_data.c:997 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_TS_READY}: (type=TCH_F) MS Power level update requested: 33 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_TS_READY}: (type=TCH_F) MS Power level update (power class 4): 0 -> 5
DCHAN INFO lchan_fsm.c:755 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_TS_READY}: (type=TCH_F) Activation requested: ACTIVATE_FOR_ASSIGNMENT voice=yes MGW-ci=new type=TCH_F tch-mode=SPEEC
H_V1 encr-alg=A5/0 ck=none
DTS DEBUG lchan_fsm.c:759 timeslot(0-3-7-TCH_F)[0x612000014920]{UNUSED}: Received Event TS_EV_LCHAN_REQUESTED
DTS DEBUG timeslot_fsm.c:380 timeslot(0-3-7-TCH_F)[0x612000014920]{UNUSED}: State change to IN_USE (no timeout)
DCHAN DEBUG timeslot_fsm.c:116 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_TS_READY}: Received Event LCHAN_EV_TS_READY
DCHAN DEBUG lchan_fsm.c:785 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_TS_READY}: State change to WAIT_ACTIV_ACK (X6, 5s)
DRSL DEBUG abis_rsl.c:613 (bts=0,trx=3,ts=7,pchan=TCH/F,state=IN_USE) Tx RSL Channel Activate with act_type=INTRA_NORM_ASS
DCHAN DEBUG fsm.c:456 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_AVAILABLE}: Allocated
DCHAN DEBUG fsm.c:486 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_AVAILABLE}: is child of lchan(0-3-7-TCH_F-0)[0x6120000225a0]
DCHAN DEBUG lchan_rtp_fsm.c:119 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_AVAILABLE}: State change to WAIT_MGW_ENDPOINT_AVAILABLE (X9, 5s)
DCHAN DEBUG lchan_rtp_fsm.c:145 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_AVAILABLE}: Audio link to-BTS via E1, skipping IPACC
DCHAN DEBUG lchan_rtp_fsm.c:146 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_AVAILABLE}: State change to WAIT_LCHAN_READY (no timeout)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_ACTIV_ACK}: (type=TCH_F) Rx CHAN_ACTIV_ACK
DCHAN DEBUG abis_rsl.c:1554 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK
DCHAN INFO lchan_fsm.c:932 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_ACTIV_ACK}: (type=TCH_F) Rx Activ ACK SPEECH_V1
DAS DEBUG lchan_fsm.c:967 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_LCHAN_ACTIVE}: Received Event ASSIGNMENT_EV_LCHAN_ACTIVE
DAS DEBUG assignment_fsm.c:684 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_LCHAN_ACTIVE}: State change to WAIT_RR_ASS_COMPLETE
(keeping T10, 5.960s remaining)
DRR DEBUG gsm_04_08_rr.c:623 -> ASSIGNMENT COMMAND tch_mode=0x01
DCHAN DEBUG lchan_fsm.c:996 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_ACTIV_ACK}: State change to WAIT_RLL_RTP_ESTABLISH (T3101, 3s)
DCHAN DEBUG lchan_fsm.c:1003 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_LCHAN_READY}: Received Event LCHAN_RTP_EV_LCHAN_READY
DCHAN DEBUG lchan_rtp_fsm.c:257 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_LCHAN_READY}: State change to WAIT_MGW_ENDPOINT_CONFIGURED (X10, 5s)
DCHAN DEBUG lchan_rtp_fsm.c:453 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_CONFIGURED}: Audio link to-BTS via E1, skipping IPACC
DCHAN DEBUG lchan_rtp_fsm.c:454 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{WAIT_MGW_ENDPOINT_CONFIGURED}: State change to READY (no timeout)
DCHAN DEBUG lchan_rtp_fsm.c:506 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_READY
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=2 meas_rep_last_seen_nr=1
DCHAN DEBUG abis_rsl.c:2585 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: Received Event LCHAN_EV_RLL_REL_IND
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334050154245996-TMSI-0x1b451a9a for ch. type 0 (attempt 10)
DCHAN DEBUG abis_rsl.c:2535 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_RLL_RTP_ESTABLISH}: (type=TCH_F) SAPI=0 ESTABLISH INDICATION
DCHAN DEBUG abis_rsl.c:2568 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND
DCHAN DEBUG lchan_fsm.c:1027 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_RLL_RTP_ESTABLISH}: (type=TCH_F) RTP already established earlier
DCHAN DEBUG lchan_fsm.c:1028 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_RLL_RTP_ESTABLISH}: State change to ESTABLISHED (no timeout)
DAS DEBUG lchan_fsm.c:229 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_RR_ASS_COMPLETE}: Received Event ASSIGNMENT_EV_LCHAN_ESTA
BLISHED
DAS DEBUG assignment_fsm.c:730 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_RR_ASS_COMPLETE}: (bts=0,trx=3,ts=7,ss=0) lchan esta
blished, still waiting for RR Assignment Complete
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) SAPI=0 DATA INDICATION
DCHAN DEBUG gsm_04_08_rr.c:981 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx ASSIGNMENT COMPLETE
DAS DEBUG gsm_04_08_rr.c:1019 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_RR_ASS_COMPLETE}: Received Event ASSIGNMENT_EV_RR_ASS
IGNMENT_COMPLETE
DAS DEBUG assignment_fsm.c:726 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_RR_ASS_COMPLETE}: State change to WAIT_LCHAN_ESTABLI
SHED (keeping T10, 5.592s remaining)
DAS DEBUG assignment_fsm.c:752 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_LCHAN_ESTABLISHED}: (bts=0,trx=3,ts=7,ss=0) lchan fu
lly established, no need to wait
DAS DEBUG assignment_fsm.c:774 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_LCHAN_ESTABLISHED}: State change to WAIT_MGW_ENDPOIN
T_TO_MSC (T23042, 5s)
DAS DEBUG assignment_fsm.c:788 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) Connec
ting MGW endpoint to the MSC's RTP port: 172.16.0.1:7138
DLMGCP DEBUG mgcp_client_pool.c:168 MGW pool is empty -- using (single) MGW mgw
DLMGCP DEBUG fsm.c:456 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{UNUSED}: Allocated
DLMGCP DEBUG fsm.c:486 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{UNUSED}: is child of SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab
55930e)[0x612000023da0]
DLMGCP NOTICE mgcp_client_endpoint_fsm.c:667 Endpoint has FSM pointer: [0x7f5b5c778c40]
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:715 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{UNUSED}: ds/e1-0/s-12/su16-6@mgw CI[0] to-MSC: CRCX 172.16.0
.1:7138: Scheduling
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:718 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{UNUSED}: State change to WAIT_MGW_RESPONSE (X2427, 5s)
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:767 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: ds/e1-0/s-12/su16-6@mgw CI[0] to-MSC: CR
CX 172.16.0.1:7138: Sending
DLMGCP DEBUG fsm.c:456 MGCP_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x6120000246a0]{ST_CRCX}: Allocated
DLMGCP DEBUG fsm.c:486 MGCP_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x6120000246a0]{ST_CRCX}: is child of mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab5
5930e)[0x612000024520]
DLMGCP DEBUG mgcp_client_fsm.c:651 MGCP_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x6120000246a0]{ST_CRCX}: Received Event EV_CRCX
DLMGCP DEBUG mgcp_client_fsm.c:221 MGCP_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x6120000246a0]{ST_CRCX}: MGW/CRCX: creating connection on MGW endpoint:ds/e1-0/s-12
/su16-6@mgw...
DLMGCP DEBUG mgcp_client.c:1122 MGW(mgw) Queued 163 bytes for MGW
DLMGCP DEBUG mgcp_client_fsm.c:239 MGCP_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x6120000246a0]{ST_CRCX}: State change to ST_CRCX_RESP (T1, 4s)
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:923 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: ds/e1-0/s-12/su16-6@mgw Sent messages: 1
DLMGCP DEBUG mgcp_client.c:748 MGW(mgw) Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=163 'CRCX 1 ds/e1-0/s-12/su16-6@mgw MGCP 1.0\r\nC'...
DLMGCP DEBUG mgcp_client.c:685 MGW(mgw) MGCP client: Rx 540 1 FAIL
DLMGCP ERROR mgcp_client_fsm.c:281 MGCP_CONN(to-MSC)[0x6120000246a0]{ST_CRCX_RESP}: MGW/CRCX: response yields error: 540 FAIL
DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x6120000246a0]{ST_CRCX_RESP}: Terminating (cause = OSMO_FSM_TERM_ERROR)
DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x6120000246a0]{ST_CRCX_RESP}: Removing from parent mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]
DLMGCP DEBUG mgcp_client_fsm.c:282 MGCP_CONN(to-MSC)[0x6120000246a0]{ST_CRCX_RESP}: Freeing instance
DLMGCP DEBUG fsm.c:568 MGCP_CONN(to-MSC)[0x6120000246a0]{ST_CRCX_RESP}: Deallocated
DLMGCP DEBUG mgcp_client_fsm.c:282 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: Received Event MGW Response for CI #0
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:867 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: ds/e1-0/s-12/su16-6@mgw CI in use: 0, wa
iting for response: 0
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:872 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: Terminating (cause = OSMO_FSM_TERM_REGUL
AR)
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:872 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: Removing from parent SUBSCR_CONN(msc0-co
nn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]
DLMGCP DEBUG mgcp_client_endpoint_fsm.c:872 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: Freeing instance
DLMGCP DEBUG fsm.c:568 mgw-endp(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000024520]{WAIT_MGW_RESPONSE}: Deallocated
DMSC DEBUG mgcp_client_endpoint_fsm.c:872 SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]{ASSIGNMENT}: Received Event FORGET_MGW_ENDPOINT
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=1 meas_rep_last_seen_nr=0
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=7,pchan=TCH/F,state=IN_USE) (ss=0,TCH_F) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Lowering MS power control level 5 (33 dBm) => 17 (9
 dBm): ms-pwr-lvl[curr 19, max 37], RSSI[curr -95, avg -95, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) MS Power level update requested: 9 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) MS Power level update (power class 4): 5 -> 17
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Tx MS POWER CONTROL (ms_power_lvl=17)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=3 meas_rep_last_seen_nr=2
DRSL INFO abis_rsl.c:1932 (bts=0) CHAN RQD: reason: Location updating (ra=0x0b, neci=0x01, chreq_reason=0x03)
DRLL DEBUG lchan_select.c:299 (bts=0) lchan_select_by_type(SDCCH)
DRLL DEBUG lchan_select.c:233 (bts=0) lchan_avail_by_type(SDCCH)
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=7,pchan=TCH/F,state=IN_USE) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=6,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=5,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=4,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=3,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=2,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=1,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:110 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=0 in type=SDCCH,state=WAIT_BEFORE_RF_RELEASE not suitable
DRLL DEBUG lchan_select.c:110 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=1 in type=SDCCH,state=ESTABLISHED not suitable
DRLL DEBUG lchan_select.c:120 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=2 interf=255=0dBm is available
DCHAN INFO lchan_select.c:320 lchan(0-3-0-SDCCH8-2)[0x612000018820]{UNUSED}: (type=SDCCH) Selected
DCHAN DEBUG abis_rsl.c:2226 lchan(0-3-0-SDCCH8-2)[0x612000018820]{UNUSED}: (type=SDCCH) MS: Channel Request: reason=LOCATION_UPDATE ra=0x0b ta=8
DCHAN DEBUG lchan_fsm.c:395 lchan(0-3-0-SDCCH8-2)[0x612000018820]{UNUSED}: Received Event LCHAN_EV_ACTIVATE
DCHAN DEBUG lchan_fsm.c:646 lchan(0-3-0-SDCCH8-2)[0x612000018820]{UNUSED}: State change to WAIT_TS_READY (X5, 5s)
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_TS_READY}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_TS_READY}: (type=SDCCH) MS Power level update (power class 0): 0 -> 3
DCHAN INFO lchan_fsm.c:755 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_TS_READY}: (type=SDCCH) Activation requested: ACTIVATE_FOR_MS_CHANNEL_REQUEST voice=no MGW-ci=none type=SDCCH tch-m
ode=SIGNALLING encr-alg=A5/0 ck=none
DTS DEBUG lchan_fsm.c:759 timeslot(0-3-0-SDCCH8)[0x612000013420]{IN_USE}: Received Event TS_EV_LCHAN_REQUESTED
DCHAN DEBUG timeslot_fsm.c:689 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_TS_READY}: Received Event LCHAN_EV_TS_READY
DCHAN DEBUG lchan_fsm.c:785 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_TS_READY}: State change to WAIT_ACTIV_ACK (X6, 5s)
DRSL DEBUG abis_rsl.c:613 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) Tx RSL Channel Activate with act_type=INITIAL
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx CHAN_ACTIV_ACK
DCHAN DEBUG abis_rsl.c:1554 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK
DCHAN INFO lchan_fsm.c:932 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx Activ ACK SIGNALLING
DCHAN DEBUG lchan_fsm.c:685 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_ACTIV_ACK}: (type=SDCCH) Tx RR Immediate Assignment
DCHAN DEBUG lchan_fsm.c:996 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_ACTIV_ACK}: State change to WAIT_RLL_RTP_ESTABLISH (T3101, 3s)
DRSL INFO abis_rsl.c:1932 (bts=0) CHAN RQD: reason: Location updating (ra=0x04, neci=0x01, chreq_reason=0x03)
DRLL DEBUG lchan_select.c:299 (bts=0) lchan_select_by_type(SDCCH)
DRLL DEBUG lchan_select.c:233 (bts=0) lchan_avail_by_type(SDCCH)
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=7,pchan=TCH/F,state=IN_USE) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=6,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=5,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=4,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=3,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=2,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:90 looking for lchan SDCCH8: (bts=0,trx=3,ts=1,pchan=TCH/F,state=UNUSED) is != SDCCH8
DRLL DEBUG lchan_select.c:110 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=0 in type=SDCCH,state=WAIT_BEFORE_RF_RELEASE not suitable
DRLL DEBUG lchan_select.c:110 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=1 in type=SDCCH,state=ESTABLISHED not suitable
DRLL DEBUG lchan_select.c:110 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=2 in type=SDCCH,state=WAIT_RLL_RTP_ESTABLISH not suitable
DRLL DEBUG lchan_select.c:120 looking for lchan SDCCH8: (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) ss=3 interf=255=0dBm is available
DCHAN INFO lchan_select.c:320 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{UNUSED}: (type=SDCCH) Selected
DCHAN DEBUG abis_rsl.c:2226 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{UNUSED}: (type=SDCCH) MS: Channel Request: reason=LOCATION_UPDATE ra=0x04 ta=1
DCHAN DEBUG lchan_fsm.c:395 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{UNUSED}: Received Event LCHAN_EV_ACTIVATE
DCHAN DEBUG lchan_fsm.c:646 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{UNUSED}: State change to WAIT_TS_READY (X5, 5s)
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_TS_READY}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_TS_READY}: (type=SDCCH) MS Power level update (power class 0): 0 -> 3
DCHAN INFO lchan_fsm.c:755 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_TS_READY}: (type=SDCCH) Activation requested: ACTIVATE_FOR_MS_CHANNEL_REQUEST voice=no MGW-ci=none type=SDCCH tch-m
ode=SIGNALLING encr-alg=A5/0 ck=none
DTS DEBUG lchan_fsm.c:759 timeslot(0-3-0-SDCCH8)[0x612000013420]{IN_USE}: Received Event TS_EV_LCHAN_REQUESTED
DCHAN DEBUG timeslot_fsm.c:689 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_TS_READY}: Received Event LCHAN_EV_TS_READY
DCHAN DEBUG lchan_fsm.c:785 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_TS_READY}: State change to WAIT_ACTIV_ACK (X6, 5s)
DRSL DEBUG abis_rsl.c:613 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) Tx RSL Channel Activate with act_type=INITIAL
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334020411955357-TMSI-0x52de2416 for ch. type 0 (attempt 5)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx CHAN_ACTIV_ACK
DCHAN DEBUG abis_rsl.c:1554 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK
DCHAN INFO lchan_fsm.c:932 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx Activ ACK SIGNALLING
DCHAN DEBUG lchan_fsm.c:685 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_ACTIV_ACK}: (type=SDCCH) Tx RR Immediate Assignment
DCHAN DEBUG lchan_fsm.c:996 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_ACTIV_ACK}: State change to WAIT_RLL_RTP_ESTABLISH (T3101, 3s)
DLGLOBAL INFO telnet_interface.c:182 Accept()ed new telnet connection r=127.0.0.1:59380<->l=127.0.0.1:4242
DLGLOBAL INFO telnet_interface.c:128 Closing telnet connection r=127.0.0.1:59380<->l=127.0.0.1:4242
DCHAN DEBUG abis_rsl.c:2535 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) SAPI=0 ESTABLISH INDICATION
DCHAN DEBUG abis_rsl.c:2568 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND
DCHAN DEBUG lchan_fsm.c:1027 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) no voice stream required
DCHAN DEBUG lchan_fsm.c:1028 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RLL_RTP_ESTABLISH}: State change to ESTABLISHED (no timeout)
DREF INFO bsc_subscriber.c:156 subscr-IMSI-334020493926012: + bsc_compl_l3: now used by 1 (bsc_compl_l3)
DMSC DEBUG fsm.c:456 SUBSCR_CONN[0x612000024820]{INIT}: Allocated
DLCLS DEBUG fsm.c:456 LCLS[0x6120000249a0]{NO_LCLS}: Allocated
DLCLS DEBUG fsm.c:486 LCLS[0x6120000249a0]{NO_LCLS}: is child of SUBSCR_CONN[0x612000024820]
DREF DEBUG gsm_08_08.c:424 subscr-IMSI-334020493926012: + conn: now used by 2 (bsc_compl_l3,conn)
DREF DEBUG gsm_08_08.c:426 subscr-IMSI-334020493926012: - bsc_compl_l3: now used by 1 (conn)
DMSC DEBUG bsc_subscr_conn_fsm.c:848 SUBSCR_CONN[0x612000024820]{INIT}: setting primary lchan for this conn to lchan(0-3-0-SDCCH8-2)[0x612000018820]
DMSC DEBUG gsm_08_08.c:277 New subscriber IMSI-334020493926012: MSC round-robin selects msc 0
DMSC INFO osmo_bsc_sigtran.c:297 Initializing resources for new SCCP connection to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP...
DRLL DEBUG gsm_data.c:979 MS Power class update: 0 -> 4
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 3 -> 5
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) Tx MS POWER CONTROL (ms_power_lvl=5)
DMSC DEBUG gsm_08_08.c:527 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-IMSI-334020493926012)[0x612000024820]{INIT}: Received Event MO_COMPL_L3
DMSC DEBUG osmo_bsc_sigtran.c:340 Allocated new connection id: 7
DMSC INFO osmo_bsc_sigtran.c:344 Opening new SCCP connection (id=7) to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
DMSC DEBUG bsc_subscr_conn_fsm.c:411 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-IMSI-334020493926012)[0x612000024820]{INIT}: State change to WAIT_CC (X3210, 20s)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 92 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:233 N-CONNECT.cnf(7, )
DMSC DEBUG osmo_bsc_sigtran.c:236 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_CC}: Received Event MO-CONNECT.cfm
DMSC DEBUG bsc_subscr_conn_fsm.c:493 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_CC}: State change to ACTIVE (no timeout)
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(7, 01 00 03 05 18 03 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 00 03 05 18 03
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: RR/MM/CC CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: Received Event MT_DTAP
DCHAN DEBUG abis_rsl.c:2535 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) SAPI=0 ESTABLISH INDICATION
DCHAN DEBUG abis_rsl.c:2568 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND
DCHAN DEBUG lchan_fsm.c:1027 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) no voice stream required
DCHAN DEBUG lchan_fsm.c:1028 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{WAIT_RLL_RTP_ESTABLISH}: State change to ESTABLISHED (no timeout)
DREF INFO bsc_subscriber.c:172 subscr-TMSI-0x20b4d476: + bsc_compl_l3: now used by 1 (bsc_compl_l3)
DMSC DEBUG fsm.c:456 SUBSCR_CONN[0x612000024ca0]{INIT}: Allocated
DLCLS DEBUG fsm.c:456 LCLS[0x612000024e20]{NO_LCLS}: Allocated
DLCLS DEBUG fsm.c:486 LCLS[0x612000024e20]{NO_LCLS}: is child of SUBSCR_CONN[0x612000024ca0]
DREF DEBUG gsm_08_08.c:424 subscr-TMSI-0x20b4d476: + conn: now used by 2 (bsc_compl_l3,conn)
DREF DEBUG gsm_08_08.c:426 subscr-TMSI-0x20b4d476: - bsc_compl_l3: now used by 1 (conn)
DMSC DEBUG bsc_subscr_conn_fsm.c:848 SUBSCR_CONN[0x612000024ca0]{INIT}: setting primary lchan for this conn to lchan(0-3-0-SDCCH8-3)[0x6120000189a0]
DMSC DEBUG gsm_08_08.c:263 TMSI-0x20B4D476 NRI(10)=0x2d3=723: No MSC found for this NRI, doing round-robin
DMSC DEBUG gsm_08_08.c:277 New subscriber TMSI-0x20B4D476: MSC round-robin selects msc 0
DMSC INFO osmo_bsc_sigtran.c:297 Initializing resources for new SCCP connection to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP...
DRLL DEBUG gsm_data.c:979 MS Power class update: 0 -> 4
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 3 -> 5
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Tx MS POWER CONTROL (ms_power_lvl=5)
DMSC DEBUG gsm_08_08.c:527 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-TMSI-0x20b4d476)[0x612000024ca0]{INIT}: Received Event MO_COMPL_L3
DMSC DEBUG osmo_bsc_sigtran.c:340 Allocated new connection id: 8
DMSC INFO osmo_bsc_sigtran.c:344 Opening new SCCP connection (id=8) to MSC 0: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
DMSC DEBUG bsc_subscr_conn_fsm.c:411 SUBSCR_CONN(msc4294967295-conn4294967295_subscr-TMSI-0x20b4d476)[0x612000024ca0]{INIT}: State change to WAIT_CC (X3210, 20s)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 88 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:233 N-CONNECT.cnf(8, )
DMSC DEBUG osmo_bsc_sigtran.c:236 SUBSCR_CONN(msc0-conn8_subscr-TMSI-0x20b4d476)[0x612000024ca0]{WAIT_CC}: Received Event MO-CONNECT.cfm
DMSC DEBUG bsc_subscr_conn_fsm.c:493 SUBSCR_CONN(msc0-conn8_subscr-TMSI-0x20b4d476)[0x612000024ca0]{WAIT_CC}: State change to ACTIVE (no timeout)
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(8, 00 0b 2f 08 08 39 43 20 10 25 91 96 84 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP COMMON ID
DMSC DEBUG osmo_bsc_bssap.c:1113 SUBSCR_CONN(msc0-conn8_subscr-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event COMMON_ID.ind
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(8, 01 00 0e 05 02 33 f4 70 01 12 17 05 f4 20 ac 55 3e )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 00 0e 05 02 33 f4 70 01 12 17 05 f4 20 ac 55 3e
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: RR/MM/CC CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MT_DTAP
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=4 meas_rep_last_seen_nr=3
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=2 meas_rep_last_seen_nr=1
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334050154245996-TMSI-0x1b451a9a for ch. type 0 (attempt 11)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=5 meas_rep_last_seen_nr=4
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=1,SDCCH) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Lowering MS power control level 5 (33 dBm) => 17 (
9 dBm): ms-pwr-lvl[curr 19, max 37], RSSI[curr -110, avg -110, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 9 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 5 -> 17
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Tx MS POWER CONTROL (ms_power_lvl=17)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=3 meas_rep_last_seen_nr=2
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=2): meas_rep_count++=1 meas_rep_last_seen_nr=0
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=2,SDCCH) (subscr-IMSI-334020493926012) Raising MS power control level 5 (33 dBm) => 3 (37 dBm): ms-pwr-lv
l[curr 5, max 37], RSSI[curr -108, avg -108, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 5 -> 5
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=1 meas_rep_last_seen_nr=0
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=3,SDCCH) (subscr-IMSI-334020152196948-TMSI-0x20b4d476) Raising MS power control level 5 (33 dBm) => 3 (37
 dBm): ms-pwr-lvl[curr 5, max 37], RSSI[curr -81, avg -81, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 5 -> 5
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) SAPI=0 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x00
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=7) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 80 0c 05 59 09 33 55 04 12 01 32 51 02 f1 )
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 56 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(7, 00 0b 2f 08 08 39 43 20 40 39 29 06 21 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP COMMON ID
DMSC DEBUG osmo_bsc_bssap.c:1113 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: Received Event COMMON_ID.ind
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(7, 01 00 0e 05 02 33 f4 70 01 12 17 05 f4 2e 5b f3 2d )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 00 0e 05 02 33 f4 70 01 12 17 05 f4 2e 5b f3 2d
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: RR/MM/CC CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: Received Event MT_DTAP
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) SAPI=0 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x00
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=8) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 80 02 05 5b )
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 44 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(8, 01 03 2c 09 01 29 01 00 07 91 44 77 58 10 06 50 00 1d 00 0b b1 96 16 10 93 04 f3 00 00 22 60 62 51 61 71 77 0b d6 30 28 0c b2 97 dd 69 39
 08 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 03 2c 09 01 29 01 00 07 91 44 77 58 10 06 50 00 1d 00 0b b1 96 16 10 93 04 f3 00 00 22 60 62 51 61 71 77 0b d6 30 28 0c b2 97 dd 69 39 0
8
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: SMS CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MT_DTAP
DRLL DEBUG abis_rsl.c:1164 (bts=0,trx=3,ts=0,ss=3) RSL RLL ESTABLISH REQ (link_id=0x03)
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(8, 01 03 2c 19 01 29 01 01 07 91 44 77 58 10 06 50 00 1d 00 0b b1 96 16 10 93 04 f3 00 00 22 60 62 51 61 71 77 0b d6 30 28 0c b2 97 dd 69 39
 08 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 03 2c 19 01 29 01 01 07 91 44 77 58 10 06 50 00 1d 00 0b b1 96 16 10 93 04 f3 00 00 22 60 62 51 61 71 77 0b d6 30 28 0c b2 97 dd 69 39 0
8
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: SMS CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MT_DTAP
DRLL DEBUG abis_rsl.c:1164 (bts=0,trx=3,ts=0,ss=3) RSL RLL ESTABLISH REQ (link_id=0x03)
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334020411955357-TMSI-0x52de2416 for ch. type 0 (attempt 6)
DCHAN DEBUG fsm.c:317 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: Timeout of T3111
DCHAN DEBUG lchan_fsm.c:1786 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_BEFORE_RF_RELEASE}: State change to WAIT_RF_RELEASE_ACK (T3111, 2s)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RF_RELEASE_ACK}: (type=SDCCH) Rx RF_CHAN_REL_ACK
DCHAN DEBUG abis_rsl.c:1574 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RF_RELEASE_ACK}: Received Event LCHAN_EV_RSL_RF_CHAN_REL_ACK
DCHAN DEBUG lchan_fsm.c:1425 lchan(0-3-0-SDCCH8-0)[0x612000018520]{WAIT_RF_RELEASE_ACK}: State change to UNUSED (no timeout)
DCHAN DEBUG lchan_fsm.c:479 lchan(0-3-0-SDCCH8-0)[0x612000018520]{UNUSED}: (type=SDCCH) Clearing lchan state
DTS DEBUG lchan_fsm.c:522 timeslot(0-3-0-SDCCH8)[0x612000013420]{IN_USE}: Received Event TS_EV_LCHAN_UNUSED
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=6 meas_rep_last_seen_nr=5
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=2): meas_rep_count++=2 meas_rep_last_seen_nr=1
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=4 meas_rep_last_seen_nr=3
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=2 meas_rep_last_seen_nr=1
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: (type=SDCCH) SAPI=0 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x00
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=7) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 80 02 05 9b )
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 44 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(7, 00 04 20 04 01 09 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC INFO osmo_bsc_bssap.c:1167 Rx MSC DT1 BSSMAP CLEAR COMMAND
DMSC DEBUG osmo_bsc_bssap.c:438 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: Received Event CLEAR_CMD
DMSC DEBUG bsc_subscr_conn_fsm.c:974 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{ACTIVE}: State change to WAIT_SCCP_RLSD (X4, 60s)
DMSC INFO osmo_bsc_sigtran.c:380 Tx MSC: BSSMAP: CLEAR COMPLETE
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=7) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 01 21 )
DCHAN DEBUG lchan_fsm.c:1896 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: lchan detaches from conn SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]
DMSC DEBUG lchan_fsm.c:1899 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: lchan lchan(0-3-0-SDCCH8-2)[0x612000018820] detaches from conn
DCHAN DEBUG lchan_fsm.c:1861 lchan(0-3-0-SDCCH8-2)[0x612000018820]{ESTABLISHED}: State change to WAIT_RLL_RTP_RELEASED (T3109, 5s)
DCHAN DEBUG lchan_fsm.c:1338 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RLL_RTP_RELEASED}: (type=SDCCH) SAPI[0] = 1
DRR DEBUG gsm_04_08_rr.c:329 Sending Channel Release: Chan: Number: 2 Type: 1 RR-Cause: 0x0 'Normal event'
DRSL DEBUG abis_rsl.c:853 (bts=0,trx=3,ts=0,ss=2) DEACTivate SACCH CMD
DCHAN DEBUG lchan_fsm.c:1368 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RLL_RTP_RELEASED}: State change to WAIT_BEFORE_RF_RELEASE (T3111, 2s)
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 44 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:263 N-DISCONNECT.ind(7, , cause=768)
DMSC DEBUG osmo_bsc_sigtran.c:270 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: Received Event DISCONNET.ind
DMSC DEBUG bsc_subscr_conn_fsm.c:979 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DLCLS DEBUG bsc_subscr_conn_fsm.c:1078 LCLS[0x6120000249a0]{NO_LCLS}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DLCLS DEBUG bsc_subscr_conn_fsm.c:1078 LCLS[0x6120000249a0]{NO_LCLS}: Removing from parent SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]
DLCLS DEBUG bsc_subscr_conn_fsm.c:1078 LCLS[0x6120000249a0]{NO_LCLS}: Freeing instance
DLCLS DEBUG fsm.c:568 LCLS[0x6120000249a0]{NO_LCLS}: Deallocated
DMSC DEBUG bsc_subscr_conn_fsm.c:1078 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: FSM instance already terminating, not dispatching event LCLS_F
AIL
DMSC DEBUG bsc_subscr_conn_fsm.c:1082 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: Releasing all lchans (if any) because this conn is terminating
DMSC DEBUG bsc_subscr_conn_fsm.c:1048 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: Putting bsc_subscr
DREF INFO bsc_subscr_conn_fsm.c:1049 subscr-IMSI-334020493926012: - conn: now used by 0 (-)
DMSC DEBUG bsc_subscr_conn_fsm.c:979 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: Freeing instance
DMSC DEBUG fsm.c:568 SUBSCR_CONN(msc0-conn7_subscr-IMSI-334020493926012)[0x612000024820]{WAIT_SCCP_RLSD}: Deallocated
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 40 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DCHAN DEBUG abis_rsl.c:2578 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) SAPI=3 ESTABLISH CONFIRM
DPAG INFO paging.c:86 (bts=0) Going to send paging commands: subscr-IMSI-334050154245996-TMSI-0x1b451a9a for ch. type 0 (attempt 12)
DCHAN DEBUG abis_rsl.c:2585 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: Received Event LCHAN_EV_RLL_REL_IND
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=7 meas_rep_last_seen_nr=6
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=5 meas_rep_last_seen_nr=4
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=7,pchan=TCH/F,state=IN_USE) (ss=0,TCH_F) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Raising MS power control level 17 (9 dBm) => 11 (21
 dBm): ms-pwr-lvl[curr 13, max 37], RSSI[curr -110, avg -110, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) MS Power level update requested: 21 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) MS Power level update (power class 4): 17 -> 11
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Tx MS POWER CONTROL (ms_power_lvl=11)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=3 meas_rep_last_seen_nr=2
DLGLOBAL INFO telnet_interface.c:182 Accept()ed new telnet connection r=127.0.0.1:59390<->l=127.0.0.1:4242
DLGLOBAL INFO telnet_interface.c:128 Closing telnet connection r=127.0.0.1:59390<->l=127.0.0.1:4242
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=8 meas_rep_last_seen_nr=7
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=4 meas_rep_last_seen_nr=3
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=6 meas_rep_last_seen_nr=5
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) SAPI=3 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x03
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=8) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 83 02 99 04 )
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 44 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DPAG INFO paging.c:283 T3113 expired for request 0x611000012660 (subscr-IMSI-334050154245996-TMSI-0x1b451a9a)
DREF INFO paging.c:72 subscr-IMSI-334050154245996-TMSI-0x1b451a9a: - paging-req: now used by 0 (-)
DCHAN DEBUG abis_rsl.c:2526 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) SAPI=3 DATA INDICATION
DMSC INFO gsm_08_08.c:548 Tx MSC DTAP LINK_ID=0x03
DMSC DEBUG gsm_08_08.c:555 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MO_DTAP
DMSC INFO osmo_bsc_sigtran.c:384 Tx MSC: DTAP
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=8) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (01 83 11 99 01 0e 04 01 01 16 41 03 00 d3 00 41 03 00 d3 f8 )
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:352 [CONNECTED] osmo_stream_cli_write(): sending 60 bytes of data
DLINP DEBUG stream.c:449 [CONNECTED] osmo_stream_cli_fd_cb(): connected write
DLINP DEBUG stream.c:445 [CONNECTED] osmo_stream_cli_fd_cb(): connected read
DLINP DEBUG stream.c:324 [CONNECTED] osmo_stream_cli_read(): message received
DMSC DEBUG osmo_bsc_sigtran.c:250 N-DATA.ind(8, 01 03 02 19 04 )
DRESET DEBUG a_reset.c:118 bssmap_reset(msc-0)[0x612000016d20]{CONN}: Received Event BSSMAP_RESET_EV_CONN_CFM_SUCCESS
DMSC DEBUG osmo_bsc_bssap.c:1241 Rx MSC DTAP: 01 03 02 19 04
DMSC INFO osmo_bsc_bssap.c:1265 Rx MSC DTAP, SAPI: SMS CHAN: 0
DMSC DEBUG osmo_bsc_bssap.c:1284 SUBSCR_CONN(msc0-conn8_subscr-IMSI-334020152196948-TMSI-0x20b4d476)[0x612000024ca0]{ACTIVE}: Received Event MT_DTAP
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=9 meas_rep_last_seen_nr=8
DLOOP INFO power_control.c:246 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=1,SDCCH) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Keeping MS power at control level 17 (5 dBm): ms-p
wr-lvl[curr 19, max 37], RSSI[curr -110, avg -110, thresh -78..-72] dBm
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=5 meas_rep_last_seen_nr=4
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=3,SDCCH) (subscr-IMSI-334020152196948-TMSI-0x20b4d476) Raising MS power control level 5 (33 dBm) => 3 (37
 dBm): ms-pwr-lvl[curr 5, max 37], RSSI[curr -79, avg -79, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) MS Power level update requested: 37 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) MS Power level update (power class 4): 5 -> 5
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=7 meas_rep_last_seen_nr=6
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=10 meas_rep_last_seen_nr=9
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) Rx MEAS_RES
DCHAN DEBUG abis_rsl.c:1391 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: (type=SDCCH) MEAS RES for inactive channel
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=6 meas_rep_last_seen_nr=5
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=8 meas_rep_last_seen_nr=7
DCHAN DEBUG fsm.c:317 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: Timeout of T3111
DCHAN DEBUG lchan_fsm.c:1786 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_BEFORE_RF_RELEASE}: State change to WAIT_RF_RELEASE_ACK (T3111, 2s)
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RF_RELEASE_ACK}: (type=SDCCH) Rx RF_CHAN_REL_ACK
DCHAN DEBUG abis_rsl.c:1574 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RF_RELEASE_ACK}: Received Event LCHAN_EV_RSL_RF_CHAN_REL_ACK
DCHAN DEBUG lchan_fsm.c:1425 lchan(0-3-0-SDCCH8-2)[0x612000018820]{WAIT_RF_RELEASE_ACK}: State change to UNUSED (no timeout)
DCHAN DEBUG lchan_fsm.c:479 lchan(0-3-0-SDCCH8-2)[0x612000018820]{UNUSED}: (type=SDCCH) Clearing lchan state
DTS DEBUG lchan_fsm.c:522 timeslot(0-3-0-SDCCH8)[0x612000013420]{IN_USE}: Received Event TS_EV_LCHAN_UNUSED
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=11 meas_rep_last_seen_nr=10
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=7 meas_rep_last_seen_nr=6
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=9 meas_rep_last_seen_nr=8
DLOOP INFO power_control.c:255 (bts=0,trx=3,ts=7,pchan=TCH/F,state=IN_USE) (ss=0,TCH_F) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Raising MS power control level 11 (21 dBm) => 9 (25
 dBm): ms-pwr-lvl[curr 11, max 37], RSSI[curr -92, avg -92, thresh -78..-72] dBm
DCHAN DEBUG gsm_data.c:997 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) MS Power level update requested: 25 dBm
DCHAN DEBUG gsm_data.c:1029 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) MS Power level update (power class 4): 11 -> 9
DCHAN DEBUG abis_rsl.c:386 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Tx MS POWER CONTROL (ms_power_lvl=9)
DLGLOBAL INFO telnet_interface.c:182 Accept()ed new telnet connection r=127.0.0.1:59398<->l=127.0.0.1:4242
DLGLOBAL INFO telnet_interface.c:128 Closing telnet connection r=127.0.0.1:59398<->l=127.0.0.1:4242
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=12 meas_rep_last_seen_nr=11
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=8 meas_rep_last_seen_nr=7
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=7,ss=0): meas_rep_count++=10 meas_rep_last_seen_nr=9
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-1)[0x6120000186a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=1): meas_rep_count++=13 meas_rep_last_seen_nr=12
DLOOP INFO power_control.c:246 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=1,SDCCH) (subscr-IMSI-334050234769596-TMSI-0xab55930e) Keeping MS power at control level 17 (5 dBm): ms-p
wr-lvl[curr 19, max 37], RSSI[curr -110, avg -110, thresh -78..-72] dBm
DCHAN DEBUG abis_rsl.c:1542 lchan(0-3-0-SDCCH8-3)[0x6120000189a0]{ESTABLISHED}: (type=SDCCH) Rx MEAS_RES
DRSL DEBUG abis_rsl.c:1463 (bts=0,trx=3,ts=0,ss=3): meas_rep_count++=9 meas_rep_last_seen_nr=8
DLOOP INFO power_control.c:246 (bts=0,trx=3,ts=0,pchan=SDCCH8,state=IN_USE) (ss=3,SDCCH) (subscr-IMSI-334020152196948-TMSI-0x20b4d476) Keeping MS power at control level 5 (33 dBm): ms-p
wr-lvl[curr 5, max 37], RSSI[curr -78, avg -78, thresh -78..-72] dBm
DAS DEBUG fsm.c:317 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: Timeout of T23042
DAS DEBUG assignment_fsm.c:983 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) increm
enting rate counter: assignment:timeout Assignment timed out
DAS DEBUG assignment_fsm.c:983 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) increm
enting rate counter: bts0 assignment:timeout_speech Assignment of speech lchan timed out
DAS ERROR assignment_fsm.c:984 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) Assign
ment failed in state WAIT_MGW_ENDPOINT_TO_MSC, cause EQUIPMENT FAILURE: Timeout
DAS DEBUG assignment_fsm.c:984 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) result
 rate counter already recorded, NOT counting as: assignment:error Assignment failed for other reason
DMSC INFO osmo_bsc_sigtran.c:380 Tx MSC: BSSMAP: ASSIGNMENT FAIL
DMSC DEBUG osmo_bsc_sigtran.c:408 Sending connection (id=6) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 04 03 04 01 20 )
DAS ERROR assignment_fsm.c:162 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=3,ts=7,ss=0) Assign
ment failed
DAS DEBUG assignment_fsm.c:163 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: Terminating (cause = OSMO_FSM_
TERM_ERROR)
DAS DEBUG assignment_fsm.c:163 assignment(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e_0-3-7-TCH_F-0)[0x612000024220]{WAIT_MGW_ENDPOINT_TO_MSC}: Removing from parent SUBSCR_CO
NN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]
DCHAN DEBUG lchan_fsm.c:1836 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{READY}: Received Event LCHAN_RTP_EV_ROLLBACK
DCHAN DEBUG lchan_rtp_fsm.c:522 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{READY}: State change to ROLLBACK (no timeout)
DCHAN DEBUG lchan_rtp_fsm.c:542 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{ROLLBACK}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
DCHAN DEBUG lchan_rtp_fsm.c:542 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{ROLLBACK}: Removing from parent lchan(0-3-7-TCH_F-0)[0x6120000225a0]
DCHAN DEBUG lchan_rtp_fsm.c:542 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{ROLLBACK}: Freeing instance
DCHAN DEBUG fsm.c:568 lchan_rtp(0-3-7-TCH_F-0)[0x6120000243a0]{ROLLBACK}: Deallocated
DCHAN DEBUG lchan_rtp_fsm.c:542 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: Received Event LCHAN_EV_RTP_RELEASED
DRSL DEBUG abis_rsl.c:853 (bts=0,trx=3,ts=7,ss=0) DEACTivate SACCH CMD
DCHAN DEBUG lchan_fsm.c:1847 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{ESTABLISHED}: State change to WAIT_RF_RELEASE_ACK (T3111, 2s)
DCHAN DEBUG lchan_fsm.c:1896 lchan(0-3-7-TCH_F-0)[0x6120000225a0]{WAIT_RF_RELEASE_ACK}: lchan detaches from conn SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x61
2000023da0]
DMSC DEBUG lchan_fsm.c:1899 SUBSCR_CONN(msc0-conn6_subscr-IMSI-334050234769596-TMSI-0xab55930e)[0x612000023da0]{ASSIGNMENT}: lchan lchan(0-3-7-TCH_F-0)[0x6120000225a0] detaches from con
n
=================================================================
==16585==ERROR: AddressSanitizer: heap-use-after-free on address 0x62b000000480 at pc 0x7f5b5c6b4889 bp 0x7ffdd0d3d290 sp 0x7ffdd0d3d288

Actions #18

Updated by laforge 2 days ago

  • Category set to RTP/Media
  • Assignee changed from keith to dexter
  • Priority changed from Normal to High

keith wrote in #note-14:

As long as I do not either restart the MGW or use the vty command free-endpoint to release these, on the first attempt from osmo-bsc to use the first channel (with chan alloc descending) TRX3/TS7 (ds/e1-0/s-12/su16-6@mgw)

Ok, thanks for nailing this down. This is clearly not how it should behave. I think we used to clear all the endpoints on BSC start. Maybe this was only implemented for the rtpbridge enpdoints, but not for the E1 endpoints? dexter, do you have more information on this?

So I think there's two bugs:
  1. osmo-bsc crashes if the mgw returns 540 FAIL
    • we should create a TTCN-3 test case
    • we should fix this bug first using the test case
  2. osmo-bsc doesn't clear E1 endpoints on bsc restart
Actions #19

Updated by laforge 2 days ago

osmo-mgw (in https://gitea.osmocom.org/cellular-infrastructure/osmo-mgw/src/commit/c9466052084750d5eb984453025c86967998dbe9/src/libosmo-mgcp/mgcp_protocol.c#L1357) seems to handle the case, at least in theory

        /* Handle wildcarded DLCX that refers to the whole trunk. This means
         * that we walk over all endpoints on the trunk in order to drop all
         * connections on the trunk. (see also RFC3435 Annex F.7) */
        if (rq->wildcarded) {
                int num_conns = 0;
                for (i = 0; i < trunk->number_endpoints; i++) {
                        num_conns += llist_count(&trunk->endpoints[i]->conns);
                        mgcp_endp_release(trunk->endpoints[i]);
                }
                rate_ctr_add(rate_ctr_group_get_ctr(rate_ctrs, MGCP_DLCX_SUCCESS), num_conns);
                return create_ok_response(trunk, NULL, 200, "DLCX", pdata->trans);
        }

So I'd expect a DLCX ds/e1-0/* should actually hit the above case.

On the client side, mgcp_client_rtpbridge_wildcard() is constructing a wild-card endpoint name, but only for rtpbridge/*, and we don't appear to be using it anywhere ecept in the CRCX situation for rtpbridge?

Actions #20

Updated by laforge 2 days ago

  • Checklist item TTCN3 reproducer for "540 FAIL" case added
  • Checklist item fix crash in "540 FAIL" situations added
  • Checklist item implement clearing all configured E1 trunks via wildcard DLCX on osmo-bsc start added
  • Status changed from Feedback to In Progress

dexter: Sending DLCX fo @rtpbridge/* might not be implemented as the mgw could be shared between multiple CA (e.g. one mgw for BSC and MSC)? In any case, what is the recovery strategy to clean up old endpoints if either BSC or MSC are restarted?

For the E1 case it is different: only the BSC ever uses it (so the BSC can authoritatively delete/clear the endpoints on restart)

In theory, aside from clearing all E1 endpoints at start, there is also the option of handling it dynamically when the situation arises: If a 540 FAIL is returned, then clear that endpoint and retry. Probably much more complex due to the impact on the client-side FSM.

Yet another theoretical alternative would be to have some kind of non-standard "CRCX --force" which would clear any pre-existing connections on the endpoint during the CRCX. I don't really like it due to its non-standard-ness. Also, it has the potential to hide / plaster over bugs.

So in summary, to me it still seems like 'clear all E1 endpoints on all the trunks configured in the BSC on startup' is the most reasonable strategy. But again, let's first avoid crashes in 540 FAIL situations, as stated.

Actions #21

Updated by neels 1 day ago

(gdb) p conn.assignment.fi
$121 = (struct osmo_fsm_inst *) 0x55ea60bac5b0
(gdb) p ci.ep.fi
$122 = (struct osmo_fsm_inst *) 0x55ea60bb5410

They are not the same. I'm not sure if what might be wanted there is something like

ci->ep->fi = conn->assignment.fi;

No, absolutely not!

"fi" means FSM instance. We have a great number of different osmo_fsm
implementations. The one is an instance of the MGW connection endpoint FSM, the
other of the BSC channel assignment FSM, completely different FSM instances.
These instances may send events to each other to orchestrate all the async
things that are happening on all those different levels.

If you grep for 'struct osmo_fsm .*=' you'll find the .c files for FSM instance
implementations. Their "handle" is always a struct osmo_fsm_inst*. Usually
there is a struct closely tied with a fi, as in

struct foo {
/* made from a definition called "struct osmo_fsm foo_fsm = {..." /
struct osmo_fsm_inst *fi;
/
fi->priv points back at its struct foo instance */

int some_state;
};

we usually cleanup and deallocate the struct foo when the fi terminates.

point being, there are many different kinds of fi.

I can't seem to try that out trivially due to dereferencing pointer to incomplete type ‘struct osmo_mgcpc_ep_ci’ , and whenever I start seeing that kind of thing I assume I'm probably on the wrong track.

This error means that some #include <osmocom/foo.h> is missing; or that it is
an opaque struct that is not meant to be accessed directly, just passed around
to API functions.

looking for the .h file that defines struct osmo_mgcpc_ep_ci, this
osmo_mgcpc_ep_ci is indeed opaque:

osmo-mgw/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:12:
struct osmo_mgcpc_ep_ci;

Only code in osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c can
access the members of that struct.

If I'm not incorrect in understanding the macros, then the logging could dereference the ci->ep->fi->fsm and not crash.

The logging originates from mgcp_client_endpoint_fsm.c,
or uses osmo_mgcpc_ep_ci_name().

hope this explains a few things...

Actions #22

Updated by keith 1 day ago

Thanks neels for taking the time. Yeah, LaF0rge already pointed out my idiocy in thinking one fi == the other fi. It was late-night attmept to quickly understand the osmo FSMs Clearly I need to study it more. Anyway, I complicated it far too much, but I think it's clear now that it's about the free'd ci.

laforge BTW, yesterday I ran osmo-bsc for a while without asan and hit this crash with six E1 EP in-use. I wanted to check some logging with the asan build so I needed the in-use EP. Afterwards, I did the vty free-endpoint in osmo-mgw, but /something/ * was still wrong. It required an osmo-mgw restart. Maybe the E1 TS is somehow not available even after doing free-endpoint in the MGw?

*Yes, sorry.. "something" is a word that should probably never appear in a bug report. I mentally tagged it to get better info, but thought it's worth mentioning.

dexter - sorry if this is useless, but it grabs my attention in thinking about "what's different with E1"

In lchan_rtp_fsm_wait_mgw_endpoint_available_onenter() we return early for a non IPACC BTS. whereas otherwise there are some calls to Endpoint related functions.

gscon_ensure_mgw_endpoint()
osmo_mgcpc_ep_ci_add()
osmo_mgcpc_ep_ci_request()

Are those calls only related to the IPACC side of the connection, or might there be something down there that stops the EP getting free'd?

Actions #23

Updated by fixeria 1 day ago

Hi keith,

I tried to write a TTCN-3 test case reproducing the segfault:

https://cgit.osmocom.org/osmo-ttcn3-hacks/commit/?h=fixeria/OS5572&id=59f292dbb3cb5f8303ef2c032e5eb32baba7666c

Unfortunately, it does not trigger the crash. I guess responding to CRCX with an error (code=540) is not enough.

Actions #24

Updated by keith 1 day ago

Thanks fixeria Did you run that test against an ASAN build?

Also, I can't read ttcn3 well enough to know if the test does it, but it needs to be an E1 trunk.

Actions #25

Updated by keith 1 day ago

In reference to my note above about "something" - that is the MGW still returning 540 after doing free-endpoint, well it's not logging anything spectacular:

20220627191114301 DLMGCP DEBUG Received message: line #00: CRCX 1 ds/e1-0/s-12/su16-6@mgw MGCP 1.0 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #01: C: b (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #02: M: sendrecv (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #03: v=0 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #04: o=- b 23 IN IP4 127.0.0.1 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #05: s=- (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #06: c=IN IP4 172.16.0.1 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #07: t=0 0 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #08: m=audio 4674 RTP/AVP 3 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG Received message: line #09: a=ptime:20 (mgcp_msg.c:68)
20220627191114301 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw (trunk:0) found endpoint: ds/e1-0/s-12/su16-6@mgw (mgcp_endp.c:302)
20220627191114301 DLMGCP DEBUG Retransmitted response: line #00: 540 1 FAIL (mgcp_msg.c:68)

Hmm. Re?? -transmitted response? Is that a typo? or maybe somehow it's maintaining some old state where it already sent a response?

Neither does osmo-e1d log any error:

20220627191114259 DXFR DEBUG (I0:L0:T10) TX Message: 30 [ 02 07 ca a8 08 21 01 40 03 00 06 04 00 03 01 00 05 06 64 40 e0 f5 72 00 04 00 0d 03 18 02 ] (mux_demux.c:84)
20220627191114259 DXFR DEBUG (I0:L0:T10) TX chunk 0/30 8 [ e4 0e 05 31 51 08 48 00 ] (mux_demux.c:102)
20220627191114259 DXFR DEBUG (I0:L0:T10) TX chunk 8/30 8 [ 31 66 9b d8 a8 55 00 00 ] (mux_demux.c:102)
20220627191114259 DXFR DEBUG (I0:L0:T10) TX chunk 16/30 8 [ 08 00 00 00 00 00 00 00 ] (mux_demux.c:102)
20220627191114259 DXFR DEBUG (I0:L0:T10) TX chunk 24/30 6 [ 70 8b 5a d9 a8 55 00 00 ] (mux_demux.c:102)
20220627191114283 DXFR DEBUG (I0:L0:T10) RX Message: 40 [ 00 07 03 08 28 01 48 1b 02 19 03 89 09 2d 04 00 0a 28 10 0b 00 12 06 15 92 12 00 46 07 e0 00 00 00 00 00 00 00 00 00 00 ] (mux_demux.c:282)
20220627191114291 DXFR DEBUG (I0:L0:T10) RX Message: 16 [ 00 07 a8 ca 03 02 01 0f 02 00 0b 00 03 06 29 00 ] (mux_demux.c:282)
20220627191114295 DXFR DEBUG (I0:L0:T10) RX Message: 11 [ 00 07 aa cc 08 22 01 40 08 b9 37 ] (mux_demux.c:282)
20220627191114303 DXFR DEBUG (I0:L0:T1) TX Message: 33 [ 02 01 94 4e 0c 16 01 90 2b 17 2d 06 3f 03 40 e0 f5 88 be 0b 02 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b ] (mux_demux.c:84)
20220627191114303 DXFR DEBUG (I0:L0:T1) TX chunk 0/33 8 [ e4 08 02 97 23 06 88 00 ] (mux_demux.c:102)
20220627191114303 DXFR DEBUG (I0:L0:T10) TX Message: 4 [ 00 07 01 aa ] (mux_demux.c:84)
20220627191114303 DXFR DEBUG (I0:L0:T10) TX chunk 0/4 4 [ e0 0e 08 05 5c ac 67 e7 ] (mux_demux.c:102)
20220627191114303 DXFR DEBUG (I0:L0:T1) TX chunk 8/33 8 [ 31 66 9b d8 a8 55 00 00 ] (mux_demux.c:102)
20220627191114303 DXFR DEBUG (I0:L0:T10) TX Message: 4 [ 00 07 01 ac ] (mux_demux.c:84)
20220627191114303 DXFR DEBUG (I0:L0:T10) TX chunk 0/4 4 [ e0 0e 08 03 5a 66 07 e7 ] (mux_demux.c:102)
20220627191114303 DXFR DEBUG (I0:L0:T1) TX chunk 16/33 8 [ 08 00 00 00 00 00 00 00 ] (mux_demux.c:102)
20220627191114303 DXFR DEBUG (I0:L0:T1) TX chunk 24/33 8 [ 70 8b 5a d9 a8 55 00 00 ] (mux_demux.c:102)
20220627191114307 DXFR DEBUG (I0:L0:T1) TX chunk 32/33 1 [ 90 3e 5b d9 a8 ] (mux_demux.c:102)
20220627191114335 DXFR DEBUG (I0:L0:T1) RX Message: 4 [ 02 01 01 96 ] (mux_demux.c:282)
20220627191114411 DXFR DEBUG (I0:L0:T10) RX Message: 15 [ 00 07 ac cc 03 02 01 0f 02 00 0b 00 02 83 41 ] (mux_demux.c:282)
20220627191114415 DXFR DEBUG (I0:L0:T10) TX Message: 4 [ 00 07 01 ae ] (mux_demux.c:84)
20220627191114415 DXFR DEBUG (I0:L0:T10) TX chunk 0/4 4 [ e0 0e 08 07 5e ea 47 e7 ] (mux_demux.c:102)


T10 would be the RSL for TRX3 (which also has SDCCH), but there's nothing logged for T12, which would be the TCH lchan.
Actions #26

Updated by keith 1 day ago

Now, if I run the non-asan,non crashing build of osmo-bsc the MGW does indeed recover after this first try for the "in-use" TS:

 20220627202354381 DLMGCP DEBUG Received message: line #00: CRCX 1 ds/e1-0/s-12/su16-6@mgw MGCP 1.0 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #01: C: 1a (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #02: M: sendrecv (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #03: v=0 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #04: o=- 1a 23 IN IP4 127.0.0.1 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #05: s=- (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #06: c=IN IP4 172.16.0.1 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #07: t=0 0 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #08: m=audio 7594 RTP/AVP 3 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG Received message: line #09: a=ptime:20 (mgcp_msg.c:68)
20220627202354381 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw (trunk:0) found endpoint: ds/e1-0/s-12/su16-6@mgw (mgcp_endp.c:302)
20220627202354381 DLMGCP DEBUG Retransmitted response: line #00: 540 1 FAIL (mgcp_msg.c:68)

[snip]

20220627202419042 DLMGCP DEBUG Received message: line #00: CRCX 2 ds/e1-0/s-12/su16-6@mgw MGCP 1.0 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #01: C: 28 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #02: M: sendrecv (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #03: v=0 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #04: o=- 28 23 IN IP4 127.0.0.1 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #05: s=- (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #06: c=IN IP4 172.16.0.1 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #07: t=0 0 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #08: m=audio 7614 RTP/AVP 3 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG Received message: line #09: a=ptime:20 (mgcp_msg.c:68)
20220627202419042 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw (trunk:0) found endpoint: ds/e1-0/s-12/su16-6@mgw (mgcp_endp.c:302)
20220627202419042 DLMGCP INFO CRCX: executing request handler "CreateConnection" for endpoint resource "ds/e1-0/s-12/su16-6@mgw" (mgcp_protocol.c:432)
20220627202419042 DLMGCP NOTICE endpoint:ds/e1-0/s-12/su16-6@mgw CRCX: creating new connection ... (mgcp_protocol.c:855)
20220627202419042 DE1 INFO trunk:0 E1 timeslot 12 already set up, skipping... (mgcp_e1.c:383)
20220627202419042 DE1 INFO endpoint:ds/e1-0/s-12/su16-6@mgw adding I.460 subchannel: ts=12, bit_offset=6, rate=16k, num_bits=320 (mgcp_e1.c:553)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw conn:(28/rtp, id:0x11B18C64, ip:(null), rtp:0 rtcp:0) (mgcp_msg.c:116)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw CI:11B18C64 connection mode 'sendrecv' 3 (mgcp_msg.c:119)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw CI:11B18C64 output_enabled 1 (mgcp_msg.c:124)
20220627202419045 DLMGCP NOTICE endpoint:ds/e1-0/s-12/su16-6@mgw CI:11B18C64 Got media info via SDP: port:7614, addr:172.16.0.1, duration:20, payload-types:3=GSM  (mgcp_sdp.c:445)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw conn:(28/rtp, id:0x11B18C64, ip:172.16.0.1, rtp:7614 rtcp:7615) codecs[0]:(pt:3=GSM, audio:GSM/8000/1 subt=GSM, rate=8000, ch=1, t=20/1000) [selected] (mgcp_codec.c:79)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw Configuring RTP endpoint: local port 7614 (mgcp_protocol.c:714)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw CI:11B18C64 CRCX: Creating connection: port: 7616 (mgcp_protocol.c:1081)
20220627202419045 DLMGCP NOTICE endpoint:ds/e1-0/s-12/su16-6@mgw CI:11B18C64 CRCX: connection successfully created (mgcp_protocol.c:1091)
20220627202419045 DLGLOBAL ERROR trau_sync(trau-sync)[0x5606bc2bb860]{WAIT_FRAME_ALIGN}: transition to state FRAME_ALIGNMENT_LOST not permitted! (trau_sync.c:518)
20220627202419045 DLMGCP DEBUG endpoint:ds/e1-0/s-12/su16-6@mgw Generated response: code=200 (mgcp_protocol.c:227)

Maybe because when osmo-bsc crashes and is gone, something does not happen in the MGW to release the endpoint?

Actions #27

Updated by fixeria about 22 hours ago

keith wrote in #note-24:

Thanks fixeria Did you run that test against an ASAN build?

Yes, both osmo-bsc and libosmomgcp were instrumented with ASAN/UBSAN.

Also, I can't read ttcn3 well enough to know if the test does it, but it needs to be an E1 trunk.

I am not sure if it's possible to test E1 specific stuff with the current ttcn3-bsc-test...

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)