Bug #5572
closedsegfault with osmo-BSC in osmo_mgcpc_ep_ci_request (rare)
100%
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}
Files
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
Updated by dexter almost 2 years 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
Updated by neels almost 2 years 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.
Updated by neels almost 2 years ago
- Project changed from OsmoMGW to OsmoBSC
This is actually a bug in osmo-bsc, moving from OsmoMGW to OsmoBSC
Updated by keith almost 2 years 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
Updated by neels almost 2 years 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.
Updated by keith almost 2 years 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?
Updated by keith almost 2 years 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?
Updated by laforge almost 2 years 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
- 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 :)
Updated by laforge almost 2 years 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?
Updated by laforge almost 2 years ago
- the endpoint fsm instance (ep->fi) is allocated first
- the 'ep' is allocated as a talloc child context to that fi' second
- 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.
Updated by keith almost 2 years 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
Updated by laforge almost 2 years 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
Updated by keith almost 2 years 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
Updated by keith almost 2 years 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.
Updated by keith almost 2 years 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.
Updated by keith almost 2 years 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
Updated by laforge almost 2 years 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:- 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
- osmo-bsc doesn't clear E1 endpoints on bsc restart
Updated by laforge almost 2 years 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?
Updated by laforge almost 2 years 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.
Updated by neels almost 2 years ago
(gdb) p conn.assignment.fi
$121 = (struct osmo_fsm_inst *) 0x55ea60bac5b0
(gdb) p ci.ep.fi
$122 = (struct osmo_fsm_inst *) 0x55ea60bb5410They 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...
Updated by keith almost 2 years 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?
Updated by fixeria almost 2 years ago
Hi keith,
I tried to write a TTCN-3 test case reproducing the segfault:
Unfortunately, it does not trigger the crash. I guess responding to CRCX with an error (code=540) is not enough.
Updated by keith almost 2 years 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.
Updated by keith almost 2 years 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.
Updated by keith almost 2 years 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?
Updated by fixeria almost 2 years 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...
Updated by dexter almost 2 years ago
Hello Keith,
I am currently looking into this. Unfortunately I am not very far yet. I have done some experiments with TTCN3 and the IPA based tests. When I send a 540 failure message back osmo-bsc does not crash. Maybe its a different thing for E1 trunks and cannot be compared. I have attached the trace.
Does your osmo-bsc config contain something like "mgw reset-endpoint ds/e1-0/*"? At least in theory that should work. It may be problematic since this has been used only with the rtpbridge yet - at least as far as I know.
Best regards.
Philipp
Updated by keith almost 2 years ago
dexter wrote in #note-28:
Hello Keith,
I am currently looking into this. Unfortunately I am not very far yet. I have done some experiments with TTCN3 and the IPA based tests. When I send a 540 failure message back osmo-bsc does not crash. Maybe its a different thing for E1 trunks and cannot be compared. I have attached the trace.
I'm pretty sure it is exclusively about E1 trunks. Testing for IPA trunks is futile here :)
Does your osmo-bsc config contain something like "mgw reset-endpoint ds/e1-0/*"? At least in theory that should work.
You mean to reset the MGW on start-up? Well, no I don't have that, I can add it for sure, but then we'll just wait a few hours/days/whatever until the the use-after-free, the ci member pointer is invalid and boom.
Updated by dexter almost 2 years ago
Hello Keith,
I'm pretty sure it is exclusively about E1 trunks. Testing for IPA trunks is futile here :)
Thats correct, we have to reproduce it on an E1 setup. I am currently working on getting my test setup running again.
Let me check if the wild carded DLCX even works correctly on E1 trunks first. I also agree that we probably shouldn't add it before the crash is fixed.
Best regards.
Philipp
Updated by dexter almost 2 years ago
Hello Keith,
I have now verified that wildcarded DLCX works with E1 trunks. You could add the following to your config to clear the entire E1 trunk:
mgw reset-endpoint ds/e1-1/*
Depending on your configuration this may cause problems when multiple BSCs use the same E1 trunk. I think its fine for a single BSC that uses one MGW instance alone.
If you want to be more precise you can also add individual endpoints to the config:
mgw reset-endpoint ds/e1-1/s-1/su16-0 mgw reset-endpoint ds/e1-1/s-1/su16-2 mgw reset-endpoint ds/e1-1/s-1/su16-4 mgw reset-endpoint ds/e1-1/s-1/su16-5 mgw reset-endpoint ds/e1-1/s-2/su16-0 mgw reset-endpoint ds/e1-1/s-2/su16-2 mgw reset-endpoint ds/e1-1/s-2/su16-4 mgw reset-endpoint ds/e1-1/s-2/su16-5
So, from that point we are good, next I will look at the crash.
Best regards.
Philipp
Updated by dexter almost 2 years ago
- Checklist item implement clearing all configured E1 trunks via wildcard DLCX on osmo-bsc start set to Done
Updated by laforge almost 2 years ago
dexter wrote in #note-31:
So, from that point we are good, next I will look at the crash.
any news here?
Updated by dexter almost 2 years ago
I have tried to reproduce the crash with a modified osmo-mgw that always returns 540 when a CRCX is attempted. I would expect that this should trigger the crash. However with a sysmo-bts it seems that the crash cannot be reproduced. My plan is to reproduce it with an E1 based BTS Ericsson DUG20+RUS02, unfortunately I am currently struggling with the lab test setup.
Updated by keith almost 2 years ago
dexter Do you want to define struggling? I'm happy to help, either online, or maybe in person as it happens, depending on where your lab is located.
Updated by dexter almost 2 years ago
Hello Keith,
a set of config files, including the dahdi configuration (I guess you are using dahdi E1 cards) definitely would help.
I have difficulties to get the E1 link to the DUG20 up. My best guess is that that the E1 configuration is messed up, either on the E1 driver side or maybe even in the BTS itsslef - which makes me wonder a bit since as far as I know there is only this internal E1 switch and that one is configured via osmo-bsc. I will look closer into this today.
best regards.
Philipp
Updated by dexter almost 2 years ago
- File idb_dug20_25072022.dbb idb_dug20_25072022.dbb added
- File testnet_e1_at_sysmo.tar testnet_e1_at_sysmo.tar added
Hello Keith,
I have the E1 link running so far, unfortunately voice calls are still not running but that does not seem to be an E1 problem. I am getting wired behaviour, it may be due to interference. It would still be interesting to have a look at your osmo-bsc and osmo-mgw configuration. I have attached the configuration of my setup in case you are interested.
Best regards.
Philipp
Updated by keith almost 2 years ago
dexter I can't access the actual config files I had in use at the site where I was seeing the crash. (since the DUG there died anyway, I flipped a switch in the puppet recipe that overwrote everything with IPA versions)
I do have a test setup in the lab that was reliably reproducing the crash that I also cannot access right now, so rather than send you anything erroneoous, I would rather revisit that, and be 100% of the config/versions that can reproduce the crash, unfortunately that can't happen for a couple of months. Maybe we can mark the ticket stalled if you don't make progress yourself?
One thing - In your attached configs, you are running two MGW, correct? I was sharing the one MGW between BSC/MSC
Updated by keith almost 2 years ago
Oh yeah, dexter I was just reviewing the above and I remember a key point - You MUST enable ASAN to catch it. Otherwise, while you will be accessing the free'd memory everytime, you can run for some days before this in itself provokes the SEGV.
Updated by dexter almost 2 years ago
Hello Keith,
thanks for the hint with ASAN. I can now reproduce the problem reliably. I am currently narrowing down where the CI gets freed.
best regards.
Philipp
Updated by dexter almost 2 years ago
- % Done changed from 50 to 80
Hello Keith,
I think I found what the problem was. There are multiple pointers to the same endpoint CI. When the MGCP client FSM terminates early only the CI reference we are locally using in bsc_subscr_conn_fsm.c is set to NULL. Later assignment_fsm.c tries to to generate a DLCX. For this it uses conn->assignment.created_ci_for_msc, which still holds a reference to the CI that is already gone. We must make sure that all CI pointers are set to NULL when we receive GSCON_EV_FORGET_MGW_ENDPOINT in bsc_subscr_conn_fsm.c. We can use gscon_forget_mgw_endpoint_ci() for that.
See also: https://gerrit.osmocom.org/c/osmo-bsc/+/28884 bsc_subscr_conn_fsm: fix use after free
Best regards.
Philipp
Updated by dexter almost 2 years ago
- Checklist item fix crash in "540 FAIL" situations set to Done
Hello Keith,
The patch that fixes this crash is now in master. However, I recommend not do update anything until #5634 is fixed/merged as well.
I am not sure if it makes sense to implement a TTCN3 test for this, since the bug is specific to E1 (I have tested it once more). Basically this would then be a generic testcase that basically only simulates a congested MGW situation.
Best regards.
Philipp
Updated by dexter almost 2 years ago
- Status changed from In Progress to Resolved
- % Done changed from 80 to 100
Hello Keith,
the patch that fixes the paging issues is now also merged. So in theory it is now safe to upgrade to current master. Nightly packages should be available tomorrow.
Best rgeards.
Philipp