Project

General

Profile

Actions

Bug #3665

closed

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

Added by pespin over 5 years ago. Updated over 3 years ago.

Status:
Closed
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


Files


Related issues

Related to OsmoBTS - Feature #3428: Implement handling of NOPE / IDLE indications from TransceiverResolveddexter07/28/2018

Actions
Related to OsmoBTS - Bug #2987: OsmoBTS RxQual/RxLev averaging broken if bursts are missignResolveddexter02/23/2018

Actions
Related to OsmoBTS - Bug #2975: OsmoBTS doesn't generate measurement indications in absence of uplink burstsResolveddexter02/21/2018

Actions
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)