Project

General

Profile

Actions

Bug #2898

closed

OsmoBSC can generate BSSMAP ASSIGNMENT FAIL after BSSMAP ASSIGNMENT COMPLETE

Added by laforge almost 5 years ago. Updated about 4 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Category:
-
Target version:
-
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

20180129-osmobsc-assignment-compl-fail.pcap 20180129-osmobsc-assignment-compl-fail.pcap 4.96 KB pcap file showing the problem laforge, 01/29/2018 09:43 PM
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)