pespin has submitted this change. ( 
https://gerrit.osmocom.org/c/libosmo-gprs/+/31347 )

Change subject: rlcmac: Implement T3164
......................................................................

rlcmac: Implement T3164

Change-Id: I1a3d7b552b36b84d84ca27572ce313265810fd3d
---
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, 246 insertions(+), 9 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 f9c5a7f..08075be 100644
--- a/include/osmocom/gprs/rlcmac/tbf_ul.h
+++ b/include/osmocom/gprs/rlcmac/tbf_ul.h
@@ -26,6 +26,8 @@
        /* Currently selected LLC frame to be scheduled/transmitted */
        struct msgb *llc_tx_msg;
        int32_t last_ul_drained_fn;
+       /* count all transmitted data blocks */
+       unsigned int n3104;

        /* Holds state of all generated in-transit RLC blocks */
        struct gprs_rlcmac_rlc_block_store *blkst;
diff --git a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h 
b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
index 1d7ff88..327acd7 100644
--- a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
+++ b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h
@@ -20,11 +20,14 @@
                struct gprs_rlcmac_tbf *tbf;
                struct gprs_rlcmac_ul_tbf *ul_tbf;
        };
+       /* Number of packet access procedure timeouts (T3164, T3166) */
+       unsigned int pkt_acc_proc_attempts;
 };

 enum tbf_ul_fsm_event {
        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_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 c6c23e6..ac489d5 100644
--- a/src/rlcmac/rlcmac.c
+++ b/src/rlcmac/rlcmac.c
@@ -42,7 +42,9 @@

 struct gprs_rlcmac_ctx *g_ctx;

+/* 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)" },
        { 0 } /* empty item at the end */
 };

diff --git a/src/rlcmac/tbf_ul.c b/src/rlcmac/tbf_ul.c
index 4a6f9ce..a47a2b3 100644
--- a/src/rlcmac/tbf_ul.c
+++ b/src/rlcmac/tbf_ul.c
@@ -761,6 +761,9 @@
                  need_padding ? ", padded" : "",
                  msgb_hexdump(msg));

+       if (ul_tbf->n3104 == 0)
+               osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, 
GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT, NULL);
+       ul_tbf->n3104++;
        return msg;
 }

diff --git a/src/rlcmac/tbf_ul_fsm.c b/src/rlcmac/tbf_ul_fsm.c
index 3cff899..72f2994 100644
--- a/src/rlcmac/tbf_ul_fsm.c
+++ b/src/rlcmac/tbf_ul_fsm.c
@@ -30,8 +30,9 @@
 #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_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" },
        { 0, NULL }
@@ -40,7 +41,7 @@
 static const struct osmo_tdef_state_timeout tbf_ul_fsm_timeouts[32] = {
        [GPRS_RLCMAC_TBF_UL_ST_NEW] = { },
        [GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN] = { },
-       [GPRS_RLCMAC_TBF_UL_ST_FLOW] = { },
+       [GPRS_RLCMAC_TBF_UL_ST_FLOW] = { .T = 3164 },
        [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { },
 };

@@ -76,6 +77,18 @@
        return gprs_rlcmac_prim_call_down_cb(rlcmac_prim);
 }

+/* 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;
+
+       /* Make sure the lower layers realize this tbf_nr has no longer any 
assigned resource: */
+       configure_ul_tbf(ctx);
+}
+
 static void st_new(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;
@@ -104,8 +117,13 @@

 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;
+       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_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);
+               break;
        case GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT:
                tbf_ul_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ST_FINISHED);
                break;
@@ -133,6 +151,7 @@
                        X(GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN) |
                        X(GPRS_RLCMAC_TBF_UL_ST_FLOW),
                .name = "NEW",
+               .onenter = st_new_on_enter,
                .action = st_new,
        },
        [GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN] = {
@@ -145,8 +164,10 @@
        },
        [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_LAST_UL_DATA_SENT),
                .out_state_mask =
+                       X(GPRS_RLCMAC_TBF_UL_ST_NEW) |
                        X(GPRS_RLCMAC_TBF_UL_ST_FINISHED),
                .name = "FLOW",
                .action = st_flow,
@@ -164,13 +185,28 @@
 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 -2001:
-               LOGPTBFUL(ctx->ul_tbf, LOGL_NOTICE, "releasing due to PACCH 
assignment timeout.\n");
-               /* fall-through */
-       case 3169:
-       case 3195:
-               gprs_rlcmac_ul_tbf_free(ctx->ul_tbf);
+       case 3164:
+               ctx->pkt_acc_proc_attempts++;
+               LOGPFSML(ctx->fi, LOGL_INFO, "T3164 timeout attempts=%u\n", 
ctx->pkt_acc_proc_attempts);
+               OSMO_ASSERT(fi->state == GPRS_RLCMAC_TBF_UL_ST_FLOW);
+               if (ctx->pkt_acc_proc_attempts == 4) {
+                       /* TS 44.060 7.1.4 "... the packet access procedure has 
already been attempted four time ..."
+                        * mobile station shall notify higher layers (TBF 
establishment failure) */
+                       /* TODO: find out how to notify higher layers */
+                       LOGPFSML(ctx->fi, LOGL_NOTICE, "TBF establishment 
failure (T3164 timeout attempts=%u)\n", ctx->pkt_acc_proc_attempts);
+                       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)
+                       gprs_rlcmac_ul_tbf_free(ctx->ul_tbf);
                break;
        default:
                OSMO_ASSERT(0);
diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c
index 658ddb3..75c18f8 100644
--- a/tests/rlcmac/rlcmac_prim_test.c
+++ b/tests/rlcmac/rlcmac_prim_test.c
@@ -21,6 +21,9 @@
 #include <osmocom/core/utils.h>
 #include <osmocom/core/msgb.h>
 #include <osmocom/core/fsm.h>
+#include <osmocom/core/timer.h>
+#include <osmocom/core/timer_compat.h>
+#include <osmocom/core/select.h>

 #include <osmocom/gprs/rlcmac/rlcmac.h>
 #include <osmocom/gprs/rlcmac/csn1_defs.h>
@@ -181,6 +184,44 @@
        0x2b, 0x2b, 0x2b, 0x2b
 };

+#define clock_debug(fmt, args...) \
+       do { \
+               struct timespec ts; \
+               struct timeval tv; \
+               osmo_clock_gettime(CLOCK_MONOTONIC, &ts); \
+               osmo_gettimeofday(&tv, NULL); \
+               fprintf(stdout, "sys={%lu.%06lu}, mono={%lu.%06lu}: " fmt "\n", 
\
+                       tv.tv_sec, tv.tv_usec, ts.tv_sec, ts.tv_nsec/1000, 
##args); \
+       } while (0)
+
+static void clock_override_enable(bool enable)
+{
+       osmo_gettimeofday_override = enable;
+       osmo_clock_override_enable(CLOCK_MONOTONIC, enable);
+}
+
+static void clock_override_set(long sec, long usec)
+{
+       struct timespec *mono;
+       osmo_gettimeofday_override_time.tv_sec = sec;
+       osmo_gettimeofday_override_time.tv_usec = usec;
+       mono = osmo_clock_override_gettimespec(CLOCK_MONOTONIC);
+       mono->tv_sec = sec;
+       mono->tv_nsec = usec*1000;
+
+       clock_debug("clock_override_set");
+}
+
+static void clock_override_add_debug(long sec, long usec, bool dbg)
+{
+       osmo_gettimeofday_override_add(sec, usec);
+       osmo_clock_override_add(CLOCK_MONOTONIC, sec, usec*1000);
+       if (dbg)
+               clock_debug("clock_override_add");
+}
+#define clock_override_add(sec, usec) clock_override_add_debug(sec, usec, true)
+
+
 static inline unsigned fn2bn(unsigned fn)
 {
        return (fn % 52) / 4;
@@ -346,6 +387,8 @@
 void prepare_test(void)
 {
        int rc;
+       clock_override_set(0, 0);
+
        rc = osmo_gprs_rlcmac_init(OSMO_GPRS_RLCMAC_LOCATION_MS);
        OSMO_ASSERT(rc == 0);

@@ -409,6 +452,39 @@
        cleanup_test();
 }

+static void test_ul_tbf_t3164_timeout(void)
+{
+       struct osmo_gprs_rlcmac_prim *rlcmac_prim;
+       int rc;
+       unsigned int i;
+
+       printf("=== %s start ===\n", __func__);
+       prepare_test();
+       uint32_t tlli = 0x2342;
+
+       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);
+
+       OSMO_ASSERT(sizeof(ccch_imm_ass_pkt_ul_tbf_normal) == GSM_MACBLOCK_LEN);
+
+       for (i = 0; i < 4; i++) {
+               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);
+               OSMO_ASSERT(rc == 0);
+
+               /* increase time 5 seconds, timeout should trigger */
+               clock_override_add(5, 0);
+               clock_debug("Expect T3164 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)
 {
@@ -473,7 +549,10 @@
        log_set_print_level(osmo_stderr_target, 1);
        log_set_use_color(osmo_stderr_target, 0);

+       clock_override_enable(true);
+
        test_ul_tbf_attach();
+       test_ul_tbf_t3164_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 8f7283d..3346867 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -25,6 +25,8 @@
 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 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
@@ -48,6 +50,83 @@
 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event FINAL_ACK_RECVD
 DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
 DLGLOBAL INFO UL_TBF{FINISHED}: 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=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 UL_TBF{FLOW}: Timeout of T3164
+DLGLOBAL INFO UL_TBF{FLOW}: T3164 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=0x7b
+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 UL_TBF{FLOW}: Timeout of T3164
+DLGLOBAL INFO UL_TBF{FLOW}: T3164 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 UL_TBF{FLOW}: Timeout of T3164
+DLGLOBAL INFO UL_TBF{FLOW}: T3164 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=0x78
+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 UL_TBF{FLOW}: Timeout of T3164
+DLGLOBAL INFO UL_TBF{FLOW}: T3164 timeout attempts=4
+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: 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 7792932..c419cb6 100644
--- a/tests/rlcmac/rlcmac_prim_test.ok
+++ b/tests/rlcmac/rlcmac_prim_test.ok
@@ -1,10 +1,34 @@
 === test_ul_tbf_attach start ===
+sys={0.000000}, mono={0.000000}: clock_override_set
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7e
 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 ]
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 
data=[00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ]
 === test_ul_tbf_attach end ===
+=== test_ul_tbf_t3164_timeout start ===
+sys={0.000000}, mono={0.000000}: clock_override_set
+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
+sys={5.000000}, mono={5.000000}: clock_override_add
+sys={5.000000}, mono={5.000000}: Expect T3164 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=0x7b
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 
ul_slotmask=0x80
+sys={10.000000}, mono={10.000000}: clock_override_add
+sys={10.000000}, mono={10.000000}: Expect T3164 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
+sys={15.000000}, mono={15.000000}: clock_override_add
+sys={15.000000}, mono={15.000000}: Expect T3164 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=0x78
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 
ul_slotmask=0x80
+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_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
 test_rlcmac_prim_up_cb(): Rx GRR-UNITDATA.indication TLLI=0x00000001 ll=[43 c0 
01 2b 2b 2b ]
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=23 
data=[40 14 00 00 00 00 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b ]

--
To view, visit https://gerrit.osmocom.org/c/libosmo-gprs/+/31347
To unsubscribe, or for help writing mail filters, visit 
https://gerrit.osmocom.org/settings

Gerrit-Project: libosmo-gprs
Gerrit-Branch: master
Gerrit-Change-Id: I1a3d7b552b36b84d84ca27572ce313265810fd3d
Gerrit-Change-Number: 31347
Gerrit-PatchSet: 4
Gerrit-Owner: pespin <[email protected]>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: laforge <[email protected]>
Gerrit-Reviewer: pespin <[email protected]>
Gerrit-MessageType: merged

Reply via email to