Project

General

Profile

Bug #4102

osmo-bts-trx: incorrect PTCCH handling

Added by fixeria about 1 month ago. Updated 26 days ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
osmo-bts-trx
Target version:
-
Start date:
07/12/2019
Due date:
% Done:

0%

Spec Reference:
3GPP TS 45.002, 3GPP TS 45.010

Description

According to 3GPP TS 45.002, section 6.3.2.2.2, and 3GPP TS 45.010, section 3.3.4.2:

  • PTCCH/D (Packet Timing advance control channel, Downlink) is used to transmit Timing Advance updates for several MS. One PTCCH/D is paired with several PTCCH/U's. PTCCH/D frames are encoded using CS-1.
  • PTCCH/U (Packet Timing advance control channel, Uplink) is used to transmit random access bursts to allow estimation of the Timing Advance for one MS in packet transfer mode. PTCCH/U has 16 sub-channels (0..15) assigned to different MS using TAI.

Therefore, neither we properly handle Downlink PTCCH nor Uplink PTCCH in osmo-bts-trx:

https://git.osmocom.org/osmo-bts/tree/src/common/scheduler.c#n536

[TRXC_PTCCH] = {
    .name = "PTCCH", /* 3GPP TS 05.02, section 3.3.4.2 */
    .desc = "Packet Timing advance control channel",
    .chan_nr = RSL_CHAN_OSMO_PDCH,

    /* Same as for TRXC_BCCH (xCCH), see above. */
    .flags = TRX_CHAN_FLAG_PDCH,
    .rts_fn = rts_data_fn,
    .dl_fn = tx_data_fn, /* FIXME: we need tx_pdtch_fn() here! */
    .ul_fn = rx_data_fn, /* FIXME: we need rx_rach_fn() here! */
},
ptcch_errors_sc5_2.pcapng.gz ptcch_errors_sc5_2.pcapng.gz 440 KB pespin, 07/23/2019 07:06 PM

Related issues

Related to OsmoPCU - Feature #1545: continuous timing advance loop using PTCCHStalled02/23/2016

History

#1 Updated by fixeria about 1 month ago

  • Related to Feature #1545: continuous timing advance loop using PTCCH added

#2 Updated by pespin 26 days ago

Consequence of not having this implemented: rx_data_fn is used to decode the PTCCH bursts, and then these errors appear all the time with osmo-bts-trx connected to an SC5 TRX:

20190723193916529 DTRX <000b> trx_if.c:120 Clock indication: fn=79572
20190723193916529 DL1C <0006> scheduler_trx.c:1772 TRX Clock Ind: elapsed_us=1061562, elapsed_fn=230, error_us= +112
20190723193916529 DL1C <0006> scheduler_trx.c:1790 GSM clock jitter: -4601us (elapsed_fn=0)
20190723193916900 DL1P <0007> scheduler_trx.c:981 079650/60/12/39/34 (bts=0,trx=0,ts=6) PTCCH: Received bad data (79572/12)
20190723193916901 DL1P <0007> scheduler_trx.c:981 079650/60/12/39/34 (bts=0,trx=0,ts=7) PTCCH: Received bad data (79572/12)
20190723193917381 DL1P <0007> scheduler_trx.c:981 079754/60/12/41/34 (bts=0,trx=0,ts=6) PTCCH: Received bad data (79676/12)
20190723193917382 DL1P <0007> scheduler_trx.c:981 079754/60/12/41/34 (bts=0,trx=0,ts=7) PTCCH: Received bad data (79676/12)
20190723193917591 DTRX <000b> trx_if.c:120 Clock indication: fn=79802
20190723193917591 DL1C <0006> scheduler_trx.c:1772 TRX Clock Ind: elapsed_us=1061499, elapsed_fn=230, error_us=  +49
20190723193917591 DL1C <0006> scheduler_trx.c:1790 GSM clock jitter: -4584us (elapsed_fn=0)
20190723193917861 DL1P <0007> scheduler_trx.c:981 079858/60/12/43/34 (bts=0,trx=0,ts=6) PTCCH: Received bad data (79780/12)
20190723193917862 DL1P <0007> scheduler_trx.c:981 079858/60/12/43/34 (bts=0,trx=0,ts=7) PTCCH: Received bad data (79780/12)
20190723193918341 DL1P <0007> scheduler_trx.c:981 079962/60/12/45/38 (bts=0,trx=0,ts=6) PTCCH: Received bad data (79884/12)
20190723193918341 DL1P <0007> scheduler_trx.c:981 079962/60/12/45/38 (bts=0,trx=0,ts=7) PTCCH: Received bad data (79884/12)
20190723193918652 DTRX <000b> trx_if.c:120 Clock indication: fn=80032
20190723193918652 DL1C <0006> scheduler_trx.c:1772 TRX Clock Ind: elapsed_us=1061489, elapsed_fn=230, error_us=  +39
20190723193918652 DL1C <0006> scheduler_trx.c:1790 GSM clock jitter: -4558us (elapsed_fn=0)
20190723193918821 DL1P <0007> scheduler_trx.c:981 080066/60/12/47/38 (bts=0,trx=0,ts=6) PTCCH: Received bad data (79988/12)
20190723193918822 DL1P <0007> scheduler_trx.c:981 080066/60/12/47/38 (bts=0,trx=0,ts=7) PTCCH: Received bad data (79988/12)
20190723193919301 DL1P <0007> scheduler_trx.c:981 080170/60/12/49/42 (bts=0,trx=0,ts=6) PTCCH: Received bad data (80092/12)
20190723193919302 DL1P <0007> scheduler_trx.c:981 080170/60/12/49/42 (bts=0,trx=0,ts=7) PTCCH: Received bad data (80092/12)
20190723193919714 DTRX <000b> trx_if.c:120 Clock indication: fn=80262
20190723193919714 DL1C <0006> scheduler_trx.c:1772 TRX Clock Ind: elapsed_us=1061622, elapsed_fn=230, error_us= +172
20190723193919714 DL1C <0006> scheduler_trx.c:1790 GSM clock jitter: -4594us (elapsed_fn=0)
20190723193919780 DL1P <0007> scheduler_trx.c:981 080274/60/12/00/42 (bts=0,trx=0,ts=6) PTCCH: Received bad data (80196/12)
20190723193919781 DL1P <0007> scheduler_trx.c:981 080274/60/12/00/42 (bts=0,trx=0,ts=7) PTCCH: Received bad data (80196/12)
20190723193920261 DL1P <0007> scheduler_trx.c:981 080378/60/12/02/42 (bts=0,trx=0,ts=6) PTCCH: Received bad data (80300/12)
20190723193920261 DL1P <0007> scheduler_trx.c:981 080378/60/12/02/42 (bts=0,trx=0,ts=7) PTCCH: Received bad data (80300/12)
20190723193920740 DL1P <0007> scheduler_trx.c:981 080482/60/12/04/46 (bts=0,trx=0,ts=6) PTCCH: Received bad data (80404/12)
20190723193920741 DL1P <0007> scheduler_trx.c:981 080482/60/12/04/46 (bts=0,trx=0,ts=7) PTCCH: Received bad data (80404/12)
20190723193920775 DTRX <000b> trx_if.c:120 Clock indication: fn=80492

#3 Updated by fixeria 26 days ago

[...] and then these errors appear all the time with osmo-bts-trx connected to an SC5 TRX [...]

I would really love to see a capture of the TRXD interface. We don't have PS Timing Advance control implemented at the moment, so I would expect nothing on PTCCH, excluding false-positive detections of course.

$ cd osmocom-bb/src/target/trx_toolkit/
$ sudo ./trx_sniff.py --direction L1 --timeslot 7 -p 5700 -o /tmp/ul_bursts.dump

#4 Updated by pespin 26 days ago

Running the command in that scenario provides no L1 log lines and a .dump file of 0 bytes (I checked the tool works fine on another scenario with osmo-trx).

#5 Updated by pespin 26 days ago

Sorry, it actually fins the packets, I was not passing the correct interface to sniff on. Once I set that correctly, .dump file is still 0 bytes, but I get lots of these messages:

[WARNING] trx_sniff.py:98 Failed to parse message, dropping...

#6 Updated by pespin 26 days ago

I attach a raw pcap dump in case it's useful.

#7 Updated by fixeria 26 days ago

Here is a part of what I've managed to decode from your capture:

$ ./trx_sniff.py -r /tmp/ptcch_errors_sc5_2.pcap --direction L1 --timeslot 6 --frame-count 52
[INFO] trx_sniff.py:72 Reading packets from '/tmp/ptcch_errors_sc5_2.pcap'...
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161148 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161149 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161150 tn=6 rssi=-103 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161151 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161152 tn=6 rssi=-103 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161153 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161154 tn=6 rssi=-103 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161155 tn=6 rssi=-102 toa256=256
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161156 tn=6 rssi=-103 toa256=-128
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161157 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161158 tn=6 rssi=-102 toa256=-448
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161159 tn=6 rssi=-102 toa256=448
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161160 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161161 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161162 tn=6 rssi=-103 toa256=0
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161163 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161164 tn=6 rssi=-103 toa256=0
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161165 tn=6 rssi=-103 toa256=640
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161166 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161167 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161168 tn=6 rssi=-103 toa256=-256
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161169 tn=6 rssi=-103 toa256=-448
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161170 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161171 tn=6 rssi=-102 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161172 tn=6 rssi=-103 toa256=448
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161173 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161174 tn=6 rssi=-102 toa256=-320
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161175 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161176 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161177 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161178 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161179 tn=6 rssi=-102 toa256=-192
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161180 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161181 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161182 tn=6 rssi=-102 toa256=-320
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161183 tn=6 rssi=-102 toa256=-320
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161184 tn=6 rssi=-103 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161185 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161186 tn=6 rssi=-103 toa256=64
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161187 tn=6 rssi=-103 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161188 tn=6 rssi=-102 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161189 tn=6 rssi=-102 toa256=256
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161190 tn=6 rssi=-103 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161191 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161192 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161193 tn=6 rssi=-102 toa256=-512
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161194 tn=6 rssi=-102 toa256=-320
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161195 tn=6 rssi=-103 toa256=704
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161196 tn=6 rssi=-103 toa256=-448
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161197 tn=6 rssi=-103 toa256=-320
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161198 tn=6 rssi=-103 toa256=768
[DEBUG] trx_sniff.py:125 TRX -> L1 burst: fn=1161199 tn=6 rssi=-103 toa256=768
[INFO] trx_sniff.py:188 Collected required amount of frames
[INFO] trx_sniff.py:194 Shutting down...
[INFO] trx_sniff.py:198 52 bursts handled, 738 dropped

As far as I can see, your SC5 TRX detects pretty much everything on PDCH - just look at TDMA frame numbers.
RSSI is quite low (looks like noise), while ToA256 values are not that bad...

You don't see PDTCH decoding errors because unlike rx_data_fn(), rx_pdtch_fn() uses LOGL_DEBUG:

LOGL1S(DL1P, LOGL_DEBUG, l1t, bi->tn, chan, bi->fn, "Received bad PDTCH (%u/%u)\n", ...);
LOGL1S(DL1P, LOGL_NOTICE, l1t, bi->tn, chan, bi->fn, "Received bad data (%u/%u)\n", ...);

Looks like a problem of SC5. Feel free to investigate and fill a separate bug report.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)