Cellular Network Infrastructure » OsmoMGW

another one. somehow it looks like we get a '250' response to a CRCX while the spec permits '250' only in response to DLCX ?!?

Sat Aug  1 15:15:20 2020 DRLL fsm.c:461 MGCP_CONN(msc0-conn5_IMSI901700000025120)[0x612000008da0]{ST_CRCX}: Allocated
Sat Aug  1 15:15:20 2020 DRLL fsm.c:491 MGCP_CONN(msc0-conn5_IMSI901700000025120)[0x612000008da0]{ST_CRCX}: is child of mgw-endp(msc0-conn5_IMSI901700000025120)[0x612000008c20]
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:633 MGCP_CONN(msc0-conn5_IMSI901700000025120)[0x612000008da0]{ST_CRCX}: Received Event EV_CRCX
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:220 MGCP_CONN(msc0-conn5_IMSI901700000025120)[0x612000008da0]{ST_CRCX}: MGW/CRCX: creating connection on MGW endpoint:ds/e1-1/s-2/su16-4@mgw...
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:238 MGCP_CONN(msc0-conn5_IMSI901700000025120)[0x612000008da0]{ST_CRCX}: state_chg to ST_CRCX_RESP
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:268 MGCP_CONN(to-MSC)[0x612000008da0]{ST_CRCX_RESP}: MGW/CRCX: response yields error: 250 OK
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:269 MGCP_CONN(to-MSC)[0x612000008da0]{ST_CRCX_RESP}: Terminating (cause = OSMO_FSM_TERM_ERROR)
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:269 MGCP_CONN(to-MSC)[0x612000008da0]{ST_CRCX_RESP}: Removing from parent mgw-endp(msc0-conn5_IMSI901700000025120)[0x612000008c20]
Sat Aug  1 15:15:20 2020 DRLL mgcp_client_fsm.c:269 MGCP_CONN(to-MSC)[0x612000008da0]{ST_CRCX_RESP}: Freeing instance
Sat Aug  1 15:15:20 2020 DRLL fsm.c:573 MGCP_CONN(to-MSC)[0x612000008da0]{ST_CRCX_RESP}: Deallocated
Sat Aug  1 15:15:20 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 03 01 01 09 02 00 0b 00 02 83 01
Sat Aug  1 15:15:20 2020 DRSL abis_rsl.c:1082 (bts=0,trx=0,ts=1,ss=0): meas_rep_count++=1 meas_rep_last_seen_nr=4
Sat Aug  1 15:15:21 2020 DRSL abis_rsl.c:1082 (bts=0,trx=0,ts=0,ss=1): meas_rep_count++=1 meas_rep_last_seen_nr=4
Sat Aug  1 15:15:21 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 03 01 01 09 02 00 0b 00 08 83 07 4c 04 80 52 21 f0
Sat Aug  1 15:15:21 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 03 01 01 09 02 00 0b 00 05 83 25 02 e7 86  
Sat Aug  1 15:15:22 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 03 01 01 09 02 00 0b 00 02 83 2a
Sat Aug  1 15:15:22 2020 DRR gsm_04_08_rr.c:322 Sending Channel Release: Chan: Number: 0 Type: 2
Sat Aug  1 15:15:22 2020 DRSL abis_rsl.c:644 (bts=0,trx=0,ts=1,ss=0) DEACTivate SACCH CMD
Sat Aug  1 15:15:22 2020 DRLL mgcp_client_endpoint_fsm.c:777 MGCP_CONN(to-MSC)[0x612000008320]{ST_READY}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Sat Aug  1 15:15:22 2020 DRLL mgcp_client_endpoint_fsm.c:777 MGCP_CONN(to-MSC)[0x612000008320]{ST_READY}: Removing from parent mgw-endp(msc0-conn4)[0x6120000081a0]
Sat Aug  1 15:15:22 2020 DRLL mgcp_client_fsm.c:526 MGCP_CONN(to-MSC)[0x612000008320]{ST_READY}: MGW/DLCX: abrupt FSM termination with connections still present, sending unconditional DLCX...
Sat Aug  1 15:15:22 2020 DRLL mgcp_client_endpoint_fsm.c:777 MGCP_CONN(to-MSC)[0x612000008320]{ST_READY}: Freeing instance
Sat Aug  1 15:15:22 2020 DRLL fsm.c:573 MGCP_CONN(to-MSC)[0x612000008320]{ST_READY}: Deallocated
Sat Aug  1 15:15:22 2020 DLMGCP mgcp_client.c:673 Cannot find matching MGCP transaction for trans_id 5
Sat Aug  1 15:15:22 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 03 01 01 09 02 00 0b 00 03 06 0d 00
Sat Aug  1 15:15:22 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 08 25 01 09
Sat Aug  1 15:15:22 2020 DRSL abis_rsl.c:1082 (bts=0,trx=0,ts=2,ss=0): meas_rep_count++=1 meas_rep_last_seen_nr=4
Sat Aug  1 15:15:23 2020 DRSL abis_rsl.c:1082 (bts=0,trx=0,ts=0,ss=1): meas_rep_count++=2 meas_rep_last_seen_nr=9
Sat Aug  1 15:15:24 2020 DLMI input/dahdi.c:263 E1TS(2:1) TX: 08 2e 01 09
Sat Aug  1 15:15:25 2020 DAS assignment_fsm.c:761 assignment(msc0-conn5_IMSI901700000025120_0-0-2-TCH_F-0)[0x612000008920]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=0,ts=2,ss=0) Assignment failed in state WAIT_MGW_ENDPOINT_TO_MSC, cause EQUIPMENT FAILURE: Timeout
Sat Aug  1 15:15:25 2020 DAS assignment_fsm.c:132 assignment(msc0-conn5_IMSI901700000025120_0-0-2-TCH_F-0)[0x612000008920]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=0,ts=2,ss=0) Assignment failed
Sat Aug  1 15:15:25 2020 DRSL abis_rsl.c:644 (bts=0,trx=0,ts=2,ss=0) DEACTivate SACCH CMD
=================================================================
==2069==ERROR: AddressSanitizer: heap-use-after-free on address 0x62b00000e489 at pc 0x7f8c6c01e550 bp 0x7ffe50ff2690 sp 0x7ffe50ff1e40
READ of size 1 at 0x62b00000e489 thread T0
    #0 0x7f8c6c01e54f  (/usr/lib/x86_64-linux-gnu/libasan.so.5+0xa854f)
    #1 0x7f8c6be9b5e1 in osmo_strlcpy /root/git/libosmocore/src/utils.c:576
    #2 0x7f8c6bc6bf3d in osmo_mgcpc_ep_ci_request /root/git/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:621
    #3 0x55b6c5441457 in osmo_mgcpc_ep_ci_dlcx /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:40
    #4 0x55b6c5441457 in assignment_reset /root/git/osmo-bsc/src/osmo-bsc/assignment_fsm.c:111
    #5 0x55b6c5441605 in assignment_fsm_cleanup /root/git/osmo-bsc/src/osmo-bsc/assignment_fsm.c:768
    #6 0x7f8c6be9a518 in _osmo_fsm_inst_term /root/git/libosmocore/src/fsm.c:949
    #7 0x55b6c543e2c1 in assignment_fsm_timer_cb /root/git/osmo-bsc/src/osmo-bsc/assignment_fsm.c:761
    #8 0x7f8c6be9a9c9 in fsm_tmr_cb /root/git/libosmocore/src/fsm.c:325
    #9 0x7f8c6be94f93 in osmo_timers_update /root/git/libosmocore/src/timer.c:257

I now had a closer look at this, but unfortunately I couln't identify the cause of the problem yet. During all my experiments I did so far the bsc did never crash. I have now tried to make it crash by various experiments, terminating osmo-mgw in the middle of the call + trying to make a call without osmo-mgw. (in the first log I see that there is no connection to the MGW).

It is strange that the CRCX is responding with 250, in protocol.c I see the 250 return code only in the DLCX code path.

Is there some more information available on how this can be reproduced?

this is what happens if osmo-mgw is not running while a MO call is initiated:

<0011> assignment_fsm.c:771 assignment(msc0-conn8_0-0-1-TCH_F-0)[0x6120000105a0]{WAIT_MGW_ENDPOINT_TO_MSC}
: (bts=0,trx=0,ts=1,ss=0) Assignment failed in state WAIT_MGW_ENDPOINT_TO_MSC, cause EQUIPMENT FAILURE: Ti
meout
<0011> assignment_fsm.c:133 assignment(msc0-conn8_0-0-1-TCH_F-0)[0x6120000105a0]{WAIT_MGW_ENDPOINT_TO_MSC}: (bts=0,trx=0,ts=1,ss=0) Assignment failed
<0003> abis_rsl.c:644 (bts=0,trx=0,ts=1,ss=0) DEACTivate SACCH CMD
=================================================================
==5427==ERROR: AddressSanitizer: heap-use-after-free on address 0x62b000023489 at pc 0x7f8ae7dc2550 bp 0x7fffe6f875e0 sp 0x7fffe6f86d90
READ of size 1 at 0x62b000023489 thread T0
    #0 0x7f8ae7dc254f  (/usr/lib/x86_64-linux-gnu/libasan.so.5+0xa854f)
    #1 0x7f8ae7c3e4b1 in osmo_strlcpy /root/git/libosmocore/src/utils.c:576
    #2 0x7f8ae7b9cf3d in osmo_mgcpc_ep_ci_request /root/git/osmo-mgw/src/libosmo-mgcp-client/mgcp_client_endpoint_fsm.c:621
    #3 0x560a634918b7 in osmo_mgcpc_ep_ci_dlcx /usr/local/include/osmocom/mgcp_client/mgcp_client_endpoint_fsm.h:40
    #4 0x560a634918b7 in assignment_reset /root/git/osmo-bsc/src/osmo-bsc/assignment_fsm.c:112
    #5 0x560a63491a65 in assignment_fsm_cleanup /root/git/osmo-bsc/src/osmo-bsc/assignment_fsm.c:778
    #6 0x7f8ae7c3d3e8 in _osmo_fsm_inst_term /root/git/libosmocore/src/fsm.c:949
    #7 0x560a6348e721 in assignment_fsm_timer_cb /root/git/osmo-bsc/src/osmo-bsc/assignment_fsm.c:771
    #8 0x7f8ae7c3d899 in fsm_tmr_cb /root/git/libosmocore/src/fsm.c:325
    #9 0x7f8ae7c37f93 in osmo_timers_update /root/git/libosmocore/src/timer.c:257
    #10 0x7f8ae7c38355 in _osmo_select_main /root/git/libosmocore/src/select.c:260
    #11 0x7f8ae7c38a35 in osmo_select_main_ctx /root/git/libosmocore/src/select.c:291
    #12 0x560a633947de in main /root/git/osmo-bsc/src/osmo-bsc/osmo_bsc_main.c:952
    #13 0x7f8ae6eb009a in __libc_start_main ../csu/libc-start.c:308
    #14 0x560a633951a9 in _start (/root/git/osmo-bsc/src/osmo-bsc/osmo-bsc+0x52d1a9)

0x62b000023489 is located 649 bytes inside of 25488-byte region [0x62b000023200,0x62b000029590)
freed by thread T0 here:
    #0 0x7f8ae7e02fb0 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.5+0xe8fb0)
    #1 0x7f8ae7ce85d2  (/usr/lib/x86_64-linux-gnu/libtalloc.so.2+0xb5d2)

previously allocated by thread T0 here:
    #0 0x7f8ae7e03330 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.5+0xe9330)
    #1 0x7f8ae7ce6140 in _talloc_zero (/usr/lib/x86_64-linux-gnu/libtalloc.so.2+0x9140)

quite reproducible here.

I have re-tested this with current master, libosmo-mgcp-client and osmo-bsc compiled with asan. I mada an MO call while the mgw for the bsc is not started. Everything looks fine.

I have retested with current master, with asan enabled for libosmo-mgcp-client and osmo-bsc. Everything looks fine. Since this is not reproduceable I would argue to close this ticket.