Bug #2988
closedunexpected bit errors when using trxcon and osmo-bts-trx
Added by laforge about 6 years ago. Updated almost 5 years ago.
100%
Description
On a fully virtual setup without any error simulation I'm seeing bit errors:
% (0/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> measurement.c:297 001880/01/08/44/36 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=2 DMEAS <0004> l1_if.c:515 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1885 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> measurement.c:297 001885/01/13/49/41 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=3 DMEAS <0004> l1_if.c:515 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1889 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> measurement.c:297 001889/01/17/02/45 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=4 DMEAS <0004> l1_if.c:515 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1893 chan_nr=0x09 MS pwr=0dBm rssi=-128.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> measurement.c:297 001893/01/21/06/49 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=5 DMEAS <0004> l1_if.c:515 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1898 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> measurement.c:297 001898/01/00/11/02 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=6 DMEAS <0004> l1_if.c:515 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1902 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> measurement.c:297 001902/01/04/15/06 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=7
Files
| 20180223-os2988-trx-ber.pcapng | 20180223-os2988-trx-ber.pcapng | 1.24 KB | laforge, 02/23/2018 05:02 PM | ||
| osmo_bts_dtrx_dl1d.log | osmo_bts_dtrx_dl1d.log | 40 KB | fixeria, 02/23/2018 09:36 PM | ||
| tch_f_gaps.pcapng.gz | tch_f_gaps.pcapng.gz | 6.23 KB | fixeria, 02/25/2018 06:09 PM |
Related issues
Updated by laforge about 6 years ago
Here some more log lines of where this happens:
DMEAS <0004> l1_if.c:515 001300/00/00/25/20 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1300 chan_nr=0x09 MS pwr=0dBm rssi=-128.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 001304/00/04/29/24 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=1304 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 000268/00/08/13/12 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=268 chan_nr=0x09 MS pwr=0dBm rssi=-128.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 000273/00/13/18/17 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=273 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 000580/00/08/19/16 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=580 chan_nr=0x09 MS pwr=0dBm rssi=-128.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 000585/00/13/24/21 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=585 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 000684/00/08/21/16 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=684 chan_nr=0x09 MS pwr=0dBm rssi=-128.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DMEAS <0004> l1_if.c:515 000689/00/13/26/21 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=689 chan_nr=0x09 MS pwr=0dBm rssi=-100.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00
all others blocks are fine, just every so often there are one/two that have high BER.
When enabling at higher amount of debugging, I can see:
DL1P <0007> scheduler_trx.c:979 000329/00/17/23/21 (bts=0,trx=0,ts=1) TCH/F: Received TCH/F, bid=0 DL1P <0007> scheduler_trx.c:979 000330/00/18/24/22 (bts=0,trx=0,ts=1) TCH/F: Received TCH/F, bid=1 DL1P <0007> scheduler_trx.c:979 000331/00/19/25/23 (bts=0,trx=0,ts=1) TCH/F: Received TCH/F, bid=2 DL1P <0007> scheduler_trx.c:979 000332/00/20/26/24 (bts=0,trx=0,ts=1) TCH/F: Received TCH/F, bid=3 DMEAS <0004> l1_if.c:515 000329/00/17/23/21 RX L1 frame (bts=0,trx=0,ts=1,ss=0) fn=329 chan_nr=0x09 MS pwr=0dBm rssi=-128.0 dBFS ber=50.00% (228/456 bits) L1_ta=0 rqd_ta=0 toa=0.00 DL1P <0007> l1sap.c:517 000329/00/17/23/21 (bts=0,trx=0,ts=1,ss=0) MPH_INFO meas ind, ta_offs_qbits=0, ber10k=5000, inv_rssi=128 DMEAS <0004> measurement.c:297 000329/00/17/23/21 (bts=0,trx=0,ts=1,ss=0) adding measurement (is_sub=0), num_ul_meas=4
So it is not UDP packet loss between trxcon and osmo-bts-trx, as all four bursts can be seen, in order from FN 329..332. So the actual burst payload likely is corrupted somehow, resulting in 50% BER being reported. As it's always 50%, I suspect that two of the four bursts are probably wrong - or decoded wrongly.
There doesn't seem to be a particular (modulo) frame number at which this happens.
What's also interesting is the -128dBm RSSI, as opposed to the -100dBm for all the good bursts. I've configured fake_trx to use constant RSSI=100.
A PCAP file containing the four burst from the last log output is attached. Doesn't look like complete garbage to me.
Updated by fixeria about 6 years ago
- File osmo_bts_dtrx_dl1d.log osmo_bts_dtrx_dl1d.log added
Hi Harald,
What's also interesting is the -128dBm RSSI, as opposed to the -100dBm
for all the good bursts. I've configured fake_trx to use constant RSSI=100.
Well, this is more than interesting ;)
And this is probably the root of the problem.
At the moment fake_trx.py sets a hard-coded RSSI value for each UL burst.
There shouldn't be any exceptions.
After playing with logging levels of both DL1D and DTRX, adding additional
verbosity to existing functions, and grepping by `grep -E "(RX burst|Received)"`,
I've got the following interesting results (sample call log is attached):
<000b> trx_if.c:562 RX burst tn=0 fn=4968 rssi=-53 toa=0.00 <0007> scheduler_trx.c:726 004968/03/02/21/00 (bts=0,trx=0,ts=0) RACH: Received RACH toa=0.00 <000b> trx_if.c:562 RX burst tn=1 fn=5064 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005064/03/20/15/44 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=0 <000b> trx_if.c:562 RX burst tn=1 fn=5065 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005065/03/21/16/45 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=1 <000b> trx_if.c:562 RX burst tn=1 fn=5066 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005066/03/22/17/46 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=2 <000b> trx_if.c:562 RX burst tn=1 fn=5067 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005067/03/23/18/47 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=3 <000b> trx_if.c:562 RX burst tn=1 fn=5217 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005217/03/17/15/45 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=0 <000b> trx_if.c:562 RX burst tn=1 fn=5218 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005218/03/18/16/46 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=1 <000b> trx_if.c:562 RX burst tn=1 fn=5219 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005219/03/19/17/47 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=2 <000b> trx_if.c:562 RX burst tn=1 fn=5220 rssi=-53 toa=0.00 <0007> scheduler_trx.c:782 005220/03/20/18/48 (bts=0,trx=0,ts=1) SDCCH/8(0): Received Data, bid=3 ...
This is how everything should work. When we've got a burst from TRX,
it is passed to the scheduler, which then passes it to a corresponding
handler. Let's try to make a call:
... trx_if.c:562 RX burst tn=2 fn=46007 rssi=-53 toa=0.00 scheduler_trx.c:979 046007/34/13/05/27 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=0, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46008 rssi=-53 toa=0.00 scheduler_trx.c:979 046008/34/14/06/28 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=1, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46009 rssi=-53 toa=0.00 scheduler_trx.c:979 046009/34/15/07/29 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=2, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46010 rssi=-53 toa=0.00 scheduler_trx.c:979 046010/34/16/08/30 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=3, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46032 rssi=-53 toa=0.00 ... trx_if.c:562 RX burst tn=2 fn=46526 rssi=-53 toa=0.00 scheduler_trx.c:782 046526/35/12/14/34 (bts=0,trx=0,ts=2) SACCH/TF: Received Data, bid=0 trx_if.c:562 RX burst tn=2 fn=46552 rssi=-53 toa=0.00 scheduler_trx.c:782 046552/35/12/40/08 (bts=0,trx=0,ts=2) SACCH/TF: Received Data, bid=1 trx_if.c:562 RX burst tn=2 fn=46557 rssi=-53 toa=0.00 scheduler_trx.c:979 046553/35/13/41/09 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=0, rssi=-128, toa=0.000000 scheduler_trx.c:979 046554/35/14/42/10 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=1, rssi=-128, toa=0.000000 scheduler_trx.c:979 046555/35/15/43/11 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=2, rssi=-128, toa=0.000000 scheduler_trx.c:979 046556/35/16/44/12 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=3, rssi=-128, toa=0.000000 scheduler_trx.c:979 046557/35/17/45/13 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=0, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46558 rssi=-53 toa=0.00 scheduler_trx.c:979 046558/35/18/46/14 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=1, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46559 rssi=-53 toa=0.00 scheduler_trx.c:979 046559/35/19/47/15 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=2, rssi=-53, toa=0.000000 trx_if.c:562 RX burst tn=2 fn=46560 rssi=-53 toa=0.00 scheduler_trx.c:979 046560/35/20/48/16 (bts=0,trx=0,ts=2) TCH/F: Received TCH/F, bid=3, rssi=-53, toa=0.000000 ...
Pay your attention at the lines with rssi=-128. Unlike others, they
aren't followed by DTRX messages. So, they don't come from transceiver,
so from where then? ;)
Updated by laforge about 6 years ago
This is burst substitution in case of discontinuous frame numbers in the bursts. It's somewhat expected with trxcon, as it only transmits bursts of active channels, and for a TCH/F, that's 24 out of the 26 multiframe.
However, such bursts ending up in the TCH means that actual TCH bursts have somehow been missed/dropped between trxcon and osmo-bts-trx, which is a real concern.
I've added a log message about this condition in https://gerrit.osmocom.org/6870
Updated by fixeria about 6 years ago
- File tch_f_gaps.pcapng.gz tch_f_gaps.pcapng.gz added
- % Done changed from 0 to 10
There is another problem, which I think also related to this issue.
Please see attached trace, and pay your attention at long gaps
between the messages sent by mobile (lapdm filter) and received
by the network (gsm_abis_rsl filter).
I think, the problem is related to to the current (probably incorrect)
implementation of TCH chanel coding in trxcon, see trx_lchan_tchf.c.
The receive part is working fine, because I managed to make actual
voice decoding work, what I cannot say about the transmit part...
The usage of 8 bursts and buffer shifting still make me hard
to understand, how does the current OsmoBTS implementation work.
Updated by fixeria about 6 years ago
For better understanding how does TCH/F burst mapping work, I am adding this great picture.
Updated by fixeria about 6 years ago
I just a bit hacked trxcon to provide constant frame flow, no matter is there anything in the TX queue:
@@ -93,6 +97,20 @@ static void sched_frame_clck_cb(struct trx_sched *sched)
if (lchan->prim == NULL)
lchan->prim = sched_prim_dequeue(&ts->tx_prims, chan);
+ /* HACK: we shall always transmit something! */
+ if (lchan->prim == NULL) {
+ /* Let's test TCH/F first */
+ if (chan == TRXC_TCHF && lchan->tch_mode == GSM48_CMODE_SPEECH_V1) {
+ LOGP(DSCH, LOGL_ERROR, "Adding dummy TCH/FR frame\n");
+
+ sched_prim_init(trx, &lchan->prim, 33, 0x08, 0x00);
+
+ /* Compose a silence frame */
+ sched_bad_frame_ind(lchan->prim->payload,
+ RSL_CMOD_SPD_SPEECH, GSM48_CMODE_SPEECH_V1);
+ }
+ }
+
/* If there is no primitive, do nothing */
if (lchan->prim == NULL)
continue;
So, now OsmoBTS says the following:
... <0007> scheduler.c:917 148706/112/12/41/18 Substituting all-zero burst (current_fn=148707, elapsed=2 <0007> scheduler.c:917 148732/112/12/16/44 Substituting all-zero burst (current_fn=148733, elapsed=2 <0007> scheduler.c:917 148862/112/12/44/22 Substituting all-zero burst (current_fn=148863, elapsed=2 <0007> scheduler.c:917 148888/112/12/19/48 Substituting all-zero burst (current_fn=148889, elapsed=2 <0007> scheduler.c:917 148914/112/12/45/22 Substituting all-zero burst (current_fn=148915, elapsed=2 <0007> scheduler.c:917 148940/112/12/20/48 Substituting all-zero burst (current_fn=148941, elapsed=2 <0007> scheduler.c:917 148966/112/12/46/22 Substituting all-zero burst (current_fn=148967, elapsed=2 <0007> scheduler.c:917 148992/112/12/21/00 Substituting all-zero burst (current_fn=148993, elapsed=2 <0007> scheduler.c:917 149018/112/12/47/26 Substituting all-zero burst (current_fn=149019, elapsed=2 <0007> scheduler.c:917 149044/112/12/22/00 Substituting all-zero burst (current_fn=149045, elapsed=2 <0007> scheduler.c:917 149174/112/12/50/26 Substituting all-zero burst (current_fn=149175, elapsed=2 <0007> scheduler.c:917 149200/112/12/25/00 Substituting all-zero burst (current_fn=149201, elapsed=2 <0007> scheduler.c:917 149226/112/12/00/26 Substituting all-zero burst (current_fn=149227, elapsed=2 <0007> scheduler.c:917 149252/112/12/26/04 Substituting all-zero burst (current_fn=149253, elapsed=2 <0007> scheduler.c:917 149382/112/12/03/30 Substituting all-zero burst (current_fn=149383, elapsed=2 <0007> scheduler.c:917 149408/112/12/29/04 Substituting all-zero burst (current_fn=149409, elapsed=2 <0007> scheduler.c:917 149434/112/12/04/30 Substituting all-zero burst (current_fn=149435, elapsed=2 <0007> scheduler.c:917 149460/112/12/30/04 Substituting all-zero burst (current_fn=149461, elapsed=2 <0007> scheduler.c:917 149590/112/12/07/34 Substituting all-zero burst (current_fn=149591, elapsed=2 <0007> scheduler.c:917 149616/112/12/33/08 Substituting all-zero burst (current_fn=149617, elapsed=2 <0007> scheduler.c:917 149642/112/12/08/34 Substituting all-zero burst (current_fn=149643, elapsed=2 <0007> scheduler.c:917 149668/112/12/34/08 Substituting all-zero burst (current_fn=149669, elapsed=2 ...
These numbers are being repeated in period...
I've created a simple Python script to calculate a position within
a multiframe for TCH/F TS2 and this is what I am getting:
fn=148031 % 104 = 39 fn=148057 % 104 = 65 fn=148083 % 104 = 91 fn=148109 % 104 = 13 fn=148239 % 104 = 39 fn=148265 % 104 = 65 fn=148291 % 104 = 91 fn=148317 % 104 = 13 fn=148447 % 104 = 39 fn=148473 % 104 = 65 fn=148499 % 104 = 91 fn=148525 % 104 = 13 fn=148655 % 104 = 39 fn=148681 % 104 = 65 fn=148707 % 104 = 91 fn=148733 % 104 = 13 fn=148863 % 104 = 39 fn=148889 % 104 = 65
Looking at the multiframe layout now...
Updated by fixeria about 6 years ago
Hmm, more interesting details:
... fn=148109 % 104 = 13 fn=148239 % 104 = 39 fn=148265 % 104 = 65 fn=148291 % 104 = 91 ...
The numbers don't seem to be random, there is sequence:
39 - 13 = 26 65 - 39 = 26 91 - 65 = 26
So, OsmoBTS detects a missing frame after each 26 frames == tch_mf_period...
What if OsmocomBB/trxcon has incorrect layout pointer?
In other words, trxcon may thing that a current frame is TRXC_IDLE, while actual frame isn't?
This is probably related to the scheduler clock advance (by default, 20), so this makes
the scheduler think 20 frames in advance, but breaks the multiframe mapping...
Updated by fixeria about 6 years ago
Damn, I was looking to the current_fn instead of the missing frame number.
... 148732/112/12/16/44 Substituting all-zero burst (current_fn=148733, elapsed=2 148862/112/12/44/22 Substituting all-zero burst (current_fn=148863, elapsed=2 148888/112/12/19/48 Substituting all-zero burst (current_fn=148889, elapsed=2 148914/112/12/45/22 Substituting all-zero burst (current_fn=148915, elapsed=2 148940/112/12/20/48 Substituting all-zero burst (current_fn=148941, elapsed=2 148966/112/12/46/22 Substituting all-zero burst (current_fn=148967, elapsed=2 ...
now, doing the same math:
... 148732 % 104 = 12 148862 % 104 = 38 148888 % 104 = 64 148914 % 104 = 90 148940 % 104 = 12 148966 % 104 = 38 ...
According to the 'tchf_ts2' multiframe structure, this always
corresponds to a TRXC_SACCHTF logical channel. Interesting.
Updated by fixeria about 6 years ago
- Project changed from OsmoBTS to OsmocomBB
- Status changed from New to In Progress
- Priority changed from Normal to High
- % Done changed from 10 to 60
The reason of this issue is that the current implementation of
trxcon's TDMA scheduler doesn't transmit anything if there are
no L2 frames in TX buffers.
This could be easily fixed if a I knew, what a mobile side
should transmit if there is nothing to transmit? ;)
Dummy bursts? Dummy LAPDm-frames?
Updated by fixeria about 6 years ago
- Status changed from In Progress to Feedback
Review: https://gerrit.osmocom.org/7206/
Updated by fixeria about 6 years ago
- Status changed from Feedback to In Progress
Merged. There are still some problems when a TCH mode is changed.
At the moment a lchan->tch_mode is changed immediately, and it
causes some decoding errors on both sides.
@LaF0rge, should I change it after a specific fn?
could you point me to the specifications?
I was (quick) looking at TS 04.08, section 5.3.4.3
"Changing the Call Mode", but didn't find any details...
Updated by fixeria about 6 years ago
- Status changed from In Progress to Feedback
After merging the https://gerrit.osmocom.org/7206/,
I am getting the following messages on the BSC side:
<0000> abis_rsl.c:2177 (bts=0,trx=0,ts=1,ss=0) SAPI=0 ERROR INDICATION <0000> abis_rsl.c:2119 (bts=0,trx=0,ts=1,ss=0) ERROR INDICATION cause=Frame not implemented in state=ACTIVE <0000> abis_rsl.c:2177 (bts=0,trx=0,ts=1,ss=0) SAPI=0 ESTABLISH INDICATION
The Calypso PHY is sending the following frame:
https://git.osmocom.org/osmocom-bb/tree/src/target/firmware/layer1/prim_utils.c#n29
static const uint8_t ubUui[23] = {
/* dummy lapdm header */
0x01, 0x03, 0x01,
/* fill bytes */
0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b,
0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b,
0x2b, 0x2b, 0x2b, 0x2b
};
while trxcon is sending:
https://git.osmocom.org/osmocom-bb/tree/src/host/trxcon/sched_prim.c?h=fixeria/trx#n248
/**
* TS 144.006, section 8.4.2.3 "Fill frames"
* A fill frame is a UI command frame for SAPI 0, P=0
* and with an information field of 0 octet length.
*/
static const uint8_t lapdm_fill_frame[] = {
0x01, 0x03, 0x01,
/* Pending part is to be randomized */
};
The only difference is that the padding is being randomized.
Updated by fixeria about 6 years ago
On the BTS side:
<0000> rsl.c:662 (bts=0,trx=0,ts=1,ss=0) Tx CHAN ACT ACK <0011> lapd_core.c:920 Store content res. (dl=0x7f9d8bc33be8) <0011> lapdm.c:644 we don't support multi-octet length <0011> lapdm.c:399 sending MDL-ERROR-IND 12 <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f9d8bc33898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f9d8bc33898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 <0000> rsl.c:636 (bts=0,trx=0,ts=1,ss=0) Tx RF CHAN REL ACK
Updated by laforge about 6 years ago
On Wed, Mar 21, 2018 at 06:46:22PM +0000, fixeria [REDMINE] wrote:
The only difference is that the padding is being randomized.
did you check the specs for randomized padding? AFAIR the first padding
cotet must be 0x2b, only the remaining ones can be randomized.
Maybe that's the issue here?
Updated by fixeria about 6 years ago
Well, I've tried to modify the source code:
diff --git a/src/host/trxcon/sched_prim.c b/src/host/trxcon/sched_prim.c
index c17fb2a4..dea09add 100644
--- a/src/host/trxcon/sched_prim.c
+++ b/src/host/trxcon/sched_prim.c
@@ -251,7 +251,7 @@ int sched_prim_dummy(struct trx_lchan_state *lchan)
* and with an information field of 0 octet length.
*/
static const uint8_t lapdm_fill_frame[] = {
- 0x01, 0x03, 0x01,
+ 0x01, 0x03, 0x01, 0x2b,
/* Pending part is to be randomized */
};
@@ -283,7 +283,7 @@ int sched_prim_dummy(struct trx_lchan_state *lchan)
memcpy(prim_buffer, lapdm_fill_frame, 3);
/* Randomize pending unused bytes */
- for (i = 3; i < GSM_MACBLOCK_LEN; i++)
+ for (i = 4; i < GSM_MACBLOCK_LEN; i++)
prim_buffer[i] = (uint8_t) rand();
Same problem :/
Updated by fixeria about 6 years ago
Hacked OsmoBTS in order to show L2 messages.
A regular prone (without randomization):
<0000> rsl.c:662 (bts=0,trx=0,ts=1,ss=0) Tx CHAN ACT ACK RX DATA (fn=1194846): 01 3f 35 05 24 78 03 53 59 a6 05 f4 27 15 16 d6 7d a7 01 e7 35 92 af <0011> lapd_core.c:920 Store content res. (dl=0x7f4a2a9cbbe8) RX DATA (fn=1194878): 0e 00 01 03 49 06 15 00 40 01 c0 00 00 00 00 00 00 00 00 00 00 00 00 RX DATA (fn=1194897): 01 00 45 06 16 03 53 59 a6 20 09 60 14 04 cf 65 00 21 e2 40 aa ee f6 RX DATA (fn=1194948): 01 22 53 0b 7b 1c 15 a1 13 02 01 00 02 01 3b 30 0b 04 01 0f 04 06 aa RX DATA (fn=1194980): 0e 00 01 03 49 06 15 a7 27 00 00 00 00 00 00 00 00 00 00 00 00 00 00 RX DATA (fn=1194999): 01 24 21 51 0c 06 1b 01 7f 01 00 f0 25 0a 67 fe 27 94 b7 08 73 02 f6 RX DATA (fn=1195050): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1195101): 03 41 01 45 1c 95 8e 23 fd 77 6f 2e 09 38 0b 97 a2 b1 68 e5 5c 26 66 RX DATA (fn=1195152): 03 61 01 b2 61 f8 7a f2 3d aa 7f ea 7d f5 f4 00 ff 0c c4 99 cf 7d 56 RX DATA (fn=1195203): 03 81 01 ed ac d8 56 d7 6b 5f 78 19 d1 61 87 5d 7f eb 39 1c 94 9a e7 RX DATA (fn=1195254): 01 53 01 59 3e 19 d1 13 3b e0 84 f5 f0 a7 86 48 99 1d 4a 21 cf 1d 10 <0000> rsl.c:636 (bts=0,trx=0,ts=1,ss=0) Tx RF CHAN REL ACK
OsmocomBB Calypso PHY (without randomization):
<0000> rsl.c:662 (bts=0,trx=0,ts=1,ss=0) Tx CHAN ACT ACK RX DATA (fn=1282974): 01 3f 35 05 24 78 03 33 19 01 05 f4 12 a1 39 05 2b 2b 2b 2b 2b 2b 2b <0011> lapd_core.c:920 Store content res. (dl=0x7f4a2a9cbbe8) RX DATA (fn=1283006): 0e 00 01 03 49 06 15 00 40 01 c0 00 00 00 00 00 00 00 00 00 00 00 00 RX DATA (fn=1283025): 01 00 35 06 16 03 33 19 81 20 05 60 14 c0 00 00 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283076): 03 21 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283108): 0e 00 01 03 49 06 15 00 40 01 c0 00 00 00 00 00 00 00 00 00 00 00 00 RX DATA (fn=1283127): 01 22 53 0b 7b 1c 15 a1 13 02 01 05 02 01 3b 30 0b 04 01 0f 04 06 aa RX DATA (fn=1283178): 01 24 15 51 0c 06 1b 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283229): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283280): 03 41 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283331): 03 61 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283382): 03 81 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283433): 03 a1 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=1283484): 01 53 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0000> rsl.c:636 (bts=0,trx=0,ts=1,ss=0) Tx RF CHAN REL ACK
OsmocomBB trxcon (with and without randomization):
<0000> rsl.c:662 (bts=0,trx=0,ts=1,ss=0) Tx CHAN ACT ACK RX DATA (fn=11474): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f60218a7898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f60218a7898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 RX DATA (fn=11493): 01 3f 35 05 24 78 03 33 19 01 05 f4 20 2b 98 27 2b 2b 2b 2b 2b 2b 2b <0011> lapd_core.c:920 Store content res. (dl=0x7f60218a7be8) RX DATA (fn=11544): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11576): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f60218a7898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f60218a7898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 RX DATA (fn=11595): 01 00 35 06 16 03 33 19 81 20 05 60 14 c0 00 00 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11646): 03 21 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11678): 0e 00 01 03 49 06 15 3c 3c 01 c0 00 00 00 00 00 00 00 00 00 00 00 00 RX DATA (fn=11697): 01 22 53 0b 7b 1c 15 a1 13 02 01 05 02 01 3b 30 0b 04 01 0f 04 06 aa RX DATA (fn=11748): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11780): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f60218a7898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f60218a7898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 RX DATA (fn=11799): 01 24 15 51 0c 06 1b 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11850): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11901): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=11952): 03 41 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12003): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12054): 03 61 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12105): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12156): 03 81 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12207): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12258): 03 a1 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12309): 01 53 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=12360): 01 03 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b <0000> rsl.c:636 (bts=0,trx=0,ts=1,ss=0) Tx RF CHAN REL ACK <0000> rsl.c:662 (bts=0,trx=0,ts=1,ss=0) Tx CHAN ACT ACK RX DATA (fn=37892): 01 03 01 2b cf 52 60 56 48 28 1c 89 e7 ca 22 d7 ab 69 ed 84 f1 b0 7b <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f60218a7898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f60218a7898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 RX DATA (fn=37911): 01 3f 35 05 24 78 03 33 19 01 05 f4 70 e1 db 36 2b 2b 2b 2b 2b 2b 2b <0011> lapd_core.c:920 Store content res. (dl=0x7f60218a7be8) RX DATA (fn=37962): 01 03 01 2b e6 e5 a2 14 47 d0 a0 cb c0 4d 53 39 1c a5 99 73 ed c2 8f RX DATA (fn=37994): 01 03 01 2b 77 a9 59 99 81 04 02 6e 88 f3 1e 04 d9 03 a6 ed 4b 76 8e <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f60218a7898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f60218a7898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 RX DATA (fn=38013): 01 00 35 06 16 03 33 19 81 20 05 60 14 c0 00 00 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38064): 03 21 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38096): 0e 00 01 03 49 06 15 3c 3c 01 c0 00 00 00 00 00 00 00 00 00 00 00 00 RX DATA (fn=38115): 01 22 53 0b 7b 1c 15 a1 13 02 01 05 02 01 3b 30 0b 04 01 0f 04 06 aa RX DATA (fn=38166): 01 03 01 2b 16 36 db 69 6f f7 0e 09 6a fc cb f9 73 74 53 0c f5 57 0e RX DATA (fn=38198): 01 03 01 2b 63 e0 01 82 e4 db 85 8a c8 d0 00 56 e7 36 31 50 a5 29 5f <0011> lapd_core.c:1239 Unnumbered frame not allowed. (dl=0x7f60218a7898) <0011> lapd_core.c:393 sending MDL-ERROR-IND cause 12 from state LAPD_STATE_IDLE (dl=0x7f60218a7898) <0011> lapdm.c:399 sending MDL-ERROR-IND 12 RX DATA (fn=38217): 01 24 15 51 0c 06 1b 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38268): 01 03 01 2b ae 93 5b 79 8d ce ee e0 da e3 37 e8 47 17 e9 c9 fb c4 4e RX DATA (fn=38319): 01 03 01 2b 85 8d 1f 85 e3 06 bb 15 56 61 3e b5 0f d1 10 89 5e de 77 RX DATA (fn=38370): 03 41 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38421): 01 03 01 2b d4 34 b0 12 ea c0 e3 fa 49 42 d9 c0 80 91 1a f6 32 bc 84 RX DATA (fn=38472): 03 61 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38523): 01 03 01 2b bc 26 0d 0a df 1b e6 b7 af a5 95 ff 79 ca af 8b b4 6f 6e RX DATA (fn=38574): 03 81 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38625): 01 03 01 2b 0c 83 9c a2 82 15 6c 32 a0 20 a1 0f ce 5a bf 56 d2 f0 6f RX DATA (fn=38676): 03 a1 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38727): 01 53 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b RX DATA (fn=38778): 01 03 01 2b 88 1c b9 29 2b 88 83 eb de 56 db 4d bb f3 07 70 b7 c8 9a <0000> rsl.c:636 (bts=0,trx=0,ts=1,ss=0) Tx RF CHAN REL ACK
My current assumption is that I shall not send dummy frames on SACCH.
Instead of that, an incorrect Measurement Report shall be sent.
Updated by laforge about 6 years ago
My current assumption is that I shall not send dummy frames on SACCH.
Instead of that, an incorrect Measurement Report shall be sent.
that makes sense and sounds plausible.
Updated by fixeria about 6 years ago
- Related to Bug #3055: osmo-bts-trx: slow TA loop feedback added
Updated by fixeria about 6 years ago
- Status changed from Feedback to In Progress
Ok, I managed to fix the problem with sending Measurement Reports on SACCH.
According to GSM TS 04.08, section 3.4.1.1 "SACCH procedures", the SACCH
shall be used at least for measurement results transmission from the mobile
station. In other words, Measurement Report messages are sent at each possible
occasion when nothing else has to be sent.
Will upload the changes soon.
About possible problems during:
- CHANNEL MODE MODIFY: GSM TS 04.08, section 3.4.6.1 "Normal channel mode modify procedure"
- CIPHERING MODE COMMAND: GSM TS 04.08, section 3.4.7 "Ciphering mode setting procedure"
I'll keep this issue open until I am sure that both above procedures are performed correctly.
Updated by fixeria about 6 years ago
- Status changed from In Progress to Feedback
Review at: https://gerrit.osmocom.org/7470/
Updated by fixeria about 6 years ago
Started a discussion: https://lists.osmocom.org/pipermail/baseband-devel/2018-March/005513.html
Updated by fixeria about 6 years ago
- Status changed from Feedback to Stalled
This issue will be finally resolved as soon as I push my changes
related to the Measurement Reporting implementation.
Updated by fixeria over 5 years ago
- Category set to trxcon
- Target version set to Improvement of the higher layers of OsmocomBB
Updated by fixeria over 5 years ago
- Status changed from Stalled to Feedback
Should be resolved now. Please see:
https://gerrit.osmocom.org/11136 trxcon/scheduler: pass lchan state to sched_prim_dequeue()
https://gerrit.osmocom.org/11137 trxcon/scheduler: pass talloc ctx directly to sched_prim_init()
https://gerrit.osmocom.org/11138 trxcon/scheduler: fix Measurement Reporting on SACCH
Updated by fixeria over 5 years ago
- Status changed from Feedback to Resolved
- % Done changed from 90 to 100
Should have been fixed now, merged. After 7 months :/
Updated by ptrkrysik almost 5 years ago
- Target version deleted (
Improvement of the higher layers of OsmocomBB)
