Actions
Bug #2898
closedOsmoBSC can generate BSSMAP ASSIGNMENT FAIL after BSSMAP ASSIGNMENT COMPLETE
Start date:
01/29/2018
Due date:
% Done:
0%
Spec Reference:
Description
I've just observed that there is at least one scenario in which we are sending a BSSMAP ASSIGNMENT FAIL after we've already confirmed it's successful
(this is with laforge/fsm branch):
Mon Jan 29 22:22:17 2018 DLINP <0013> input/ipa.c:263 accept()ed new link from 127.0.0.1 to port 3003 Mon Jan 29 22:22:17 2018 DRSL <0004> bsc_init.c:332 bootstrapping RSL for BTS/TRX (0/0) on ARFCN 871 using MCC=1 MNC=1 LAC=1 CID=0 BSIC=63 Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:1891 BTS 0 CHAN RQD: reason: answer to paging (ra=0x23, neci=0x01, chreq_reason=0x01) Mon Jan 29 22:22:19 2018 DRLL <0000> chan_alloc.c:412 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Allocating lchan=0 as SDCCH Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:1973 (bts=0,trx=0,ts=0,ss=0) Activating ARFCN(871) SS(0) lctype SDCCH r=PAGING ra=0x23 ta=0 Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:597 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:626 (bts=0,trx=0,ts=0,ss=0) state NONE -> ACTIVATION REQUESTED Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:1637 (bts=0,trx=0,ts=0,ss=0) CHANNEL ACTIVATE ACK Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:1289 (bts=0,trx=0,ts=0,ss=0) state ACTIVATION REQUESTED -> ACTIVE Mon Jan 29 22:22:19 2018 DRLL <0000> abis_rsl.c:2177 (bts=0,trx=0,ts=0,ss=0) SAPI=0 ESTABLISH INDICATION Mon Jan 29 22:22:19 2018 DMSC <0008> fsm.c:243 SUBSCR_CONN[0x5631ee52f2f0]{INIT}: Allocated Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_api.c:225 Tx MSC COMPL L3 Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:251 Initializing resources for new SIGTRAN connection to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP... Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_api.c:303 SUBSCR_CONN[0x5631ee52f2f0]{INIT}: Received Event MO-CONNECT.req Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:293 Allocated new connection id: 39 Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:297 Opening new SIGTRAN connection (id=39) to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP Mon Jan 29 22:22:19 2018 DMSC <0008> bsc_subscr_conn_fsm.c:106 SUBSCR_CONN[0x5631ee52f2f0]{INIT}: state_chg to WAIT_CC Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:187 N-CONNECT.cnf(39, ) Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:190 SUBSCR_CONN[0x5631ee52f2f0]{WAIT_CC}: Received Event MO-CONNET.cfm Mon Jan 29 22:22:19 2018 DMSC <0008> bsc_subscr_conn_fsm.c:138 SUBSCR_CONN[0x5631ee52f2f0]{WAIT_CC}: state_chg to ACTIVE Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:204 N-DATA.ind(39, 00 11 01 0b 03 01 08 01 7c 06 01 02 03 04 09 26 7d 01 80 ) Mon Jan 29 22:22:19 2018 DMSC <0008> a_reset.c:187 A-RESET(msc-0)[0x5631ee52d8f0]{CONN}: Received Event 2 Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_bssap.c:917 Rx MSC DT1 BSSMAP ASSIGNMENT REQ Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_bssap.c:817 Found matching audio type: full rate SPEECH_V1 for channel_type = { ch_indctr=0x1, ch_rate_type=0x8, perm_spch=[ 01 ] } Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_mgcp.c:283 SUBSCR_CONN[0x5631ee52f2f0]{ACTIVE}: Received Event ASSIGNMENT_CMD Mon Jan 29 22:22:19 2018 DMSC <0008> bsc_subscr_conn_fsm.c:164 SUBSCR_CONN[0x5631ee52f2f0]{ACTIVE}: ASSIGNMENT_CMD(full_rate=1, chan_mode=1) Mon Jan 29 22:22:19 2018 DRLL <0000> chan_alloc.c:412 (bts=0,trx=0,ts=1,pchan=TCH/F) Allocating lchan=0 as TCH_F Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:597 (bts=0,trx=0,ts=1,pchan=TCH/F) Tx RSL Channel Activate with act_type=INTRA_NORM_ASS Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:626 (bts=0,trx=0,ts=1,ss=0) state NONE -> ACTIVATION REQUESTED Mon Jan 29 22:22:19 2018 DMSC <0008> bsc_subscr_conn_fsm.c:167 SUBSCR_CONN[0x5631ee52f2f0]{ACTIVE}: state_chg to WAIT_ASS_CMPL Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:1637 (bts=0,trx=0,ts=1,ss=0) CHANNEL ACTIVATE ACK Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:1289 (bts=0,trx=0,ts=1,ss=0) state ACTIVATION REQUESTED -> ACTIVE Mon Jan 29 22:22:19 2018 DMSC <0008> bsc_api.c:916 Sending assignment on chan: 0x7f882be7d328 Mon Jan 29 22:22:19 2018 DRLL <0000> abis_rsl.c:2177 (bts=0,trx=0,ts=1,ss=0) SAPI=0 DATA INDICATION Mon Jan 29 22:22:19 2018 DRLL <0000> chan_alloc.c:538 (bts=0,trx=0,ts=0,ss=0) starting release sequence Mon Jan 29 22:22:19 2018 DRSL <0004> chan_alloc.c:539 (bts=0,trx=0,ts=0,ss=0) state ACTIVE -> RELEASE REQUESTED Mon Jan 29 22:22:19 2018 DRLL <0000> abis_rsl.c:1205 (bts=0,trx=0,ts=0,ss=0) RSL RLL RELEASE REQ (link_id=0x00, reason=1) Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:2400 (bts=0,trx=0,ts=1,ss=0) IPAC_BIND speech_mode=0x10 RTP_PAYLOAD=3 Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_api.c:443 POSTPONE MSC ASSIGN COMPL Mon Jan 29 22:22:19 2018 DRLL <0000> abis_rsl.c:2177 (bts=0,trx=0,ts=0,ss=0) SAPI=0 RELEASE CONFIRMATION Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:2567 (bts=0,trx=0,ts=1,ss=0) IPAC_CRCX_ACK LOCAL_IP=127.0.0.2 LOCAL_PORT=9002 CON_ID=1 RTP_PAYLOAD2=0x03 Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_audio.c:55 Connecting BTS to port: 10002 conn: 1 Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:2439 (bts=0,trx=0,ts=1,ss=0) IPAC_MDCX IP=127.0.0.3 PORT=10002 RTP_PAYLOAD=3 RTP_PAYLOAD2=3 CONN_ID=1 speech_mode=0x00 Mon Jan 29 22:22:19 2018 DRSL <0004> abis_rsl.c:2578 (bts=0,trx=0,ts=1,ss=0) IPAC_MDCX_ACK CON_ID=1 RTP_PAYLOAD2=0x03 REMOTE_IP=127.0.0.3 REMOTE_PORT=10002 Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_audio.c:94 Tx MSC ASSIGN COMPL (POSTPONED) Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_bssap.c:1055 Sending assignment complete message... (id=39) Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:326 Tx MSC ASSIGNMENT COMPL Mon Jan 29 22:22:19 2018 DMSC <0008> osmo_bsc_sigtran.c:347 Sending connection (id=39) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 14 02 15 00 21 98 2c 01 40 01 7c 06 7f 00 00 03 2a fa 7e 01 80 ) Mon Jan 29 22:22:21 2018 DRSL <0004> abis_rsl.c:1771 (bts=0,trx=0,ts=0,ss=0) T3111 expired: releasing RF Channel Mon Jan 29 22:22:21 2018 DRSL <0004> abis_rsl.c:873 (bts=0,trx=0,ts=0,ss=0) RF Channel Release Mon Jan 29 22:22:21 2018 DRSL <0004> abis_rsl.c:943 (bts=0,trx=0,ts=0,ss=0) RF CHANNEL RELEASE ACK Mon Jan 29 22:22:21 2018 DRSL <0004> abis_rsl.c:86 (bts=0,trx=0,ts=0,ss=0) state RELEASE REQUESTED -> NONE Mon Jan 29 22:22:25 2018 DMSC <0008> fsm.c:182 SUBSCR_CONN[0x5631ee52f2f0]{WAIT_ASS_CMPL}: Timeout of T10 Mon Jan 29 22:22:25 2018 DMSC <0008> osmo_bsc_sigtran.c:326 Tx MSC ASSIGNMENT FAIL Mon Jan 29 22:22:25 2018 DMSC <0008> osmo_bsc_sigtran.c:347 Sending connection (id=39) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 04 03 04 01 01 ) Mon Jan 29 22:22:25 2018 DMSC <0008> bsc_subscr_conn_fsm.c:447 SUBSCR_CONN[0x5631ee52f2f0]{WAIT_ASS_CMPL}: state_chg to ACTIVE Mon Jan 29 22:22:31 2018 DMSC <0008> osmo_bsc_sigtran.c:204 N-DATA.ind(39, 00 0c 53 0a 09 01 00 01 02 03 04 05 06 07 ) Mon Jan 29 22:22:31 2018 DMSC <0008> a_reset.c:187 A-RESET(msc-0)[0x5631ee52d8f0]{CONN}: Received Event 2 Mon Jan 29 22:22:31 2018 DMSC <0008> osmo_bsc_bssap.c:917 Rx MSC DT1 BSSMAP CIPHER MODE CMD Mon Jan 29 22:22:31 2018 DRSL <0004> bsc_api.c:774 (subscr unknown) Cipher Mode: cipher=0 key=0001020304050607 include_imeisv=1 Mon Jan 29 22:22:31 2018 DRLL <0000> abis_rsl.c:2177 (bts=0,trx=0,ts=1,ss=0) SAPI=0 DATA INDICATION Mon Jan 29 22:22:31 2018 DMSC <0008> osmo_bsc_api.c:167 CIPHER MODE COMPLETE from MS, forwarding to MSC Mon Jan 29 22:22:31 2018 DMSC <0008> osmo_bsc_sigtran.c:326 Tx MSC CIPHER MODE COMPLETE Mon Jan 29 22:22:31 2018 DMSC <0008> osmo_bsc_sigtran.c:347 Sending connection (id=39) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 03 55 2c 01 )
As the log shows, this is related to the fact that T10 is expiring, and also due to the fact that the MGCP FSM is doing things that are none of its concern (such as delaying the ASSIGNMENT COMPLETE). This needs to be untangled.
Files
Actions