Actions
Bug #4622
openLots of "dumping STALE burst in TRX->SDR interface" messages in osmo-trx after osmo-bts-trx proper restart
Start date:
06/18/2020
Due date:
% Done:
0%
Spec Reference:
Description
Running osmo-bts-trx with osmo-trx-uhd using a B200 with multi-arfcn enabled and 2 TRX.
Then osmo-bts-trx enters a "graceful exit" due to Abis signal lost (eg: kill BSC process). As part of "graceful exit", BTS will ramp down power, and finally send CMD POWEROFF and wait for RSP POWEROFF before exiting the process.
At this point in time, osmo-trx is still running waiting for next osmo-bts-trx to connect to it and do a "POWERON".
When osmo-bts-trx is restarted and connects to it after a few seconds, and does the "POWERON", then LOTS of messages like this show up in the log during a few seconds/minutes
Remark: I'm using my WIP branch to have all those graceful shutdown features I'm mentioning, but they will be merged soon and they are not the "cause" of the issue.
So clearly there's something wrong during 2nd POWERON (POWERON->POWEROFF->wait some time->POWERON). Probably some state is kept regarding reading timestamps and then upon 2nd POWERON osmo-trx somehow tries to catch up.
20200618185527592 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967881 vs 5:967952), retrans=0 20200618185527592 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967881 vs 5:967952), retrans=0 20200618185527592 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (5:967881 vs 5:967952), retrans=0 20200618185527592 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (6:967881 vs 5:967952), retrans=0 20200618185527592 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (7:967883 vs 5:967952), retrans=0 20200618185527592 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (7:967881 vs 6:967952), retrans=0 20200618185527596 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (0:967882 vs 4:967953), retrans=0 20200618185527596 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (1:967882 vs 4:967953), retrans=0 20200618185527596 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (6:967884 vs 4:967953), retrans=0 20200618185527596 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (2:967882 vs 5:967953), retrans=0 20200618185527597 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967882 vs 5:967953), retrans=0 20200618185527597 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967882 vs 5:967953), retrans=0 20200618185527597 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (5:967882 vs 5:967953), retrans=0 20200618185527597 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (7:967884 vs 5:967953), retrans=0 20200618185527597 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (6:967882 vs 6:967953), retrans=0 20200618185527597 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (7:967882 vs 6:967953), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (0:967883 vs 4:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (6:967885 vs 4:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (1:967883 vs 5:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (2:967883 vs 5:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967883 vs 5:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967883 vs 5:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (5:967883 vs 5:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (6:967883 vs 5:967954), retrans=0 20200618185527601 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (7:967885 vs 5:967954), retrans=0 20200618185527602 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (7:967883 vs 6:967954), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (0:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (1:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (2:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (5:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (6:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (7:967884 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (6:967886 vs 5:967955), retrans=0 20200618185527606 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (7:967886 vs 5:967955), retrans=0 20200618185527610 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (0:967885 vs 5:967956), retrans=0 20200618185527610 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (1:967885 vs 5:967956), retrans=0 20200618185527610 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (2:967885 vs 5:967956), retrans=0 20200618185527610 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967885 vs 5:967956), retrans=0 20200618185527610 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967885 vs 5:967956), retrans=0 20200618185527610 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (5:967885 vs 5:967956), retrans=0 20200618185527611 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (6:967885 vs 5:967956), retrans=0 20200618185527611 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (7:967885 vs 5:967956), retrans=0 20200618185527611 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (6:967887 vs 5:967956), retrans=0 20200618185527611 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (7:967887 vs 5:967956), retrans=0 20200618185527614 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (0:967886 vs 4:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (6:967888 vs 4:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (1:967886 vs 5:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (2:967886 vs 5:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967886 vs 5:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967886 vs 5:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (5:967886 vs 5:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=1] dumping STALE burst in TRX->SDR interface (7:967888 vs 5:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (6:967886 vs 6:967957), retrans=0 20200618185527615 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (7:967886 vs 6:967957), retrans=0 20200618185527620 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (0:967887 vs 5:967958), retrans=0 20200618185527620 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (1:967887 vs 5:967958), retrans=0 20200618185527620 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (2:967887 vs 5:967958), retrans=0 20200618185527620 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (3:967887 vs 5:967958), retrans=0 20200618185527620 DTRXDDL <0003> Transceiver.cpp:428 [tid=139983326238464][chan=0] dumping STALE burst in TRX->SDR interface (4:967887 vs 5:967958), retrans=0
Updated by Hoernchen almost 4 years ago
I'm a bit suprised this works at all, since the internal state is kept on stop/poweroff, so the smpl_buf keep their timestamps, which means that at least for the IPC backend a restart where the other side resets the timestamps (as expected) does not work. In this case it works as long as the timeout until it restarts is not long enough for the timestamp to wrap, so the data is still "newer".
Obviious question here: do we want to support start/stop without restarting osmo-trx? In that case the state needs to be reset upon stopping.
Updated by pespin almost 4 years ago
Yes we should support it. I'm happy if you want to take care about this one since you already seem to found the issue.
bear in mind the issue was found with osmo-trx-uhd, but I guess it affects other backends too.
Updated by fixeria almost 4 years ago
Huh, this may be related to a similar thing I saw with fake_trx.py [1]:
2020-06-30 07:45:56 [DEBUG] ctrl_if_trx.py:123 (BTS@172.18.9.20:5700) Recv POWEROFF cmd 2020-06-30 07:45:56 [INFO] ctrl_if_trx.py:125 (BTS@172.18.9.20:5700) Stopping transceiver... 2020-06-30 07:45:56 [INFO] transceiver.py:257 Stopping clock generator 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=0 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=1 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=2 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=3 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=4 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=5 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=6 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2197 tn=7 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=0 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=1 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=2 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=3 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=4 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=5 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=6 bl=148 pwr=0), but transceiver is not running => dropping... 2020-06-30 07:45:56 [WARNING] transceiver.py:269 (BTS@172.18.9.20:5700) RX TRXD message (ver=1 fn=2198 tn=7 bl=148 pwr=0), but transceiver is not running => dropping...
so osmo-bts-trx keeps scheduling and sending Downlink bursts even after sending TRXC POWEROFF command.
Probably, until the response is received from transceiver.
Actions
