Project

General

Profile

Bug #4207

multi-arfcn not working properly

Added by pespin 3 months ago. Updated 8 days ago.

Status:
In Progress
Priority:
Normal
Assignee:
Category:
-
Target version:
-
Start date:
09/16/2019
Due date:
% Done:

0%

Spec Reference:

Description

I did some tests today with multi-arfcn with a B200 device (only kind of device supporting the feature now) before working on adding multiTRX support on LimeSDR (requires multi-arfcn support too).

I did some code clean up and applied some fixes submitted by other people. Some of them:
https://gerrit.osmocom.org/c/osmo-trx/+/15541 radioInterface: Mark setRxGain as virtual
https://gerrit.osmocom.org/c/osmo-trx/+/15542 Move multi-ARFCN chan amount modification from UHDDevice to parent class
https://gerrit.osmocom.org/c/osmo-trx/+/15413 Transceiver: Fixed copying of history into and from channelizer buffer.
https://gerrit.osmocom.org/c/osmo-trx/+/15521/1 radioInterfaceMulti: Override setTxGain() to avoid chan!=0 calls

I also had to --disable-sanitize on osmo-trx, otherwise I'm unable to have my laptop running everything on time.

I am using 2 TRX on ARFCN 870 and 872 (band 1800), and using channel allocator descend to have 2nd TRX being used at LU time.

Well, it seems RACH is working fine, but then after Assignment Request (on SDCCH in 2nd TRX), the BTS doesn't see any answer on that channel in the 2nd TRX.

However, some related notification seems to arrive to OsmoBTS but FN of the indication seems to be wrong:

20190916175256262 DRSL <0000> rsl.c:2948 (bts=0,trx=0,ts=0,ss=4) Fwd RLL msg CHAN_RQD from LAPDm to A-bis
20190916175256262 DRSL <0000> rsl.c:3042 (bts=0,trx=1,ts=0,pchan=SDCCH8) ss=0 Rx RSL CHAN_ACTIV
20190916175256262 DRSL <0000> rsl.c:1234 (bts=0,trx=1,ts=0,ss=0) chan_nr=SDCCH/8(0) on TS0 type=0x00 mode=SIGNALLING
20190916175256262 DL1C <0006> l1sap.c:1503 (bts=0,trx=1,ts=0,ss=0) activating channel chan_nr=SDCCH/8(0) on TS0 trx=1
20190916175256262 DL1C <0006> scheduler.c:981 Activating SDCCH/8(0) on trx=1 ts=0
20190916175256262 DL1C <0006> scheduler.c:981 Activating SACCH/8(0) on trx=1 ts=0
20190916175256262 DL1C <0006> scheduler.c:1029 Set mode 3, 0, handover 0 on SDCCH/8(0) of trx=1 ts=0
20190916175256262 DTRX <000b> trx_if.c:239 phy0.1: Enqueuing TRX control command 'CMD NOHANDOVER 0 0'
20190916175256262 DLLAPD <0011> lapd_core.c:296 Init DL layer: sequence range = 8, k = 1, history range = 2 (dl=0x7ffff6c1d388)
20190916175256262 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d388)
20190916175256262 DLLAPD <0011> lapd_core.c:296 Init DL layer: sequence range = 8, k = 1, history range = 2 (dl=0x7ffff6c1d510)
20190916175256262 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d510)
20190916175256262 DLLAPD <0011> lapd_core.c:296 Init DL layer: sequence range = 8, k = 1, history range = 2 (dl=0x7ffff6c1d6d8)
20190916175256262 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d6d8)
20190916175256262 DLLAPD <0011> lapd_core.c:296 Init DL layer: sequence range = 8, k = 1, history range = 2 (dl=0x7ffff6c1d860)
20190916175256262 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d860)
20190916175256262 DL1C <0006> scheduler.c:1094 Set a5/0 uplink for SDCCH/8(0) on trx=1 ts=0
20190916175256262 DL1C <0006> scheduler.c:1094 Set a5/0 uplink for SACCH/8(0) on trx=1 ts=0
20190916175256262 DL1C <0006> scheduler.c:1094 Set a5/0 downlink for SDCCH/8(0) on trx=1 ts=0
20190916175256262 DL1C <0006> scheduler.c:1094 Set a5/0 downlink for SACCH/8(0) on trx=1 ts=0
20190916175256262 DL1C <0006> l1sap.c:620 (bts=0,trx=1,ts=0,ss=0) activate confirm chan_nr=SDCCH/8(0) on TS0 trx=1
20190916175256262 DRSL <0000> rsl.c:810 (bts=0,trx=1,ts=0,pchan=SDCCH8) (ss=0) SDCCH Tx CHAN ACT ACK
20190916175256262 DTRX <000b> trx_if.c:581 phy0.1: Response message: 'RSP NOHANDOVER 0 0 0'
20190916175256262 DRSL <0000> rsl.c:2982 (bts=0,trx=0,ts=0,ss=0) Rx RSL IMM_ASS_CMD
20190916175256356 DTRX <000b> trx_if.c:120 phy0.0: Clock indication: fn=501217
20190916175256356 DL1C <0006> scheduler_trx.c:1796 TRX Clock Ind: elapsed_us= 997122, elapsed_fn=216, error_us= +282
20190916175256356 DL1C <0006> scheduler_trx.c:1815 GSM clock jitter: -3473us (elapsed_fn=0)
20190916175256367 DL1P <0007> scheduler.c:664 501260/378/06/32/12 (bts=0,trx=1,ts=0) SACCH/8(0): Prim 498274 vs exp 501260 = 2712662 <--- I added this print myself to log the difference, since I usually saw the line below:
20190916175256367 DL1P <0007> scheduler.c:666 501260/378/06/32/12 (bts=0,trx=1,ts=0) SACCH/8(0): Prim 2712662 is out of range (100), or channel (bts=0,trx=1,ts=0,ss=1) with type SACCH/8(0) is already disabled. If this happens in conjunction with PCU, increase 'rts-advance' by 5.
20190916175257354 DTRX <000b> trx_if.c:120 phy0.0: Clock indication: fn=501433
20190916175257354 DL1C <0006> scheduler_trx.c:1796 TRX Clock Ind: elapsed_us= 997662, elapsed_fn=216, error_us= +822
20190916175257354 DL1C <0006> scheduler_trx.c:1815 GSM clock jitter: -4218us (elapsed_fn=0)
20190916175258351 DTRX <000b> trx_if.c:120 phy0.0: Clock indication: fn=501650
20190916175258351 DL1C <0006> scheduler_trx.c:1796 TRX Clock Ind: elapsed_us= 997527, elapsed_fn=217, error_us=-3928
20190916175258351 DL1C <0006> scheduler_trx.c:1815 GSM clock jitter: -201us (elapsed_fn=0)
20190916175259263 DRSL <0000> rsl.c:3042 (bts=0,trx=1,ts=0,pchan=SDCCH8) ss=0 Rx RSL RF_CHAN_REL
20190916175259263 DL1C <0006> l1sap.c:1551 (bts=0,trx=1,ts=0,ss=0) deactivating channel chan_nr=SDCCH/8(0) on TS0 trx=1
20190916175259263 DL1C <0006> scheduler.c:981 Deactivating SACCH/8(0) on trx=1 ts=0
20190916175259263 DTRX <000b> trx_if.c:239 phy0.1: Enqueuing TRX control command 'CMD NOHANDOVER 0 0'
20190916175259263 DL1C <0006> scheduler.c:981 Deactivating SDCCH/8(0) on trx=1 ts=0
20190916175259263 DL1C <0006> l1sap.c:643 (bts=0,trx=1,ts=0,ss=0) deactivate confirm chan_nr=SDCCH/8(0) on TS0 trx=1
20190916175259263 DRSL <0000> rsl.c:789 (bts=0,trx=1,ts=0,pchan=SDCCH8) (ss=0) SDCCH Tx CHAN REL ACK
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_IDLE (dl=0x7ffff6c1d388)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d388)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_IDLE (dl=0x7ffff6c1d510)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d510)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_IDLE (dl=0x7ffff6c1d6d8)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d6d8)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_IDLE (dl=0x7ffff6c1d860)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d860)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d388)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d388)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d510)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d510)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d6d8)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d6d8)
20190916175259263 DLLAPD <0011> lapd_core.c:311 Resetting LAPDm instance
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_NULL -> LAPD_STATE_IDLE (dl=0x7ffff6c1d860)
20190916175259263 DLLAPD <0011> lapd_core.c:237 new state LAPD_STATE_IDLE -> LAPD_STATE_NULL (dl=0x7ffff6c1d860)
20190916175259263 DTRX <000b> trx_if.c:581 phy0.1: Response message: 'RSP NOHANDOVER 0 0 0'

So it seems some related indication is received but time seems to be incorrect and hecne the indication is dropped...

History

#1 Updated by pespin 3 months ago

I have the feeling osmo-trx is somehow keeping behind osmo-bts-trx over time. It can be seen from some osmo-trx log messages I see from time to time (see receive buffer becoming more and more filled over time):

Mon Sep 16 18:16:44 2019 DMAIN <0000> Transceiver.cpp:1122 [tid=139802715313920] ClockInterface: sending IND CLOCK 810722
Mon Sep 16 18:16:45 2019 DMAIN <0000> sigProcLib.cpp:1639 [tid=139802706921216] Detected RACH Burst: TSC=0
Mon Sep 16 18:16:45 2019 DMAIN <0000> sigProcLib.cpp:1639 [tid=139802706921216] Detected RACH Burst: TSC=0
Mon Sep 16 18:16:45 2019 DMAIN <0000> Transceiver.cpp:1122 [tid=139802715313920] ClockInterface: sending IND CLOCK 810938
ULMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:6 (underrun 2:811040 vs 3:490224)
OMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1482.84 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4745172891 time_end=4745094307
ULLLLLLMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:7 (underrun 6:811050 vs 2:811050)
LLLLOMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1482.89 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4745340933 time_end=4745245420
ULLLLLLMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:8 (underrun 6:811061 vs 6:811060)
LLLOMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1482.94 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4745520506 time_end=4745413462
OMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4745696546 time_end=4745593035
UMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:9 (underrun 4:811081 vs 6:811071)
LLOMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.05 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4745890977 time_end=4745769075
ULLMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:10 (underrun 7:811092 vs 4:811091)
LLLULULLLLLLMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:11 (underrun 3:811103 vs 7:811102)
OMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.11 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4746108473 time_end=4745963506
OMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.18 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4746334160 time_end=4746181002
ULMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:12 (underrun 0:811120 vs 3:811113)
LLULMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:13 (underrun 3:811133 vs 0:811130)
OMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.25 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4746578764 time_end=4746406689
Mon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1122 [tid=139802715313920] ClockInterface: sending IND CLOCK 811154
OMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.33 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4746827043 time_end=4746651293
ULMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:14 (underrun 4:811159 vs 3:811143)
LLOMon Sep 16 18:16:46 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.41 sec.
Mon Sep 16 18:16:46 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4747094775 time_end=4746899572
UUMon Sep 16 18:16:46 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:15 (underrun 2:811171 vs 4:811169)
LULMon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:16 (underrun 6:811181 vs 2:811181)
UOMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.49 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4747393497 time_end=4747167304
ULULMon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:17 (underrun 4:811195 vs 6:811191)
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.58 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4747694939 time_end=4747466026
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.68 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4747996277 time_end=4747767468
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.77 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4748310961 time_end=4748068806
UMon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:18 (underrun 5:811252 vs 4:811205)
UMon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:19 (underrun 5:811265 vs 5:811262)
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.87 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4748643246 time_end=4748383490
UMon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:20 (underrun 4:811286 vs 5:811275)
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1483.97 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4748992660 time_end=4748715775
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.08 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4749346284 time_end=4749065189
ULMon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:21 (underrun 4:811320 vs 4:811296)
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.19 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4749710087 time_end=4749418813
Mon Sep 16 18:16:47 2019 DMAIN <0000> Transceiver.cpp:1122 [tid=139802715313920] ClockInterface: sending IND CLOCK 811370
OMon Sep 16 18:16:47 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.31 sec.
Mon Sep 16 18:16:47 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4750066756 time_end=4749782616
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.42 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4750432663 time_end=4750139285
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.53 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4750771684 time_end=4750505192
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.64 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4751101341 time_end=4750844213
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.74 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4751445543 time_end=4751173870
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.85 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4751800369 time_end=4751518072
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1484.96 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4752169849 time_end=4751872898
UMon Sep 16 18:16:48 2019 DMAIN <0000> Transceiver.cpp:1087 [tid=139802723706624] new latency: 0:22 (underrun 4:811514 vs 4:811330)
LLLLULOMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1485.08 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4752554365 time_end=4752242378
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1485.2 sec.
Mon Sep 16 18:16:48 2019 DDEV <0002> smpl_buf.cpp:109 [tid=139802715313920] Skipping buffer data: timestamp=4752923864 time_end=4752626894
Mon Sep 16 18:16:48 2019 DMAIN <0000> Transceiver.cpp:1122 [tid=139802715313920] ClockInterface: sending IND CLOCK 811586
Mon Sep 16 18:16:48 2019 DMAIN <0000> sigProcLib.cpp:1639 [tid=139802706921216] Detected RACH Burst: TSC=0
OMon Sep 16 18:16:48 2019 DDEV <0002> UHDDevice.cpp:648 [tid=139802715313920] An internal receive buffer has filled at 1485.31 sec.

#2 Updated by pespin 3 months ago

As soon as I change "channel allocator descending" to "ascending", then MS can register and I no longer receive that kind of errors in osmo-bts-trx.

#3 Updated by pespin 14 days ago

#4 Updated by pespin 8 days ago

BSC tears down the channel due to no response (Establish Indication, T3101) after assignment request on the 2nd TRX:

20191127132649176 DRSL <0003> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/abis_rsl.c:1372 (bts=0) CHAN RQD: reason: Location updating (ra=0x02, neci=0x01, chreq_reason=0x03)
...
20191127132649176 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_select.c:235 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{UNUSED}: (type=SDCCH) Selected
...
20191127132649176 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/abis_rsl.c:1154 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK
20191127132649176 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_fsm.c:737 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_ACTIV_ACK}: (type=SDCCH) Tx RR Immediate Assignment
20191127132649176 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_fsm.c:787 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_ACTIV_ACK}: state_chg to WAIT_RLL_RTP_ESTABLISH
20191127132649176 DLMI <0018> /home/pespin/dev/sysmocom/git/libosmo-abis/src/input/ipaccess.c:358 TX 2: 0c 16 01 90 2b 17 2d 06 3f 03 40 e3 68 02 83 a1 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b
20191127132649185 DHODEC <0009> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/handover_decision_2.c:1837 (BTS 0) No congestion check: Assignment and Handover both disabled
20191127132649185 DHODEC <0009> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/handover_decision_2.c:161 HO algorithm 2: next periodical congestion check in 10 seconds
20191127132650082 DLMI <0018> /home/pespin/dev/sysmocom/git/libosmo-abis/src/input/ipaccess.c:253 RX 2: 0c 12 01 90 0f ff ff
20191127132651082 DLMI <0018> /home/pespin/dev/sysmocom/git/libosmo-abis/src/input/ipaccess.c:253 RX 2: 0c 12 01 90 0f ff ff
20191127132652082 DLMI <0018> /home/pespin/dev/sysmocom/git/libosmo-abis/src/input/ipaccess.c:253 RX 2: 0c 12 01 90 0f ff ff
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/libosmocore/src/fsm.c:322 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RLL_RTP_ESTABLISH}: Timeout of T3101
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_fsm.c:1325 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) Handling failure, will then transition to state WAIT_RF_RELEASE_ACK
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_fsm.c:80 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) lchan allocation failed in state WAIT_RLL_RTP_ESTABLISH: Timeout
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_fsm.c:1325 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK
20191127132652178 DLMI <0018> /home/pespin/dev/sysmocom/git/libosmo-abis/src/input/ipaccess.c:358 TX 3: 08 2e 01 40
20191127132652178 DLMI <0018> /home/pespin/dev/sysmocom/git/libosmo-abis/src/input/ipaccess.c:253 RX 3: 08 33 01 40
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/abis_rsl.c:1142 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RF_RELEASE_ACK}: (type=SDCCH) Rx RF_CHAN_REL_ACK
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/abis_rsl.c:1174 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RF_RELEASE_ACK}: Received Event LCHAN_EV_RSL_RF_CHAN_REL_ACK
20191127132652178 DCHAN <0010> /home/pespin/dev/sysmocom/git/osmo-bsc/src/osmo-bsc/lchan_fsm.c:1057 lchan(0-1-0-SDCCH8-0)[0x55555592b830]{WAIT_RF_RELEASE_ACK}: state_chg to WAIT_AFTER_ERROR

I'm still trying to find out what's going wrong at the TRX/BTS.

I attach a pcap file with TRXD, TRXC, GMSTAP, RSL, and gsmtap_log with following config:

log gsmtap 127.0.0.2
 logging level set-all info
 logging filter all 1

#6 Updated by fixeria 8 days ago

I attach a pcap file with TRXD, TRXC, GMSTAP, RSL, and gsmtap_log with following config:

I don't see anything received on the Uplink TRX1/TS0 from the MS. Several Uplink bursts between RSL CHAN_ACTIV and RSL CHAN_REL look more like noise (false-positive detection), given that their C/I values are too low.

Can you try with OsmocomBB? So we could understand what's happening on the MS side.
Do you also see this behaviour when using fake_trx.py / trxcon?

#7 Updated by pespin 8 days ago

I just tried with a TEMS phone and I can see the ARFCN 872 SDCCH TS 0 appearing in the GSM Dedicated Mode page, but I don't seem to be able to get more information than that. The TEMS phone acts exactly as the other regular phone I was using. But at least we know that the assignment request arrives correctly to the MS over ARFCN 870 (TRX0). I'll give a try to osmocom-bb with trxcon and so.

#8 Updated by pespin 8 days ago

  • Status changed from New to In Progress

I'm still fighting to set up my osmo-bts-trx + fake_trx + trxcon + mobile (so far everything loks fine except mobile not properly using simcard info and not doing LU). Meanwhile fixeria did a quick test with his setup (same as explained above) and multi-trx seems to be working fine.

Next step will be re-using mobile with the motrola CXX + osmocon + osmo-trx + osmo-bts-trx to confirm it's then broken somewhere in osmo-trx.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)