Bug #3665
closedTTCN3 BTS_Tests last SACCH burst received too late -> wrong fake uplink measurement report
50%
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
Updated by pespin almost 6 years ago
- File 0001-WIP-Try-decoding-uplink-data-if-not-all-bursts-yet-r.patch 0001-WIP-Try-decoding-uplink-data-if-not-all-bursts-yet-r.patch added
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)
Updated by pespin almost 6 years 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.
Updated by pespin almost 6 years 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"
Updated by pespin almost 6 years 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
Updated by pespin almost 6 years ago
- Related to Feature #3428: Implement handling of NOPE / IDLE indications from Transceiver added
Updated by fixeria almost 6 years 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.
Updated by pespin almost 6 years ago
- Status changed from In Progress to Stalled
Setting as stalled, waiting for #3428
Updated by pespin almost 6 years ago
- Related to Bug #2987: OsmoBTS RxQual/RxLev averaging broken if bursts are missign added
Updated by pespin almost 6 years ago
- Related to Bug #2975: OsmoBTS doesn't generate measurement indications in absence of uplink bursts added
Updated by pespin about 4 years ago
I would say a lot of stuff has been improved in code related to measurement reports over last year, so the status described in this ticket is currently invalid most probably. Furthermore, I haven't been looking at TTCN3 BTS_Tests with real hardware and most tests are not passing nowadays there for probably other reasons (need to catch up with all BTS_Tests.cfg and osmo-bts.cfg in osmo-ttcn3-hacks/docker-playgroun over last year).
So I'd probably go for closing the ticket and creating a new one or reopening if we somehow see this kind of issue after spending time again on these tests.
Updated by pespin about 4 years ago
- Status changed from Stalled to Closed
Closing as described 2 weeks ago.