Project

General

Profile

Bug #3665

TTCN3 BTS_Tests last SACCH burst received too late -> wrong fake uplink measurement report

Added by pespin 23 days ago. Updated 22 days ago.

Status:
Stalled
Priority:
Normal
Assignee:
Category:
-
Target version:
-
Start date:
10/23/2018
Due date:
% Done:

50%

Spec Reference:

Description

Since last commit osmo-ttcn3-hacks 4ebdad65a28aa6d26363906b0bafc7b7bf15f284 checking rxlev and rxqual values of uplink meas report in TTCN3 BTS_Tests, lots of tests checking for those fail, like TC_meas_res_sign_sdcch4. That happens too in the virtual setup, where we should receive a good quality.

Issue shows up in TTCN3 like this:

10:54:02.013678 6 BTS_Tests.ttcn:1311 Matching on port RSL .ies[2].body.uplink_meas.rxq_f_u := 7 with (0 .. 1) unmatched.ies[2].body.uplink_meas.rxq_s_u := 7 with (0 .. 1) unmatched: First message

So at some point rxqual goes from expected 0 (good quality), to 7 (really bad quality).

wireshark shows indeed that at some point uplink measurement report generated from BTS changes from expected values (rssi=-100, fed through ttcn3 test, toa=512) change to rssi=-110, toa=0 and bad quality. Enabling MEAS category debugging, we see indeed BTS shows those:

Usual expected one:
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000751/00/23/37/31 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=751 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512
Wrong one:
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000756/00/02/42/36 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=756 chan_nr=0x20 MS pwr=0dBm rssi=-110.0 dBFS ber=100.00% (456/456 bits) L1_ta=0 rqd_ta=1 toa256=0

Looking at osmo-bts-trx code, we can find a fake uplink meas report being pushed by code with exactly those values in scheduler_trx.c:202 in tx_data_fn:

            l1if_process_meas_res(l1t->trx, tn, fn, trx_chan_desc[chan].chan_nr | tn,
                456, 456, -110, 0);

That's indeed the call generating the wrong values.

I used following patch while running the test to figure out what was going on:

diff --git a/src/common/scheduler.c b/src/common/scheduler.c
index 65ece7ff..806d5973 100644
--- a/src/common/scheduler.c
+++ b/src/common/scheduler.c
@@ -25,6 +25,7 @@
 #include <errno.h>
 #include <stdint.h>
 #include <ctype.h>
+#include <inttypes.h>

 #include <osmocom/core/msgb.h>
 #include <osmocom/core/talloc.h>
@@ -369,6 +370,7 @@ int _sched_compose_ph_data_ind(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
        if (l2_len)
                memcpy(msg->l2h, l2, l2_len);

+       LOGP(DMEAS, LOGL_INFO, "PESPIN: _sched_compose_ph_data_ind (--) fn=%" PRIu32 " lost_frames=%" PRIu8 "\n", fn, l1ts->chan_state[chan].lost_frames);
        if (L1SAP_IS_LINK_SACCH(trx_chan_desc[chan].link_id))
                l1ts->chan_state[chan].lost_frames = 0;

@@ -399,6 +401,8 @@ int _sched_compose_tch_ind(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
        if (tch_len)
                memcpy(msg->l2h, tch, tch_len);

+       LOGP(DMEAS, LOGL_INFO, "PESPIN: _sched_compose_tch_ind (--) fn=%" PRIu32 " lost_frames=%" PRIu8 "\n", fn, l1ts->chan_state[chan].lost_frames);
+
        if (l1ts->chan_state[chan].lost_frames)
                l1ts->chan_state[chan].lost_frames--;

@@ -463,7 +467,7 @@ int trx_sched_tch_req(struct l1sched_trx *l1t, struct osmo_phsap_prim *l1sap)
 }

-/*
+/*
  * ready-to-send indication (to upper layer)
  */

diff --git a/src/osmo-bts-trx/scheduler_trx.c b/src/osmo-bts-trx/scheduler_trx.c
index fa3aed22..6db6f174 100644
--- a/src/osmo-bts-trx/scheduler_trx.c
+++ b/src/osmo-bts-trx/scheduler_trx.c
@@ -193,10 +193,11 @@ got_msg:
        /* handle loss detection of SACCH */
        if (L1SAP_IS_LINK_SACCH(trx_chan_desc[chan].link_id)) {
                /* count and send BFI */
+               LOGP(DMEAS, LOGL_INFO, "PESPIN: tx_data_fn (++) fn=%" PRIu32 " lost_frames=%" PRIu8 " chan_state=%p\n", fn, l1ts->chan_state[chan].lost_frames, &l1ts->chan_state[chan]);
                if (++(l1ts->chan_state[chan].lost_frames) > 1) {
                        /* TODO: Should we pass old TOA here? Otherwise we risk
                         * unnecessary decreasing TA */
-
+                       LOGP(DMEAS, LOGL_INFO, "PESPIN: Sending bad MEAS RES\n");
                        /* Send uplink measurement information to L2 */
                        l1if_process_meas_res(l1t->trx, tn, fn, trx_chan_desc[chan].chan_nr | tn,
                                456, 456, -110, 0);
@@ -350,6 +351,7 @@ static void tx_tch_common(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
        uint8_t tch_mode = chan_state->tch_mode;
        struct osmo_phsap_prim *l1sap;

+       LOGP(DMEAS, LOGL_INFO, "PESPIN: tx_tch_common (++) fn=%" PRIu32 " lost_frames=%" PRIu8 " chan_state=%p\n", fn, l1ts->chan_state[chan].lost_frames, chan_state);
        /* handle loss detection of received TCH frames */
        if (rsl_cmode == RSL_CMOD_SPD_SPEECH
            && ++(chan_state->lost_frames) > 5) {
@@ -776,7 +778,7 @@ int rx_data_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
        if (chan_state->ho_rach_detect == 1)
                return rx_rach_fn(l1t, tn, fn, chan, bid, bits, GSM_BURST_LEN, rssi, toa256);

-       LOGL1S(DL1P, LOGL_DEBUG, l1t, tn, chan, fn, "Received Data, bid=%u\n", bid);
+       LOGL1S(DL1P, LOGL_NOTICE, l1t, tn, chan, fn, "Received Data, bid=%u\n", bid);

        /* allocate burst memory, if not already */
        if (!*bursts_p) {

With it, we get following output which shows the failure (attached full output of test):

Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000651/00/01/39/35 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=2
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000652/00/02/40/36 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=3
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000649/00/25/37/33 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=649 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:348 000649/00/25/37/33 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=0, fn_mod=37
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=649 lost_frames=0                                    // LAST UPLINK SDCCH BURSTS HAVE ARRIVED, WE PUSHED UPLINK MEAS RES FOR IT AND PASS MSG TO UPPER LAYER
Tue Oct 23 14:53:18 2018 DL1P <0007> sysinfo.c:175 (bts=0,trx=0,ts=0,ss=0) SACCH no SI available
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler.c:884 000669/00/19/06/01 Too many contiguous elapsed fn, dropping 17
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000669/00/19/06/01 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=0
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000670/00/20/07/02 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=1
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000671/00/21/08/03 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=2
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000672/00/22/09/04 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=3
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000669/00/19/06/01 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=669 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:348 000669/00/19/06/01 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=1, fn_mod=57
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=669 lost_frames=0                                 // LAST UPLINK SACCH BURSTS HAVE ARRIVED, WE PUSHED UPLINK MEAS RES FOR IT AND PASS MSG TO UPPER LAYER
Tue Oct 23 14:53:18 2018 DRSL <0000> rsl.c:2691 (bts=0,trx=0,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler_trx.c:196 PESPIN: tx_data_fn (++) fn=654 lost_frames=0 chan_state=0xb4cb90                        // WE TRANSMIT BURSTS IN DOWNLINK SACCH, WE RECEIVED AN UPLINK SACCH BEFORE SO EVERYTHING IS FINE
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler.c:884 000700/00/24/37/32 Too many contiguous elapsed fn, dropping 28
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000700/00/24/37/32 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=0
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000701/00/25/38/33 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=1
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000702/00/00/39/34 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=2
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000703/00/01/40/35 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=3
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000700/00/24/37/32 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=700 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:348 000700/00/24/37/32 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=2, fn_mod=88
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:293 (bts=0,trx=0,ts=0,ss=0) meas period end fn:700, fn_mod:88, status:1, pchan:CCCH+SDCCH4
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:564 (bts=0,trx=0,ts=0,ss=0) Calculating measurement results for physical channel:CCCH+SDCCH4
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:586 (bts=0,trx=0,ts=0,ss=0) received 3 UL measurements, expected 3
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:638 (bts=0,trx=0,ts=0,ss=0) received UL measurements contain 3 SUB measurements, expected 3
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:640 (bts=0,trx=0,ts=0,ss=0) replaced 0 measurements with dummy values, from which 0 were SUB measurements
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:680 (bts=0,trx=0,ts=0,ss=0) Computed TA256( 512) BER-FULL( 0.00%), RSSI-FULL(-100dBm), BER-SUB( 0.00%), RSSI-SUB(-100dBm)
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:693 (bts=0,trx=0,ts=0,ss=0) UL MEAS RXLEV_FULL(10), RXLEV_SUB(10),RXQUAL_FULL(0), RXQUAL_SUB(0), num_meas_sub(3), num_ul_meas(3)
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=700 lost_frames=0                              // LAST UPLINK SDCCH BURSTS HAVE ARRIVED, WE PUSHED UPLINK MEAS RES FOR IT AND PASS MSG TO UPPER LAYER.
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler.c:884 000751/00/23/37/31 Too many contiguous elapsed fn, dropping 48
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000751/00/23/37/31 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=0                 //WE START RECEIVING NEXT UPLINK SDCCH
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000752/00/24/38/32 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=1
Tue Oct 23 14:53:18 2018 DTRX <000b> trx_if.c:124 Clock indication: fn=714
Tue Oct 23 14:53:18 2018 DL1C <0006> scheduler_trx.c:1580 TRX Clock Ind: elapsed_us= 463257, elapsed_fn=102, error_us=-7473
Tue Oct 23 14:53:18 2018 DL1C <0006> scheduler_trx.c:1598 GSM clock jitter: 6024us (elapsed_fn=2)
Tue Oct 23 14:53:18 2018 DL1C <0006> scheduler_trx.c:1621 We were 2 FN slower than TRX, compensated
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000753/00/25/39/33 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=2
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000754/00/00/40/34 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=3                  //WE END RECEIVED SDCCH, AS YOU CAN SEE SCHEDULER COMPENSATED, CLOCK A BIT FLACKY
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000751/00/23/37/31 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=751 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:348 000751/00/23/37/31 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=0, fn_mod=37
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=751 lost_frames=0                       // LAST UPLINK SDCCH BURSTS HAVE ARRIVED, WE PUSHED UPLINK MEAS RES FOR IT AND PASS MSG TO UPPER LAYER.
Tue Oct 23 14:53:18 2018 DL1P <0007> sysinfo.c:175 (bts=0,trx=0,ts=0,ss=0) SACCH no SI available
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler.c:884 000771/00/17/06/03 Too many contiguous elapsed fn, dropping 17
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000771/00/17/06/03 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=0           //WE START RECEIVING NEXT UPLINK SACCH
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000772/00/18/07/04 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=1
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000773/00/19/08/05 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=2
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler_trx.c:196 PESPIN: tx_data_fn (++) fn=756 lost_frames=1 chan_state=0xb4cb90               // WE SEND NEXT DOWNLINK SACCH BEFORE RECEIVING LAST UPLINK SACCH BURST!!!!
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler_trx.c:200 PESPIN: Sending bad MEAS RES                                                   //AS A RESULT, lost_frames=1 BECAUSE WE ONLY SET IT TO 0 AFTER RECEIVING 4 BURSTS
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000756/00/02/42/36 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=756 chan_nr=0x20 MS pwr=0dBm rssi=-110.0 dBFS ber=100.00% (456/456 bits) L1_ta=0 rqd_ta=1 toa256=0  // INSTEAD OF USING 3 KNOWN BURSTS OR WAITING FOR 4th ONE, WE SEND COMPLETE CRAP REPORT!!!
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:348 000756/00/02/42/36 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=1, fn_mod=42
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=0 lost_frames=2
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1sap.c:1005 (bts=0,trx=0,ts=0,ss=0) counting down radio link counter S=31
Tue Oct 23 14:53:18 2018 DL1P <0007> scheduler_trx.c:781 000774/00/20/09/06 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=3        // WE FINALLY RECEIVE THE 4th BURST!!!! TO LATE!!!
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1_if.c:519 000771/00/17/06/03 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=771 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512 // WE NOW SEND THE (DUPLICATED) UPLINK MEASUREMENT RESULT WHEN WE END UP RECEIVING ALL THE BURSTS! WE SHOULD HAVE SENT ONLY 1 OF THESE LAST 2!
Tue Oct 23 14:53:18 2018 DMEAS <0004> measurement.c:348 000771/00/17/06/03 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=2, fn_mod=57
Tue Oct 23 14:53:18 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=771 lost_frames=0
Tue Oct 23 14:53:18 2018 DMEAS <0004> l1sap.c:1017 (bts=0,trx=0,ts=0,ss=0) counting up radio link counter S=32


Related issues

Related to OsmoBTS - Bug #3428: Too many contiguous elapsed fn, dropping...Stalled2018-07-28

Related to OsmoBTS - Bug #2987: OsmoBTS RxQual/RxLev averaging broken if bursts are missignStalled2018-02-23

Related to OsmoBTS - Bug #2975: OsmoBTS doesn't generate measurement indications in absence of uplink burstsStalled2018-02-21

History

#1 Updated by pespin 23 days ago

After attached patch, the issue of course is still there (last burst arriving too late, I guess due to scheduling issues + ovehead of ttcn3->trxcon->fake_trx. But at least we try to decode first 3 bursts and send related ul measurement reports:

Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000771/00/17/06/03 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=0
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000772/00/18/07/04 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=1
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000773/00/19/08/05 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=2
Tue Oct 23 17:24:48 2018 DMEAS <0004> scheduler_trx.c:251 PESPIN: tx_data_fn (++) fn=756 lost_frames=1 chan_state=0x1070b90
Tue Oct 23 17:24:48 2018 DMEAS <0004> scheduler_trx.c:253 PESPIN: Sending bad MEAS RES
Tue Oct 23 17:24:48 2018 DMEAS <0004> l1_if.c:519 000771/00/17/06/03 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=771 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=25.00% (114/456 bits) L1_ta=0 rqd_ta=1 toa256=512    // RSSI AND TOA ARE FINE, BER IS 25% NOW vs 100% BEFORE PATCH.
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:348 000771/00/17/06/03 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=1, fn_mod=57
Tue Oct 23 17:24:48 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=771 lost_frames=2
Tue Oct 23 17:24:48 2018 DRSL <0000> rsl.c:2691 (bts=0,trx=0,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000774/00/20/09/06 (bts=0,trx=0,ts=0) SACCH/4(0): Received Data, bid=3
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:866 000774/00/20/09/06 (bts=0,trx=0,ts=0) SACCH/4(0): Received incomplete data (771/57)
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler.c:884 000802/00/22/37/34 Too many contiguous elapsed fn, dropping 28
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000802/00/22/37/34 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=0
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000803/00/23/38/35 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=1
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000804/00/24/39/36 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=2
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000805/00/25/40/37 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=3
Tue Oct 23 17:24:48 2018 DMEAS <0004> l1_if.c:519 000802/00/22/37/34 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=802 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:348 000802/00/22/37/34 (bts=0,trx=0,ts=0,ss=0) adding measurement (is_sub=1), num_ul_meas=2, fn_mod=88
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:293 (bts=0,trx=0,ts=0,ss=0) meas period end fn:802, fn_mod:88, status:1, pchan:CCCH+SDCCH4
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:564 (bts=0,trx=0,ts=0,ss=0) Calculating measurement results for physical channel:CCCH+SDCCH4
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:586 (bts=0,trx=0,ts=0,ss=0) received 3 UL measurements, expected 3
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:638 (bts=0,trx=0,ts=0,ss=0) received UL measurements contain 3 SUB measurements, expected 3
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:640 (bts=0,trx=0,ts=0,ss=0) replaced 0 measurements with dummy values, from which 0 were SUB measurements
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:680 (bts=0,trx=0,ts=0,ss=0) Computed TA256( 512) BER-FULL( 8.33%), RSSI-FULL(-100dBm), BER-SUB( 8.33%), RSSI-SUB(-100dBm)
Tue Oct 23 17:24:48 2018 DMEAS <0004> measurement.c:693 (bts=0,trx=0,ts=0,ss=0) UL MEAS RXLEV_FULL(10), RXLEV_SUB(10),RXQUAL_FULL(6), RXQUAL_SUB(6), num_meas_sub(3), num_ul_meas(3)
Tue Oct 23 17:24:48 2018 DMEAS <0004> scheduler.c:373 PESPIN: _sched_compose_ph_data_ind (--) fn=802 lost_frames=0
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler.c:884 000853/00/21/37/33 Too many contiguous elapsed fn, dropping 48
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000853/00/21/37/33 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=0
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000854/00/22/38/34 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=1
Tue Oct 23 17:24:48 2018 DTRX <000b> trx_if.c:124 Clock indication: fn=816
Tue Oct 23 17:24:48 2018 DL1C <0006> scheduler_trx.c:1603 TRX Clock Ind: elapsed_us= 463366, elapsed_fn=102, error_us=-7364
Tue Oct 23 17:24:48 2018 DL1C <0006> scheduler_trx.c:1621 GSM clock jitter: 4318us (elapsed_fn=1)
Tue Oct 23 17:24:48 2018 DL1C <0006> scheduler_trx.c:1644 We were 1 FN slower than TRX, compensated
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000855/00/23/39/35 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=2
Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:826 000856/00/24/40/36 (bts=0,trx=0,ts=0) SDCCH/4(0): Received Data, bid=3
Tue Oct 23 17:24:48 2018 DMEAS <0004> l1_if.c:519 000853/00/21/37/33 RX UL measurement for (bts=0,trx=0,ts=0,ss=0) fn=853 chan_nr=0x20 MS pwr=0dBm rssi=-100.0 dBFS ber=0.00% (0/456 bits) L1_ta=0 rqd_ta=1 toa256=512

Furthermore, we don't send an extra measurement report like before, because it will be dropped by regular rx_chan since mask has been erased, See line:

Tue Oct 23 17:24:48 2018 DL1P <0007> scheduler_trx.c:866 000774/00/20/09/06 (bts=0,trx=0,ts=0) SACCH/4(0): Received incomplete data (771/57)

#2 Updated by pespin 23 days ago

  • Status changed from New to In Progress
  • % Done changed from 0 to 50

New cleaned up (and slightly fixed) version of the above patch submitted below:
https://gerrit.osmocom.org/#/c/osmo-bts/+/11446 bts-trx: Try decoding received UL bursts when SACCH frame detected as lost

With it, TTCN3 tests still fail but results are better (rxqual 6 instead of 7):

17:24:48.811921 6 BTS_Tests.ttcn:1311 Matching on port RSL .ies[2].body.uplink_meas.rxq_f_u := 6 with (0 .. 1) unmatched.ies[2].body.uplink_meas.rxq_s_u := 6 with (0 .. 1)

We could try optimizing trxcon/fake_trx, or running everything with higher priority and see if it helps. Otherwise, just increase rxqal tolerance to be 0..6 and we are done.

#3 Updated by pespin 23 days ago

I tried running the virtual setup (docker) with osmo-bts-trx with rt-prio 18 and 98, to see if there was any change, but there wasn't. The process taking most CPU seems to be fake_trx (30%).

 echo Starting container with BTS
-docker run     --rm \
+docker run     --rm --privileged \
                --network $NET_NAME --ip 172.18.9.20 \
                -v $VOL_BASE_DIR/bts:/data \
                -v $VOL_BASE_DIR/unix:/data/unix \
                --name ${BUILD_TAG}-bts -d \
                $REPO_USER/osmo-bts-master \
-               /usr/local/bin/respawn.sh /usr/local/bin/osmo-bts-trx -c /data/osmo-bts.cfg -i 172.18.9.10
+               bash -c "/usr/local/bin/respawn.sh /usr/local/bin/osmo-bts-trx -c /data/osmo-bts.cfg -i 172.18.9.10 -r 98 >/data/bts.stdout 2>&1" 

#4 Updated by pespin 22 days ago

After discussion with fixeria , I tried different values of trx-advance in trxcon and switching that to 21 from default 20 is enough to have tests passing.

I still see some issues with rxqual in TCH/H related tests, but that seems to have a different origin.

Patch changing trx-advance submitted here:
https://gerrit.osmocom.org/#/c/docker-playground/+/11453 bts: jenkins.sh: increase trx-advance in trxcon

#5 Updated by pespin 22 days ago

  • Related to Bug #3428: Too many contiguous elapsed fn, dropping... added

#6 Updated by fixeria 22 days ago

https://gerrit.osmocom.org/#/c/osmo-bts/+/11446 bts-trx: Try decoding received UL bursts when SACCH frame detected as lost
https://gerrit.osmocom.org/#/c/docker-playground/+/11453 bts: jenkins.sh: increase trx-advance in trxcon

Both changes are just workaround. As I already said, we need to fix the hackish way of SACCH frame loss detection.

#7 Updated by pespin 22 days ago

  • Status changed from In Progress to Stalled

Setting as stalled, waiting for #3428

#8 Updated by pespin 22 days ago

  • Related to Bug #2987: OsmoBTS RxQual/RxLev averaging broken if bursts are missign added

#9 Updated by pespin 22 days ago

  • Related to Bug #2975: OsmoBTS doesn't generate measurement indications in absence of uplink bursts added

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)