Project

General

Profile

Bug #2606

LC15 BTS variant crashed with the FSM naming rules in latest libosmocore

Added by mqng2 12 months ago. Updated 10 months ago.

Status:
Closed
Priority:
High
Assignee:
Category:
-
Target version:
-
Start date:
10/31/2017
Due date:
% Done:

100%

Spec Reference:

Description

LC15 BTS variant built against the latest libosmocore (31/10/2017) crashed with DTX enabled for AMR codec configured in osmo-NITB.

Below is BTS log at the moment of the crash:

Tue Oct 31 20:05:45 2017 <0007> l1sap.c:1185 RACH for RR access (toa=0, ra=13)
Tue Oct 31 20:05:45 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=1,ss=0) Rx RSL CHAN_ACTIV
Tue Oct 31 20:05:45 2017 <0000> rsl.c:1202 chan_nr=0x41 type=0x00 mode=0x00
Tue Oct 31 20:05:45 2017 <0007> l1sap.c:1331 activating channel chan_nr=0x41 trx=0
Tue Oct 31 20:05:45 2017 <0007> l1sap.c:581 activate confirm chan_nr=0x41 trx=0
Tue Oct 31 20:05:45 2017 <0000> rsl.c:827 (bts=0,trx=0,ts=1,ss=0) Tx CHAN ACT ACK
Tue Oct 31 20:05:45 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=1,ss=0) MPH-CONFIG.conf (Configure ciphering params)
Tue Oct 31 20:05:45 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=1,ss=0) MPH-CONFIG.conf (Configure ciphering params)
Tue Oct 31 20:05:45 2017 <0000> rsl.c:3385 (bts=0,trx=0,ts=0,ss=0) Rx RSL IMM_ASS_CMD
Tue Oct 31 20:05:47 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=1,ss=0) Rx RSL DEACTIVATE_SACCH
Tue Oct 31 20:05:47 2017 <0007> l1sap.c:1387 deactivating sacch chan_nr=0x41 trx=0
Tue Oct 31 20:05:47 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=1,ss=0) Rx RSL RF_CHAN_REL
Tue Oct 31 20:05:47 2017 <0007> l1sap.c:1371 deactivating channel chan_nr=0x41 trx=0
Tue Oct 31 20:05:47 2017 <0007> l1sap.c:606 deactivate confirm chan_nr=0x41 trx=0
Tue Oct 31 20:05:47 2017 <0000> rsl.c:798 (bts=0,trx=0,ts=1,ss=0) Tx RF CHAN REL ACK
Tue Oct 31 20:05:48 2017 <0007> l1sap.c:1176 RACH for packet access (toa=0, ra=120)
Tue Oct 31 20:05:52 2017 <0007> l1sap.c:1185 RACH for RR access (toa=0, ra=69)
Tue Oct 31 20:05:52 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=2,ss=0) Rx RSL CHAN_ACTIV
Tue Oct 31 20:05:52 2017 <0000> rsl.c:1202 chan_nr=0x12 type=0x00 mode=0x00
Tue Oct 31 20:05:52 2017 <0007> l1sap.c:1331 activating channel chan_nr=0x12 trx=0
Tue Oct 31 20:05:52 2017 <0010> fsm.c:216 Attempting to allocate FSM instance of type 'DTX_DL_AMR_FSM' with illegal identifier '(bts=0,trx=0,ts=2,ss=0)'
Tue Oct 31 20:05:52 2017 <0007> l1sap.c:581 activate confirm chan_nr=0x12 trx=0
Tue Oct 31 20:05:52 2017 <0000> rsl.c:827 (bts=0,trx=0,ts=2,ss=0) Tx CHAN ACT ACK
Tue Oct 31 20:05:52 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=0) MPH-CONFIG.conf (Configure ciphering params)
Tue Oct 31 20:05:52 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=0) MPH-CONFIG.conf (Configure ciphering params)
Tue Oct 31 20:05:52 2017 <0000> rsl.c:3385 (bts=0,trx=0,ts=0,ss=0) Rx RSL IMM_ASS_CMD
Tue Oct 31 20:05:53 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=2,ss=0) Rx RSL MODE_MODIFY_REQ
Tue Oct 31 20:05:53 2017 <0007> l1sap.c:1398 modifying channel chan_nr=0x12 trx=0
Tue Oct 31 20:05:53 2017 <0006> oml.c:1400 (bts=0,trx=0,ts=2,ss=0) MPH-CONFIG.req (TCH/H) cfgParams Tn=2, subCh=0, dir=0x2 amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1488 (bts=0,trx=0,ts=2,ss=0) Tx MODE MODIF ACK
Tue Oct 31 20:05:53 2017 <0000> rsl.c:3544 (bts=0,trx=0,ts=2,ss=0) Rx RSL IPAC_CRCX
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1863 connect_ip 1059066028
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1870 connect_port 12405
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1877 speech mode: 21
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1883 payload type: 98
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1956 (bts=0,trx=0,ts=2,ss=0) IPAC set RTP socket parameters: 1
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1693 (bts=0,trx=0,ts=2,ss=0) RSL Tx IPAC_CRCX_ACK (local 172.16.35.220:55696, remote 172.16.32.63:30000)
Tue Oct 31 20:05:53 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=0) MPH-CONFIG.conf (Set logical channel params) amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:53 2017 <0006> oml.c:1400 (bts=0,trx=0,ts=2,ss=0) MPH-CONFIG.req (TCH/H) cfgParams Tn=2, subCh=0, dir=0x4 amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:53 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=0) MPH-CONFIG.conf (Set logical channel params) amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:53 2017 <0000> rsl.c:3385 (bts=0,trx=0,ts=0,ss=0) Rx RSL PAGING_CMD
Tue Oct 31 20:05:53 2017 <0005> paging.c:213 Add paging to queue (group=18, queue_len=1)
Tue Oct 31 20:05:53 2017 <0007> l1sap.c:1185 RACH for RR access (toa=0, ra=44)
Tue Oct 31 20:05:53 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=2,ss=1) Rx RSL CHAN_ACTIV
Tue Oct 31 20:05:53 2017 <0000> rsl.c:1202 chan_nr=0x1a type=0x00 mode=0x00
Tue Oct 31 20:05:53 2017 <0007> l1sap.c:1331 activating channel chan_nr=0x1a trx=0
Tue Oct 31 20:05:53 2017 <0010> fsm.c:216 Attempting to allocate FSM instance of type 'DTX_DL_AMR_FSM' with illegal identifier '(bts=0,trx=0,ts=2,ss=1)'
Tue Oct 31 20:05:53 2017 <0007> l1sap.c:581 activate confirm chan_nr=0x1a trx=0
Tue Oct 31 20:05:53 2017 <0000> rsl.c:827 (bts=0,trx=0,ts=2,ss=1) Tx CHAN ACT ACK
Tue Oct 31 20:05:53 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=1) MPH-CONFIG.conf (Configure ciphering params)
Tue Oct 31 20:05:53 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=1) MPH-CONFIG.conf (Configure ciphering params)
Tue Oct 31 20:05:53 2017 <0000> rsl.c:3385 (bts=0,trx=0,ts=0,ss=0) Rx RSL IMM_ASS_CMD
Tue Oct 31 20:05:54 2017 <0005> paging.c:512 Removed paging record, queue_len=0
Tue Oct 31 20:05:54 2017 <0000> rsl.c:3439 (bts=0,trx=0,ts=2,ss=1) Rx RSL MODE_MODIFY_REQ
Tue Oct 31 20:05:54 2017 <0007> l1sap.c:1398 modifying channel chan_nr=0x1a trx=0
Tue Oct 31 20:05:54 2017 <0006> oml.c:1400 (bts=0,trx=0,ts=2,ss=1) MPH-CONFIG.req (TCH/H) cfgParams Tn=2, subCh=1, dir=0x2 amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1488 (bts=0,trx=0,ts=2,ss=1) Tx MODE MODIF ACK
Tue Oct 31 20:05:54 2017 <0000> rsl.c:3544 (bts=0,trx=0,ts=2,ss=1) Rx RSL IPAC_CRCX
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1863 connect_ip 1059066028
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1870 connect_port 12405
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1877 speech mode: 21
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1883 payload type: 98
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1956 (bts=0,trx=0,ts=2,ss=1) IPAC set RTP socket parameters: 1
Tue Oct 31 20:05:54 2017 <0000> rsl.c:1693 (bts=0,trx=0,ts=2,ss=1) RSL Tx IPAC_CRCX_ACK (local 172.16.35.220:36310, remote 172.16.32.63:30000)
Tue Oct 31 20:05:54 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=1) MPH-CONFIG.conf (Set logical channel params) amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:54 2017 <0006> oml.c:1400 (bts=0,trx=0,ts=2,ss=1) MPH-CONFIG.req (TCH/H) cfgParams Tn=2, subCh=1, dir=0x4 amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:54 2017 <0006> oml.c:1316 (bts=0,trx=0,ts=2,ss=1) MPH-CONFIG.conf (Set logical channel params) amrCmiPhase=0x01 amrInitCodec=0x00 (3 0 0 0 )
Tue Oct 31 20:05:59 2017 <0000> rsl.c:3544 (bts=0,trx=0,ts=2,ss=1) Rx RSL IPAC_MDCX
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1863 connect_ip 1059066028
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1870 connect_port 13429
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1877 speech mode: 5
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1883 payload type: 98
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1693 (bts=0,trx=0,ts=2,ss=1) RSL Tx IPAC_MDCX_ACK (local 172.16.35.220:36310, remote 172.16.32.63:30004)
Tue Oct 31 20:05:59 2017 <0000> rsl.c:3544 (bts=0,trx=0,ts=2,ss=0) Rx RSL IPAC_MDCX
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1863 connect_ip 1059066028
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1870 connect_port 12917
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1877 speech mode: 5
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1883 payload type: 98
Tue Oct 31 20:05:59 2017 <0000> rsl.c:1693 (bts=0,trx=0,ts=2,ss=0) RSL Tx IPAC_MDCX_ACK (local 172.16.35.220:55696, remote 172.16.32.63:30002)

Program received signal SIGSEGV, Segmentation fault.
0x0003b3ac in dtx_dl_amr_fsm_step (lchan=lchan@entry=0xb6bbdc50, rtp_pl=rtp_pl@entry=0xf8040 " \024\351Y\363_\337\345\351f\177\373\300\210\201\200\210",
rtp_pl_len=17, fn=48005, l1_payload=0xf8225 "", marker=marker@entry=true, len=len@entry=0xf82c4 "\024", ft_out=0xbefff7d7 "\002\002",
ft_out@entry=0xbefff7cf "\276\205\273") at msg_utils.c:233
233 msg_utils.c: No such file or directory.
(gdb)
(gdb)

It looks like lchan->name containing illegal characters passed to osmo_fsm_inst_alloc in l1sap_chan_act of l1sap.c cause the issue

/* Init DTX DL FSM if necessary */
if (trx->bts->dtxd && lchan->type != GSM_LCHAN_SDCCH)
lchan->tch.dtx.dl_amr_fsm = osmo_fsm_inst_alloc(&dtx_dl_amr_fsm,
tall_bts_ctx,
lchan,
LOGL_DEBUG,
lchan->name);
This issue does not appear with DTX disabled.

History

#1 Updated by laforge 11 months ago

  • Priority changed from Normal to High

#2 Updated by laforge 11 months ago

See patch in https://gerrit.osmocom.org/#/c/5030/ which still needs to be modified. Rather than having no identifier at all, the identifier needs to be structured in a way acceptable to libosmocore.

#3 Updated by laforge 11 months ago

  • Subject changed from LC15 BTS variant crashed with the latest libosmocore to LC15 BTS variant crashed with the FSM naming rules in latest libosmocore
  • Status changed from New to Feedback
  • Assignee set to mqng2
  • % Done changed from 0 to 80

Hi Minh,

I pushed an alternative version of the patch for your reference. Rather than not having a useful FSM name anymore, it just formats the name differently. Also, it should return a channel allocation error if FSM allocation fails, rather than crashing.

Please test and provide feedback in gerrit, so we can merge it.

#4 Updated by laforge 10 months ago

  • Status changed from Feedback to Closed
  • % Done changed from 80 to 100

patch was merged.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)