Actions
Bug #3841
opencosmetic: tearing down the old lchan after inter-BSC handover always goes through RELEASE_AFTER_ERROR (instead of normal release)
Added by neels about 5 years ago. Updated almost 5 years ago.
Start date:
03/15/2019
Due date:
% Done:
0%
Spec Reference:
Description
After a successful outgoing inter-BSC Handover, osmo-bsc receives a Clear Command from the MSC and should gracefully release the lchan.
For some intricate ordering of things, though, this Clear Command results in the lchan release being interpreted as an error
and triggers the internal release-in-error code path.
The end result is not harmful at all, just always seeing the lchan transition through WAIT_AFTER_ERROR doesn't accurately reflect that this is what should be happening.
A log transcript follows.
Updated by neels about 5 years ago
20190315022711477 DRSL DEBUG handover(interBSCout_conn1)[0x61200000aba0]{inter-BSC-OUT:WAIT_HO_COMMAND}: state_chg to inter-BSC-OUT:WAIT_CLEAR (handover_fsm.c:1169)
^ Handover ended successfully
20190315022711837 DCHAN DEBUG lchan(0-0-2-TCH_F-0)[0x612000006820]{ESTABLISHED}: (type=TCH_F) Rx MEAS_RES (abis_rsl.c:1130)
20190315022711837 DRSL DEBUG (bts=0,trx=0,ts=2,ss=0): meas_rep_count++=41 meas_rep_last_seen_nr=40 (abis_rsl.c:1060)
20190315022711915 DMSC DEBUG N-DATA.ind(1, 00 04 20 04 01 00 ) (osmo_bsc_sigtran.c:242)
20190315022711915 DMSC DEBUG A-RESET(msc-0)[0x6120000054a0]{CONN}: Received Event EV_N_CONNECT (a_reset.c:204)
20190315022711915 DMSC INFO Rx MSC DT1 BSSMAP CLEAR COMMAND (osmo_bsc_bssap.c:966)
20190315022711915 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{HANDOVER}: Received Event CLEAR_CMD (osmo_bsc_bssap.c:437)
20190315022711915 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{HANDOVER}: state_chg to CLEARING (bsc_subscr_conn_fsm.c:728)
^ Rx Clear Command from MSC as expected
20190315022711915 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Releasing all lchans (if any) after BSSMAP Clear Command (bsc_subscr_conn_fsm.c:729)
20190315022711915 DCHAN DEBUG lchan_rtp(0-0-3-TCH_F-0)[0x612000009fa0]{ESTABLISHED}: Received Event LCHAN_RTP_EV_ROLLBACK (lchan_fsm.c:1334)
20190315022711915 DCHAN DEBUG lchan_rtp(0-0-3-TCH_F-0)[0x612000009fa0]{ESTABLISHED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (lchan_rtp_fsm.c:574)
20190315022711915 DCHAN DEBUG lchan_rtp(0-0-3-TCH_F-0)[0x612000009fa0]{ESTABLISHED}: Removing from parent lchan(0-0-3-TCH_F-0)[0x6120000069a0] (lchan_rtp_fsm.c:574)
20190315022711915 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: (rtpbridge/2@bsc) CI[0] to-BTS CI=13622AA2: DLCX :0: notify=NULL (mgw_endpoint_fsm.c:441)
20190315022711915 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: (rtpbridge/2@bsc) CI[0] to-BTS CI=13622AA2: DLCX :0: Scheduling (mgw_endpoint_fsm.c:482)
20190315022711915 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: state_chg to WAIT_MGW_RESPONSE (mgw_endpoint_fsm.c:485)
20190315022711915 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{WAIT_MGW_RESPONSE}: (rtpbridge/2@bsc) CI[0] to-BTS CI=13622AA2: Sending MGCP: DLCX 13622AA2 (mgw_endpoint_fsm.c:530)
20190315022711915 DRLL DEBUG MGCP_CONN(to-BTS)[0x61200000a2a0]{ST_READY}: Received Event EV_DLCX (mgcp_client_fsm.c:697)
20190315022711915 DLMGCP DEBUG Queued 53 bytes for MGCP GW (mgcp_client.c:908)
20190315022711915 DRLL DEBUG MGCP_CONN(to-BTS)[0x61200000a2a0]{ST_READY}: state_chg to ST_DLCX_RESP (mgcp_client_fsm.c:358)
20190315022711915 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{WAIT_MGW_RESPONSE}: (rtpbridge/2@bsc) Sent messages: 1 (mgw_endpoint_fsm.c:625)
20190315022711916 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{WAIT_MGW_RESPONSE}: (rtpbridge/2@bsc) CI[1] to-MSC CI=9D6A768B: CRCX 192.168.2.4:50004: rtpbridge/2@bsc:192.168.2.3:50022 (mgw_endpoint_fsm.c:580)
20190315022711916 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{WAIT_MGW_RESPONSE}: (rtpbridge/2@bsc) CI in use: 1, waiting for response: 0 (mgw_endpoint_fsm.c:598)
20190315022711916 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{WAIT_MGW_RESPONSE}: state_chg to IN_USE (mgw_endpoint_fsm.c:609)
20190315022711916 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: (rtpbridge/2@bsc) CI[1] to-MSC CI=9D6A768B: CRCX 192.168.2.4:50004: rtpbridge/2@bsc:192.168.2.3:50022 (mgw_endpoint_fsm.c:580)
20190315022711916 DCHAN DEBUG lchan_rtp(0-0-3-TCH_F-0)[0x612000009fa0]{ESTABLISHED}: Freeing instance (lchan_rtp_fsm.c:574)
20190315022711916 DCHAN DEBUG lchan_rtp(0-0-3-TCH_F-0)[0x612000009fa0]{ESTABLISHED}: Deallocated (fsm.c:402)
20190315022711916 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{ESTABLISHED}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:574)
20190315022711916 DRR DEBUG Sending Channel Release: Chan: Number: 0 Type: 2 (gsm_04_08_rr.c:320)
20190315022711916 DRSL DEBUG (bts=0,trx=0,ts=3,ss=0) DEACTivate SACCH CMD (abis_rsl.c:633)
20190315022711916 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{ESTABLISHED}: state_chg to WAIT_RF_RELEASE_ACK (lchan_fsm.c:1345)
20190315022711916 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: conn detaches lchan lchan(0-0-3-TCH_F-0)[0x6120000069a0] (bsc_subscr_conn_fsm.c:684)
20190315022711916 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: conn SUBSCR_CONN(conn1)[0x612000009b20] detaches lchan (primary lchan) (bsc_subscr_conn_fsm.c:688)
20190315022711916 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: lchan detaches from conn SUBSCR_CONN(conn1)[0x612000009b20] (lchan_fsm.c:1390)
20190315022711916 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: lchan lchan(0-0-3-TCH_F-0)[0x6120000069a0] detaches from conn (lchan_fsm.c:1393)
20190315022711916 DRSL DEBUG handover(interBSCout_conn1)[0x61200000aba0]{inter-BSC-OUT:WAIT_CLEAR}: (0-0-0-?-0-?) --HO-> (BTS 0 to ARFCN 870 BSIC 1) (subscr unknown) HO-interBSC-Out: incrementing rate counter: interbsc_ho_out:stopped Connection ended during HO. (handover_fsm.c:842)
20190315022711916 DRSL INFO handover(interBSCout_conn1)[0x61200000aba0]{inter-BSC-OUT:WAIT_CLEAR}: (0-0-0-?-0-?) --HO-> (BTS 0 to ARFCN 870 BSIC 1) (subscr unknown) HO-interBSC-Out: Result: Connection released (handover_fsm.c:844)
20190315022711916 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Received Event HANDOVER_END (handover_fsm.c:851)
20190315022711916 DMSC ERROR SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Event HANDOVER_END not permitted (handover_fsm.c:851)
^ (error doesn't matter)
20190315022711916 DRSL DEBUG handover(interBSCout_conn1)[0x61200000aba0]{inter-BSC-OUT:WAIT_CLEAR}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (handover_fsm.c:873)
20190315022711917 DRSL DEBUG handover(interBSCout_conn1)[0x61200000aba0]{inter-BSC-OUT:WAIT_CLEAR}: Freeing instance (handover_fsm.c:873)
20190315022711917 DRSL DEBUG handover(interBSCout_conn1)[0x61200000aba0]{inter-BSC-OUT:WAIT_CLEAR}: Deallocated (fsm.c:402)
20190315022711917 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (mgw_endpoint_fsm.c:551)
20190315022711917 DRLL DEBUG MGCP_CONN(to-MSC)[0x61200000a720]{ST_READY}: Terminating (cause = OSMO_FSM_TERM_PARENT) (mgw_endpoint_fsm.c:551)
20190315022711917 DRLL DEBUG MGCP_CONN(to-MSC)[0x61200000a720]{ST_READY}: Removing from parent mgw-endpoint(conn1)[0x61200000a120] (mgw_endpoint_fsm.c:551)
20190315022711917 DRLL ERROR MGCP_CONN(to-MSC)[0x61200000a720]{ST_READY}: MGW/DLCX: abrupt FSM termination with connections still present, sending unconditional DLCX... (mgcp_client_fsm.c:501)
20190315022711917 DLMGCP DEBUG Queued 53 bytes for MGCP GW (mgcp_client.c:908)
20190315022711917 DRLL DEBUG MGCP_CONN(to-MSC)[0x61200000a720]{ST_READY}: Freeing instance (mgw_endpoint_fsm.c:551)
20190315022711917 DRLL DEBUG MGCP_CONN(to-MSC)[0x61200000a720]{ST_READY}: Deallocated (fsm.c:402)
20190315022711917 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: Removing from parent SUBSCR_CONN(conn1)[0x612000009b20] (mgw_endpoint_fsm.c:551)
20190315022711917 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: Freeing instance (mgw_endpoint_fsm.c:551)
20190315022711917 DRSL DEBUG mgw-endpoint(conn1)[0x61200000a120]{IN_USE}: Deallocated (fsm.c:402)
20190315022711917 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Received Event FORGET_MGW_ENDPOINT (mgw_endpoint_fsm.c:551)
20190315022711917 DMSC INFO Tx MSC: BSSMAP: CLEAR COMPLETE (osmo_bsc_sigtran.c:370)
20190315022711917 DMSC DEBUG Sending connection (id=1) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 01 21 ) (osmo_bsc_sigtran.c:393)
20190315022711917 DLMGCP DEBUG Tx MGCP: r=192.168.2.3:2427<->l=192.168.2.3:2728: len=53 'DLCX 12 rtpbridge/2@bsc MGCP 1.0\r\nC: 1\r\nI:'... (mgcp_client.c:676)
20190315022711917 DLMGCP DEBUG Tx MGCP: r=192.168.2.3:2427<->l=192.168.2.3:2728: len=53 'DLCX 13 rtpbridge/2@bsc MGCP 1.0\r\nC: 1\r\nI:'... (mgcp_client.c:676)
20190315022711918 DRLL DEBUG MGCP_CONN(to-BTS)[0x61200000a2a0]{ST_DLCX_RESP}: Received Event EV_DLCX_RESP (mgcp_client_fsm.c:434)
20190315022711918 DRLL DEBUG MGCP_CONN(to-BTS)[0x61200000a2a0]{ST_DLCX_RESP}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (mgcp_client_fsm.c:450)
20190315022711918 DRLL DEBUG MGCP_CONN(to-BTS)[0x61200000a2a0]{ST_DLCX_RESP}: Freeing instance (mgcp_client_fsm.c:450)
20190315022711918 DRLL DEBUG MGCP_CONN(to-BTS)[0x61200000a2a0]{ST_DLCX_RESP}: Deallocated (fsm.c:402)
20190315022711919 DLMGCP DEBUG MGCP response ignored (NULL cb) (mgcp_client.c:208)
20190315022711919 DMSC DEBUG N-DISCONNECT.ind(1, , cause=768) (osmo_bsc_sigtran.c:255)
20190315022711919 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Received Event DISCONNET.ind (osmo_bsc_sigtran.c:262)
20190315022711919 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (bsc_subscr_conn_fsm.c:744)
20190315022711919 DLCLS DEBUG LCLS[0x612000009ca0]{NO_LCLS}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (bsc_subscr_conn_fsm.c:801)
20190315022711919 DLCLS DEBUG LCLS[0x612000009ca0]{NO_LCLS}: Removing from parent SUBSCR_CONN(conn1)[0x612000009b20] (bsc_subscr_conn_fsm.c:801)
20190315022711919 DLCLS DEBUG LCLS[0x612000009ca0]{NO_LCLS}: Freeing instance (bsc_subscr_conn_fsm.c:801)
20190315022711919 DLCLS DEBUG LCLS[0x612000009ca0]{NO_LCLS}: Deallocated (fsm.c:402)
20190315022711919 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Received Event LCLS_FAIL (bsc_subscr_conn_fsm.c:801)
20190315022711919 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Releasing all lchans (if any) because this conn is terminating (bsc_subscr_conn_fsm.c:805)
20190315022711919 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Freeing instance (bsc_subscr_conn_fsm.c:744)
20190315022711919 DMSC DEBUG SUBSCR_CONN(conn1)[0x612000009b20]{CLEARING}: Deallocated (fsm.c:402)
20190315022711921 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: (type=TCH_F) Rx IPAC_DLCX_IND (abis_rsl.c:2011)
20190315022711921 DCHAN NOTICE lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: (type=TCH_F) Rx IPACC DLCX IND (abis_rsl.c:1985)
20190315022711926 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: (type=TCH_F) Rx RF_CHAN_REL_ACK (abis_rsl.c:1130)
20190315022711926 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: Received Event LCHAN_EV_RSL_RF_CHAN_REL_ACK (abis_rsl.c:1162)
20190315022711926 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_RF_RELEASE_ACK}: state_chg to WAIT_AFTER_ERROR (lchan_fsm.c:1039)
^ this transition to WAIT_AFTER_ERROR makes no sense, this should have been a normal release.
20190315022715927 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_AFTER_ERROR}: Timeout of T993111 (fsm.c:210)
20190315022715927 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{WAIT_AFTER_ERROR}: state_chg to UNUSED (lchan_fsm.c:1301)
20190315022715927 DCHAN DEBUG lchan(0-0-3-TCH_F-0)[0x6120000069a0]{UNUSED}: (type=TCH_F) Clearing lchan state (lchan_fsm.c:377)
20190315022715927 DTS DEBUG timeslot(0-0-3-TCH_F)[0x6120000036a0]{IN_USE}: Received Event TS_EV_LCHAN_UNUSED (lchan_fsm.c:410)
20190315022715927 DTS DEBUG timeslot(0-0-3-TCH_F)[0x6120000036a0]{IN_USE}: state_chg to UNUSED (timeslot_fsm.c:628)
Actions
