Cellular Network Infrastructure » OsmoGSMTester

Since a few days ago, the osmo-bts-octphy tests fail during startup of the OCTBTS:

(launched: 2018-05-16_13:19:33.210299)
<0006> l1_if.c:770 model_init()
[0;m20180516131933306 [1;33mDLCTRL[0;m <0017> control_if.c:866 CTRL at 127.0.0.1 4238
[0;m20180516131933306 [1;33mDLGLOBAL[0;m <0010> telnet_interface.c:104 telnet at 127.0.0.1 4241
[0;m20180516131933307 [1;33mDLINP[0;m <0012> input/ipaccess.c:891 enabling ipaccess BTS mode, OML connecting to 10.42.42.7:3002
[0;m20180516131933307 [1;34mDABIS[0;m <000d> abis.c:229 Input Signal 4 received
[0;m20180516131933307 [1;32mDL1C[0;m <0006> phy_link.c:58 PHY link state change shutdown -> connecting
[0;m20180516131933307 [1;33mDL1C[0;m <0006> l1_if.c:1740 Opening L1 interface for OctPHY (enp2s0)
[0;m20180516131933321 [1;33mDLINP[0;m <0012> input/ipa.c:131 10.42.42.7:3002 connection done
[0;m20180516131933321 [1;33mDLINP[0;m <0012> input/ipaccess.c:712 received ID get from 8/0/0
[0;m20180516131933322 [1;32mDABIS[0;m <000d> abis.c:107 OML Signalling link up
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=SITE-MANAGER INST=(ff,ff,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=GPRS-NSE INST=(00,ff,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=GPRS-CELL INST=(00,ff,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=GPRS-NSVC INST=(00,00,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=GPRS-NSVC INST=(00,01,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
[0;m[1;36m20180516131933322 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=RADIO-CARRIER INST=(00,00,ff) AVAIL STATE Power off -> OK
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=RADIO-CARRIER INST=(00,00,ff) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:467 OC=RADIO-CARRIER INST=(00,00,ff) Tx SW ACT REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) AVAIL STATE Power off -> OK
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:467 OC=BASEBAND-TRANSCEIVER INST=(00,00,ff) Tx SW ACT REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,00) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,00) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,00) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,01) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,01) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,01) Tx STATE CHG REP
[0;m[1;36m20180516131933323 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,02) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,02) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,02) Tx STATE CHG REP
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,03) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,03) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,03) Tx STATE CHG REP
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,04) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,04) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,04) Tx STATE CHG REP
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,05) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,05) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,05) Tx STATE CHG REP
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,06) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,06) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,06) Tx STATE CHG REP
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:348 OC=CHANNEL INST=(00,00,07) AVAIL STATE Power off -> Dependency
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=CHANNEL INST=(00,00,07) OPER STATE NULL -> Disabled
[0;m[1;36m20180516131933324 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=CHANNEL INST=(00,00,07) Tx STATE CHG REP
[0;m[1;36m20180516131933325 [1;34mDOML[0;m[1;36m <0001> oml.c:548 OC=BTS(01) INST=(ff,ff,ff) [0;m[1;36mRx GET ATTR
[0;m[1;36m20180516131933325 [1;32mDOML[0;m[1;36m <0001> oml.c:277 BTS Tx Get Attribute Response
[0;m[1;36m20180516131933380 [1;34mDOML[0;m[1;36m <0001> oml.c:548 OC=BASEBAND-TRANSCEIVER(04) INST=(00,00,ff) [0;m[1;36mRx GET ATTR
[0;m[1;36m20180516131933380 [1;32mDOML[0;m[1;36m <0001> oml.c:277 BASEBAND-TRANSCEIVER Tx Get Attribute Response
[0;m[1;36m20180516131933380 [1;31mDOML[0;m[1;36m <0001> oml.c:229 O&M Get Attributes [0], Manufacturer Dependent State is unsupported by TRX.
[0;m[1;36m20180516131933382 [1;34mDOML[0;m[1;36m <0001> oml.c:1001 OC=SITE-MANAGER(00) INST=(ff,ff,ff) [0;m[1;36mRx OPSTART
[0;m[1;36m20180516131933382 [1;34mDOML[0;m[1;36m <0001> oml.c:1012 ... automatic ACK, OP state already was Enabled
[0;m[1;36m20180516131933383 [1;34mDOML[0;m[1;36m <0001> oml.c:580 OC=BTS(01) INST=(00,ff,ff) [0;m[1;36mRx SET BTS ATTR
[0;m[1;36m20180516131933383 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933383 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933383 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933383 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933383 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933384 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933384 [1;33mDOML[0;m[1;36m <0001> oml.c:681 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
[0;m[1;36m20180516131933384 [1;34mDOML[0;m[1;36m <0001> oml.c:451 Sending FOM ACK.
[0;m[1;36m20180516131933385 [1;34mDOML[0;m[1;36m <0001> oml.c:1029 OC=BTS(01) INST=(00,ff,ff) [0;m[1;36mRx CHG ADM STATE
[0;m[1;36m20180516131933385 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933386 [1;34mDOML[0;m[1;36m <0001> oml.c:1001 OC=BTS(01) INST=(00,ff,ff) [0;m[1;36mRx OPSTART
[0;m[1;36m20180516131933386 [1;32mDOML[0;m[1;36m <0001> oml.c:355 OC=BTS INST=(00,ff,ff) OPER STATE NULL -> Enabled
[0;m[1;36m20180516131933386 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=BTS INST=(00,ff,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933430 [1;34mDOML[0;m[1;36m <0001> oml.c:1001 OC=RADIO-CARRIER(02) INST=(00,00,ff) [0;m[1;36mRx OPSTART
[0;m[1;36m20180516131933432 [1;34mDOML[0;m[1;36m <0001> oml.c:750 OC=RADIO-CARRIER(02) INST=(00,00,ff) [0;m[1;36mRx SET RADIO CARRIER ATTR
[0;m[1;36m20180516131933432 [1;32mDOML[0;m[1;36m <0001> oml.c:782 Set RF Max Power Reduction = 0 dBm
[0;m20180516131933432 [1;32mDL1C[0;m <0006> tx_power.c:248 power_ramp_start(cur=0, tgt=0)
[0;m[1;36m20180516131933432 [1;34mDOML[0;m[1;36m <0001> oml.c:451 Sending FOM ACK.
[0;m[1;36m20180516131933433 [1;34mDOML[0;m[1;36m <0001> oml.c:1029 OC=RADIO-CARRIER(02) INST=(00,00,ff) [0;m[1;36mRx CHG ADM STATE
[0;m[1;36m20180516131933434 [1;33mDOML[0;m[1;36m <0001> oml.c:1055 ADM state already was Unlocked
[0;m[1;36m20180516131933434 [1;32mDOML[0;m[1;36m <0001> oml.c:313 OC=RADIO-CARRIER INST=(00,00,ff) Tx STATE CHG REP
[0;m[1;36m20180516131933435 [1;34mDOML[0;m[1;36m <0001> oml.c:1001 OC=RADIO-CARRIER(02) INST=(00,00,ff) [0;m[1;36mRx OPSTART
[0;m20180516131933435 [1;32mDL1C[0;m <0006> l1_oml.c:1228 Tx APP-INFO.req
[0;m20180516131933435 [1;32mDL1C[0;m <0006> l1_oml.c:1159 Tx APP-INFO-SYSTEM.req
[0;m20180516131933436 [1;32mDL1C[0;m <0006> l1_oml.c:1364 Tx TRX-OPEN.req(trx=0, rf_port=0, arfcn=868, center=868, tsc=7, rx_gain=70, tx_atten=0)
[0;m20180516131934384 [1;31mDLINP[0;m <0012> e1_input.c:235 abis_sendmsg: msg->dst == NULL: 0c 12 01 90 0f ff ff 
[0;m20180516131934433 [1;32mDL1C[0;m <0006> tx_power.c:181 ramping TRX board output power to 0 mdBm.
[0;m20180516131935385 [1;31mDLINP[0;m <0012> e1_input.c:235 abis_sendmsg: msg->dst == NULL: 0c 12 01 90 0f ff ff 
[0;m20180516131936385 [1;31mDLINP[0;m <0012> e1_input.c:235 abis_sendmsg: msg->dst == NULL: 0c 12 01 90 0f ff ff 
[0;m20180516131937386 [1;31mDLINP[0;m <0012> e1_input.c:235 abis_sendmsg: msg->dst == NULL: 0c 12 01 90 0f ff ff 
[0;m20180516131938321 [1;31mDL1C[0;m <0006> l1_if.c:203 Timeout waiting for L1 primitive TRX-CLOSE-ALL

Attach a run.tar.gz from osmo-gsm-tester showing the issue.