Project

General

Profile

Bug #1804

osmo-bts-sysmo, osmo-bts-litecell15: L1 phy unusable after PCU disconnects

Added by neels over 1 year ago. Updated 8 months ago.

Status:
Stalled
Priority:
Low
Assignee:
sysmocom
Category:
-
Target version:
-
Start date:
08/23/2016
Due date:
% Done:

40%

Spec Reference:

Description

On SysmoBTS as well as litecell15, osmo-bts works fine when no osmo-pcu is running.

However, if osmo-pcu has connected and the PCU process is then stopped (e.g. kill -2),
then the BTS phy is rendered completely unusable, even after a osmo-bts restart.

The normal osmo-bts-lc15 startup without a PCU looks like this:

((*))
  |
 / \ OsmoBTS
<0012> input/ipaccess.c:876 enabling ipaccess BTS mode
<0006> phy_link.c:58 PHY link state change shutdown -> connectiong
<0006> l1_if.c:1417 Litecell 1.5 BTS L1IF compiled against API headers v1.0.0
<0006> l1_if.c:186 Tx SYS prim LAYER1-RESET.req
<0006> phy_link.c:58 PHY link state change connectiong -> connected
<0006> phy_link.c:68 trx_set_avail(1)
<0012> input/ipa.c:129 connection done.
<0012> input/ipaccess.c:700 received ID get
<0001> oml.c:217 OC=SITE-MANAGER INST=(ff,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,01,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
<0006> l1_if.c:1319 Rx L1-RESET.conf (status=Success)
<0006> l1_if.c:1356 Tx SET-TRACE-FLAGS.req (0x00000000)
<0006> l1_if.c:186 Tx SYS prim SYSTEM-INFO.req
<0006> l1_if.c:1281 DSP v1.0.0, FPGA v0.2.0
n<0006> l1_if.c:186 Tx SYS prim ACTIVATE-RF.req
<0006> calib_file.c:294 Calibration file path not specified
<0006> l1_if.c:1294 Operating without calibration; unable to load tables!
<0001> oml.c:547 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:256 OC=BTS INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=BTS INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=GPRS-NSE INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=GPRS-CELL INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=GPRS-NSVC INST=(00,00,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=GPRS-NSE INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=GPRS-CELL INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=GPRS-NSVC INST=(00,00,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:547 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:901 ADM state already was Unlocked
<0006> l1_if.c:1128 Rx RF-ACT.conf (status=Success)
<0006> main.c:130 Set global status #0 to 1 (0000 -> 0001), LEDs: ACT 1
<0001> oml.c:249 OC=RADIO-CARRIER INST=(00,00,ff) AVAIL STATE Power off -> OK
<0001> oml.c:256 OC=RADIO-CARRIER INST=(00,00,ff) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:362 OC=RADIO-CARRIER INST=(00,00,ff) Tx SW ACT REP
<0001> oml.c:249 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) AVAIL STATE Power off -> OK
<0001> oml.c:217 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:362 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx SW ACT REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,00) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,00) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,01) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,01) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,02) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,02) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,03) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,03) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,04) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,04) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,05) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,05) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,06) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,06) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
<0001> oml.c:249 OC=CHANNEL INST=(00,00,07) AVAIL STATE Power off -> Dependency
<0001> oml.c:256 OC=CHANNEL INST=(00,00,07) OPER STATE NULL -> Disabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
<0001> oml.c:642 Set RF Max Power Reduction = 10 dBm
<0001> oml.c:901 ADM state already was Unlocked
<0006> l1_if.c:1251 Tx RF-MUTE.req (0, 0, 0, 0, 0, 0, 0, 0)
<0006> l1_if.c:186 Tx SYS prim MUTE-RF.req
<0006> l1_if.c:1225 Rx RF-MUTE.conf with status=Success
<0006> main.c:130 Set global status #1 to 0 (0001 -> 0001), LEDs: ACT 1
<0006> oml.c:417 Init TRX (Band 2, ARFCN 868, TSC 7, RxPower -75.000000 dBm, TxPower  0.00 dBm
<0006> oml.c:340 Rx MPH-INIT.conf (status=Success)
<0006> tx_power.c:248 power_ramp_start(cur=0, tgt=30000)
<0001> oml.c:249 OC=RADIO-CARRIER INST=(00,00,ff) AVAIL STATE OK -> OK
<0001> oml.c:256 OC=RADIO-CARRIER INST=(00,00,ff) OPER STATE Disabled -> Enabled
<0001> oml.c:217 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:1158 Rx IPA RSL CONNECT IP=10.9.1.120 PORT=3003 STREAM=0x00
<0012> input/ipa.c:129 connection done.
<0001> oml.c:834 OC=CHANNEL INST=(00,00,00) SET CHAN ATTR (TSC = 7)
<0012> input/ipaccess.c:700 received ID get
<0000> rsl.c:244 Tx RSL RF RESource INDication
<0001> oml.c:249 OC=CHANNEL INST=(00,00,00) AVAIL STATE Dependency -> OK
<0001> oml.c:256 OC=CHANNEL INST=(00,00,00) OPER STATE Disabled -> Enabled
<0001> oml.c:217 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
<0006> oml.c:1048 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, FCCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (FCCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, SCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (SCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, BCCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (BCCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, AGCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (AGCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, PCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (PCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.req (hL2=0x000004bb, RACH RxUL)
<0006> oml.c:791 (bts=0,trx=0,ts=0,ss=4) MPH-ACTIVATE.conf (RACH RxUL)
<0000> rsl.c:545 (bts=0,trx=0,ts=0,ss=0) Tx CHAN ACT ACK
<0006> oml.c:1384 (bts=0,trx=0,ts=0,ss=4) SET_CIPHERING (ALG=0 TxDL)
<0006> oml.c:749 (bts=0,trx=0,ts=0,ss=4) End of queue encountered. Now empty? 0
<0006> oml.c:1229 (bts=0,trx=0,ts=0,ss=4) MPH-CONFIG.conf (Configure ciphering params) 
<0006> oml.c:1384 (bts=0,trx=0,ts=0,ss=4) SET_CIPHERING (ALG=0 RxUL)
<0006> oml.c:1229 (bts=0,trx=0,ts=0,ss=4) MPH-CONFIG.conf (Configure ciphering params) 
<0006> oml.c:749 (bts=0,trx=0,ts=0,ss=4) End of queue encountered. Now empty? 1
[...]
<0009> pcu_sock.c:637 PCU socket not connected, dropping message
<0009> pcu_sock.c:637 PCU socket not connected, dropping message
<0009> pcu_sock.c:637 PCU socket not connected, dropping message

Then when the osmo-pcu comes up, we see

<0009> pcu_sock.c:637 PCU socket not connected, dropping message
<0009> pcu_sock.c:637 PCU socket not connected, dropping message
<0009> pcu_sock.c:834 PCU socket connected to external PCU
<0006> oml.c:1048 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.req (hL2=0x000200bb, PDTCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.req (hL2=0x000300bb, PDTCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.conf (PDTCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.req (hL2=0x000200bb, PDTCH RxUL)
<0006> oml.c:791 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.conf (PDTCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.req (hL2=0x000300bb, PDTCH RxUL)
<0006> oml.c:791 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.conf (PDTCH RxUL)
<0006> oml.c:1048 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.req (hL2=0x000200bb, PTCCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.conf (PDTCH RxUL)
<0006> oml.c:1048 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.req (hL2=0x000300bb, PTCCH TxDL)
<0006> oml.c:791 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.conf (PTCCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.req (hL2=0x000200bb, PRACH RxUL)
<0006> oml.c:791 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.conf (PTCCH TxDL)
<0006> oml.c:1048 (bts=0,trx=0,ts=3,ss=0) MPH-ACTIVATE.req (hL2=0x000300bb, PRACH RxUL)
<0006> oml.c:791 (bts=0,trx=0,ts=2,ss=0) MPH-ACTIVATE.conf (PRACH RxUL)
[...]

And GPRS works.
(Note: no actual MS needs to be attached to reproduce the issue.)

When I then stop the PCU process by means of `kill -2', the BTS log says:

<0009> pcu_sock.c:658 PCU socket has LOST connection
[wait some seconds]
<0006> oml.c:876 DSP L1 is no longer sending primitives!

and at that point all logging stops and the RF cell goes down completely.

A restart of the osmo-bts process does not bring the RF cell back up,
and the log looks like:

((*))
  |
 / \ OsmoBTS
<0012> input/ipaccess.c:876 enabling ipaccess BTS mode
<0006> phy_link.c:58 PHY link state change shutdown -> connectiong
<0006> l1_if.c:1417 Litecell 1.5 BTS L1IF compiled against API headers v1.0.0
<0006> l1_if.c:186 Tx SYS prim LAYER1-RESET.req
<0006> phy_link.c:58 PHY link state change connectiong -> connected
<0006> phy_link.c:68 trx_set_avail(1)
<0012> input/ipa.c:129 connection done.
<0012> input/ipaccess.c:700 received ID get
<0001> oml.c:217 OC=SITE-MANAGER INST=(ff,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,01,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
<0001> oml.c:217 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
<0001> oml.c:547 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:256 OC=BTS INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=BTS INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=GPRS-NSE INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=GPRS-CELL INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:249 OC=GPRS-NSVC INST=(00,00,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=GPRS-NSE INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=GPRS-CELL INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:256 OC=GPRS-NSVC INST=(00,00,ff) OPER STATE NULL -> Enabled
<0001> oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:547 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:547 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:901 ADM state already was Unlocked
[after a while]
<0006> l1_if.c:94 Timeout waiting for SYS primitive LAYER1-RESET.conf

i.e. startup is not working out as above.

Can this be recovered from without a system reboot?
Can osmo-bts do this automagically?

osmoBTS_1804.log Magnifier (30.2 KB) wirelesss, 11/17/2016 01:50 PM

pcu _1804.log Magnifier - PCU Log file (1.81 KB) wirelesss, 11/17/2016 02:31 PM

bts_serial.log Magnifier - bts serial output (3.48 KB) wirelesss, 02/10/2017 05:48 PM

bts.log Magnifier - bts log file (27.3 KB) wirelesss, 02/10/2017 05:50 PM

nitb.log Magnifier - nitb log file (16.7 KB) wirelesss, 02/10/2017 05:59 PM

eth_trace.pcap (24 Bytes) wirelesss, 02/10/2017 06:16 PM

lo_trace.pcap (153 KB) wirelesss, 02/10/2017 06:16 PM


Related issues

Related to OsmoBTS - Bug #57: sysmobts L1 is not properly closed, DSP firmware reload is required New

History

#1 Updated by laforge over 1 year ago

  • Assignee set to neels

The question is why does it stop. The system is clearly not designed that way, and I actually believe it was behaving differently in the past. You could stop and re-start the PCU as you pleased.

The PCU/PDCH message queue is separate from the other message queues to/from the DSP specifically to separate the processes. So if the PCU stops, the PDCH message queue will stall, but it should not affect the operation of the circuit switched side.

So the question is: Are we doing something wrong from osmo-bts/osmo-pcu, or is L1 not handling this correctly [anymore]?

#2 Updated by neels about 1 year ago

Since 2011, osmo-bts exits when the DSP L1 is dead:
https://git.osmocom.org/osmo-bts/commit/?id=39eadbbb17c8e634b2f641c2f6148f27a975f7de

+/* we regularly check if the DSP L1 is still sending us primitives.
+ * if not, we simply stop the BTS program (and be re-spawned) */
+static void alive_timer_cb(void *data)
+{
+    struct femtol1_hdl *fl1h = data;
+
+    if (fl1h->alive_prim_cnt == 0) {
+        LOGP(DL1C, LOGL_FATAL, "DSP L1 is no longer sending primitives!\n");
+        exit(23);
+    }
+    fl1h->alive_prim_cnt = 0;
+    osmo_timer_schedule(&fl1h->alive_timer, 5, 0);
+}

So, the idea is to be re-spawned presumably by systemctl.

The question remains whether the DSP L1 dropped dead before when the PCU disconnected.
Also, a manual re-spawn didn't help, so this seems to be "new" behavior?

#3 Updated by neels about 1 year ago

Verified that this issue also happens on newest sysmobts built with nightly SDK v1.5.4.
Pending: check with old sysmobts software

#4 Updated by neels about 1 year ago

  • Description updated (diff)

#5 Updated by neels about 1 year ago

  • Assignee changed from neels to wirelesss

@wirelesss, please go on and:

  • reproduce this issue on your sysmoBTS.
  • test a selection of older DSP firmware versions on your sysmoBTS to see whether
    older DSP firmwares show the issue or not.
  • if not, find out which DSP firmware version is the first that fails this way.

I have just added a chapter to the sysmoBTS manual that describes how to exchange
firmware versions. Grab the newest manual and see section 9.6.
https://downloads.sysmocom.de/generic/documents/sysmobts-1002-manual.pdf

#6 Updated by wirelesss about 1 year ago

Log file from BTS related to the above described Bug is attached. This issue was detected and reproduced using SDK 1.5.4 with sysmoBTS. After sending command 'kill -2' to PCU, which was followed by restart of PCU and BTS processes, did not bring BTS back in operation.

#7 Updated by neels about 1 year ago

wirelesss wrote:

This issue was detected and reproduced using SDK 1.5.4

The interesting information here would be the DSP/FPGA firmware version, not the SDK version.
Please describe in more detail.
Also update the Status and possibly the %Done. So far these don't match the situation at all.

#8 Updated by wirelesss about 1 year ago

  • File pcu _1804.logMagnifier added
  • Subject changed from osmo-bts-sysmo, osmo-bts-litecell15: L1 phy unusable after PCU disconnects to kosmo-bts-sysmo, osmo-bts-litecell15: L1 phy unusable after PCU disconnects

#9 Updated by wirelesss about 1 year ago

  • Subject changed from kosmo-bts-sysmo, osmo-bts-litecell15: L1 phy unusable after PCU disconnects to osmo-bts-sysmo, osmo-bts-litecell15: L1 phy unusable after PCU disconnects
  • Status changed from New to In Progress
  • % Done changed from 10 to 30

Issue is detected in DSP/FPGA v3.11. Behavior is identical with the one written in the initial ticket description. Stopping of PCU process breaks logging in BTS and PCU and RBS output looks as below:


<0007> l1sap.c:966 RACH for packet access
<0005> paging.c:254 Add IMM.ASS to queue (group=0)
<0007> l1sap.c:1160 deactivating channel chan_nr=0x0f trx=0
<0007> l1_if.c:165 Tx L1 prim MPH-DEACTIVATE.req
<0007> l1_if.c:165 Tx L1 prim MPH-DEACTIVATE.req
<0007> l1_if.c:165 Tx L1 prim MPH-DEACTIVATE.req
<0007> l1_if.c:165 Tx L1 prim MPH-DEACTIVATE.req
<0007> l1sap.c:475 deactivate confirm chan_nr=0x0f trx=0
<0000> rsl.c:517 (bts=0,trx=0,ts=7,ss=0) not sending REL ACK
<0006> oml.c:900 DSP L1 is no longer sending primitives!
root@sysmobts-v2:~#

Attempt to start PCU displays following PCUs output:


<0001> osmobts_sock.cpp:227 Opening OsmoPCU L1 interface to OsmoBTS
<0001> osmobts_sock.cpp:264 Failed to connect to the osmo-bts PCU socket, delaying... '/tmp/pcu_bts'
<0001> osmobts_sock.cpp:227 Opening OsmoPCU L1 interface to OsmoBTS
<0001> osmobts_sock.cpp:264 Failed to connect to the osmo-bts PCU socket, delaying... '/tmp/pcu_bts'
<0001> osmobts_sock.cpp:227 Opening OsmoPCU L1 interface to OsmoBTS

Starting sysmobts by entering command osmo-bts-sysmo leads to below output.

root@sysmobts-v2:~# osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M
((*)) |
/ \ OsmoBTS
&lt;0017&gt; control_if.c:693 CTRL at 127.0.0.1 4238
&lt;0010&gt; telnet_interface.c:95 telnet at 127.0.0.1 4241
&lt;0012&gt; input/ipaccess.c:876 enabling ipaccess BTS mode
&lt;0006&gt; l1_if.c:1602 Read clock calibration(677) from EEPROM.
&lt;0012&gt; input/ipa.c:129 connection done.
&lt;0012&gt; input/ipaccess.c:700 received ID get
&lt;0001&gt; oml.c:217 OC=SITE-MANAGER INST=(ff,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=GPRS-NSVC INST=(00,01,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
&lt;0001&gt; oml.c:217 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
&lt;0001&gt; oml.c:847 OC=SITE-MANAGER(00) INST=(ff,ff,ff) Rx OPSTART
&lt;0001&gt; oml.c:858 ... automatic ACK, OP state already was Enabled
&lt;0001&gt; oml.c:465 OC=BTS(01) INST=(00,ff,ff) Rx SET BTS ATTR
&lt;0001&gt; oml.c:547 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:875 OC=BTS(01) INST=(00,ff,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:847 OC=BTS(01) INST=(00,ff,ff) Rx OPSTART
&lt;0001&gt; oml.c:256 OC=BTS INST=(00,ff,ff) OPER STATE NULL -> Enabled
&lt;0001&gt; oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:249 OC=BTS INST=(00,ff,ff) AVAIL STATE Dependency -> OK
&lt;0001&gt; oml.c:217 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:249 OC=GPRS-NSE INST=(00,ff,ff) AVAIL STATE Dependency -> OK
&lt;0001&gt; oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:249 OC=GPRS-CELL INST=(00,ff,ff) AVAIL STATE Dependency -> OK
&lt;0001&gt; oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:249 OC=GPRS-NSVC INST=(00,00,ff) AVAIL STATE Dependency -> OK
&lt;0001&gt; oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:1203 OC=GPRS-NSE(f0) INST=(00,ff,ff) Rx IPACCESS(0xf5): &lt;0001&gt; oml.c:1117 OC=GPRS-NSE(f0) INST=(00,ff,ff) Rx IPA SET ATTR
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:847 OC=GPRS-NSE(f0) INST=(00,ff,ff) Rx OPSTART
&lt;0001&gt; oml.c:256 OC=GPRS-NSE INST=(00,ff,ff) OPER STATE NULL -> Enabled
&lt;0001&gt; oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:1203 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx IPACCESS(0xf5): &lt;0001&gt; oml.c:1117 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx IPA SET ATTR
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:847 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx OPSTART
&lt;0001&gt; oml.c:256 OC=GPRS-CELL INST=(00,ff,ff) OPER STATE NULL -> Enabled
&lt;0001&gt; oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:875 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:875 OC=GPRS-NSE(f0) INST=(00,ff,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:1203 OC=GPRS-NSVC(f2) INST=(00,00,ff) Rx IPACCESS(0xf5): &lt;0001&gt; oml.c:1117 OC=GPRS-NSVC(f2) INST=(00,00,ff) Rx IPA SET ATTR

Command systemctl status sysmobts displays active status of BTS. A few moments later BTS status is deactivating and then activating (auto-restart) which is followed by active state. At this moment BTS returns to the operation and is capable to handle CS and PS traffic.

root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: active (running) since Thu 2016-11-17 16:09:31 UTC; 17s ago
Process: 1030 ExecStopPost=/bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s (code=exited, status=0/SUCCESS)
Process: 1024 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1069 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1074 (osmo-bts-sysmo)
CGroup: /system.slice/sysmobts.service
└─1074 /usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M
root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: deactivating (stop-post) (Result: exit-code) since Thu 2016-11-17 16:10:02 UTC; 2s ago
Process: 1078 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1074 ExecStart=/usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M (code=exited, status=23)
Process: 1069 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1074 (code=exited, status=23); : 1084 (sh)
CGroup: /system.slice/sysmobts.service
└─control
├─1084 /bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s
└─1095 sleep 3s
root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: deactivating (stop-post) (Result: exit-code) since Thu 2016-11-17 16:10:02 UTC; 4s ago
Process: 1078 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1074 ExecStart=/usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M (code=exited, status=23)
Process: 1069 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1074 (code=exited, status=23); : 1084 (sh)
CGroup: /system.slice/sysmobts.service
└─control
├─1084 /bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s
└─1099 sleep 1s
root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: activating (auto-restart) (Result: exit-code) since Thu 2016-11-17 16:10:07 UTC; 100ms ago
Process: 1084 ExecStopPost=/bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s (code=exited, status=0/SUCCESS)
Process: 1078 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1074 ExecStart=/usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M (code=exited, status=23)
Process: 1069 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1074 (code=exited, status=23)
root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: activating (auto-restart) (Result: exit-code) since Thu 2016-11-17 16:10:07 UTC; 1s ago
Process: 1084 ExecStopPost=/bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s (code=exited, status=0/SUCCESS)
Process: 1078 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1074 ExecStart=/usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M (code=exited, status=23)
Process: 1069 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1074 (code=exited, status=23)
root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: active (running) since Thu 2016-11-17 16:10:09 UTC; 1s ago
Process: 1084 ExecStopPost=/bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s (code=exited, status=0/SUCCESS)
Process: 1078 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1104 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1108 (osmo-bts-sysmo)
CGroup: /system.slice/sysmobts.service
└─1108 /usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M
root@sysmobts-v2:~# systemctl status sysmobts
sysmobts.service - sysmocom sysmoBTS
Loaded: loaded (/lib/systemd/system/sysmobts.service; disabled)
Active: active (running) since Thu 2016-11-17 16:10:09 UTC; 2s ago
Process: 1084 ExecStopPost=/bin/sh -c cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s (code=exited, status=0/SUCCESS)
Process: 1078 ExecStopPost=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Process: 1104 ExecStartPre=/bin/sh -c echo 0 > /sys/class/leds/activity_led/brightness (code=exited, status=0/SUCCESS)
Main PID: 1108 (osmo-bts-sysmo)
CGroup: /system.slice/sysmobts.service
└─1108 /usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M

#10 Updated by wirelesss about 1 year ago

  • % Done changed from 30 to 40

Some additional comments to the previous post.

Firmware v3.11
------------------------
When the PCU is stopped by issuing of 'kill -2' command, sysmobts.service goes to status disabled. Starting sysmobts.service process brings RF cell up.
In any case stopping of PCU provokes disabling of sysmobts.service and it is detected in this version of Firmware.

Firmware v3.1
---------------------
When using firmware v3.1, osmo-bts-sysmo attempt to start automatically but after a while failed. Issuing command /usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M
shows :

&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:847 OC=GPRS-NSE(f0) INST=(00,ff,ff) Rx OPSTART
&lt;0001&gt; oml.c:256 OC=GPRS-NSE INST=(00,ff,ff) OPER STATE NULL -> Enabled
&lt;0001&gt; oml.c:217 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:1203 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx IPACCESS(0xf5): &lt;0001&gt; oml.c:1117 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx IPA SET ATTR
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:847 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx OPSTART
&lt;0001&gt; oml.c:256 OC=GPRS-CELL INST=(00,ff,ff) OPER STATE NULL -> Enabled
&lt;0001&gt; oml.c:217 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:875 OC=GPRS-CELL(f1) INST=(00,00,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:875 OC=GPRS-NSE(f0) INST=(00,ff,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:1203 OC=GPRS-NSVC(f2) INST=(00,00,ff) Rx IPACCESS(0xf5): &lt;0001&gt; oml.c:1117 OC=GPRS-NSVC(f2) INST=(00,00,ff) Rx IPA SET ATTR
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:847 OC=GPRS-NSVC(f2) INST=(00,00,ff) Rx OPSTART
&lt;0001&gt; oml.c:256 OC=GPRS-NSVC INST=(00,00,ff) OPER STATE NULL -> Enabled
&lt;0001&gt; oml.c:217 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:875 OC=GPRS-NSVC(f2) INST=(00,00,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:465 OC=BTS(01) INST=(00,ff,ff) Rx SET BTS ATTR
&lt;0001&gt; oml.c:547 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:547 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:875 OC=BTS(01) INST=(00,ff,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:901 ADM state already was Unlocked
&lt;0001&gt; oml.c:847 OC=BTS(01) INST=(00,ff,ff) Rx OPSTART
&lt;0001&gt; oml.c:858 ... automatic ACK, OP state already was Enabled
&lt;0001&gt; oml.c:847 OC=RADIO-CARRIER(02) INST=(00,00,ff) Rx OPSTART
&lt;0001&gt; oml.c:614 OC=RADIO-CARRIER(02) INST=(00,00,ff) Rx SET RADIO CARRIER ATTR
&lt;0001&gt; oml.c:642 Set RF Max Power Reduction = 20 dBm
&lt;0001&gt; oml.c:346 Sending FOM ACK.
&lt;0001&gt; oml.c:875 OC=RADIO-CARRIER(02) INST=(00,00,ff) Rx CHG ADM STATE
&lt;0001&gt; oml.c:901 ADM state already was Unlocked
&lt;0006&gt; l1_if.c:1394 RF-MUTE.req not supported by SuperFemto
&lt;0012&gt; input/ipa.c:67 connection closed with server
&lt;000d&gt; abis.c:135 Signalling link down
&lt;0001&gt; bts.c:206 Shutting down BTS 0, Reason Abis close
&lt;0006&gt; oml.c:450 Close TRX 0
&lt;0007&gt; l1_if.c:165 Tx L1 prim MPH-CLOSE.req
&lt;0001&gt; oml.c:249 OC=RADIO-CARRIER INST=(00,00,ff) AVAIL STATE OK -> Off line
&lt;0001&gt; oml.c:256 OC=RADIO-CARRIER INST=(00,00,ff) OPER STATE Disabled -> Disabled
&lt;0001&gt; oml.c:217 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
&lt;0001&gt; oml.c:249 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) AVAIL STATE OK -> Off line
&lt;0001&gt; oml.c:256 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) OPER STATE NULL -> Disabled
&lt;0001&gt; oml.c:217 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
Shutdown timer expired
root@sysmobts-v2:~#

Firmware v2.7
---------------------
During cross-compiling procedure following error message appears:

osmo-bts-sysmo/sysmo_l1_if.c:340:18: note: each undeclared identifier is reported only once for each function it appears in
Makefile:642: recipe for target 'osmo-bts-sysmo/sysmo_l1_if.o' failed
make[1]:*** [osmo-bts-sysmo/sysmo_l1_if.o] Error 1
make[1]:*** Waiting for unfinished jobs....
In file included from osmo-bts-sysmo/sysmo_l1_hw.c:45:0:
osmo-bts-sysmo/femtobts.h:25:46: error: 'SuperFemto_PrimId_NUM' undeclared here (not in a function)
const enum l1prim_type femtobts_sysprim_type[SuperFemto_PrimId_NUM];
^
osmo-bts-sysmo/femtobts.h:27:1: error: unknown type name 'SuperFemto_PrimId_t'
const SuperFemto_PrimId_t femtobts_sysprim_req2conf[SuperFemto_PrimId_NUM];
^

#11 Updated by wirelesss about 1 year ago

Firmware 3.11:
Killing PCU by issuing of 'kill -2' command disables sysmobts.service. It is possible to start sysmobts.service manually this brings RF cell on air.

Firmware v3.1:
osmo-bts-sysmo can not start after killing pcu.

Firmware v2.7:
Cross-compiling procedure fails with error message, which is shown in the above post.

#12 Updated by wirelesss about 1 year ago

wirelesss wrote:

Firmware 3.11:
Killing PCU by issuing of 'kill -2' command disables sysmobts.service. It is possible to start sysmobts.service manually this brings RF cell on air.

Firmware 3.10:
After change of Firmware to 3.10 followed by powercycle of sysmoBTS leads to cycling restarts of sysmopcu.service.
systemctl command shows stable active (running) state of sysmobts.service.

Firmware v3.1:
osmo-bts-sysmo can not start after killing pcu.

Firmware v2.7:
Cross-compiling procedure fails with error message, which is shown in the above post.

#13 Updated by wirelesss about 1 year ago

wirelesss wrote:

wirelesss wrote:

Firmware 3.11:
Killing PCU by issuing of 'kill -2' command disables sysmobts.service. It is possible to start sysmobts.service manually this brings RF cell on air.

Firmware 3.10:
After change of firmware to 3.10 followed by power-cycle of sysmoBTS leads to cycling restarts of sysmopcu.service.
systemctl command shows stable active (running) state of sysmobts.service. The LED indicator "RF state" is off.

Firmware 3.6:
Changing firmware to 3.6 and power-cycling the sysmoBTS leads to cycling restarts of sysmopcu.service.
sysmobts.service is in stable active (running) state. The LED indicator "RF state" is off.

Firmware v3.1:
osmo-bts-sysmo can not start after killing pcu.

Firmware v2.7:
Cross-compiling procedure fails with error message, which is shown in the above post.

#14 Updated by laforge about 1 year ago

Hi wireless,

On Mon, Dec 12, 2016 at 10:50:17AM +0000, wirelesss [REDMINE] wrote:

Issue #1804 has been updated by wirelesss.
wirelesss wrote:

wirelesss wrote:

This is the second time I see an update to this ticket from you, where
you apparently full-quote a reply you sent earlier. Please don't do
that.

Ah, after more careful comparison I see now you actually extended the
information from before. In that case, please don't add new information
formatted as if it was a quote from a previous ticket. You quote old
information but add (non-quoted) new information.
--
- Harald Welte <> http://laforge.gnumonks.org/ ============================================================================
"Privacy in residential applications is a desirable marketing option."
(ETSI EN 300 175-7 Ch. A6)

#15 Updated by neels about 1 year ago

Once this happened, another way to make the BTS usable is to re-flash the DSP images:

cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; sleep 3s; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0; sleep 1s

#16 Updated by neels 12 months ago

The firwmare v3.1 log output looks like the link to the osmo-nitb went down,
so I assume there was a problem unrelated to this question whether the L1 communication breaks down.
We should re-test v3.1 and make sure that it wasn't an odd osmo-nitb problem.

Otherwise I'm not sure what to do here. It seems to take substantial effort to get things
to run with older firmwares (3.10, 3.6, 2.7).

So far we have no conclusion that would allow requesting Nutaq to fix a regression, yet.
We could inform Nutaq of the problem without a reference to an older working state...?

#17 Updated by laforge 12 months ago

On Tue, Feb 07, 2017 at 12:42:43PM +0000, neels [REDMINE] wrote:

It seems to take substantial effort to get things to run with older
firmwares (3.10, 3.6, 2.7).

why is that? http://jenkins.osmocom.org/jenkins/job/osmo-bts/ builds
every osmo-bts commit against v2.4, v2.7, v3.0 v3.1 and v5.1

Does this mean that the code compiles against those old API headers but
fails to work? If so, are there specific bug tickets on this?

We could inform Nutaq of the problem without a reference to an older working state...?

yes, seems like a good idea.

#18 Updated by wirelesss 12 months ago

v 3.1 of the firmware has been re-tested.

osmo-bts-sysmo and osmo-pcu make cycling restarts. The RF Active link comes for a few seconds and then goes off.

A log from bts is shown below. I have also take pcaps from eth and lo interfaces.


/usr/bin/osmo-bts-sysmo -s -c /etc/osmocom/osmo-bts.cfg -M

((*))
  |
 / \ OsmoBTS
<0017> control_if.c:693 CTRL at 127.0.0.1 4238
<0010> telnet_interface.c:95 telnet at 127.0.0.1 4241
<0012> input/ipaccess.c:885 enabling ipaccess BTS mode, OML connecting to 10.9.1.112:3002
<0006> phy_link.c:58 PHY link state change shutdown -> connectiong
<0006> l1_if.c:1622 sysmoBTSv2 L1IF compiled against API headers v3.1.0
<0006> l1_if.c:1610 Read clock calibration(677) from EEPROM.
<0006> l1_if.c:183 Tx SYS prim LAYER1-RESET.req
<0006> phy_link.c:58 PHY link state change connectiong -> connected
<0006> phy_link.c:68 trx_set_avail(1)
<0012> input/ipa.c:129 connection done.
<0012> input/ipaccess.c:706 received ID get
<0001> oml.c:156 OC=SITE-MANAGER INST=(ff,ff,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=GPRS-NSVC INST=(00,01,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
<0001> oml.c:156 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
<0006> l1_if.c:1496 Rx L1-RESET.conf (status=Success)
<0006> l1_if.c:1533 Tx SET-TRACE-FLAGS.req (0x00000000)
<0006> l1_if.c:183 Tx SYS prim SYSTEM-INFO.req
<0006> l1_if.c:1440 DSP v3.1.0, FPGA v3.1.0
n<0006> l1_if.c:1309 Using external attenuator.
<0006> l1_if.c:183 Tx SYS prim ACTIVATE-RF.req
<0006> calib_file.c:191 No calibration table fix-up needed, firmware < 3.3
<0006> l1_if.c:183 Tx SYS prim SET-RX-CALIB.req
<0001> oml.c:473 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:473 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:473 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:473 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:473 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:473 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:473 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
<0001> oml.c:195 OC=BTS INST=(00,ff,ff) OPER STATE NULL -> Enabled
<0001> oml.c:156 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:188 OC=BTS INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:156 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:188 OC=GPRS-NSE INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:156 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:188 OC=GPRS-CELL INST=(00,ff,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:156 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
<0001> oml.c:188 OC=GPRS-NSVC INST=(00,00,ff) AVAIL STATE Dependency -> OK
<0001> oml.c:156 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
<0006> l1_if.c:1213 Rx RF-ACT.conf (status=Success)
<0006> main.c:109 Set global status #0 to 1 (0000 -> 0001), LEDs: ACT 1
<0001> oml.c:188 OC=RADIO-CARRIER INST=(00,00,ff) AVAIL STATE Power off -> OK
<0001> oml.c:195 OC=RADIO-CARRIER INST=(00,00,ff) OPER STATE NULL -> Disabled
<0001> oml.c:156 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:301 OC=RADIO-CARRIER INST=(00,00,ff) Tx SW ACT REP
<0001> oml.c:188 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) AVAIL STATE Power off -> OK
<0001> oml.c:156 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
<0001> oml.c:301 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx SW ACT REP
<0001> oml.c:188 OC=CHANNEL INST=(00,00,00) AVAIL STATE Power off -> Dependency
<0001> oml.c:195 OC=CHANNEL INST=(00,00,00) OPER STATE NULL -> Disabled
<0001> oml.c:156 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
<0001> oml.c:188 OC=CHANNEL INST=(00,00,01) AVAIL STATE Power off -> Dependency
<0001> oml.c:195 OC=CHANNEL INST=(00,00,01) OPER STATE NULL -> Disabled
<0001> oml.c:156 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
<0001> oml.c:188 OC=CHANNEL INST=(00,00,02) AVAIL STATE Power off -> Dependency
<0001> oml.c:195 OC=CHANNEL INST=(00,00,02) OPER STATE NULL -> Disabled

#19 Updated by wirelesss 11 months ago

  • Assignee changed from wirelesss to Osmocom Developers

#20 Updated by laforge 8 months ago

  • Status changed from In Progress to Stalled
  • Assignee changed from Osmocom Developers to sysmocom
  • Priority changed from Normal to Low

#21 Updated by laforge about 2 months ago

  • Related to Bug #57: sysmobts L1 is not properly closed, DSP firmware reload is required added

Also available in: Atom PDF