From 422636d7520b1c19a8d89994a4870003bc3fe971 Mon Sep 17 00:00:00 2001 From: Pau Espin Pedrol Date: Tue, 28 Sep 2021 15:59:35 +0200 Subject: [PATCH] tests: TbfTest: Fix wrong behavior in test_tbf_dl_reuse() The test uses get_poll_fn() to submit a UL ctrl block on the next expected poll TS+FN. During initial transmit_dl_data(), 2 POLLs for DL_ACK are set on different TS, but the test only updates the clock for one of them in send_ul_mac_block(). As a result, one POLL item is left in the rb_tree, and later on, when send_control_ack() is called, get_poll_fn() will pick that 2nd DL_ACK poll FN+TS which was left untouched (due to sending no events to the PCU clock) instead of the FN+TS which was expected to be allocated by PCU for DL_ASS. Until now this was not an issue since rcv_control_ack() was not properly veirfying what the poll scheduler was expecting and accepted it. This is no longer the case after the follow up patch refactoring rcv_control_ack() and improving its robustness. Change-Id: I3a4b089fe66a99e73e07bd1c690cd4d67752fad9 --- tests/tbf/TbfTest.cpp | 3 + tests/tbf/TbfTest.err | 127 ++++++++++++++++++++++-------------------- 2 files changed, 69 insertions(+), 61 deletions(-) diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp index ae12f1e7..8700347d 100644 --- a/tests/tbf/TbfTest.cpp +++ b/tests/tbf/TbfTest.cpp @@ -2199,6 +2199,9 @@ static void test_tbf_dl_reuse() send_dl_data(bts, tlli1, imsi, (const uint8_t *)buf, rc); } + /* Drop first DL_ACK poll queued */ + send_empty_block(dl_tbf1, dl_tbf1->control_ts, get_poll_fn(dl_tbf1, dl_tbf1->control_ts)); + /* Fake Final DL Ack/Nack */ ulreq.u.MESSAGE_TYPE = MT_PACKET_DOWNLINK_ACK_NACK; Packet_Downlink_Ack_Nack_t *ack = &ulreq.u.Packet_Downlink_Ack_Nack; diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err index f3a49220..99e82df7 100644 --- a/tests/tbf/TbfTest.err +++ b/tests/tbf/TbfTest.err @@ -3215,45 +3215,6 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) appending 21 bytes TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) appending 21 bytes TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) appending 21 bytes Detected FN jump! 2654288 -> 2654379 -PDCH(bts=0,trx=0,ts=7) FN=2654379 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ -PDCH(bts=0,trx=0,ts=7) FN=2654379 ------------------------- RX : Uplink Control Block ------------------------- -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) RX: [PCU <- BTS] Packet Downlink Ack/Nack -PDCH(bts=0,trx=0,ts=7) Got GPRS DL ACK bitmap: SSN: 0, BSN 0 to 28 - 1 (28 blocks), "RRRRRRRRRRRRRRRRRRRRRRRRRRRR" -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) downlink acknowledge -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) stopping timer T3191 [ACK/NACK received] -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) ack: (BSN=0)"RRRRRRRRRRRRRRRRRRRRRRRRRRRR"(BSN=27) R=ACK I=NACK -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) DL analysis, range=0:28, lost=0, recv=28, skipped=0, bsn=0, info='RRRRRRRRRRRRRRRRRRRRRRRRRRRR....................................' -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) V(B): (V(A)=28)""(V(S)-1=27) A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Final ACK received. -TBF(DL-TFI_0){FINISHED}: Received Event FINAL_ACK_RECVD -TBF(DL-TFI_0){FINISHED}: state_chg to WAIT_RELEASE -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) starting timer T3193 with 0 sec. 100000 microsec -MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) ********** DL-TBF starts here ********** -MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Allocating DL TBF -TBF{NULL}: Allocated -UL_ASS_TBF{NONE}: Allocated -DL_ASS_TBF{NONE}: Allocated -[DL] algo A (suggested TRX: 0): Alloc start -- Skipping TS 0, because not enabled -- Skipping TS 1, because not enabled -- Skipping TS 2, because not enabled -- Skipping TS 3, because not enabled -- Skipping TS 4, because not enabled -- Skipping TS 5, because not enabled -- Skipping TS 6, because not enabled -[DL] Assign downlink TS=7 TFI=1 -PDCH(bts=0,trx=0,ts=7) Attaching TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL), 2 TBFs, USFs = 01, TFIs = 00000003. -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) Setting Control TS 7 -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 80, dl_slots = 80 -MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Attaching DL TBF: TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) Trigger downlink assignment on PACCH -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) exists -DL_ASS_TBF(DL-TFI_0){NONE}: Received Event SCHED_ASS -DL_ASS_TBF(DL-TFI_0){NONE}: state_chg to SEND_ASS -TBF(DL-TFI_1){NULL}: Received Event ASSIGN_ADD_PACCH -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) set ass. type PACCH [prev CCCH:0, PACCH:0] -TBF(DL-TFI_1){NULL}: state_chg to ASSIGN -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) Starting timer X2001 [assignment (PACCH)] with 2 sec. 0 microsec PDCH(bts=0,trx=0,ts=7) Expiring FN=2654379 but previous FN=2654283 is still reserved! PDCH(bts=0,trx=0,ts=7) Timeout for registered USF (FN=2654283): TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) N3101 1 => 2 (< MAX 10) @@ -3323,30 +3284,51 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) N3101 21 => 22 (< MAX 10) PDCH(bts=0,trx=0,ts=7) Expiring FN=2654379 but previous FN=2654374 is still reserved! PDCH(bts=0,trx=0,ts=7) Timeout for registered USF (FN=2654374): TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) N3101 22 => 23 (< MAX 10) -DL_ASS_TBF(DL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG -PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654400 + 13 = 2654413 -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) -+++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ -------------------------- TX : Packet Downlink Assignment ------------------------- -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) Scheduled DL Assignment polling on PACCH (FN=2654413, TS=7) -DL_ASS_TBF(DL-TFI_0){SEND_ASS}: state_chg to WAIT_ACK -PDCH(bts=0,trx=0,ts=7) FN=2654400 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) +PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654379): TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) poll timeout for FN=2654379, TS=7 (curr FN 2654379) +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) N3105 0 => 1 (< MAX 8) +TBF(DL-TFI_0){FINISHED}: Received Event DL_ACKNACK_MISS Detected FN jump! 2654379 -> 2654409 PDCH(bts=0,trx=0,ts=7) FN=2654409 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ PDCH(bts=0,trx=0,ts=7) FN=2654409 ------------------------- RX : Uplink Control Block ------------------------- -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) FN=2654409 Rx Packet Control Ack (reason=DL_ACK) -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) [UPLINK] DOWNLINK ASSIGNED -DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: Received Event RX_ASS_CTRL_ACK -DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: state_chg to NONE -TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) free -PDCH(bts=0,trx=0,ts=7) Detaching TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE), 1 TBFs, USFs = 01, TFIs = 00000002. -MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Detaching TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) -********** DL-TBF ends here ********** -TBF(DL-TFI_0){WAIT_RELEASE}: Deallocated -UL_ASS_TBF(DL-TFI_0){NONE}: Deallocated -DL_ASS_TBF(DL-TFI_0){NONE}: Deallocated -TBF(DL-TFI_1){ASSIGN}: Received Event ASSIGN_ACK_PACCH -TBF(DL-TFI_1){ASSIGN}: state_chg to FLOW +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) RX: [PCU <- BTS] Packet Downlink Ack/Nack +PDCH(bts=0,trx=0,ts=7) Got GPRS DL ACK bitmap: SSN: 0, BSN 0 to 28 - 1 (28 blocks), "RRRRRRRRRRRRRRRRRRRRRRRRRRRR" +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) downlink acknowledge +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) stopping timer T3191 [ACK/NACK received] +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) ack: (BSN=0)"RRRRRRRRRRRRRRRRRRRRRRRRRRRR"(BSN=27) R=ACK I=NACK +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) DL analysis, range=0:28, lost=0, recv=28, skipped=0, bsn=0, info='RRRRRRRRRRRRRRRRRRRRRRRRRRRR....................................' +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) V(B): (V(A)=28)""(V(S)-1=27) A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Final ACK received. +TBF(DL-TFI_0){FINISHED}: Received Event FINAL_ACK_RECVD +TBF(DL-TFI_0){FINISHED}: state_chg to WAIT_RELEASE +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) starting timer T3193 with 0 sec. 100000 microsec +MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) ********** DL-TBF starts here ********** +MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Allocating DL TBF +TBF{NULL}: Allocated +UL_ASS_TBF{NONE}: Allocated +DL_ASS_TBF{NONE}: Allocated +[DL] algo A (suggested TRX: 0): Alloc start +- Skipping TS 0, because not enabled +- Skipping TS 1, because not enabled +- Skipping TS 2, because not enabled +- Skipping TS 3, because not enabled +- Skipping TS 4, because not enabled +- Skipping TS 5, because not enabled +- Skipping TS 6, because not enabled +[DL] Assign downlink TS=7 TFI=1 +PDCH(bts=0,trx=0,ts=7) Attaching TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL), 2 TBFs, USFs = 01, TFIs = 00000003. +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) Setting Control TS 7 +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 80, dl_slots = 80 +MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Attaching DL TBF: TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) Trigger downlink assignment on PACCH +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) exists +DL_ASS_TBF(DL-TFI_0){NONE}: Received Event SCHED_ASS +DL_ASS_TBF(DL-TFI_0){NONE}: state_chg to SEND_ASS +TBF(DL-TFI_1){NULL}: Received Event ASSIGN_ADD_PACCH +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) set ass. type PACCH [prev CCCH:0, PACCH:0] +TBF(DL-TFI_1){NULL}: state_chg to ASSIGN +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) Starting timer X2001 [assignment (PACCH)] with 2 sec. 0 microsec PDCH(bts=0,trx=0,ts=7) Expiring FN=2654409 but previous FN=2654383 is still reserved! PDCH(bts=0,trx=0,ts=7) Timeout for registered USF (FN=2654383): TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) N3101 23 => 24 (< MAX 10) @@ -3362,6 +3344,29 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) N3101 26 => 27 (< MAX 10) PDCH(bts=0,trx=0,ts=7) Expiring FN=2654409 but previous FN=2654400 is still reserved! PDCH(bts=0,trx=0,ts=7) Timeout for registered USF (FN=2654400): TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=RELEASING) N3101 27 => 28 (< MAX 10) +DL_ASS_TBF(DL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG +PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654400 + 13 = 2654413 +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) ++++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ +------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) Scheduled DL Assignment polling on PACCH (FN=2654413, TS=7) +DL_ASS_TBF(DL-TFI_0){SEND_ASS}: state_chg to WAIT_ACK +PDCH(bts=0,trx=0,ts=7) FN=2654400 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) +PDCH(bts=0,trx=0,ts=7) FN=2654413 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ +PDCH(bts=0,trx=0,ts=7) FN=2654413 ------------------------- RX : Uplink Control Block ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) FN=2654413 Rx Packet Control Ack (reason=DL_ASS) +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) [UPLINK] DOWNLINK ASSIGNED +DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: Received Event RX_ASS_CTRL_ACK +DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: state_chg to NONE +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) free +PDCH(bts=0,trx=0,ts=7) Detaching TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE), 1 TBFs, USFs = 01, TFIs = 00000002. +MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Detaching TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) +********** DL-TBF ends here ********** +TBF(DL-TFI_0){WAIT_RELEASE}: Deallocated +UL_ASS_TBF(DL-TFI_0){NONE}: Deallocated +DL_ASS_TBF(DL-TFI_0){NONE}: Deallocated +TBF(DL-TFI_1){ASSIGN}: Received Event ASSIGN_ACK_PACCH +TBF(DL-TFI_1){ASSIGN}: state_chg to FLOW PDCH(bts=0,trx=0,ts=0) Received RTS on disabled TS PDCH(bts=0,trx=0,ts=1) Received RTS on disabled TS PDCH(bts=0,trx=0,ts=2) Received RTS on disabled TS @@ -3551,7 +3556,7 @@ TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Copying data unit 0 (BSN 10) TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduling Ack/Nack polling, because it was requested explicitly (e.g. first final block sent). PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654448 + 13 = 2654461 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduled DL Acknowledgement polling on PACCH (FN=2654461, TS=7) -TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) starting timer T3191 [final block (DL-TBF)] with 5 sec. 0 microsec, cur_fn=2654409 +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) starting timer T3191 [final block (DL-TBF)] with 5 sec. 0 microsec, cur_fn=2654413 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduled Ack/Nack polling on FN=2654461, TS=7 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) msg block (BSN 10, CS-1): 0f 03 14 4d 43 20 50 41 43 4b 45 54 20 30 39 20 28 54 42 46 20 32 29 === end test_tbf_dl_reuse ===