tbf/test: Add test for delayed release

This tests checks the implementation of the delayed release of an
downlink TBF.

Ticket: #556
Sponsored-by: On-Waves ehf

3 files changed, 293 insertions, 0 deletions

diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp
index a5effd38..c3230809 100644
--- a/tests/tbf/TbfTest.cpp
+++ b/tests/tbf/TbfTest.cpp
@@ -23,6 +23,7 @@
 #include "bts.h"
 #include "tbf.h"
 #include "gprs_debug.h"
+#include "pcu_utils.h"
 
 extern "C" {
 #include <osmocom/core/application.h>
@@ -213,6 +214,79 @@ static void test_tbf_final_ack(enum test_tbf_final_ack_mode test_mode)
 	}
 }
 
+static void test_tbf_delayed_release()
+{
+	BTS the_bts;
+	gprs_rlcmac_bts *bts;
+	uint8_t ts_no = 4;
+	unsigned i;
+	uint8_t ms_class = 45;
+	uint32_t fn = 0;
+	uint8_t block_nr = 0;
+	uint8_t trx_no;
+
+	uint8_t rbb[64/8];
+
+	gprs_rlcmac_dl_tbf *dl_tbf;
+
+	printf("=== start %s ===\n", __func__);
+
+	bts = the_bts.bts_data();
+
+	setup_bts(&the_bts, ts_no);
+	bts->dl_tbf_idle_msec = 200;
+
+	dl_tbf = create_dl_tbf(&the_bts, ms_class, &trx_no);
+
+	for (i = 0; i < sizeof(llc_data); i++)
+		llc_data[i] = i%256;
+
+	OSMO_ASSERT(dl_tbf->state_is(GPRS_RLCMAC_FLOW));
+
+	/* Schedule two LLC frames */
+	dl_tbf->append_data(ms_class, 1000, llc_data, sizeof(llc_data));
+	dl_tbf->append_data(ms_class, 1000, llc_data, sizeof(llc_data));
+
+	OSMO_ASSERT(dl_tbf->state_is(GPRS_RLCMAC_FLOW));
+
+	/* Drain the queue */
+	while (dl_tbf->have_data())
+		/* Request to send one RLC/MAC block */
+		send_rlc_block(bts, trx_no, ts_no, 0, &fn, &block_nr);
+
+	OSMO_ASSERT(dl_tbf->state_is(GPRS_RLCMAC_FLOW));
+
+	/* ACK all blocks */
+	memset(rbb, 0xff, sizeof(rbb));
+	/* Receive an ACK */
+	dl_tbf->rcvd_dl_ack(0, dl_tbf->m_window.v_s(), rbb);
+	OSMO_ASSERT(dl_tbf->m_window.window_empty());
+
+	/* Force sending of a single block containing an LLC dummy command */
+	send_rlc_block(bts, trx_no, ts_no, 0, &fn, &block_nr);
+
+	/* Receive an ACK */
+	dl_tbf->rcvd_dl_ack(0, dl_tbf->m_window.v_s(), rbb);
+	OSMO_ASSERT(dl_tbf->m_window.window_empty());
+
+	/* Timeout (make sure fn % 52 remains valid) */
+	fn += 52 * ((msecs_to_frames(bts->dl_tbf_idle_msec + 100) + 51)/ 52);
+	send_rlc_block(bts, trx_no, ts_no, 0, &fn, &block_nr);
+
+	OSMO_ASSERT(dl_tbf->state_is(GPRS_RLCMAC_FINISHED));
+
+	/* Receive a final ACK */
+	dl_tbf->rcvd_dl_ack(1, dl_tbf->m_window.v_s(), rbb);
+
+	/* Clean up and ensure tbfs are in the correct state */
+	OSMO_ASSERT(dl_tbf->state_is(GPRS_RLCMAC_WAIT_RELEASE));
+	OSMO_ASSERT(dl_tbf->new_tbf() == dl_tbf);
+	dl_tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
+	check_tbf(dl_tbf);
+	tbf_free(dl_tbf);
+	printf("=== end %s ===\n", __func__);
+}
+
 static const struct log_info_cat default_categories[] = {
         {"DCSN1", "\033[1;31m", "Concrete Syntax Notation One (CSN1)", LOGL_INFO, 0},
         {"DL1IF", "\033[1;32m", "GPRS PCU L1 interface (L1IF)", LOGL_DEBUG, 1},
@@ -252,6 +326,7 @@ int main(int argc, char **argv)
 	test_tbf_tlli_update();
 	test_tbf_final_ack(TEST_MODE_STANDARD);
 	test_tbf_final_ack(TEST_MODE_REVERSE_FREE);
+	test_tbf_delayed_release();
 	return EXIT_SUCCESS;
 }
 
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index b8aa0af8..b6b6748f 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -143,3 +143,219 @@ TBF(TFI=1 TLLI=0x00000000 DIR=DL STATE=ASSIGN) Old TBF TBF(TFI=0 TLLI=0x00000000
 DL packet loss of IMSI= / TLLI=0x00000000: 0%
 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) free
 ********** TBF ends here **********
+Searching for first unallocated TFI: TRX=0 first TS=4
+ Found TFI=0.
+********** TBF starts here **********
+Allocating DL TBF: TFI=0 TRX=0 MS_CLASS=45
+Slot Allocation (Algorithm A) for class 45
+- Skipping TS 0, because not enabled
+- Skipping TS 1, because not enabled
+- Skipping TS 2, because not enabled
+- Skipping TS 3, because not enabled
+- Assign downlink TS=4
+- Setting Control TS 4
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) changes state from NULL to FLOW
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) append
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) append
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)  start Packet Downlink Assignment (PACCH)
++++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
+------------------------- TX : Packet Downlink Assignment -------------------------
+Scheduling control message at RTS for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) (TRX=0, TS=4)
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=0 block=0 data=4f 08 20 00 44 02 00 02 08 04 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==0)
+- Sending new block at BSN 0
+-- Chunk with length 200 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 01 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 11 12 13 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=4 block=1 data=07 00 01 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 11 12 13 
+Received RTS for PDCH: TRX=0 TS=4 FN=8 block_nr=2 scheduling free USF for polling at FN=13 of TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==1)
+- Sending new block at BSN 1
+-- Chunk with length 180 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 03 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22 23 24 25 26 27 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=8 block=2 data=07 00 03 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22 23 24 25 26 27 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==2)
+- Sending new block at BSN 2
+-- Chunk with length 160 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 05 28 29 2a 2b 2c 2d 2e 2f 30 31 32 33 34 35 36 37 38 39 3a 3b 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=13 block=3 data=07 00 05 28 29 2a 2b 2c 2d 2e 2f 30 31 32 33 34 35 36 37 38 39 3a 3b 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==3)
+- Sending new block at BSN 3
+-- Chunk with length 140 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 07 3c 3d 3e 3f 40 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=17 block=4 data=07 00 07 3c 3d 3e 3f 40 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==4)
+- Sending new block at BSN 4
+-- Chunk with length 120 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 09 50 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 61 62 63 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=21 block=5 data=07 00 09 50 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 61 62 63 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==5)
+- Sending new block at BSN 5
+-- Chunk with length 100 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 0b 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 71 72 73 74 75 76 77 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=26 block=6 data=07 00 0b 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 71 72 73 74 75 76 77 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==6)
+- Sending new block at BSN 6
+-- Chunk with length 80 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 0d 78 79 7a 7b 7c 7d 7e 7f 80 81 82 83 84 85 86 87 88 89 8a 8b 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=30 block=7 data=07 00 0d 78 79 7a 7b 7c 7d 7e 7f 80 81 82 83 84 85 86 87 88 89 8a 8b 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==7)
+- Sending new block at BSN 7
+-- Chunk with length 60 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 0f 8c 8d 8e 8f 90 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=34 block=8 data=07 00 0f 8c 8d 8e 8f 90 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==8)
+- Sending new block at BSN 8
+-- Chunk with length 40 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 11 a0 a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 b1 b2 b3 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=39 block=9 data=07 00 11 a0 a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 b1 b2 b3 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==9)
+- Sending new block at BSN 9
+-- Chunk with length 20 would exactly fit into space (20): add length header with LI=0, to make frame extend to next block, and we are done
+data block: 07 00 12 01 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 c1 c2 c3 c4 c5 c6 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=43 block=10 data=07 00 12 01 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 c1 c2 c3 c4 c5 c6 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==10)
+- Sending new block at BSN 10
+-- Chunk with length 1 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)len=200
+- Dequeue next LLC for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) (len=200)
+-- Chunk with length 200 larger than space (18) left in block: copy only remaining space, and we are done
+data block: 07 00 14 07 c7 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 11 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=47 block=11 data=07 00 14 07 c7 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 11 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==11)
+- Sending new block at BSN 11
+-- Chunk with length 182 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 17 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22 23 24 25 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=52 block=12 data=07 00 17 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22 23 24 25 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==12)
+- Sending new block at BSN 12
+-- Chunk with length 162 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 19 26 27 28 29 2a 2b 2c 2d 2e 2f 30 31 32 33 34 35 36 37 38 39 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=56 block=13 data=07 00 19 26 27 28 29 2a 2b 2c 2d 2e 2f 30 31 32 33 34 35 36 37 38 39 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==13)
+- Sending new block at BSN 13
+-- Chunk with length 142 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 1b 3a 3b 3c 3d 3e 3f 40 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=60 block=14 data=07 00 1b 3a 3b 3c 3d 3e 3f 40 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==14)
+- Sending new block at BSN 14
+-- Chunk with length 122 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 1d 4e 4f 50 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 61 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=65 block=15 data=07 00 1d 4e 4f 50 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 61 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==15)
+- Sending new block at BSN 15
+-- Chunk with length 102 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 1f 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 71 72 73 74 75 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=69 block=16 data=07 00 1f 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 71 72 73 74 75 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==16)
+- Sending new block at BSN 16
+-- Chunk with length 82 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 21 76 77 78 79 7a 7b 7c 7d 7e 7f 80 81 82 83 84 85 86 87 88 89 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=73 block=17 data=07 00 21 76 77 78 79 7a 7b 7c 7d 7e 7f 80 81 82 83 84 85 86 87 88 89 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==17)
+- Sending new block at BSN 17
+-- Chunk with length 62 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 23 8a 8b 8c 8d 8e 8f 90 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=78 block=18 data=07 00 23 8a 8b 8c 8d 8e 8f 90 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==18)
+- Sending new block at BSN 18
+-- Chunk with length 42 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 25 9e 9f a0 a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 b1 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=82 block=19 data=07 00 25 9e 9f a0 a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 b1 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==19)
+- Sending new block at BSN 19
+-- Chunk with length 22 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 00 27 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 c1 c2 c3 c4 c5 
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=86 block=20 data=07 00 27 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 c1 c2 c3 c4 c5 
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==20)
+- Sending new block at BSN 20
+-- Chunk with length 2 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)len=200
+-- Empty chunk, added LLC dummy command of size 16, drained_since=0
+-- Chunk with length 16 is less than remaining space (17): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)len=16
+-- No space left, so we are done.
+data block: 07 00 28 0a 41 c6 c7 43 c0 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+- Scheduling Ack/Nack polling, because is was requested explicitly (e.g. first final block sent).
+Polling is already sheduled for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW), so we must wait for requesting downlink ack
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=91 block=21 data=07 00 28 0a 41 c6 c7 43 c0 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink acknowledge
+- ack:  (BSN=85)"RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR"(BSN=20)  R=ACK I=NACK
+- got ack for BSN=20
+- got ack for BSN=19
+- got ack for BSN=18
+- got ack for BSN=17
+- got ack for BSN=16
+- got ack for BSN=15
+- got ack for BSN=14
+- got ack for BSN=13
+- got ack for BSN=12
+- got ack for BSN=11
+- got ack for BSN=10
+- got ack for BSN=9
+- got ack for BSN=8
+- got ack for BSN=7
+- got ack for BSN=6
+- got ack for BSN=5
+- got ack for BSN=4
+- got ack for BSN=3
+- got ack for BSN=2
+- got ack for BSN=1
+- got ack for BSN=0
+- V(B): (V(A)=21)""(V(S)-1=20)  A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==21 .. V(S)==21)
+- Sending new block at BSN 21
+-- Empty chunk, added LLC dummy command of size 19, drained_since=4
+-- Chunk with length 19 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)len=19
+-- No space left, so we are done.
+data block: 07 00 2a 4d 43 c0 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+- Scheduling Ack/Nack polling, because is was requested explicitly (e.g. first final block sent).
+Polling is already sheduled for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW), so we must wait for requesting downlink ack
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=95 block=22 data=07 00 2a 4d 43 c0 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink acknowledge
+- ack:  (BSN=86)"RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR"(BSN=21)  R=ACK I=NACK
+- got ack for BSN=21
+- V(B): (V(A)=22)""(V(S)-1=21)  A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid
+Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4)
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) downlink (V(A)==22 .. V(S)==22)
+- Sending new block at BSN 22
+-- Empty chunk, added LLC dummy command of size 19, drained_since=112
+-- Chunk with length 19 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW)len=19
+-- Final block, so we done.
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FLOW) changes state from FLOW to FINISHED
+data block: 07 01 2c 4d 43 c0 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+- Scheduling Ack/Nack polling, because is was requested explicitly (e.g. first final block sent).
+Polling is already sheduled for TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FINISHED), so we must wait for requesting downlink ack
+Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=203 block=23 data=07 01 2c 4d 43 c0 01 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FINISHED) downlink acknowledge
+- Final ACK received.
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=FINISHED) changes state from FINISHED to WAIT RELEASE
+- No new message, so we release.
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) starting timer 3193.
+DL packet loss of IMSI= / TLLI=0x00000000: 0%
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) free
+TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) stopping timer 3193.
+********** TBF ends here **********
diff --git a/tests/tbf/TbfTest.ok b/tests/tbf/TbfTest.ok
index e69de29b..13d14581 100644
--- a/tests/tbf/TbfTest.ok
+++ b/tests/tbf/TbfTest.ok
@@ -0,0 +1,2 @@
+=== start test_tbf_delayed_release ===
+=== end test_tbf_delayed_release ===