Bug #1804
Updated by neels over 7 years ago
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: <pre> ((*)) | / \ 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 </pre> Then when the osmo-pcu comes up, we see <pre> <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) [...] </pre> 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: <pre> <0009> pcu_sock.c:658 PCU socket has LOST connection [wait some seconds] <0006> oml.c:876 DSP L1 is no longer sending primitives! </pre> 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: <pre> ((*)) | / \ 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 </pre> i.e. startup is not working out as above. Can this be recovered from without a system reboot? Can osmo-bts do this automagically?