pespin has submitted this change. (
https://gerrit.osmocom.org/c/libosmo-gprs/+/31350 )
Change subject: rlcmac: Implement T3166
......................................................................
rlcmac: Implement T3166
Change-Id: I58dd757cbb5d8279fdf7fbdfb6f38ec0119c6156
---
M include/osmocom/gprs/rlcmac/tbf_ul.h
M include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
M src/rlcmac/rlcmac.c
M src/rlcmac/tbf_ul.c
M src/rlcmac/tbf_ul_fsm.c
M tests/rlcmac/rlcmac_prim_test.c
M tests/rlcmac/rlcmac_prim_test.err
M tests/rlcmac/rlcmac_prim_test.ok
8 files changed, 288 insertions(+), 15 deletions(-)
Approvals:
laforge: Looks good to me, but someone else must approve
Jenkins Builder: Verified
pespin: Looks good to me, approved
diff --git a/include/osmocom/gprs/rlcmac/tbf_ul.h
b/include/osmocom/gprs/rlcmac/tbf_ul.h
index 08075be..f1b7128 100644
--- a/include/osmocom/gprs/rlcmac/tbf_ul.h
+++ b/include/osmocom/gprs/rlcmac/tbf_ul.h
@@ -45,6 +45,8 @@
struct gprs_rlcmac_ul_tbf *gprs_rlcmac_ul_tbf_alloc(struct gprs_rlcmac_entity
*gre);
void gprs_rlcmac_ul_tbf_free(struct gprs_rlcmac_ul_tbf *ul_tbf);
+bool gprs_rlcmac_ul_tbf_in_contention_resolution(const struct
gprs_rlcmac_ul_tbf *ul_tbf);
+
bool gprs_rlcmac_ul_tbf_data_rts(const struct gprs_rlcmac_ul_tbf *ul_tbf,
const struct gprs_rlcmac_rts_block_ind *bi);
bool gprs_rlcmac_ul_tbf_dummy_rts(const struct gprs_rlcmac_ul_tbf *ul_tbf,
const struct gprs_rlcmac_rts_block_ind *bi);
diff --git a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
index 327acd7..6957992 100644
--- a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
+++ b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
@@ -28,6 +28,7 @@
GPRS_RLCMAC_TBF_UL_EV_UL_ASS_START,
GPRS_RLCMAC_TBF_UL_EV_UL_ASS_COMPL,
GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT,
+ GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS,
GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT,
GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD,
};
diff --git a/src/rlcmac/rlcmac.c b/src/rlcmac/rlcmac.c
index ac489d5..cff7c79 100644
--- a/src/rlcmac/rlcmac.c
+++ b/src/rlcmac/rlcmac.c
@@ -45,6 +45,7 @@
/* TS 44.060 Table 13.1.1 */
static struct osmo_tdef T_defs_rlcmac[] = {
{ .T=3164, .default_val=5, .desc="Wait for Uplink State Flag After
Assignment (s)" },
+ { .T=3166, .default_val=5, .desc="Wait for Packet Uplink ACK/NACK after
sending of first data block (s)" },
{ 0 } /* empty item at the end */
};
diff --git a/src/rlcmac/tbf_ul.c b/src/rlcmac/tbf_ul.c
index a47a2b3..993f694 100644
--- a/src/rlcmac/tbf_ul.c
+++ b/src/rlcmac/tbf_ul.c
@@ -90,6 +90,28 @@
talloc_free(ul_tbf);
}
+/* whether the UL TBF is in Contention Resolution state (false = already
succeeded)*/
+bool gprs_rlcmac_ul_tbf_in_contention_resolution(const struct
gprs_rlcmac_ul_tbf *ul_tbf)
+{
+ struct osmo_fsm_inst *fi = ul_tbf->state_fsm.fi;
+ switch (fi->state) {
+ case GPRS_RLCMAC_TBF_UL_ST_NEW:
+ case GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN:
+ return true;
+ case GPRS_RLCMAC_TBF_UL_ST_FLOW:
+ case GPRS_RLCMAC_TBF_UL_ST_FINISHED:
+ /* TS 44.60 7.1.3.3: For 2hase access, contention resolution is
+ * successful once we get out of
GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN
+ * (when we receive a Pkt Ul Ass, see TS 44.60 7.1.3.3) */
+ /* 1phase access: Check if either T3164 or T3166 are active: */
+ return (ul_tbf->ul_ass_fsm.ass_type ==
GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE &&
+ osmo_timer_pending(&fi->timer) &&
+ (fi->T == 3164 || fi->T == 3166));
+ default:
+ return false;
+ }
+}
+
/* Used by the scheduler to find out whether an Uplink Dummy Control Block can
be transmitted. If
* true, it will potentially call gprs_rlcmac_ul_tbf_dummy_create() to
generate a new dummy message to transmit. */
bool gprs_rlcmac_ul_tbf_dummy_rts(const struct gprs_rlcmac_ul_tbf *ul_tbf,
const struct gprs_rlcmac_rts_block_ind *bi)
@@ -171,6 +193,9 @@
int rc;
rc = gprs_rlcmac_ul_tbf_update_window(ul_tbf, first_bsn, rbb);
+ if (gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf))
+ osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi,
GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS, NULL);
+
if (final_ack) {
LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Final ACK received.\n");
rc = gprs_rlcmac_ul_tbf_handle_final_ack(ul_tbf);
diff --git a/src/rlcmac/tbf_ul_fsm.c b/src/rlcmac/tbf_ul_fsm.c
index 72f2994..19d352d 100644
--- a/src/rlcmac/tbf_ul_fsm.c
+++ b/src/rlcmac/tbf_ul_fsm.c
@@ -25,16 +25,18 @@
#include <osmocom/gprs/rlcmac/tbf_ul_fsm.h>
#include <osmocom/gprs/rlcmac/tbf_ul.h>
+#include <osmocom/gprs/rlcmac/rlc_window_ul.h>
#include <osmocom/gprs/rlcmac/gre.h>
#define X(s) (1 << (s))
static const struct value_string tbf_ul_fsm_event_names[] = {
- { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_START, "UL_ASS_START" },
- { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_COMPL, "UL_ASS_COMPL" },
- { GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT, "FIRST_UL_DATA_SENT" },
- { GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT, "LAST_UL_DATA_SENT" },
- { GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD, "FINAL_ACK_RECVD" },
+ { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_START, "UL_ASS_START"
},
+ { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_COMPL, "UL_ASS_COMPL"
},
+ { GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT,
"FIRST_UL_DATA_SENT" },
+ { GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS,
"CONTENTION_RESOLUTION_SUCCESS" },
+ { GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT,
"LAST_UL_DATA_SENT" },
+ { GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD,
"FINAL_ACK_RECVD" },
{ 0, NULL }
};
@@ -42,7 +44,7 @@
[GPRS_RLCMAC_TBF_UL_ST_NEW] = { },
[GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN] = { },
[GPRS_RLCMAC_TBF_UL_ST_FLOW] = { .T = 3164 },
- [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { },
+ [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { .keep_timer = true }, /* keep FLOW
state's T3164 / T3166 */
};
/* Transition to a state, using the T timer defined in tbf_fsm_timeouts.
@@ -77,14 +79,29 @@
return gprs_rlcmac_prim_call_down_cb(rlcmac_prim);
}
+static void reinit_pkt_acces_procedure(struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx)
+{
+ int rc;
+ /* TS 44.060 sub-clause 7.1.4. Reinitiate the packet access procedure:
+ * Move to NEW state, start Ass and wait for
GPRS_RLCMAC_TBF_UL_ASS_EV_START */
+ tbf_ul_fsm_state_chg(ctx->fi, GPRS_RLCMAC_TBF_UL_ST_NEW);
+ /* We always use 1phase for now... */
+ rc = gprs_rlcmac_tbf_ul_ass_start(ctx->ul_tbf,
GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE);
+ if (rc < 0)
+ gprs_rlcmac_ul_tbf_free(ctx->ul_tbf);
+}
+
/* This one is triggered when packet access procedure fails, which can happen
* either in WAIT_IMM_ASS (ImmAss timeout), FLOW (T3164) or FINISHED (T3164,
T3166) */
static void st_new_on_enter(struct osmo_fsm_inst *fi, uint32_t prev_state)
{
struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct
gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv;
+
memset(&ctx->ul_tbf->cur_alloc, 0, sizeof(ctx->ul_tbf->cur_alloc));
ctx->ul_tbf->n3104 = 0;
+ /* Mark everything we transmitted so far as NACKed: */
+ gprs_rlcmac_rlc_ul_window_mark_for_resend(ctx->ul_tbf->ulw);
/* Make sure the lower layers realize this tbf_nr has no longer any
assigned resource: */
configure_ul_tbf(ctx);
}
@@ -118,11 +135,26 @@
static void st_flow(struct osmo_fsm_inst *fi, uint32_t event, void *data)
{
struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct
gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv;
+ unsigned long val_sec;
+
switch (event) {
case GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT:
LOGPFSML(ctx->fi, LOGL_INFO, "First UL block sent, stop
T3164\n");
OSMO_ASSERT(fi->T == 3164);
osmo_timer_del(&fi->timer);
+ if (ctx->ul_tbf->ul_ass_fsm.ass_type ==
GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE) {
+ LOGPFSML(ctx->fi, LOGL_INFO, "First UL block sent (1
phase access), start T3166\n");
+ fi->T = 3166;
+ val_sec = osmo_tdef_get(g_ctx->T_defs, fi->T,
OSMO_TDEF_S, -1);
+ osmo_timer_schedule(&fi->timer, val_sec, 0);
+ }
+ break;
+ case GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS:
+ LOGPFSML(ctx->fi, LOGL_INFO, "Contention resolution succeeded,
stop T3166\n");
+ OSMO_ASSERT(ctx->ul_tbf->ul_ass_fsm.ass_type ==
GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE);
+ OSMO_ASSERT(fi->T == 3166);
+ osmo_timer_del(&fi->timer);
+ fi->T = 0;
break;
case GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT:
tbf_ul_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ST_FINISHED);
@@ -134,8 +166,15 @@
static void st_finished(struct osmo_fsm_inst *fi, uint32_t event, void *data)
{
- //struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct
gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv;
+ struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct
gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv;
switch (event) {
+ case GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS:
+ LOGPFSML(ctx->fi, LOGL_INFO, "Contention resolution succeeded,
stop T3166\n");
+ OSMO_ASSERT(ctx->ul_tbf->ul_ass_fsm.ass_type ==
GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE);
+ OSMO_ASSERT(fi->T == 3166);
+ osmo_timer_del(&fi->timer);
+ fi->T = 0;
+ break;
case GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD:
break;
default:
@@ -165,6 +204,7 @@
[GPRS_RLCMAC_TBF_UL_ST_FLOW] = {
.in_event_mask =
X(GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT) |
+ X(GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS) |
X(GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT),
.out_state_mask =
X(GPRS_RLCMAC_TBF_UL_ST_NEW) |
@@ -174,9 +214,10 @@
},
[GPRS_RLCMAC_TBF_UL_ST_FINISHED] = {
.in_event_mask =
+ X(GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS) |
X(GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD),
.out_state_mask =
- X(GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN),
+ X(GPRS_RLCMAC_TBF_UL_ST_NEW),
.name = "FINISHED",
.action = st_finished,
},
@@ -185,7 +226,6 @@
static int tbf_ul_fsm_timer_cb(struct osmo_fsm_inst *fi)
{
struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct
gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv;
- int rc;
switch (fi->T) {
case 3164:
@@ -200,13 +240,23 @@
gprs_rlcmac_ul_tbf_free(ctx->ul_tbf);
return 0;
}
- /* TS 44.060 sub-clause 7.1.4. Reinitiate the packet access
procedure:
- * Move to NEW state, start Ass and wait for
GPRS_RLCMAC_TBF_UL_ASS_EV_START */
- tbf_ul_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ST_NEW);
- /* We always use 1phase for now... */
- rc = gprs_rlcmac_tbf_ul_ass_start(ctx->ul_tbf,
GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE);
- if (rc < 0)
+ reinit_pkt_acces_procedure(ctx);
+ break;
+ case 3166:
+ ctx->pkt_acc_proc_attempts++;
+ LOGPFSML(ctx->fi, LOGL_INFO, "T3166 timeout attempts=%u\n",
ctx->pkt_acc_proc_attempts);
+ OSMO_ASSERT(fi->state == GPRS_RLCMAC_TBF_UL_ST_FLOW ||
+ fi->state == GPRS_RLCMAC_TBF_UL_ST_FINISHED);
+ if (ctx->pkt_acc_proc_attempts == 4) {
+ /* TS 44.060 7.1.4 "... expiry of timers T3166 ... the
+ * mobile station shall remain in packet idle mode and
+ * notify higher layer (TBF establishment failure)" */
+ /* TODO: find out how to notify higher layers */
+ LOGPFSML(ctx->fi, LOGL_NOTICE, "TBF establishment
failure (T3166 timeout attempts=%u)\n", ctx->pkt_acc_proc_attempts);
gprs_rlcmac_ul_tbf_free(ctx->ul_tbf);
+ return 0;
+ }
+ reinit_pkt_acces_procedure(ctx);
break;
default:
OSMO_ASSERT(0);
diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c
index 75c18f8..09fa3c4 100644
--- a/tests/rlcmac/rlcmac_prim_test.c
+++ b/tests/rlcmac/rlcmac_prim_test.c
@@ -485,6 +485,45 @@
cleanup_test();
}
+static void test_ul_tbf_t3166_timeout(void)
+{
+ struct osmo_gprs_rlcmac_prim *rlcmac_prim;
+ int rc;
+
+ printf("=== %s start ===\n", __func__);
+ prepare_test();
+ uint32_t tlli = 0x2342;
+ uint8_t ts_nr = 7;
+ uint8_t usf = 0;
+ uint32_t rts_fn = 4;
+ unsigned int i;
+
+ rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_grr_unitdata_req(tlli,
pdu_llc_gmm_att_req,
+ sizeof(pdu_llc_gmm_att_req));
+ rlcmac_prim->grr.unitdata_req.sapi = OSMO_GPRS_RLCMAC_LLC_SAPI_GMM;
+ rc = osmo_gprs_rlcmac_prim_upper_down(rlcmac_prim);
+
+ for (i = 0; i < 4; i++) {
+ OSMO_ASSERT(sizeof(ccch_imm_ass_pkt_ul_tbf_normal) ==
GSM_MACBLOCK_LEN);
+ ccch_imm_ass_pkt_ul_tbf_normal[7] = last_rach_req_ra; /* Update
RA to match */
+ rlcmac_prim =
osmo_gprs_rlcmac_prim_alloc_l1ctl_ccch_data_ind(0,
ccch_imm_ass_pkt_ul_tbf_normal);
+ rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
+
+ /* Trigger transmission of LLC data (GMM Attach) (first part) */
+ rlcmac_prim =
osmo_gprs_rlcmac_prim_alloc_l1ctl_pdch_rts_ind(ts_nr, rts_fn, usf);
+ rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
+ OSMO_ASSERT(rc == 0);
+
+ /* increase time 5 seconds, timeout should trigger */
+ clock_override_add(5, 0);
+ clock_debug("Expect T3166 timeout");
+ osmo_select_main(0);
+ }
+
+ printf("=== %s end ===\n", __func__);
+ cleanup_test();
+}
+
/* PCU allocates a DL TBF through PCH ImmAss for MS (when in packet-idle) */
static void test_dl_tbf_ccch_assign(void)
{
@@ -553,6 +592,7 @@
test_ul_tbf_attach();
test_ul_tbf_t3164_timeout();
+ test_ul_tbf_t3166_timeout();
test_dl_tbf_ccch_assign();
talloc_free(tall_ctx);
diff --git a/tests/rlcmac/rlcmac_prim_test.err
b/tests/rlcmac/rlcmac_prim_test.err
index 3346867..26deb79 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -27,6 +27,7 @@
DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01
c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11
e5 10 00 00
DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166
DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication
DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 1, CS=CS-2
DLGLOBAL DEBUG -- Chunk with length 3 is less than remaining space (30): add
length header to delimit LLC frame
@@ -46,6 +47,8 @@
DLGLOBAL DEBUG - got ack for BSN=0
DLGLOBAL DEBUG - got ack for BSN=1
DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=2)""(V(S)-1=1) A=Acked
N=Nacked U=Unacked X=Resend-Unacked I=Invalid
+DLGLOBAL INFO UL_TBF{FINISHED}: Received Event CONTENTION_RESOLUTION_SUCCESS
+DLGLOBAL INFO UL_TBF{FINISHED}: Contention resolution succeeded, stop T3166
DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Final ACK received.
DLGLOBAL INFO UL_TBF{FINISHED}: Received Event FINAL_ACK_RECVD
DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
@@ -127,6 +130,122 @@
DLGLOBAL NOTICE UL_TBF{FLOW}: TBF establishment failure (T3164 timeout
attempts=4)
DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
DLGLOBAL INFO UL_TBF{FLOW}: Deallocated
+DLGLOBAL INFO Rx from upper layers: GRR-UNITDATA.request
+DLGLOBAL INFO TLLI=0x00002342 not found, creating entity on the fly
+DLGLOBAL INFO UL_TBF{NEW}: Allocated
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Allocated
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START
+DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START
+DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x7a
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS
+DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase
access) ts_nr=7 usf=0
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED
+DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL
+DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80
+DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW
+DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE
+DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 0, CS=CS-2
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Dequeue next LLC (len=33)
+DLGLOBAL DEBUG -- Chunk with length 33 larger than space (30) left in block:
copy only remaining space, and we are done
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 0, CS-2): 01 c0 00
08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0
(BSN1 0 BSN2 -1)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01
c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11
e5 10 00 00
+DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166
+DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=1
+DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW
+DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x00
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START
+DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START
+DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x7c
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS
+DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase
access) ts_nr=7 usf=0
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED
+DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL
+DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80
+DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW
+DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE
+DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 0
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0
(BSN1 0 BSN2 -1)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01
c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11
e5 10 00 00
+DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166
+DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=2
+DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW
+DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x00
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START
+DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START
+DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x79
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS
+DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase
access) ts_nr=7 usf=0
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED
+DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL
+DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80
+DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW
+DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE
+DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 0
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0
(BSN1 0 BSN2 -1)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01
c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11
e5 10 00 00
+DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166
+DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=3
+DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW
+DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x00
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START
+DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START
+DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x7d
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS
+DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase
access) ts_nr=7 usf=0
+DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED
+DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL
+DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80
+DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW
+DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE
+DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 0
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0
(BSN1 0 BSN2 -1)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01
c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11
e5 10 00 00
+DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164
+DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166
+DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=4
+DLGLOBAL NOTICE UL_TBF{FLOW}: TBF establishment failure (T3166 timeout
attempts=4)
+DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
+DLGLOBAL INFO UL_TBF{FLOW}: Deallocated
DLGLOBAL INFO Rx from upper layers: GMMRR-ASSIGN.request
DLGLOBAL INFO GMMRR-ASSIGN.req: creating new entity TLLI=0x00000001
DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication
diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok
index c419cb6..9c61988 100644
--- a/tests/rlcmac/rlcmac_prim_test.ok
+++ b/tests/rlcmac/rlcmac_prim_test.ok
@@ -27,6 +27,32 @@
sys={20.000000}, mono={20.000000}: clock_override_add
sys={20.000000}, mono={20.000000}: Expect T3164 timeout
=== test_ul_tbf_t3164_timeout end ===
+=== test_ul_tbf_t3166_timeout start ===
+sys={0.000000}, mono={0.000000}: clock_override_set
+test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7a
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x80
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34
data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2
24 6c 84 44 04 11 e5 10 00 00 ]
+sys={5.000000}, mono={5.000000}: clock_override_add
+sys={5.000000}, mono={5.000000}: Expect T3166 timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x00
+test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7c
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x80
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34
data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2
24 6c 84 44 04 11 e5 10 00 00 ]
+sys={10.000000}, mono={10.000000}: clock_override_add
+sys={10.000000}, mono={10.000000}: Expect T3166 timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x00
+test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x79
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x80
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34
data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2
24 6c 84 44 04 11 e5 10 00 00 ]
+sys={15.000000}, mono={15.000000}: clock_override_add
+sys={15.000000}, mono={15.000000}: Expect T3166 timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x00
+test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7d
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0
ul_slotmask=0x80
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34
data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2
24 6c 84 44 04 11 e5 10 00 00 ]
+sys={20.000000}, mono={20.000000}: clock_override_add
+sys={20.000000}, mono={20.000000}: Expect T3166 timeout
+=== test_ul_tbf_t3166_timeout end ===
=== test_dl_tbf_ccch_assign start ===
sys={0.000000}, mono={0.000000}: clock_override_set
test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_DL_TBF.request dl_tbf_nr=0
dl_slotmask=0x80 dl_tfi=0
--
To view, visit https://gerrit.osmocom.org/c/libosmo-gprs/+/31350
To unsubscribe, or for help writing mail filters, visit
https://gerrit.osmocom.org/settings
Gerrit-Project: libosmo-gprs
Gerrit-Branch: master
Gerrit-Change-Id: I58dd757cbb5d8279fdf7fbdfb6f38ec0119c6156
Gerrit-Change-Number: 31350
Gerrit-PatchSet: 2
Gerrit-Owner: pespin <[email protected]>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: laforge <[email protected]>
Gerrit-Reviewer: pespin <[email protected]>
Gerrit-MessageType: merged
