Project

General

Profile

Actions

Bug #2988

closed

unexpected bit errors when using trxcon and osmo-bts-trx

Added by laforge about 6 years ago. Updated almost 5 years ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
trxcon
Target version:
-
Start date:
02/23/2018
Due date:
% Done:

100%

Resolution:
Spec Reference:

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

Related to OsmoBTS - Bug #3055: osmo-bts-trx: slow TA loop feedbackClosedtnt03/10/2018

Actions
Actions #1

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.

Actions #2

Updated by fixeria about 6 years ago

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? ;)

Actions #3

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

Actions #4

Updated by laforge about 6 years ago

  • Assignee changed from laforge to fixeria
Actions #5

Updated by fixeria about 6 years ago

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.

Actions #6

Updated by fixeria about 6 years ago

For better understanding how does TCH/F burst mapping work, I am adding this great picture.

Actions #7

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

Actions #8

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

Actions #9

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.

Actions #10

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?

Actions #11

Updated by fixeria about 6 years ago

  • % Done changed from 60 to 90
Actions #12

Updated by fixeria about 6 years ago

  • Status changed from In Progress to Feedback
Actions #13

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

Actions #14

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.

Actions #15

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
Actions #16

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?

Actions #17

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 :/

Actions #18

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.

Actions #19

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.

Actions #20

Updated by fixeria about 6 years ago

  • Related to Bug #3055: osmo-bts-trx: slow TA loop feedback added
Actions #21

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.

Actions #22

Updated by fixeria about 6 years ago

  • Status changed from In Progress to Feedback
Actions #24

Updated by fixeria almost 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.

Actions #25

Updated by fixeria over 5 years ago

  • Category set to trxcon
  • Target version set to Improvement of the higher layers of OsmocomBB
Actions #26

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

Actions #27

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 :/

Actions #28

Updated by ptrkrysik almost 5 years ago

  • Target version deleted (Improvement of the higher layers of OsmocomBB)
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)