diff --git a/include/osmocom/gprs/rlcmac/llc_queue.h b/include/osmocom/gprs/rlcmac/llc_queue.h index 80016e0..842969e 100644 --- a/include/osmocom/gprs/rlcmac/llc_queue.h +++ b/include/osmocom/gprs/rlcmac/llc_queue.h @@ -54,6 +54,8 @@ int gprs_rlcmac_llc_queue_enqueue(struct gprs_rlcmac_llc_queue *q, uint8_t *ll_p struct msgb *gprs_rlcmac_llc_queue_dequeue(struct gprs_rlcmac_llc_queue *q); uint8_t gprs_rlcmac_llc_queue_highest_radio_prio_pending(struct gprs_rlcmac_llc_queue *q); +void gprs_rlcmac_llc_queue_merge_prepend(struct gprs_rlcmac_llc_queue *q, struct gprs_rlcmac_llc_queue *old_q); + static inline size_t gprs_rlcmac_llc_queue_size(const struct gprs_rlcmac_llc_queue *q) { return q->queue_size; diff --git a/include/osmocom/gprs/rlcmac/rlcmac_enc.h b/include/osmocom/gprs/rlcmac/rlcmac_enc.h index 406109a..298d364 100644 --- a/include/osmocom/gprs/rlcmac/rlcmac_enc.h +++ b/include/osmocom/gprs/rlcmac/rlcmac_enc.h @@ -29,7 +29,7 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data( struct gprs_rlcmac_rlc_block_info *rdbi, enum gprs_rlcmac_coding_scheme cs, struct msgb *llc_msg, int *offset, int *num_chunks, - uint8_t *data_block, bool is_final, int *count_payload); + uint8_t *data_block, int *count_payload); void gprs_rlcmac_rlc_data_to_ul_append_egprs_li_padding(const struct gprs_rlcmac_rlc_block_info *rdbi, int *offset, int *num_chunks, uint8_t *data_block); diff --git a/include/osmocom/gprs/rlcmac/tbf_ul.h b/include/osmocom/gprs/rlcmac/tbf_ul.h index e5cfa91..660cf5a 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul.h @@ -40,6 +40,13 @@ struct gprs_rlcmac_ul_tbf { /* (M)CS used to transmit uplink blocks, assigned by PCU: */ enum gprs_rlcmac_coding_scheme tx_cs; + + /* Whether the UL TBF entered the countdown procedure (TS 44.060 9.3.1)*/ + struct { + bool active; + uint8_t cv; + struct gprs_rlcmac_llc_queue *llc_queue; + } countdown_proc; }; struct gprs_rlcmac_ul_tbf *gprs_rlcmac_ul_tbf_alloc(struct gprs_rlcmac_entity *gre); diff --git a/src/rlcmac/llc_queue.c b/src/rlcmac/llc_queue.c index 47cb1e9..3ff80d9 100644 --- a/src/rlcmac/llc_queue.c +++ b/src/rlcmac/llc_queue.c @@ -227,3 +227,31 @@ uint8_t gprs_rlcmac_llc_queue_highest_radio_prio_pending(struct gprs_rlcmac_llc_ OSMO_ASSERT(prioq); return prioq->radio_prio; } + +/* Merge old_q messages into q, prepending them. old_q must be freed by the caller. */ +void gprs_rlcmac_llc_queue_merge_prepend(struct gprs_rlcmac_llc_queue *q, struct gprs_rlcmac_llc_queue *old_q) +{ + unsigned int i, j; + + /* Nothing to do: */ + if (old_q->queue_size == 0) + return; + + for (i = 0; i < ARRAY_SIZE(old_q->pq); i++) { + for (j = 0; j < ARRAY_SIZE(old_q->pq[i]); j++) { + struct llist_head *old_pq = &old_q->pq[i][j].queue; + struct llist_head *pq = &q->pq[i][j].queue; + struct llist_head *it; + + /* Remove from old_pq and prepend to pq: */ + while ((it = old_pq->next) != old_pq) + llist_move(it, pq); + } + } + + q->queue_size += old_q->queue_size; + q->queue_octets += old_q->queue_octets; + + old_q->queue_size = 0; + old_q->queue_octets = 0; +} diff --git a/src/rlcmac/rlcmac_enc.c b/src/rlcmac/rlcmac_enc.c index 1c849a1..1e10d3a 100644 --- a/src/rlcmac/rlcmac_enc.c +++ b/src/rlcmac/rlcmac_enc.c @@ -67,12 +67,13 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data( struct gprs_rlcmac_rlc_block_info *rdbi, enum gprs_rlcmac_coding_scheme cs, struct msgb *llc_msg, int *offset, int *num_chunks, - uint8_t *data_block, bool is_final, int *count_payload) + uint8_t *data_block, int *count_payload) { int chunk; int space; struct gprs_rlcmac_rlc_li_field *li; uint8_t *delimiter, *data, *e_pointer; + const bool is_final = rdbi->cv == 0; data = data_block + *offset; delimiter = data_block + *num_chunks; @@ -117,7 +118,6 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data( *count_payload = space; *offset = rdbi->data_len; (*num_chunks)++; - rdbi->cv = 0; return GPRS_RLCMAC_AR_COMPLETED_BLOCK_FILLED; } /* if chunk would fit exactly in space left */ @@ -191,7 +191,6 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data( /* if we don't have more LLC frames */ if (is_final) { LOGRLCMAC(LOGL_DEBUG, "-- Final block, so we done.\n"); - rdbi->cv = 0; return GPRS_RLCMAC_AR_COMPLETED_BLOCK_FILLED; } /* we have no space left */ diff --git a/src/rlcmac/tbf_ul.c b/src/rlcmac/tbf_ul.c index b38c750..6bea79e 100644 --- a/src/rlcmac/tbf_ul.c +++ b/src/rlcmac/tbf_ul.c @@ -72,6 +72,13 @@ void gprs_rlcmac_ul_tbf_free(struct gprs_rlcmac_ul_tbf *ul_tbf) if (!ul_tbf) return; + if (ul_tbf->countdown_proc.llc_queue) { + gprs_rlcmac_llc_queue_merge_prepend(ul_tbf->tbf.gre->llc_queue, + ul_tbf->countdown_proc.llc_queue); + gprs_rlcmac_llc_queue_free(ul_tbf->countdown_proc.llc_queue); + ul_tbf->countdown_proc.llc_queue = NULL; + } + if (ul_tbf->tbf.gre->ul_tbf == ul_tbf) ul_tbf->tbf.gre->ul_tbf = NULL; @@ -146,7 +153,7 @@ bool gprs_rlcmac_ul_tbf_can_request_new_ul_tbf(const struct gprs_rlcmac_ul_tbf * return false; /* the mobile station has new data to transmit */ - if (!gprs_rlcmac_ul_tbf_have_data(ul_tbf)) + if (!gprs_rlcmac_entity_have_tx_data_queued(ul_tbf->tbf.gre)) return false; /* "the mobile station has no other ongoing downlink TBFs */ @@ -312,8 +319,12 @@ free_ret: bool gprs_rlcmac_ul_tbf_have_data(const struct gprs_rlcmac_ul_tbf *ul_tbf) { - return (ul_tbf->llc_tx_msg && msgb_length(ul_tbf->llc_tx_msg) > 0) || - gprs_rlcmac_entity_have_tx_data_queued(ul_tbf->tbf.gre); + if (ul_tbf->llc_tx_msg && msgb_length(ul_tbf->llc_tx_msg) > 0) + return true; + if (ul_tbf->countdown_proc.active) + return gprs_rlcmac_llc_queue_size(ul_tbf->countdown_proc.llc_queue) > 0; + else + return gprs_rlcmac_entity_have_tx_data_queued(ul_tbf->tbf.gre); } bool gprs_rlcmac_ul_tbf_shall_keep_open(const struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi) @@ -331,13 +342,20 @@ bool gprs_rlcmac_ul_tbf_shall_keep_open(const struct gprs_rlcmac_ul_tbf *ul_tbf, void gprs_rlcmac_ul_tbf_schedule_next_llc_frame(struct gprs_rlcmac_ul_tbf *ul_tbf) { struct osmo_gprs_rlcmac_prim *rlcmac_prim_tx; + struct gprs_rlcmac_llc_queue *llc_queue; if (ul_tbf->llc_tx_msg && msgb_length(ul_tbf->llc_tx_msg)) return; msgb_free(ul_tbf->llc_tx_msg); + + if (ul_tbf->countdown_proc.active) + llc_queue = ul_tbf->countdown_proc.llc_queue; + else + llc_queue = ul_tbf->tbf.gre->llc_queue; + /* dequeue next LLC frame, if any */ - ul_tbf->llc_tx_msg = gprs_rlcmac_llc_queue_dequeue(ul_tbf->tbf.gre->llc_queue); + ul_tbf->llc_tx_msg = gprs_rlcmac_llc_queue_dequeue(llc_queue); if (!ul_tbf->llc_tx_msg) return; @@ -354,9 +372,188 @@ void gprs_rlcmac_ul_tbf_schedule_next_llc_frame(struct gprs_rlcmac_ul_tbf *ul_tb gprs_rlcmac_prim_call_up_cb(rlcmac_prim_tx); } +/* TS 44.060 9.3.1.1 Countdown procedure */ +struct blk_count_state { + const struct gprs_rlcmac_ul_tbf *ul_tbf; + uint8_t blk_data_len; /* length of usable data block (single data unit w/o header) */ + uint8_t bs_cv_max; + uint8_t nts; + uint8_t k; + uint8_t nts_x_k; + unsigned blk_count; + uint8_t offset; /* offset in bytes in the current blk */ + bool extra_li0; /* if last appended chunk is an LI=0 case */ +}; +static void blk_count_state_init(struct blk_count_state *st, const struct gprs_rlcmac_ul_tbf *ul_tbf) +{ + OSMO_ASSERT(ul_tbf->cur_alloc.num_ts > 0); + memset(st, 0, sizeof(*st)); + st->ul_tbf = ul_tbf; + st->blk_data_len = gprs_rlcmac_mcs_max_data_block_bytes(ul_tbf->tx_cs); + st->bs_cv_max = g_rlcmac_ctx->si13ro.u.PBCCH_Not_present.GPRS_Cell_Options.BS_CV_MAX; + st->nts = ul_tbf->cur_alloc.num_ts; + st->blk_count = 0; + st->offset = 0; + + if (gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf)) + st->blk_data_len -= 4; + + switch (ul_tbf->tx_cs) { + case GPRS_RLCMAC_MCS_7: + case GPRS_RLCMAC_MCS_8: + case GPRS_RLCMAC_MCS_9: + st->k = 2; + break; + default: + st->k = 1; + } + st->nts_x_k = st->nts * st->k; +} + +static inline unsigned blk_count_to_x(const struct blk_count_state *st) +{ + if (st->blk_count == 0) + return 0; + return (st->blk_count + (st->nts_x_k - 1) - 1) / st->nts_x_k; +} + +static void blk_count_append_llc(struct blk_count_state *st, unsigned int llc_payload_len) +{ + int chunk = llc_payload_len; + int space = st->blk_data_len - st->offset; + OSMO_ASSERT(st->offset < st->blk_data_len); + + if (chunk == 0) + return; /* Should not happen in here? */ + + /* reset flag: */ + st->extra_li0 = false; + + /* if chunk will exceed block limit */ + if (chunk > space) { + st->blk_count++; + st->offset = 0; + chunk -= space; + blk_count_append_llc(st, chunk); + return; + } + if (chunk == space) { + st->blk_count++; + st->offset = 0; + chunk -= space - 1; /* Extra LI=0 */ + blk_count_append_llc(st, chunk); + /* case is_final==true (CV==0) has no extra LI=0. Store the + * context to subtract if this was the last step. */ + st->extra_li0 = true; + return; + } + /* chunk < space */ + /* Append a new LI byte */ + st->offset++; + st->offset += chunk; + if (st->blk_data_len - st->offset == 0) { + st->blk_count++; + st->offset = 0; + } +} + +/* Returned as early return from function when amount of RLC blocks goes clearly over BS_CV_MAX */ +#define BLK_COUNT_TOOMANY 0xff +/* We cannot early-check if extra_li0=true, since there may temporarily have too many rlc blocks: */ +#define BLK_COUNT_EARLY_CHECK_TOOMANY(st) (!(st)->extra_li0) && blk_count_to_x(st) > (st)->bs_cv_max) +static uint8_t blk_count_append_llc_prio_queue(struct blk_count_state *st, const struct gprs_llc_prio_queue *pq) +{ + struct msgb *msg; + + llist_for_each_entry(msg, &pq->queue, list) { + blk_count_append_llc(st, msgb_l2len(msg)); + /* We cannot early-check if extra_li0=true, since there may temporarily have too many rlc blocks. */ + if (BLK_COUNT_EARLY_CHECK_TOOMANY(st) + return BLK_COUNT_TOOMANY; /* early return, not entering countdown procedure */ + } + return 0; +} + +/* return BLK_COUNT_TOOMANY: not entering countdown procedure, X > BS_CV_MAX. +_* return 0: check blk_count_to_x(st) */ +static uint8_t gprs_rlcmac_ul_tbf_calculate_cv(const struct gprs_rlcmac_ul_tbf *ul_tbf) +{ + struct blk_count_state st; + const struct gprs_rlcmac_llc_queue *q = ul_tbf->tbf.gre->llc_queue; + unsigned int i, j; + unsigned x; + + blk_count_state_init(&st, ul_tbf); + + /* TODO: Here we could do an heuristic optimization by doing a rough calculation + * using gprs_rlcmac_llc_queue_size() and gprs_rlcmac_llc_queue_octets() + * for cases were we are clearly above BS_CV_MAX. This is specially useful + * when the LLC queue is long since we skip iterating counting lots of + * data. + * if (blk_count_herustic_toomany(&st)) + * return 15; + */ + + /* First of all, the current LLC frame in progress: */ + if (ul_tbf->llc_tx_msg) { + blk_count_append_llc(&st, msgb_length(ul_tbf->llc_tx_msg)); + if (BLK_COUNT_EARLY_CHECK_TOOMANY(&st) + goto done; /* early return, not entering countdown procedure */ + } + + for (i = 0; i < ARRAY_SIZE(q->pq); i++) { + for (j = 0; j < ARRAY_SIZE(q->pq[i]); j++) { + int rc; + if (llist_empty(&q->pq[i][j].queue)) + continue; + rc = blk_count_append_llc_prio_queue(&st, &q->pq[i][j]); + if (rc == BLK_COUNT_TOOMANY) + goto done; /* early return, not entering countdown procedure */ + } + } + +done: + /* In final block (CV==0), a chunk filling exactly an RLC block doesn't + * have the LI=0 and 2 bytes (1 LI + 1 data) spanning next block. Fix calculation: */ + if (st.extra_li0) { + OSMO_ASSERT(st.offset == 2); + st.offset -= 2; + } + /* Remaining one would already be a block. Include it before calculating "X": */ + if (st.offset > 0) { + st.blk_count++; + st.offset = 0; + } + x = blk_count_to_x(&st); + return x <= st.bs_cv_max ? (uint8_t)x : 15; +} + +static void gprs_rlcmac_ul_tbf_steal_llc_queue_from_gre(struct gprs_rlcmac_ul_tbf *ul_tbf) +{ + ul_tbf->countdown_proc.llc_queue = ul_tbf->tbf.gre->llc_queue; + ul_tbf->tbf.gre->llc_queue = gprs_rlcmac_llc_queue_alloc(ul_tbf->tbf.gre); +} + +static void gprs_rlcmac_ul_tbf_check_countdown_proc(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi) +{ + + if (ul_tbf->countdown_proc.active) + return; + ul_tbf->countdown_proc.cv = gprs_rlcmac_ul_tbf_calculate_cv(ul_tbf); + if (ul_tbf->countdown_proc.cv < 15) { + if (gprs_rlcmac_ul_tbf_shall_keep_open(ul_tbf, bi)) { + LOGPTBFUL(ul_tbf, LOGL_INFO, "Delaying start Countdown procedure CV=%u\n", ul_tbf->countdown_proc.cv); + ul_tbf->countdown_proc.cv = 15; + return; + } + LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Entering Countdown procedure CV=%u\n", ul_tbf->countdown_proc.cv); + ul_tbf->countdown_proc.active = true; + gprs_rlcmac_ul_tbf_steal_llc_queue_from_gre(ul_tbf); + } +} + static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi, enum gprs_rlcmac_coding_scheme cs) { - struct gprs_rlcmac_llc_queue *llc_queue = ul_tbf->tbf.gre->llc_queue; const uint16_t bsn = gprs_rlcmac_rlc_ul_window_v_s(ul_tbf->ulw); struct gprs_rlcmac_rlc_block *blk; struct gprs_rlcmac_rlc_block_info *rdbi; @@ -365,6 +562,8 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r int write_offset = 0; enum gpr_rlcmac_append_result ar; + gprs_rlcmac_ul_tbf_check_countdown_proc(ul_tbf, bi); + if (!ul_tbf->llc_tx_msg || msgb_length(ul_tbf->llc_tx_msg) == 0) gprs_rlcmac_ul_tbf_schedule_next_llc_frame(ul_tbf); OSMO_ASSERT(ul_tbf->llc_tx_msg); @@ -391,7 +590,7 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r rdbi->data_len = block_data_len; rdbi->ti = gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf); - rdbi->cv = 15; /* Final Block Indicator, set late, if true */ + rdbi->cv = ul_tbf->countdown_proc.cv--; rdbi->bsn = bsn; /* Block Sequence Number */ rdbi->e = 1; /* Extension bit, maybe set later (1: no extension) */ @@ -407,7 +606,6 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r } do { - bool is_final; int payload_written = 0; if (msgb_length(ul_tbf->llc_tx_msg) == 0) { @@ -424,14 +622,6 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r "LLC queue completely drained and there's " "still %d free bytes in rlcmac data block\n", space); - /* We may need to update fbi in header here - * since ul_tbf->last_ul_drained_fn was updated above - * Specially important when X2031 is 0. */ - is_final = gprs_rlcmac_llc_queue_size(llc_queue) == 0 && - !gprs_rlcmac_ul_tbf_shall_keep_open(ul_tbf, bi); - if (is_final) - rdbi->cv = 0; - if (gprs_rlcmac_mcs_is_edge(cs)) { /* in EGPRS there's no M bit, so we need * to flag padding with LI=127 */ @@ -442,12 +632,8 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r } } - is_final = gprs_rlcmac_llc_queue_size(llc_queue) == 0 && - !gprs_rlcmac_ul_tbf_shall_keep_open(ul_tbf, bi); - - ar = gprs_rlcmac_enc_append_ul_data(rdbi, cs, ul_tbf->llc_tx_msg, - &write_offset, &num_chunks, data, - is_final, &payload_written); + ar = gprs_rlcmac_enc_append_ul_data(rdbi, cs, ul_tbf->llc_tx_msg, &write_offset, + &num_chunks, data, &payload_written); if (ar == GPRS_RLCMAC_AR_NEED_MORE_BLOCKS) break; @@ -460,8 +646,8 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r gprs_rlcmac_ul_tbf_schedule_next_llc_frame(ul_tbf); } while (ar == GPRS_RLCMAC_AR_COMPLETED_SPACE_LEFT); - LOGPTBFUL(ul_tbf, LOGL_DEBUG, "data block (BSN %d, %s): %s\n", - bsn, gprs_rlcmac_mcs_name(blk->cs_last), + LOGPTBFUL(ul_tbf, LOGL_DEBUG, "data block (BSN=%d, %s, CV=%u): %s\n", + bsn, gprs_rlcmac_mcs_name(blk->cs_last), rdbi->cv, osmo_hexdump(blk->buf, block_data_len)); /* raise send state and set ack state array */ gprs_rlcmac_rlc_v_b_mark_unacked(&ul_tbf->ulw->v_b, bsn); @@ -850,8 +1036,8 @@ static struct msgb *create_ul_acked_block(struct gprs_rlcmac_ul_tbf *ul_tbf, rdbi->bsn = bsn; is_final = is_final || rdbi->cv == 0; - LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Copying data unit %d (BSN %d)\n", - data_block_idx, bsn); + LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Copying data unit %d (BSN=%d CV=%d)\n", + data_block_idx, bsn, rdbi->cv); gprs_rlcmac_rlc_copy_from_aligned_buffer(&rlc, data_block_idx, msg_data, block_data); } diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c index c8d1616..ba06fab 100644 --- a/tests/rlcmac/rlcmac_prim_test.c +++ b/tests/rlcmac/rlcmac_prim_test.c @@ -934,6 +934,71 @@ static void test_ul_tbf_last_data_cv0_retrans_max(void) cleanup_test(); } +/* 9.3.1 Countdown procedure */ +static void test_ul_tbf_countdown_procedure(void) +{ + struct osmo_gprs_rlcmac_prim *rlcmac_prim; + int rc; + + printf("=== %s start ===\n", __func__); + prepare_test(); + uint32_t tlli = 0x2342; + uint8_t ul_tfi = 0; + uint8_t ts_nr = 7; + uint8_t usf = 0; + uint32_t rts_fn = 4; + uint8_t bs_cv_max = 4; + unsigned int i; + RlcMacDownlink_t dl_block; + struct msgb *llc_msg = msgb_alloc(200, "llc_msg"); + Ack_Nack_Description_t *ack_desc = &dl_block.u.Packet_Uplink_Ack_Nack.u.PU_AckNack_GPRS_Struct.Ack_Nack_Description; + + /* Submit an SI13 with bs_cv_max: */ + rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_l1ctl_ccch_data_ind(0, create_si13(bs_cv_max)); + rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim); + OSMO_ASSERT(rc == 0); + + + /* Submit LLC bytes */ + msgb_put(llc_msg, msgb_tailroom(llc_msg)); + memset(msgb_data(llc_msg), 0xab, msgb_length(llc_msg)); + rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_grr_unitdata_req(tlli, msgb_data(llc_msg), msgb_length(llc_msg)); + rlcmac_prim->grr.unitdata_req.sapi = OSMO_GPRS_RLCMAC_LLC_SAPI_SNDCP3; + rc = osmo_gprs_rlcmac_prim_upper_down(rlcmac_prim); + + 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); + + /* Trigger transmission of LLC data (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); + + /* PCU acks it: */ + ul_ack_nack_init(&dl_block, ul_tfi, GPRS_RLCMAC_CS_2); + ack_desc->STARTING_SEQUENCE_NUMBER = 1; + ack_desc->FINAL_ACK_INDICATION = 0; + ul_ack_nack_mark(ack_desc, 0, true); + rlcmac_prim = create_dl_ctrl_block(&dl_block, ts_nr, rts_fn); + rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim); + OSMO_ASSERT(rc == 0); + + for (i = 0; i < 6; i++) { + rts_fn = fn_next_block(rts_fn); + printf("RTS %u: FN=%u\n", i, rts_fn); + /* Trigger transmission of LLC data (GMM Attach) (second 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); + } + + printf("=== %s end ===\n", __func__); + msgb_free(llc_msg); + cleanup_test(); +} + /* PCU allocates a DL TBF through PCH ImmAss for MS (when in packet-idle) */ static void test_dl_tbf_ccch_assign(void) { @@ -1128,6 +1193,7 @@ int main(int argc, char *argv[]) test_ul_tbf_n3104_timeout(); test_ul_tbf_t3182_timeout(); test_ul_tbf_last_data_cv0_retrans_max(); + test_ul_tbf_countdown_procedure(); test_ul_tbf_request_another_ul_tbf(); test_dl_tbf_ccch_assign(); test_dl_tbf_ccch_assign_requests_ul_tbf_pacch(); diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err index a02739a..120458a 100644 --- a/tests/rlcmac/rlcmac_prim_test.err +++ b/tests/rlcmac/rlcmac_prim_test.err @@ -23,10 +23,10 @@ DLGLOBAL DEBUG 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 (26) 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): 00 00 23 42 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=15): 00 00 23 42 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 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -35,13 +35,14 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request DLGLOBAL DEBUG 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 TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=0 DLGLOBAL DEBUG -- Chunk with length 7 is less than remaining space (26): add length header to delimit LLC frame DLGLOBAL DEBUG -- Final block, so we done. DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 1, CS-2): 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=1, CS-2, CV=0): 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 01 02 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED @@ -185,10 +186,10 @@ DLGLOBAL DEBUG 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 (26) 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): 00 00 23 42 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=15): 00 00 23 42 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 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -220,7 +221,7 @@ DLGLOBAL DEBUG 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -252,7 +253,7 @@ DLGLOBAL DEBUG 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -284,7 +285,7 @@ DLGLOBAL DEBUG 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -326,10 +327,10 @@ DLGLOBAL DEBUG 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 (26) 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): 00 00 23 42 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=15): 00 00 23 42 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 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -338,13 +339,14 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request DLGLOBAL DEBUG 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 TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=0 DLGLOBAL DEBUG -- Chunk with length 7 is less than remaining space (26): add length header to delimit LLC frame DLGLOBAL DEBUG -- Final block, so we done. DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 1, CS-2): 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=1, CS-2, CV=0): 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 01 02 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED @@ -355,7 +357,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (3) DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request @@ -363,7 +365,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 01 02 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=1 @@ -374,7 +376,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (5) DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request @@ -382,7 +384,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 01 02 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=2 @@ -393,7 +395,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (7) DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request @@ -401,7 +403,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 01 02 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=3 @@ -412,7 +414,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL NOTICE TBF(UL:NR-0:TLLI-00002342) N3104_MAX (9) reached DLGLOBAL INFO UL_TBF{FINISHED}: Received Event N3104_MAX @@ -466,10 +468,10 @@ DLGLOBAL DEBUG 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 (26) 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): 00 00 23 42 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=15): 00 00 23 42 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 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -486,13 +488,14 @@ DLGLOBAL INFO UL_TBF{FLOW}: Received Event RX_UL_ACK_NACK DLGLOBAL INFO UL_TBF{FLOW}: Contention resolution succeeded, stop T3166 DLGLOBAL DEBUG 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 TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=0 DLGLOBAL DEBUG -- Chunk with length 7 is less than remaining space (30): add length header to delimit LLC frame DLGLOBAL DEBUG -- Final block, so we done. DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 1, CS-2): 1d 11 e5 10 00 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=1, CS-2, CV=0): 1d 11 e5 10 00 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 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: Last UL block sent (CV=0), start T3182 @@ -529,10 +532,10 @@ DLGLOBAL DEBUG 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 (26) 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): 00 00 23 42 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=15): 00 00 23 42 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 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) Copying data unit 0 (BSN=0 CV=15) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -549,13 +552,14 @@ DLGLOBAL INFO UL_TBF{FLOW}: Received Event RX_UL_ACK_NACK DLGLOBAL INFO UL_TBF{FLOW}: Contention resolution succeeded, stop T3166 DLGLOBAL DEBUG 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 TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=0 DLGLOBAL DEBUG -- Chunk with length 7 is less than remaining space (30): add length header to delimit LLC frame DLGLOBAL DEBUG -- Final block, so we done. DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 1, CS-2): 1d 11 e5 10 00 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 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=1, CS-2, CV=0): 1d 11 e5 10 00 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 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: Last UL block sent (CV=0), start T3182 @@ -566,7 +570,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=1 @@ -577,7 +581,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=2 @@ -588,7 +592,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=3 @@ -599,7 +603,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=4 @@ -611,6 +615,8 @@ DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request DLGLOBAL INFO UL_TBF{FINISHED}: Deallocated DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request DLGLOBAL INFO DL_TBF_ASS{IDLE}: Deallocated +DLGLOBAL DEBUG Rx from lower layers: L1CTL-CCCH_DATA.indication +DLGLOBAL DEBUG Rx SI13 from lower layers DLGLOBAL INFO Rx from upper layers: GRR-UNITDATA.request DLGLOBAL INFO TLLI=0x00002342 not found, creating entity on the fly DLGLOBAL INFO DL_TBF_ASS{IDLE}: Allocated @@ -634,14 +640,123 @@ DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE DLGLOBAL DEBUG 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=200) +DLGLOBAL DEBUG -- Chunk with length 200 larger than space (26) 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, CV=15): 00 00 23 42 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +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 CV=15) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_DATA.indication +DLGLOBAL INFO TS=7 FN=4 Rx Pkt UL ACK/NACK +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Got GPRS UL ACK bitmap: SSN: 1, BSN 0 to 1 - 1 (1 blocks), "R" +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) ack: (BSN=0)"R"(BSN=0) R=ACK I=NACK +DLGLOBAL DEBUG - got ack for BSN=0 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=1)""(V(S)-1=0) A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid +DLGLOBAL INFO UL_TBF{FLOW}: Received Event RX_UL_ACK_NACK +DLGLOBAL INFO UL_TBF{FLOW}: Contention resolution succeeded, stop T3166 +DLGLOBAL DEBUG 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 174 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=1, CS-2, CV=15): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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=1 CV=15) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 3c 00 03 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 2, CS=CS-2 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=4 +DLGLOBAL DEBUG -- Chunk with length 144 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=2, CS-2, CV=4): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 2 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=2 CV=4) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 2, CS-2): 10 00 05 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 3, CS=CS-2 +DLGLOBAL DEBUG -- Chunk with length 114 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=3, CS-2, CV=3): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 3 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=3 CV=3) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 3, CS-2): 0c 00 07 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 4, CS=CS-2 +DLGLOBAL DEBUG -- Chunk with length 84 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=4, CS-2, CV=2): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 4 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=4 CV=2) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 4, CS-2): 08 00 09 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 5, CS=CS-2 +DLGLOBAL DEBUG -- Chunk with length 54 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=5, CS-2, CV=1): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 5 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=5 CV=1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 5, CS-2): 04 00 0b ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 6, CS=CS-2 +DLGLOBAL DEBUG -- Chunk with length 24 is less than remaining space (30): add length header to delimit LLC frame +DLGLOBAL DEBUG -- Final block, so we done. +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=6, CS-2, CV=0): 61 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 2b 2b 2b 2b 2b +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 6 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=6 CV=0) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 6, CS-2): 00 00 0c 61 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 2b 2b 2b 2b 2b 00 +DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT +DLGLOBAL INFO UL_TBF{FLOW}: Last UL block sent (CV=0), start T3182 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED +DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request +DLGLOBAL INFO DL_TBF_ASS{IDLE}: Deallocated +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated +DLGLOBAL INFO UL_TBF{FINISHED}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release) +DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request +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 DL_TBF_ASS{IDLE}: Allocated +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=0x7e +DLGLOBAL DEBUG Tx to lower layers: L1CTL-RACH.request +DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS +DLGLOBAL DEBUG 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 TFI=0 initCS=CS-2 startTimeFN=0 +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-CFG_UL_TBF.req ul_tbf_nr=0 ul_slotmask=0x80 +DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request +DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW +DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE +DLGLOBAL DEBUG 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) Entering Countdown procedure CV=0 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Dequeue next LLC (len=14) DLGLOBAL DEBUG -- Chunk with length 14 is less than remaining space (26): add length header to delimit LLC frame DLGLOBAL DEBUG -- Final block, so we done. DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 0, CS-2): 39 00 00 23 42 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=0): 39 00 00 23 42 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 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) Copying data unit 0 (BSN=0 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 00 01 00 39 00 00 23 42 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 @@ -775,14 +890,15 @@ DLGLOBAL DEBUG GRE(00000001) Tx Packet Control Ack DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Sending new block at BSN 0, CS=CS-2 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Entering Countdown procedure CV=0 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Dequeue next LLC (len=14) DLGLOBAL DEBUG -- Chunk with length 14 is less than remaining space (30): add length header to delimit LLC frame DLGLOBAL DEBUG -- Final block, so we done. DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Complete UL frame, len=0 -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) data block (BSN 0, CS-2): 39 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) data block (BSN=0, CS-2, CV=0): 39 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) need_padding 0 spb_status 0 spb 0 (BSN1 0 BSN2 -1) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Copying 1 RLC blocks, 1 BSNs -DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Copying data unit 0 (BSN 0) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Copying data unit 0 (BSN=0 CV=0) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) msg block (BSN 0, CS-2): 00 06 00 39 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok index 100749a..b555cbe 100644 --- a/tests/rlcmac/rlcmac_prim_test.ok +++ b/tests/rlcmac/rlcmac_prim_test.ok @@ -115,11 +115,31 @@ RTS 3: FN=26 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-PDCH_DATA.request fn=26 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ] === test_ul_tbf_last_data_cv0_retrans_max end === -=== test_ul_tbf_request_another_ul_tbf start === +=== test_ul_tbf_countdown_procedure start === sys={0.000000}, mono={0.000000}: clock_override_set 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 test_rlcmac_prim_up_cb(): Rx GMMRR-LLC_TRANSMITTED.indication TLLI=0x00002342 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 01 01 00 00 23 42 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 ] +RTS 0: FN=8 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 data=[3c 00 03 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 ] +RTS 1: FN=13 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=13 ts=7 data_len=34 data=[10 00 05 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 ] +RTS 2: FN=17 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=17 ts=7 data_len=34 data=[0c 00 07 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 ] +RTS 3: FN=21 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=34 data=[08 00 09 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 ] +RTS 4: FN=26 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=26 ts=7 data_len=34 data=[04 00 0b ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 ] +RTS 5: FN=30 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=30 ts=7 data_len=34 data=[00 00 0c 61 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 2b 2b 2b 2b 2b 00 ] +=== test_ul_tbf_countdown_procedure end === +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00 +=== test_ul_tbf_request_another_ul_tbf 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_up_cb(): Rx GMMRR-LLC_TRANSMITTED.indication TLLI=0x00002342 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[00 01 00 39 00 00 23 42 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ] 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-PDCH_DATA.request fn=17 ts=7 data_len=23 data=[40 16 40 00 08 d0 a0 bc 00 00 00 00 00 00 70 00 38 00 00 2b 2b 2b 2b ]