ms: Store references to replaced TBFs in the MS object
Currently when calling GprsMs::attach_tbf and a TBF of the same
direction already exists, the old TBF gets detached from the MS
object.
Therefore that TBF object loses access to that MS object including
for instance TLLI and IMSI.
This leads to failing DL TBF reuses, since the downlink assigment
cannot be sent on the PACCH later on because that must be sent on the
old DL TBF which ms() is NULL and the new DL TBF cannot be retrieved.
This commit fixes this bug by changing the GprsMs implementation to
keep a list of replaced (old) TBFs. TBFs are only removed when they
are being detached explicitely (see tbf_free and set_ms).
Addresses:
tbf.cpp:741 We have a schedule for downlink assignment at uplink
TBF(TFI=1 TLLI=0xf35a680e DIR=UL STATE=RELEASING), but there is no
downlink TBF
Sponsored-by: On-Waves ehf
diff --git a/src/gprs_ms.cpp b/src/gprs_ms.cpp
index cb7773f..807f345 100644
--- a/src/gprs_ms.cpp
+++ b/src/gprs_ms.cpp
@@ -140,6 +140,8 @@
GprsMs::~GprsMs()
{
+ LListHead<gprs_rlcmac_tbf> *pos, *tmp;
+
LOGP(DRLCMAC, LOGL_INFO, "Destroying MS object, TLLI = 0x%08x\n", tlli());
set_reserved_slots(NULL, 0, 0);
@@ -156,6 +158,10 @@
m_dl_tbf->set_ms(NULL);
m_dl_tbf = NULL;
}
+
+ llist_for_each_safe(pos, tmp, &m_old_tbfs)
+ pos->entry()->set_ms(NULL);
+
m_llc_queue.clear(m_bts);
}
@@ -227,7 +233,7 @@
Guard guard(this);
if (m_ul_tbf)
- detach_tbf(m_ul_tbf);
+ llist_add_tail(&m_ul_tbf->ms_list(), &m_old_tbfs);
m_ul_tbf = tbf;
@@ -246,7 +252,7 @@
Guard guard(this);
if (m_dl_tbf)
- detach_tbf(m_dl_tbf);
+ llist_add_tail(&m_dl_tbf->ms_list(), &m_old_tbfs);
m_dl_tbf = tbf;
@@ -256,12 +262,26 @@
void GprsMs::detach_tbf(gprs_rlcmac_tbf *tbf)
{
- if (m_ul_tbf && tbf == static_cast<gprs_rlcmac_tbf *>(m_ul_tbf))
+ if (tbf == static_cast<gprs_rlcmac_tbf *>(m_ul_tbf)) {
m_ul_tbf = NULL;
- else if (m_dl_tbf && tbf == static_cast<gprs_rlcmac_tbf *>(m_dl_tbf))
+ } else if (tbf == static_cast<gprs_rlcmac_tbf *>(m_dl_tbf)) {
m_dl_tbf = NULL;
- else
- return;
+ } else {
+ bool found = false;
+
+ LListHead<gprs_rlcmac_tbf> *pos, *tmp;
+ llist_for_each_safe(pos, tmp, &m_old_tbfs) {
+ if (pos->entry() == tbf) {
+ llist_del(pos);
+ found = true;
+ break;
+ }
+ }
+
+ /* Protect against recursive calls via set_ms() */
+ if (!found)
+ return;
+ }
LOGP(DRLCMAC, LOGL_INFO, "Detaching TBF from MS object, TLLI = 0x%08x, TBF = %s\n",
tlli(), tbf->name());
diff --git a/src/gprs_ms.h b/src/gprs_ms.h
index c490e7a..1f080ff 100644
--- a/src/gprs_ms.h
+++ b/src/gprs_ms.h
@@ -109,13 +109,14 @@
void update_error_rate(gprs_rlcmac_tbf *tbf, int percent);
- bool is_idle() const {return !m_ul_tbf && !m_dl_tbf && !m_ref;}
+ bool is_idle() const;
void* operator new(size_t num);
void operator delete(void* p);
LListHead<GprsMs>& list() {return this->m_list;}
const LListHead<GprsMs>& list() const {return this->m_list;}
+ const LListHead<gprs_rlcmac_tbf>& old_tbfs() const {return m_old_tbfs;}
void update_l1_meas(const pcu_l1_meas *meas);
const pcu_l1_meas* l1_meas() const {return &m_l1_meas;};
@@ -136,6 +137,8 @@
Callback * m_cb;
gprs_rlcmac_ul_tbf *m_ul_tbf;
gprs_rlcmac_dl_tbf *m_dl_tbf;
+ LListHead<gprs_rlcmac_tbf> m_old_tbfs;
+
uint32_t m_tlli;
uint32_t m_new_ul_tlli;
uint32_t m_new_dl_tlli;
@@ -167,6 +170,11 @@
struct gprs_codel *m_codel_state;
};
+inline bool GprsMs::is_idle() const
+{
+ return !m_ul_tbf && !m_dl_tbf && !m_ref && llist_empty(&m_old_tbfs);
+}
+
inline uint32_t GprsMs::tlli() const
{
return m_new_ul_tlli ? m_new_ul_tlli :
diff --git a/src/tbf.cpp b/src/tbf.cpp
index 9d4363f..4a59faa 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -42,7 +42,8 @@
static void tbf_timer_cb(void *_tbf);
gprs_rlcmac_tbf::gprs_rlcmac_tbf(gprs_rlcmac_tbf_direction dir) :
- direction(dir)
+ direction(dir),
+ m_ms_list(this)
{
}
diff --git a/src/tbf.h b/src/tbf.h
index f1484f0..4a92bbf 100644
--- a/src/tbf.h
+++ b/src/tbf.h
@@ -23,6 +23,7 @@
#include "gprs_rlcmac.h"
#include "llc.h"
#include "rlc.h"
+#include "cxx_linuxlist.h"
#include <gprs_debug.h>
#include <stdint.h>
@@ -165,6 +166,9 @@
/* attempt to make things a bit more fair */
void rotate_in_list();
+ LListHead<gprs_rlcmac_tbf>& ms_list() {return this->m_ms_list;}
+ const LListHead<gprs_rlcmac_tbf>& ms_list() const {return this->m_ms_list;}
+
struct llist_pods list;
uint32_t state_flags;
enum gprs_rlcmac_tbf_direction direction;
@@ -238,6 +242,8 @@
uint8_t m_ms_class;
private:
+ LListHead<gprs_rlcmac_tbf> m_ms_list;
+
mutable char m_name_buf[60];
};
diff --git a/tests/ms/MsTest.cpp b/tests/ms/MsTest.cpp
index 7255da3..4e9c7e2 100644
--- a/tests/ms/MsTest.cpp
+++ b/tests/ms/MsTest.cpp
@@ -196,36 +196,42 @@
OSMO_ASSERT(!ms->is_idle());
OSMO_ASSERT(ms->ul_tbf() == NULL);
OSMO_ASSERT(ms->dl_tbf() == dl_tbf[0]);
+ OSMO_ASSERT(llist_empty(&ms->old_tbfs()));
OSMO_ASSERT(!was_idle);
ms->attach_tbf(dl_tbf[1]);
OSMO_ASSERT(!ms->is_idle());
OSMO_ASSERT(ms->ul_tbf() == NULL);
OSMO_ASSERT(ms->dl_tbf() == dl_tbf[1]);
+ OSMO_ASSERT(!llist_empty(&ms->old_tbfs()));
OSMO_ASSERT(!was_idle);
ms->attach_tbf(ul_tbf);
OSMO_ASSERT(!ms->is_idle());
OSMO_ASSERT(ms->ul_tbf() == ul_tbf);
OSMO_ASSERT(ms->dl_tbf() == dl_tbf[1]);
+ OSMO_ASSERT(!llist_empty(&ms->old_tbfs()));
OSMO_ASSERT(!was_idle);
ms->detach_tbf(ul_tbf);
OSMO_ASSERT(!ms->is_idle());
OSMO_ASSERT(ms->ul_tbf() == NULL);
OSMO_ASSERT(ms->dl_tbf() == dl_tbf[1]);
+ OSMO_ASSERT(!llist_empty(&ms->old_tbfs()));
OSMO_ASSERT(!was_idle);
ms->detach_tbf(dl_tbf[0]);
OSMO_ASSERT(!ms->is_idle());
OSMO_ASSERT(ms->ul_tbf() == NULL);
OSMO_ASSERT(ms->dl_tbf() == dl_tbf[1]);
+ OSMO_ASSERT(llist_empty(&ms->old_tbfs()));
OSMO_ASSERT(!was_idle);
ms->detach_tbf(dl_tbf[1]);
OSMO_ASSERT(ms->is_idle());
OSMO_ASSERT(ms->ul_tbf() == NULL);
OSMO_ASSERT(ms->dl_tbf() == NULL);
+ OSMO_ASSERT(llist_empty(&ms->old_tbfs()));
OSMO_ASSERT(was_idle);
delete ms;
diff --git a/tests/ms/MsTest.err b/tests/ms/MsTest.err
index ed53f48..a2e4a0c 100644
--- a/tests/ms/MsTest.err
+++ b/tests/ms/MsTest.err
@@ -13,10 +13,10 @@
Creating MS object, TLLI = 0xffeeddbb
Attaching TBF to MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL)
Attaching TBF to MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL)
-Detaching TBF from MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL)
Attaching TBF to MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL)
Detaching TBF from MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL)
Detaching TBF from MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL)
+Detaching TBF from MS object, TLLI = 0xffeeddbb, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL)
Destroying MS object, TLLI = 0xffeeddbb
Creating MS object, TLLI = 0xaa000000
Modifying MS object, UL TLLI: 0xaa000000 -> 0xff001111, not yet confirmed
diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp
index 3ed8341..5e1b0de 100644
--- a/tests/tbf/TbfTest.cpp
+++ b/tests/tbf/TbfTest.cpp
@@ -1051,15 +1051,13 @@
OSMO_ASSERT(dl_tbf1 != dl_tbf2);
send_control_ack(dl_tbf1);
- /* OSMO_ASSERT(dl_tbf2->state_is(GPRS_RLCMAC_FLOW)); */
+ OSMO_ASSERT(dl_tbf2->state_is(GPRS_RLCMAC_FLOW));
/* Transmit all data */
- /* TODO: This blocks with the current implementation, enable when fixed
transmit_dl_data(&the_bts, tlli1, &fn);
OSMO_ASSERT(ms2->llc_queue()->size() == 0);
OSMO_ASSERT(ms2->dl_tbf());
OSMO_ASSERT(ms2->dl_tbf()->state_is(GPRS_RLCMAC_FINISHED));
- */
printf("=== end %s ===\n", __func__);
}
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index 9a46824..55e46d0 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -95,16 +95,16 @@
PDCH(TS 4, TRX 0): Attaching TBF(TFI=1 TLLI=0x00000000 DIR=DL STATE=NULL), 2 TBFs, USFs = 00, TFIs = 00000003.
- Setting Control TS 4
Attaching TBF to MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NULL)
-Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE)
Allocated TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NULL): trx = 0, ul_slots = 10, dl_slots = 10
-TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between
-Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) exists
+TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between
+Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) exists
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NULL) changes state from NULL to ASSIGN
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN) starting timer 0.
-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.
-PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE), 1 TBFs, USFs = 00, TFIs = 00000002.
+DL packet loss of IMSI= / TLLI=0xffeeddcc: 0%
+TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) free
+TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) stopping timer 3193.
+PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE), 1 TBFs, USFs = 00, TFIs = 00000002.
+Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE)
********** TBF ends here **********
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN) free
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN) stopping timer 0.
@@ -172,10 +172,9 @@
PDCH(TS 4, TRX 0): Attaching TBF(TFI=1 TLLI=0x00000000 DIR=DL STATE=NULL), 2 TBFs, USFs = 00, TFIs = 00000003.
- Setting Control TS 4
Attaching TBF to MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NULL)
-Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE)
Allocated TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NULL): trx = 0, ul_slots = 10, dl_slots = 10
-TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between
-Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) exists
+TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between
+Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) exists
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NULL) changes state from NULL to ASSIGN
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN) starting timer 0.
TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN) free
@@ -183,10 +182,11 @@
PDCH(TS 4, TRX 0): Detaching TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN), 1 TBFs, USFs = 00, TFIs = 00000001.
Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=ASSIGN)
********** TBF ends here **********
-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.
-PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE), 0 TBFs, USFs = 00, TFIs = 00000000.
+DL packet loss of IMSI= / TLLI=0xffeeddcc: 0%
+TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) free
+TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE) stopping timer 3193.
+PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE), 0 TBFs, USFs = 00, TFIs = 00000000.
+Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT RELEASE)
********** TBF ends here **********
Destroying MS object, TLLI = 0xffeeddcc
Searching for first unallocated TFI: TRX=0
@@ -2630,15 +2630,214 @@
PDCH(TS 7, TRX 0): Attaching TBF(TFI=1 TLLI=0x00000000 DIR=DL STATE=NULL), 2 TBFs, USFs = 01, TFIs = 00000003.
- Setting Control TS 7
Attaching TBF to MS object, TLLI = 0xf1223344, TBF = TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL)
-Detaching TBF from MS object, TLLI = 0xf1223344, TBF = TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE)
Allocated TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL): trx = 0, ul_slots = 80, dl_slots = 80
-TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between
-Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE) exists
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) Trigger dowlink assignment on PACCH, because another LLC PDU has arrived in between
+Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) exists
TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) starting timer 0.
Received RTS for PDCH: TRX=0 TS=7 FN=2654400 block_nr=2 scheduling USF=0 for required uplink resource of UL TFI=0
-We have a schedule for downlink assignment at TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=WAIT RELEASE), but there is no downlink TBF
-Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654400 block=2 data=40 94 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
++++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
+------------------------- TX : Packet Downlink Assignment -------------------------
+Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) (TRX=0, TS=7)
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654400 block=2 data=48 08 20 08 0c 72 00 02 18 00 80 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b
+++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++
------------------------- RX : Uplink Control Block -------------------------
-PACKET CONTROL ACK with unknown FN=2654379 TLLI=0x00000000 (TRX 0 TS 7)
+RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) Packet Control Ack
+TBF: [UPLINK] DOWNLINK ASSIGNED TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE)
+DL packet loss of IMSI=0011223344 / TLLI=0xf1223344: 0%
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) free
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) stopping timer 3193.
+PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE), 1 TBFs, USFs = 01, TFIs = 00000002.
+Detaching TBF from MS object, TLLI = 0xf1223344, TBF = TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE)
+********** TBF ends here **********
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) changes state from ASSIGN to FLOW
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) stopping timer 0.
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654405 block_nr=3 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==0)
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+- Sending new block at BSN 0, CS=1
+-- Chunk with length 21 larger than space (20) left in block: copy only remaining space, and we are done
+data block: 07 02 01 4c 4c 43 20 50 41 43 4b 45 54 20 30 30 20 28 54 42 46 20 32
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654405 block=3 data=00 02 01 4c 4c 43 20 50 41 43 4b 45 54 20 30 30 20 28 54 42 46 20 32
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654409 block_nr=4 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==1)
+- Sending new block at BSN 1, CS=1
+-- Chunk with length 1 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (18) left in block: copy only remaining space, and we are done
+data block: 07 02 02 07 29 4c 4c 43 20 50 41 43 4b 45 54 20 30 31 20 28 54 42 46
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654409 block=4 data=00 02 02 07 29 4c 4c 43 20 50 41 43 4b 45 54 20 30 31 20 28 54 42 46
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654413 block_nr=5 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==2)
+- Sending new block at BSN 2, CS=1
+-- Chunk with length 3 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (16) left in block: copy only remaining space, and we are done
+data block: 07 02 04 0f 20 32 29 4c 4c 43 20 50 41 43 4b 45 54 20 30 32 20 28 54
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654413 block=5 data=00 02 04 0f 20 32 29 4c 4c 43 20 50 41 43 4b 45 54 20 30 32 20 28 54
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654418 block_nr=6 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==3)
+- Sending new block at BSN 3, CS=1
+-- Chunk with length 5 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (14) left in block: copy only remaining space, and we are done
+data block: 07 02 06 17 42 46 20 32 29 4c 4c 43 20 50 41 43 4b 45 54 20 30 33 20
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654418 block=6 data=00 02 06 17 42 46 20 32 29 4c 4c 43 20 50 41 43 4b 45 54 20 30 33 20
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654422 block_nr=7 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==4)
+- Sending new block at BSN 4, CS=1
+-- Chunk with length 7 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (12) left in block: copy only remaining space, and we are done
+data block: 07 02 08 1f 28 54 42 46 20 32 29 4c 4c 43 20 50 41 43 4b 45 54 20 30
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654422 block=7 data=00 02 08 1f 28 54 42 46 20 32 29 4c 4c 43 20 50 41 43 4b 45 54 20 30
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654426 block_nr=8 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==5)
+- Sending new block at BSN 5, CS=1
+-- Chunk with length 9 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (10) left in block: copy only remaining space, and we are done
+data block: 07 02 0a 27 34 20 28 54 42 46 20 32 29 4c 4c 43 20 50 41 43 4b 45 54
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654426 block=8 data=00 02 0a 27 34 20 28 54 42 46 20 32 29 4c 4c 43 20 50 41 43 4b 45 54
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654431 block_nr=9 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==6)
+- Sending new block at BSN 6, CS=1
+-- Chunk with length 11 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (8) left in block: copy only remaining space, and we are done
+data block: 07 02 0c 2f 20 30 35 20 28 54 42 46 20 32 29 4c 4c 43 20 50 41 43 4b
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654431 block=9 data=00 02 0c 2f 20 30 35 20 28 54 42 46 20 32 29 4c 4c 43 20 50 41 43 4b
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654435 block_nr=10 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==7)
+- Sending new block at BSN 7, CS=1
+-- Chunk with length 13 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (6) left in block: copy only remaining space, and we are done
+data block: 07 02 0e 37 45 54 20 30 36 20 28 54 42 46 20 32 29 4c 4c 43 20 50 41
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654435 block=10 data=00 02 0e 37 45 54 20 30 36 20 28 54 42 46 20 32 29 4c 4c 43 20 50 41
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654439 block_nr=11 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==8)
+- Sending new block at BSN 8, CS=1
+-- Chunk with length 15 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (4) left in block: copy only remaining space, and we are done
+data block: 07 02 10 3f 43 4b 45 54 20 30 37 20 28 54 42 46 20 32 29 4c 4c 43 20
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654439 block=11 data=00 02 10 3f 43 4b 45 54 20 30 37 20 28 54 42 46 20 32 29 4c 4c 43 20
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654444 block_nr=0 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==9)
+- Sending new block at BSN 9, CS=1
+-- Chunk with length 17 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+- Dequeue next LLC for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) (len=21)
+-- Chunk with length 21 larger than space (2) left in block: copy only remaining space, and we are done
+data block: 07 02 12 47 50 41 43 4b 45 54 20 30 38 20 28 54 42 46 20 32 29 4c 4c
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654444 block=0 data=00 02 12 47 50 41 43 4b 45 54 20 30 38 20 28 54 42 46 20 32 29 4c 4c
+Received RTS on disabled PDCH: TRX=0 TS=0
+Received RTS on disabled PDCH: TRX=0 TS=1
+Received RTS on disabled PDCH: TRX=0 TS=2
+Received RTS on disabled PDCH: TRX=0 TS=3
+Received RTS on disabled PDCH: TRX=0 TS=4
+Received RTS on disabled PDCH: TRX=0 TS=5
+Received RTS on disabled PDCH: TRX=0 TS=6
+Received RTS for PDCH: TRX=0 TS=7 FN=2654448 block_nr=1 scheduling USF=0 for required uplink resource of UL TFI=0
+Scheduling data message at RTS for DL TFI=1 (TRX=0, TS=7) prio=3
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==10)
+- Sending new block at BSN 10, CS=1
+-- Chunk with length 19 is less than remaining space (20): add length header to to delimit LLC frame
+Complete DL frame for TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=21
+-- Final block, so we done.
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FLOW) changes state from FLOW to FINISHED
+data block: 07 03 14 4d 43 20 50 41 43 4b 45 54 20 30 39 20 28 54 42 46 20 32 29
+- Scheduling Ack/Nack polling, because is was requested explicitly (e.g. first final block sent).
+Polling sheduled in this TS 7
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) starting timer 3191.
+Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654448 block=1 data=08 03 14 4d 43 20 50 41 43 4b 45 54 20 30 39 20 28 54 42 46 20 32 29