Project

General

Profile

Bug #4207

multi-arfcn not working properly

Added by pespin 4 months ago. Updated 9 days ago.

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

100%

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...


Related issues

Related to OsmoTRX - Bug #3346: osmo-trx-lms: Multi channel support: "R_CTL_LPF range limit reached"Rejected06/13/2018

History

#1 Updated by pespin 4 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 4 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 2 months ago

#4 Updated by pespin about 2 months 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 about 2 months 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 about 2 months 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 about 2 months 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.

#9 Updated by pespin about 1 month ago

I was finally able to get my osmo-bts-trx + fake_trx + trxcon + mobile set up (I was having issues with cell selection using "sim none" instead of "sim test", and other stuff).

I attach a pcap file showing a working LU over 2nd TRX in a 2 TRX multi-trx setup with osmo-bts-trx.
Hence, it is confirmed that the bug is somewhere in osmo-trx.

#10 Updated by pespin about 1 month ago

  • Related to Bug #3346: osmo-trx-lms: Multi channel support: "R_CTL_LPF range limit reached" added

#11 Updated by pespin about 1 month ago

I now did set up similar env but this time using osmo-trx attached to osmo-bts-trx connected through air to motorola CXX + osmocon attached to mobile.

This time the bug appears as expected. I attach a pcap trace with all GSMTAP, TRXD, etc. GSMTAP enabled in mobile uses 127.0.0.2, while the one enabled in osmo-bts-trx uses 127.0.0.1. This way it's easy to see who receives/sees and sends what.

  • On one hand, it seems mobile doesn't see the downlink LAPDm frames sent by bts-trx on ARFCN 872 (2nd TRX). It only sees some empty Paging Requests from time to time (which could be crafted in lower layers by mobile itself? because I don't see them in GSMTAP of the bts-trx sender).
  • On the other hand, it seems bts-trx doesn't see the uplink Location Update Request frames being sent over and over by mobile in the 2nd TRX as requested (ARFCN 872).

While debugging this, I fixed the uplink ARFCN send in mobile during gsmtap_send, which was always zero:
https://gerrit.osmocom.org/c/osmocom-bb/+/16658 mobile: Send correct ARFCN in UL gsmtap

#12 Updated by pespin about 1 month ago

BTW, that's the output of mobile during the LU process:

<000e> /src/host/layer23/src/mobile/gsm48_mm.c:343 Location update retry
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:344 timer T3211 (loc. upd. retry delay) has fired
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:4310 (ms mymobile) Received 'MM_EVENT_TIMEOUT_T3211' event in state MM IDLE, attempting to update
<000e> /src/host/layer23/src/mobile/gsm48_mm.c:2204 Perform location update (MCC 234, MNC 70 LAC 0x0005)
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:2340 LOCATION UPDATING REQUEST
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:2360  using LAI (mcc 234 mnc 70 lac 0x0000)
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:2373  using IMSI 901700000015254
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:909 new state MM IDLE, attempting to update -> wait for RR connection (location updating)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:5441 (ms mymobile) Message 'RR_EST_REQ' received in state idle (sapi 0)
<000e> /src/host/layer23/src/mobile/gsm48_rr.c:1297 Establish radio link due to mobility management request
<0003> /src/host/layer23/src/mobile/gsm322.c:4054 (ms mymobile) Event 'EVENT_LEAVE_IDLE' for Cell selection in state 'C3 camped normally'
<0003> /src/host/layer23/src/mobile/gsm322.c:833 new state 'C3 camped normally' -> 'connected mode 1'
<0003> /src/host/layer23/src/mobile/gsm322.c:3671 Going to camping (normal) ARFCN 870(DCS).
<0003> /src/host/layer23/src/mobile/gsm322.c:464 Sync to ARFCN=870(DCS) rxlev=-63 (Sysinfo, ccch mode COMB)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:357 new state idle -> connection pending
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1444 CHANNEL REQUEST: 00 (Location Update with NECI)
<0003> /src/host/layer23/src/mobile/gsm322.c:2950 Channel synched. (ARFCN=870(DCS), snr=16, BSIC=63)
<0001> /src/host/layer23/src/mobile/gsm322.c:2973 using DSC of 90
<0003> /src/host/layer23/src/mobile/gsm48_rr.c:4814 Channel provides data.
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1583 RANDOM ACCESS (requests left 8)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1639 RANDOM ACCESS (Tx-integer 12 combined yes S(lots) 0 ra 0x0f)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1675 Use MS-TXPWR-MAX-CCH power value 31 (32 dBm)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1583 RANDOM ACCESS (requests left 7)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1639 RANDOM ACCESS (Tx-integer 12 combined yes S(lots) 115 ra 0x06)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:1675 Use MS-TXPWR-MAX-CCH power value 31 (32 dBm)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-57 snr= 0 ber=  0 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2424 IMMEDIATE ASSIGNMENT:
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2442  (ta 0/0m ra 0x0f chan_nr 0x40 ARFCN 872(DCS) TS 0 SS 0 TSC 7)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2358 request 0f matches (fn=28,5,23)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2472 resetting scheduler
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:3213 sending establish message
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:229 Using and incrementing V(SD) = 0 (pdisc 5)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2949 setting indicated TA 0 (actual TA 0)
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2964 using last BCCH timeout 32
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:823 stopping pending timer T_meas
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=1 rxlev-full=-110 rxlev-sub=-110 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2983 establishing channel in dedicated mode
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2985  Channel type 64, subch 0, ts 0, mode 0, audio-mode 5, cipher 1
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 79 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 31
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 87 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 30
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 75 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-87 snr=61 ber=100 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-87 rxlev-sub=-87 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 75 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 29
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 83 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 88 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 75 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 28
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 90 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-98 snr=82 ber=120 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-98 rxlev-sub=-98 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 27
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 87 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 80 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 26
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 75 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 78 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-96 snr=81 ber=132 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-96 rxlev-sub=-96 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 25
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 86 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 80 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 24
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 77 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 87 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 68 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-96 snr=80 ber=129 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-96 rxlev-sub=-96 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 23
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 75 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 68 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 22
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-99 snr=78 ber=180 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-99 rxlev-sub=-99 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 21
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 75 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 83 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 20
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 89 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 73 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 77 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-98 snr=80 ber=174 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-98 rxlev-sub=-98 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 19
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 79 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 77 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 84 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 18
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 85 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 82 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 17
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 84 bit errors
<0015> /home/pespin/dev/sysmocom/git/libosmocore/src/gsm/lapd_core.c:392 sending MDL-ERROR-IND cause 1 from state LAPD_STATE_IDLE (dl=0x555555710f78)
<0015> /home/pespin/dev/sysmocom/git/libosmocore/src/gsm/lapdm.c:481 sending MDL-ERROR-IND 1
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-99 snr=82 ber=157 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-99 rxlev-sub=-99 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<0000> /src/host/layer23/src/mobile/gsm48_rr.c:5312 RSLms message 'ERROR_IND' unhandled
<000e> /src/host/layer23/src/mobile/gsm48_rr.c:3341 Radio link is released
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:777 starting T_rel_wait with 1.500 seconds
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:357 new state connection pending -> release pending
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:3902 (ms mymobile) Received 'RR_REL_IND' from RR in state wait for RR connection (location updating) (sapi 0)
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:2739 RR link released after loc. upd.
<000e> /src/host/layer23/src/mobile/gsm48_mm.c:2683 Location update failed
<0005> /src/host/layer23/src/mobile/subscriber.c:1074 (ms mymobile) new state U2_NOT_UPDATED -> U2_NOT_UPDATED
<000e> /src/host/layer23/src/mobile/gsm48_mm.c:2722 Try location update later
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:1086 Not camping, wait for CS process to camp, it sends us CELL_SELECTED then.
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 85 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 74 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 16
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 79 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 80 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 77 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 15
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 86 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 84 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:665 MON: f=870 lev=-98 snr=81 ber=135 LAI=234 70 0005 ID=0000
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:2845 MEAS REP: pwr=31 TA=0 meas-invalid=0 rxlev-full=-98 rxlev-sub=-98 rxqual-full=0 rxqual-sub=0 dtx 0 ba 0 no-ncell-n 7
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 90 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:216 LOSS counter for ACCH 14
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 85 bit errors
<000c> /src/host/layer23/src/common/l1ctl.c:226 Dropping frame with 81 bit errors
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:709 L2 release timer has fired, done waiting
<0001> /src/host/layer23/src/mobile/gsm48_rr.c:357 new state release pending -> idle
<0003> /src/host/layer23/src/mobile/gsm322.c:4054 (ms mymobile) Event 'EVENT_RET_IDLE' for Cell selection in state 'connected mode 1'
<0003> /src/host/layer23/src/mobile/gsm322.c:3583 Selecting ARFCN 870(DCS). after LOC.UPD.
<0003> /src/host/layer23/src/mobile/gsm322.c:464 Sync to ARFCN=870(DCS) rxlev=-63 (Sysinfo, ccch mode COMB)
<0003> /src/host/layer23/src/mobile/gsm322.c:833 new state 'connected mode 1' -> 'C3 camped normally'
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:4315 (ms mymobile) Received 'MM_EVENT_CELL_SELECTED' event in state wait for RR connection (location updating)
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:1093 Starting T3211 after RR release.
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:411 starting T3211 (loc. upd. retry delay) with 15.0 seconds
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:1141 We are camping normally as returning to MM IDLE
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:1166 Loc. upd. allowed.
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:914 new state wait for RR connection (location updating) -> MM IDLE, location updating needed
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:904 new MM IDLE state location updating needed -> attempting to update
<0005> /src/host/layer23/src/mobile/gsm48_mm.c:2222 Loc. upd. already pending.

So AFAIU it confirms that MS doesn't receive anything on that ARFCN.

#13 Updated by laforge about 1 month ago

On Thu, Dec 19, 2019 at 05:30:18PM +0000, pespin [REDMINE] wrote:

It only sees some empty Paging Requests from time to time (which could be crafted in lower layers by mobile itself? because I don't see them in GSMTAP of the bts-trx sender).

If the MS is on the dedicated channel of the second TRX, it shouldn't see any DL PCH. DL PCH only exists on
the primary TRX. Maybe it interprets some other frames as such? For sure the MS is not generating any
downlink frames itself.

  • On the other hand, it seems bts-trx doesn't see the uplink Location Update Request frames being sent over and over by mobile in the 2nd TRX as requested (ARFCN 872).

Maybe they're tuned to different frequencies? It would probably be best to verify that there is actually
energy transmitted by the second TRX (using RSSI app on osmocomBB). To see that best, you would want to
activate all timeslots / lchans on the second TRX, as it will only transmit on active TS, and not on inactive ones.

#14 Updated by pespin about 1 month ago

laforge wrote:

On Thu, Dec 19, 2019 at 05:30:18PM +0000, pespin [REDMINE] wrote:

It only sees some empty Paging Requests from time to time (which could be crafted in lower layers by mobile itself? because I don't see them in GSMTAP of the bts-trx sender).

If the MS is on the dedicated channel of the second TRX, it shouldn't see any DL PCH. DL PCH only exists on
the primary TRX. Maybe it interprets some other frames as such? For sure the MS is not generating any
downlink frames itself.

Sorry I was not clear here. The lines showing up on mobile gsmtap for PCH apparently come from CCCH (PCH), ARFCN 870, that's the 1st TRX.

Interestingly, filtering for PCH received in mobile, those messages appearing have a pattern. It's always: ABB-ABB-ABB-ABB-... where A is a gsmtap message with empty payload, and B is the empty Paging request Type. Between A and first B there's always 6 FN, and between the 2 B's it's always 4 FN.

BTW, current code sending GSMTAP from received content in mobile cannot distinguish between PCH and AGCH, so it can show stuff as coming from PCH which actually is received over AGCH (for instance the Immediate Assignment asking it to jump to the SDCCH on the 2nd TRX), it's explained in a comment in the code too.

And actually looking at the pattern the Immediate Assignment is in the place where the empty PCH is usually seen, so that means the empty PCH is usually AGCH I guess.

  • On the other hand, it seems bts-trx doesn't see the uplink Location Update Request frames being sent over and over by mobile in the 2nd TRX as requested (ARFCN 872).

Maybe they're tuned to different frequencies? It would probably be best to verify that there is actually
energy transmitted by the second TRX (using RSSI app on osmocomBB). To see that best, you would want to
activate all timeslots / lchans on the second TRX, as it will only transmit on active TS, and not on inactive ones.

tuned to different frequencies? how can that be? the ARFCNs have a specific related frequency right? You mean something's wrong in the multi-arfcn which may be putting the 2nd trx into the wrong frequency?

I'll check that RSSI app tomorrow. IIRC there's a VTY to activate lchans in BSC, I'll check that too.

#15 Updated by laforge about 1 month ago

On Thu, Dec 19, 2019 at 11:16:24PM +0000, pespin [REDMINE] wrote:

tuned to different frequencies? how can that be? the ARFCNs have a specific related frequency right?

yes, they should. The question is what you can trust and what not.

You mean something's wrong in the multi-arfcn which may be putting the 2nd trx into the wrong frequency?

possibly.

I'll check that RSSI app tomorrow. IIRC there's a VTY to activate lchans in BSC, I'll check that too.

yes, that exists in the BSC. Keep in mind you also want to set an indefinite/unlimited radio link timeout as
otherwise they will be closed automatically after a few seconds without any uplink traffic.

another thing that could happen is that the TSC is somehow different. If you see energy on the right ARFCN,
but it cannot be decoded, the TSC might be wrong. As there's only 8, it's possible to brute-force by
hard-coding different ones in the receiver.

I believe RSSI app can also show you energy in each timeslot, so you should be able to see if that
matches your expectations in terms of which timeslots are transmitting and which not:
https://osmocom.org/projects/baseband/wiki/Rssibin
- however, it may be that the app only can do that for TRX0 and not any other ARFCN.

#16 Updated by pespin about 1 month ago

Phantom AGCH/PCH messages in GSMTAP from mobile are fixed and don't show up after applying:
https://gerrit.osmocom.org/c/osmocom-bb/+/16663 layer23: Identify AGCH from PCH on tx of GSMTAP downlink messages
https://gerrit.osmocom.org/c/osmocom-bb/+/16664 layer23: Avoid sending downlink AGCH/PCH fill frames over GSMTAP

#17 Updated by pespin about 1 month ago

  • % Done changed from 0 to 50

I found the issue thanks to rssibin spectrum view and some later tests.

The multi-arfcn feature allocates trx in following order of ARFCN: N, N+4, N+2, and I was using ARFCN=870, ARFCN=872. As soon as I move it to ARFCN=874 it works fine.

so the problem is that osmo-trx is not checking that requested RX/TX TUNE are compatible with limitations of multi-arfcn.

TODO:
  • Add checks in RXTUNE/TXTUNE commands to fail if tunning doesn't make sense regarding how ARFCNs are set when multi-arfcn is enabled.
  • Make sure this limitation (N, N+4, N+2) is explained in osmo-trx user manual.

#18 Updated by pespin about 1 month ago

  • Status changed from In Progress to Feedback
  • % Done changed from 50 to 90

Typo in my last comment:

s/following order of ARFCN: N, N+4, N+2/following order of ARFCN: N, N+4, N+8/

User Manual is already up to date explaining correctly that spacing is 4 ARFCNs and not 2.

osmo-trx now fails during RXTUNE/TXTUNE if frequencies don't follow correct spacing when multi-arfcn is used:
https://gerrit.osmocom.org/c/osmo-trx/+/16668 radioInterfaceMulti: Fail to tune on freq not following multi-arfcn restrictions

TODO:
  • reenable multi-arfcn test in osmo-gsm-tester, but I think that can be done as part of #3346

#19 Updated by pespin 9 days ago

  • Status changed from Feedback to Resolved
  • % Done changed from 90 to 100

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)