MS Initial Registration failure observed in osmo-trx setup - OpenBSC

14 Sep 2016

Hello All,

We are trying to bring up osmo-trx setup in Ettus USRP B200 Board for Testing CS and PS
call .  When we tried to do the initial Registration for UE it  is failing.
Could you please help to point out what could be the issue and how to resolve this.

Please find below the observation  and log snippet for reference:

After MS  power Up Network is getting detected on the MS ,  Rach is received at BTS ,
Channel Activation is successful at A-bis interface and later Immediate Assignment is seen
in the log.
After Immediate assignment no further message is observed in Uplink/Downlink and later BSC
is releasing the SDCCH/SACCH channel as observed from the log.

BTS LOG Snippet:

OsmoBTS# <0000> rsl.c:2209 (bts=0,trx=0,ts=0,ss=4) Fwd RLL msg CHAN_RQD from LAPDm
to A-bis
<0000> rsl.c:2290 (bts=0,trx=0,ts=0,ss=0) Rx RSL CHAN_ACTIV
<0000> rsl.c:926  chan_nr=0x20 type=0x00 mode=0x00
<0006> scheduler.c:1344 Activating SDCCH/4(0) on trx=0 ts=0
<0006> scheduler.c:1344 Activating SACCH/4(0) on trx=0 ts=0
<0006> scheduler.c:1393 Set mode 3, 0, handover 0 on SDCCH/4(0) of trx=0 ts=0
<0006> scheduler.c:1458 Set a5/0 uplink for SDCCH/4(0) on trx=0 ts=0
<0006> scheduler.c:1458 Set a5/0 uplink for SACCH/4(0) on trx=0 ts=0
<0006> scheduler.c:1458 Set a5/0 downlink for SDCCH/4(0) on trx=0 ts=0
<0006> scheduler.c:1458 Set a5/0 downlink for SACCH/4(0) on trx=0 ts=0
<0000> rsl.c:559 (bts=0,trx=0,ts=0,ss=0) Tx CHAN ACT ACK
<000b> trx_if.c:485 Tx burst length 0 invalid
<0000> rsl.c:2236 (bts=0,trx=0,ts=0,ss=0) Rx RSL IMM_ASS_CMD
<000b> trx_if.c:485 Tx burst length 0 invalid
<000b> trx_if.c:485 Tx burst length 0 invalid
<000b> trx_if.c:485 Tx burst length 0 invalid
<0006> scheduler_trx.c:867 Received incomplete data frame at fn=0 (0/102) for
SDCCH/4(0)
<0006> scheduler_trx.c:867 Received incomplete data frame at fn=0 (0/102) for
SACCH/4(0)
<0000> rsl.c:2290 (bts=0,trx=0,ts=0,ss=0) Rx RSL DEACTIVATE_SACCH
<0006> scheduler.c:1344 Deactivating SACCH/4(0) on trx=0 ts=0
<0000> rsl.c:2290 (bts=0,trx=0,ts=0,ss=0) Rx RSL RF_CHAN_REL
<0006> scheduler.c:1344 Deactivating SDCCH/4(0) on trx=0 ts=0
<0000> rsl.c:519 (bts=0,trx=0,ts=0,ss=0) Tx RF CHAN REL ACK
<0006> scheduler_trx.c:867 Received incomplete data frame at fn=1421484 (12/104) for
PTCCH
<0006> scheduler_trx.c:867 Received incomplete data frame at fn=1421484 (12/104) for
PTCCH
<0000> rsl.c:2209 (bts=0,trx=0,ts=0,ss=4) Fwd RLL msg CHAN_RQD from LAPDm to A-bis
<0000> rsl.c:2290 (bts=0,trx=0,ts=2,ss=0) Rx RSL CHAN_ACTIV
<0000> rsl.c:926  chan_nr=0x0a type=0x00 mode=0x00
<0006> scheduler.c:1344 Activating TCH/F on trx=0 ts=2
<0006> scheduler.c:1344 Activating SACCH/TF on trx=0 ts=2
<0006> scheduler.c:1393 Set mode 3, 0, handover 0 on TCH/F of trx=0 ts=2
<0006> scheduler.c:1393 Set mode 3, 0, handover 0 on PDTCH of trx=0 ts=2
<0006> scheduler.c:1393 Set mode 3, 0, handover 0 on PTCCH of trx=0 ts=2
<0006> scheduler.c:1458 Set a5/0 uplink for TCH/F on trx=0 ts=2
<0006> scheduler.c:1458 Set a5/0 uplink for SACCH/TF on trx=0 ts=2
<0006> scheduler.c:1458 Set a5/0 downlink for TCH/F on trx=0 ts=2
<0006> scheduler.c:1458 Set a5/0 downlink for SACCH/TF on trx=0 ts=2
<0000> rsl.c:559 (bts=0,trx=0,ts=2,ss=0) Tx CHAN ACT ACK
<0000> rsl.c:2236 (bts=0,trx=0,ts=0,ss=0) Rx RSL IMM_ASS_CMD
<0006> scheduler.c:267 Prim for trx=0 ts=2 at fn=1085114 is out of range, or channel
already disabled. If this happens in conjunction with PCU, increase 'rts-advance'
by 5. (current fn=1436721)
<0006> scheduler_trx.c:1054 Received incomplete TCH frame ending at fn=1436997
(29/104) for TCH/F
<0006> gsm0503_coding.c:1690 tch_fr_decode(): error decoding  FACCH frame (399/456
bits)
<0006> scheduler_trx.c:1104 Received bad TCH frame ending at fn=1436997 for TCH/F
<0006> gsm0503_coding.c:1690 tch_fr_decode(): error decoding  FACCH frame (286/456
bits)
<0006> scheduler_trx.c:1104 Received bad TCH frame ending at fn=1437213 for TCH/F
<0006> gsm0503_coding.c:1706 tch_fr_decode(): error checking CRC8 for the FR part of
an FR frame
<0006> scheduler_trx.c:1104 Received bad TCH frame ending at fn=1438301 for TCH/F
<0006> scheduler_trx.c:1054 Received incomplete TCH frame ending at fn=1438522
(98/104) for TCH/F
<0006> gsm0503_coding.c:1690 tch_fr_decode(): error decoding  FACCH frame (159/456
bits)
<0006> scheduler_trx.c:1104 Received bad TCH frame ending at fn=1438522 for TCH/F
<0006> scheduler_trx.c:1054 Received incomplete TCH frame ending at fn=1438652
(20/104) for TCH/F
<0006> gsm0503_coding.c:1706 tch_fr_decode(): error checking CRC8 for the FR part of
an FR frame
<0006> scheduler_trx.c:1104 Received bad TCH frame ending at fn=1438652 for TCH/F
<0000> rsl.c:2290 (bts=0,trx=0,ts=2,ss=0) Rx RSL DEACTIVATE_SACCH
<0006> scheduler.c:1344 Deactivating SACCH/TF on trx=0 ts=2
<0000> rsl.c:2290 (bts=0,trx=0,ts=2,ss=0) Rx RSL RF_CHAN_REL
<0006> scheduler.c:1344 Deactivating TCH/F on trx=0 ts=2
<0000> rsl.c:519 (bts=0,trx=0,ts=2,ss=0) Tx RF CHAN REL ACK
<0006> scheduler_trx.c:867 Received incomplete data frame at fn=1462772 (12/104) for
PTCCH

BSC log Snippet :

OpenBSC# <0000> chan_alloc.c:342 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Allocating
lchan=0 as SDCCH
<0004> abis_rsl.c:1727 (bts=0,trx=0,ts=0,ss=0) Activating ARFCN(990) SS(0) lctype
SDCCH r=LOCATION_UPDATE ra=0x0d ta=0
<0004> abis_rsl.c:536 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate
with act_type=INITIAL
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state NONE -> ACTIVATION
REQUESTED
<0004> abis_rsl.c:1456 (bts=0,trx=0,ts=0,ss=0) CHANNEL ACTIVATE ACK
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state ACTIVATION REQUESTED ->
ACTIVE
<0004> abis_rsl.c:806 (bts=0,trx=0,ts=0,ss=0) RF Channel Release CMD due error 1
<0004> abis_rsl.c:718 (bts=0,trx=0,ts=0,ss=0) DEACTivate SACCH CMD
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state ACTIVE -> RELEASE DUE ERROR
<0004> abis_rsl.c:863 (bts=0,trx=0,ts=0,ss=0) RF CHANNEL RELEASE ACK
<0004> abis_rsl.c:767 (bts=0,trx=0,ts=0,ss=0) is back in operation.
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state RELEASE DUE ERROR -> NONE
<0000> chan_alloc.c:342 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Allocating lchan=0 as
SDCCH
<0004> abis_rsl.c:1727 (bts=0,trx=0,ts=0,ss=0) Activating ARFCN(990) SS(0) lctype
SDCCH r=LOCATION_UPDATE ra=0x0b ta=0
<0004> abis_rsl.c:536 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate
with act_type=INITIAL
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state NONE -> ACTIVATION
REQUESTED
<0004> abis_rsl.c:1456 (bts=0,trx=0,ts=0,ss=0) CHANNEL ACTIVATE ACK
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state ACTIVATION REQUESTED ->
ACTIVE
<0004> abis_rsl.c:806 (bts=0,trx=0,ts=0,ss=0) RF Channel Release CMD due error 1
<0004> abis_rsl.c:718 (bts=0,trx=0,ts=0,ss=0) DEACTivate SACCH CMD
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state ACTIVE -> RELEASE DUE ERROR
<0004> abis_rsl.c:863 (bts=0,trx=0,ts=0,ss=0) RF CHANNEL RELEASE ACK
<0004> abis_rsl.c:767 (bts=0,trx=0,ts=0,ss=0) is back in operation.
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=0,ss=0) state RELEASE DUE ERROR -> NONE
<0000> chan_alloc.c:342 (bts=0,trx=0,ts=2,pchan=TCH/F) Allocating lchan=0 as TCH_F
<0004> abis_rsl.c:1727 (bts=0,trx=0,ts=2,ss=0) Activating ARFCN(990) SS(0) lctype
TCH_F r=OTHER ra=0xe7 ta=0
<0004> abis_rsl.c:536 (bts=0,trx=0,ts=2,pchan=TCH/F) Tx RSL Channel Activate with
act_type=INITIAL
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=2,ss=0) state NONE -> ACTIVATION
REQUESTED
<0004> abis_rsl.c:1456 (bts=0,trx=0,ts=2,ss=0) CHANNEL ACTIVATE ACK
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=2,ss=0) state ACTIVATION REQUESTED ->
ACTIVE
<0004> abis_rsl.c:806 (bts=0,trx=0,ts=2,ss=0) RF Channel Release CMD due error 1
<0004> abis_rsl.c:718 (bts=0,trx=0,ts=2,ss=0) DEACTivate SACCH CMD
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=2,ss=0) state ACTIVE -> RELEASE DUE ERROR
<0004> abis_rsl.c:863 (bts=0,trx=0,ts=2,ss=0) RF CHANNEL RELEASE ACK
<0004> abis_rsl.c:767 (bts=0,trx=0,ts=2,ss=0) is back in operation.
<0004> abis_rsl.c:1127 (bts=0,trx=0,ts=2,ss=0) state RELEASE DUE ERROR -> NONE

Note : We are using internal clock of osmo-trx no external Clock is connected.

Thanks and Regards,
Mrinal