Bug #4102
closedosmo-bts-trx: incorrect PTCCH handling
Added by fixeria almost 5 years ago. Updated over 4 years ago.
100%
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! */ },
Files
ptcch_errors_sc5_2.pcapng.gz | ptcch_errors_sc5_2.pcapng.gz | 440 KB | pespin, 07/23/2019 07:06 PM |
Related issues
Updated by fixeria almost 5 years ago
- Related to Feature #1545: continuous timing advance loop using PTCCH added
Updated by pespin almost 5 years 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
Updated by fixeria almost 5 years 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
Updated by pespin almost 5 years 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).
Updated by pespin almost 5 years 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...
Updated by pespin almost 5 years ago
I attach a raw pcap dump in case it's useful.
Updated by fixeria almost 5 years 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.
Updated by pespin over 4 years ago
Related patches for trxcon:
https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/15637
https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/15638
Something similar needs to be done in osmo-bts-trx.
Updated by fixeria over 4 years ago
- Status changed from New to In Progress
- Assignee set to fixeria
Updated by fixeria over 4 years ago
- Status changed from In Progress to Feedback
- % Done changed from 0 to 80
Please see: https://gerrit.osmocom.org/c/osmo-bts/+/15656 scheduler: fix handling of PTCCH/U and PTCCH/D logical channels.
Now we need a TTCN-3 test case to verify PTCCH operation in both directions (changes for trxcon need to be merged first).
Updated by fixeria over 4 years ago
- % Done changed from 80 to 100
https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/15792 BTS_Tests.ttcn: add a test case for PTCCH/D and PTCCH/U