Restructured debugging levels to get better overview of TBFs/processes
Only when using LOGL_DEBUG, every detailled information is displayed.
When using LOGL_INFO, a summary of the process is displayed.
When using LOGL_NOTICE, only errors and warnings like timeouts
or invalid received informations are displayed.
When using LOGL_ERROR, only local error like software errorss are
displayed.
diff --git a/src/gprs_rlcmac_data.cpp b/src/gprs_rlcmac_data.cpp
index 71bad5c..ea813c6 100644
--- a/src/gprs_rlcmac_data.cpp
+++ b/src/gprs_rlcmac_data.cpp
@@ -127,10 +127,10 @@
struct gprs_rlcmac_tbf *tbf;
RlcMacUplink_t * ul_control_block = (RlcMacUplink_t *)malloc(sizeof(RlcMacUplink_t));
- LOGP(DRLCMAC, LOGL_NOTICE, "+++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++\n");
decode_gsm_rlcmac_uplink(rlc_block, ul_control_block);
- LOGPC(DRLCMAC, LOGL_NOTICE, "\n");
- LOGP(DRLCMAC, LOGL_NOTICE, "------------------------- RX : Uplink Control Block -------------------------\n");
+ LOGPC(DCSN1, LOGL_NOTICE, "\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- RX : Uplink Control Block -------------------------\n");
switch (ul_control_block->u.MESSAGE_TYPE) {
case MT_PACKET_CONTROL_ACK:
tlli = ul_control_block->u.Packet_Control_Acknowledgement.TLLI;
@@ -142,27 +142,27 @@
}
tfi = tbf->tfi;
if (tlli != tbf->tlli) {
- LOGP(DRLCMAC, LOGL_NOTICE, "Phone changed TLLI to "
+ LOGP(DRLCMAC, LOGL_INFO, "Phone changed TLLI to "
"0x%08x\n", tlli);
tbf->tlli = tlli;
}
- LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet Control Ack\n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet Control Ack\n", tbf->tfi, tbf->tlli);
tbf->poll_state = GPRS_RLCMAC_POLL_NONE;
/* check if this control ack belongs to packet uplink ack */
if (tbf->ul_ack_state == GPRS_RLCMAC_UL_ACK_WAIT_ACK) {
- LOGP(DRLCMAC, LOGL_NOTICE, "TBF: [UPLINK] END TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [UPLINK] END TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
tbf->ul_ack_state = GPRS_RLCMAC_UL_ACK_NONE;
tbf_free(tbf);
break;
}
if (tbf->dl_ass_state == GPRS_RLCMAC_DL_ASS_WAIT_ACK) {
- LOGP(DRLCMAC, LOGL_NOTICE, "TBF: [UPLINK] DOWNLINK ASSIGNED TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [UPLINK] DOWNLINK ASSIGNED TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
break;
}
if (tbf->ul_ass_state == GPRS_RLCMAC_UL_ASS_WAIT_ACK) {
- LOGP(DRLCMAC, LOGL_NOTICE, "TBF: [DOWNLINK] UPLINK ASSIGNED TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [DOWNLINK] UPLINK ASSIGNED TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
break;
}
@@ -174,7 +174,7 @@
tbf = tbf_by_poll_fn(fn);
if (!tbf) {
LOGP(DRLCMAC, LOGL_NOTICE, "PACKET DOWNLINK ACK with "
- "unknown FN=%u TFI=%d\n", fn, tfi);
+ "unknown FN=%u TBF=%d\n", fn, tfi);
break;
}
/* reset N3105 */
@@ -182,7 +182,7 @@
/* stop timer T3191 */
tbf_timer_stop(tbf);
tlli = tbf->tlli;
- LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet Downlink Ack/Nack\n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet Downlink Ack/Nack\n", tbf->tfi, tbf->tlli);
tbf->poll_state = GPRS_RLCMAC_POLL_NONE;
gprs_rlcmac_downlink_ack(tbf,
@@ -219,7 +219,6 @@
ul_tbf->dir.ul.usf = usf;
tbf_new_state(ul_tbf, GPRS_RLCMAC_FLOW);
tbf_timer_start(ul_tbf, 3169, bts->t3169, 0);
- LOGP(DRLCMAC, LOGL_NOTICE, "TBF: [UPLINK] START TFI: %u\n", ul_tbf->tfi);
/* schedule uplink assignment */
tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_SEND_ASS;
}
@@ -238,27 +237,27 @@
tfi = ul_control_block->u.Packet_Resource_Request.ID.u.Global_TFI.u.DOWNLINK_TFI;
tbf = tbf_by_tfi(tfi, GPRS_RLCMAC_DL_TBF);
if (!tbf) {
- LOGP(DRLCMAC, LOGL_NOTICE, "PACKET RESSOURCE REQ unknown downlink TFI=%d\n", tlli);
+ LOGP(DRLCMAC, LOGL_NOTICE, "PACKET RESSOURCE REQ unknown downlink TBF=%d\n", tlli);
break;
}
} else {
tfi = ul_control_block->u.Packet_Resource_Request.ID.u.Global_TFI.u.UPLINK_TFI;
tbf = tbf_by_tfi(tfi, GPRS_RLCMAC_UL_TBF);
if (!tbf) {
- LOGP(DRLCMAC, LOGL_NOTICE, "PACKET RESSOURCE REQ unknown uplink TFI=%d\n", tlli);
+ LOGP(DRLCMAC, LOGL_NOTICE, "PACKET RESSOURCE REQ unknown uplink TBF=%d\n", tlli);
break;
}
}
tlli = tbf->tlli;
}
- LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet ressource request\n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet ressource request\n", tbf->tfi, tbf->tlli);
#warning FIXME
puts("FIXME: UL request during UL request"); exit(0);
break;
default:
- LOGP(DRLCMAC, LOGL_ERROR, "RX: [PCU <- BTS] unknown control block received\n");
+ LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] unknown control block received\n");
}
free(ul_control_block);
return 1;
@@ -290,8 +289,11 @@
break;
case 3169:
case 3191:
- case 3193:
case 3195:
+ LOGP(DRLCMAC, LOGL_NOTICE, "TBF T%d timeout during "
+ "transsmission\n", tbf->T);
+ /* fall through */
+ case 3193:
LOGP(DRLCMAC, LOGL_DEBUG, "TBF will be freed due to timeout\n");
/* free TBF */
tbf_free(tbf);
@@ -377,7 +379,7 @@
break;
/* M == 0 and E == 0 is not allowed in this version. */
if (!m && !e) {
- LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TFI=%d "
+ LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TBF=%d "
"ignored, because M='0' and E='0'.\n",
tbf->tfi);
return 0;
@@ -457,8 +459,9 @@
/* Check if last offset would exceed frame. */
if (offset > len) {
- LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TFI=%d ignored, "
- "because LI exceeds frame length.\n", tbf->tfi);
+ LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TBF=%d ignored, "
+ "because LI delimits data that exceeds block size.\n",
+ tbf->tfi);
return -EINVAL;
}
@@ -489,7 +492,7 @@
if (i != frames - 1) {
/* send frame to SGSN */
LOGP(DRLCMACUL, LOGL_INFO, "Complete UL frame for "
- "TFI=%d: %s\n", tbf->tfi,
+ "TBF=%d: %s\n", tbf->tfi,
osmo_hexdump(tbf->llc_frame, tbf->llc_index));
gprs_rlcmac_tx_ul_ud(tbf);
tbf->llc_index = 0; /* reset frame space */
@@ -500,7 +503,7 @@
} else if (rh->cv == 0) {
/* send frame to SGSN */
LOGP(DRLCMACUL, LOGL_INFO, "Complete UL frame for "
- "TFI=%d that fits precisely in last block: "
+ "TBF=%d that fits precisely in last block: "
"%s\n", tbf->tfi,
osmo_hexdump(tbf->llc_frame, tbf->llc_index));
gprs_rlcmac_tx_ul_ud(tbf);
@@ -585,49 +588,49 @@
/* find TBF inst from given TFI */
tbf = tbf_by_tfi(rh->tfi, GPRS_RLCMAC_UL_TBF);
if (!tbf) {
- LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA unknown TFI=%d\n",
+ LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA unknown TBF=%d\n",
rh->tfi);
return 0;
}
if (tbf->direction != GPRS_RLCMAC_UL_TBF) {
- LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TFI=%d not Uplink "
+ LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TBF=%d not Uplink "
"tbf\n", rh->tfi);
return 0;
}
- LOGP(DRLCMACUL, LOGL_INFO, "UL DATA TFI=%d received (V(Q)=%d .. "
+ LOGP(DRLCMACUL, LOGL_DEBUG, "UL DATA TBF=%d received (V(Q)=%d .. "
"V(R)=%d)\n", rh->tfi, tbf->dir.ul.v_q, tbf->dir.ul.v_r);
/* get TLLI */
if (!tbf->tlli_valid) {
/* no TLLI yet */
if (!rh->ti) {
- LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TFI=%d without "
+ LOGP(DRLCMACUL, LOGL_NOTICE, "UL DATA TBF=%d without "
"TLLI, but no TLLI received yet\n", rh->tfi);
return 0;
}
rc = tlli_from_ul_data(data, len, &tbf->tlli);
if (rc) {
LOGP(DRLCMACUL, LOGL_NOTICE, "Failed to decode TLLI "
- "of UL DATA TFI=%d.\n", rh->tfi);
+ "of UL DATA TBF=%d.\n", rh->tfi);
return 0;
}
tbf->tlli_valid = 1;
- LOGP(DRLCMACUL, LOGL_DEBUG, " Decoded premier TLLI=0x%08x of "
- "UL DATA TFI=%d.\n", tbf->tlli, rh->tfi);
+ LOGP(DRLCMACUL, LOGL_INFO, "Decoded premier TLLI=0x%08x of "
+ "UL DATA TBF=%d.\n", tbf->tlli, rh->tfi);
/* already have TLLI, but we stille get another one */
} else if (rh->ti) {
uint32_t tlli;
rc = tlli_from_ul_data(data, len, &tlli);
if (rc) {
LOGP(DRLCMACUL, LOGL_NOTICE, "Failed to decode TLLI "
- "of UL DATA TFI=%d.\n", rh->tfi);
+ "of UL DATA TBF=%d.\n", rh->tfi);
return 0;
}
if (tlli != tbf->tlli) {
LOGP(DRLCMACUL, LOGL_NOTICE, "TLLI mismatch on UL "
- "DATA TFI=%d. (Ignoring due to contention "
+ "DATA TBF=%d. (Ignoring due to contention "
"resolution)\n", rh->tfi);
return 0;
}
@@ -770,6 +773,7 @@
msg = msgb_alloc(23, "rlcmac_ul_ass");
if (!msg)
return NULL;
+ LOGP(DRLCMAC, LOGL_INFO, "TBF: START TFI: %u TLLI: 0x%08x Packet Uplink Assignment (PACCH)\n", new_tbf->tfi, new_tbf->tlli);
bitvec *ass_vec = bitvec_alloc(23);
if (!ass_vec) {
msgb_free(msg);
@@ -783,10 +787,10 @@
new_tbf->tsc, POLLING_ASSIGNMENT);
bitvec_pack(ass_vec, msgb_put(msg, 23));
RlcMacDownlink_t * mac_control_block = (RlcMacDownlink_t *)malloc(sizeof(RlcMacDownlink_t));
- LOGP(DRLCMAC, LOGL_NOTICE, "+++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++\n");
decode_gsm_rlcmac_downlink(ass_vec, mac_control_block);
- LOGPC(DRLCMAC, LOGL_NOTICE, "\n");
- LOGP(DRLCMAC, LOGL_NOTICE, "------------------------- TX : Packet Uplink Assignment -------------------------\n");
+ LOGPC(DCSN1, LOGL_NOTICE, "\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- TX : Packet Uplink Assignment -------------------------\n");
bitvec_free(ass_vec);
#if POLLING_ASSIGNMENT == 1
@@ -833,9 +837,9 @@
tbf->dir.ul.usf = usf;
tbf_new_state(tbf, GPRS_RLCMAC_FLOW);
tbf_timer_start(tbf, 3169, bts->t3169, 0);
- LOGP(DRLCMAC, LOGL_NOTICE, "TBF: [UPLINK] START TFI: %u\n", tbf->tfi);
- LOGP(DRLCMAC, LOGL_NOTICE, "RX: [PCU <- BTS] TFI: %u RACH qbit-ta=%d ra=%d, Fn=%d (%d,%d,%d)\n", tbf->tfi, qta, ra, Fn, (Fn / (26 * 51)) % 32, Fn % 51, Fn % 26);
- LOGP(DRLCMAC, LOGL_NOTICE, "TX: [PCU -> BTS] TFI: %u Packet Immidiate Assignment (AGCH)\n", tbf->tfi);
+ LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [UPLINK] START TFI: %u\n", tbf->tfi);
+ LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] TFI: %u RACH qbit-ta=%d ra=%d, Fn=%d (%d,%d,%d)\n", tbf->tfi, qta, ra, Fn, (Fn / (26 * 51)) % 32, Fn % 51, Fn % 26);
+ LOGP(DRLCMAC, LOGL_INFO, "TX: START TFI: %u Immediate Assignment Uplink (AGCH)\n", tbf->tfi);
bitvec *immediate_assignment = bitvec_alloc(22) /* without plen */;
bitvec_unhex(immediate_assignment, "2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b");
int plen = write_immediate_assignment(immediate_assignment, 0, ra, Fn, tbf->ta, tbf->arfcn, tbf->ts, tbf->tsc, tbf->tfi, usf, 0, 0, 0);
@@ -871,7 +875,7 @@
uint8_t len;
uint16_t space, chunk;
- LOGP(DRLCMACDL, LOGL_INFO, "DL DATA TFI=%d downlink (V(A)==%d .. "
+ LOGP(DRLCMACDL, LOGL_DEBUG, "DL DATA TBF=%d downlink (V(A)==%d .. "
"V(S)==%d)\n", tbf->tfi, tbf->dir.dl.v_a, tbf->dir.dl.v_s);
do_resend:
@@ -1001,6 +1005,10 @@
"would exactly fit into space (%d): because "
"this is a final block, we don't add length "
"header, and we are done\n", chunk, space);
+ LOGP(DRLCMACDL, LOGL_INFO, "Complete DL frame for "
+ "TBF=%d that fits precisely in last block: "
+ "%s\n", tbf->tfi,
+ osmo_hexdump(tbf->llc_frame, tbf->llc_length));
/* block is filled, so there is no extension */
*e_pointer |= 0x01;
/* fill space */
@@ -1058,13 +1066,16 @@
memcpy(data, tbf->llc_frame + tbf->llc_index, chunk);
data += chunk;
space -= chunk;
+ LOGP(DRLCMACDL, LOGL_INFO, "Complete DL frame for TBF=%d: %s\n",
+ tbf->tfi,
+ osmo_hexdump(tbf->llc_frame, tbf->llc_length));
/* reset LLC frame */
tbf->llc_index = tbf->llc_length = 0;
/* dequeue next LLC frame, if any */
msg = msgb_dequeue(&tbf->llc_queue);
if (msg) {
- LOGP(DRLCMACDL, LOGL_INFO, "- Dequeue next LLC "
- "(len=%d)\n", msg->len);
+ LOGP(DRLCMACDL, LOGL_INFO, "- Dequeue next LLC for "
+ "TBF=%d (len=%d)\n", tbf->tfi, msg->len);
memcpy(tbf->llc_frame, msg->data, msg->len);
tbf->llc_length = msg->len;
msgb_free(msg);
@@ -1076,7 +1087,7 @@
}
/* if we don't have more LLC frames */
if (!tbf->llc_length) {
- LOGP(DRLCMACDL, LOGL_INFO, "-- Final block, so we "
+ LOGP(DRLCMACDL, LOGL_DEBUG, "-- Final block, so we "
"done.\n");
li->e = 1; /* we cannot extend */
rh->fbi = 1; /* we indicate final block */
@@ -1084,7 +1095,7 @@
break;
}
/* we have no space left */
- LOGP(DRLCMACDL, LOGL_INFO, "-- No space left, so we are "
+ LOGP(DRLCMACDL, LOGL_DEBUG, "-- No space left, so we are "
"done.\n");
li->e = 1; /* we cannot extend */
break;
@@ -1122,7 +1133,7 @@
ACK_AFTER_FRAMES);
}
if (tbf->poll_state != GPRS_RLCMAC_POLL_NONE)
- LOGP(DRLCMACDL, LOGL_NOTICE, "Polling is already "
+ LOGP(DRLCMACDL, LOGL_DEBUG, "Polling is already "
"sheduled for TBF=%d, so we must wait for "
"requesting downlink ack\n", tbf->tfi);
else {
@@ -1161,7 +1172,7 @@
uint16_t bsn;
struct msgb *msg;
- LOGP(DRLCMACDL, LOGL_INFO, "TFI=%d downlink acknowledge\n",
+ LOGP(DRLCMACDL, LOGL_DEBUG, "TBF=%d downlink acknowledge\n",
tbf->tfi);
if (!final) {
@@ -1299,16 +1310,17 @@
}
bitvec_unhex(ass_vec,
"2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b");
+ LOGP(DRLCMAC, LOGL_INFO, "TBF: START TFI: %u TLLI: 0x%08x Packet Downlink Assignment (PACCH)\n", new_tbf->tfi, new_tbf->tlli);
write_packet_downlink_assignment(ass_vec, tbf->tfi,
(tbf->direction == GPRS_RLCMAC_DL_TBF), new_tbf->tfi,
new_tbf->arfcn, new_tbf->ts, new_tbf->ta, new_tbf->tsc,
POLLING_ASSIGNMENT);
bitvec_pack(ass_vec, msgb_put(msg, 23));
RlcMacDownlink_t * mac_control_block = (RlcMacDownlink_t *)malloc(sizeof(RlcMacDownlink_t));
- LOGP(DRLCMAC, LOGL_NOTICE, "+++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++\n");
decode_gsm_rlcmac_downlink(ass_vec, mac_control_block);
- LOGPC(DRLCMAC, LOGL_NOTICE, "\n");
- LOGP(DRLCMAC, LOGL_NOTICE, "------------------------- TX : Packet Downlink Assignment -------------------------\n");
+ LOGPC(DCSN1, LOGL_NOTICE, "\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- TX : Packet Downlink Assignment -------------------------\n");
bitvec_free(ass_vec);
#if POLLING_ASSIGNMENT == 1
@@ -1324,7 +1336,7 @@
static void gprs_rlcmac_downlink_assignment(gprs_rlcmac_tbf *tbf, uint8_t poll)
{
- LOGP(DRLCMAC, LOGL_NOTICE, "TX: [PCU -> BTS] TFI: %u TLLI: 0x%08x Immidiate Assignment (CCCH)\n", tbf->tfi, tbf->tlli);
+ LOGP(DRLCMAC, LOGL_INFO, "TX: START TFI: %u TLLI: 0x%08x Immediate Assignment Downlink (AGCH)\n", tbf->tfi, tbf->tlli);
bitvec *immediate_assignment = bitvec_alloc(22); /* without plen */
bitvec_unhex(immediate_assignment, "2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b");
/* use request reference that has maximum distance to current time,
@@ -1359,10 +1371,10 @@
/* wait one second until assignment */
tbf_timer_start(tbf, 1234, 1,0);
#else
- LOGP(DRLCMAC, LOGL_DEBUG, "Trigger dowlink assignment on "
- "PACCH, because %slink TBF=%d exists for TLLI\n",
+ LOGP(DRLCMAC, LOGL_DEBUG, "Send dowlink assignment on "
+ "PACCH, because %slink TBF=%d exists for TLLI=0x%08x\n",
(tbf->direction == GPRS_RLCMAC_DL_TBF) ? "down" : "up",
- old_tbf->tfi);
+ old_tbf->tfi, old_tbf->tlli);
old_tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_SEND_ASS;
/* use TA from old TBF */
tbf->ta = old_tbf->ta;
@@ -1372,9 +1384,7 @@
tbf_timer_start(tbf, 0, Tassign_pacch);
#endif
} else {
- LOGP(DRLCMAC, LOGL_DEBUG, "Trigger dowlink assignment on AGCH, "
- "because no uplink/downlink TBF exists for TLLI. "
- "(providing last timing advance)\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "Send dowlink assignment for TBF=%d on AGCH, no TBF exist\n", tbf->tfi);
/* send immediate assignment */
gprs_rlcmac_downlink_assignment(tbf, 0);
/* change state */