cellular-infrastructure
/
osmo-pcu
mirror of https://gerrit.osmocom.org/osmo-pcu
9
0
Fork 1
Code Issues Releases Wiki Activity

Add new log category 'ms' 

This is useful to track the lifecycle of MS objects. The RLCMAC cateogry
used so far in those log messages is too broad.

Change-Id: Ib4ce88d0f7309ac77c064a94bb0d667e8dbc33dd
This commit is contained in:
Pau Espin 2023-04-19 20:38:40 +02:00
parent 8456a3642b
commit fe4d2f7dca
7 changed files with 38 additions and 30 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
src/gprs_debug.c
View File

@ -79,6 +79,13 @@ static const struct log_info_cat default_categories[] = {
.loglevel = LOGL_NOTICE, .loglevel = LOGL_NOTICE,
.enabled = 1, .enabled = 1,
}, },
[DMS] = {
.name = "DMS",
.color = "\033[1;34m",
.description = "Mobile Station (MS)",
.loglevel = LOGL_NOTICE,
.enabled = 1,
},
[DTBF] = { [DTBF] = {
.name = "DTBF", .name = "DTBF",
.color = "\033[1;34m", .color = "\033[1;34m",

1
src/gprs_debug.h
View File

@ -34,6 +34,7 @@ enum {
DRLCMACUL, DRLCMACUL,
DRLCMACSCHED, DRLCMACSCHED,
DRLCMACMEAS, DRLCMACMEAS,
DMS,
DTBF, DTBF,
DTBFDL, DTBFDL,
DTBFUL, DTBFUL,

52
src/gprs_ms.c
View File

@ -82,7 +82,7 @@ static int ms_use_cb(struct osmo_use_count_entry *e, int32_t old_use_count, cons
level = LOGL_DEBUG; level = LOGL_DEBUG;
LOGPSRC(DRLCMAC, level, file, line, "%s: %s %s: now used by %s\n", LOGPSRC(DMS, level, file, line, "%s: %s %s: now used by %s\n",
ms_name(ms), ms_name(ms),
(e->count - old_use_count) > 0 ? "+" : "-", e->use, (e->count - old_use_count) > 0 ? "+" : "-", e->use,
(osmo_use_count_to_str_buf(buf, sizeof(buf), &ms->use_count), buf)); (osmo_use_count_to_str_buf(buf, sizeof(buf), &ms->use_count), buf));
@ -100,7 +100,7 @@ static int ms_use_cb(struct osmo_use_count_entry *e, int32_t old_use_count, cons
static void ms_release_timer_cb(void *data) static void ms_release_timer_cb(void *data)
{ {
struct GprsMs *ms = (struct GprsMs *) data; struct GprsMs *ms = (struct GprsMs *) data;
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Release timer expired\n"); LOGPMS(ms, DMS, LOGL_INFO, "Release timer expired\n");
/* Finally free the MS after being idle for a while according to config */ /* Finally free the MS after being idle for a while according to config */
talloc_free(ms); talloc_free(ms);
@ -148,7 +148,7 @@ struct GprsMs *ms_alloc(struct gprs_rlcmac_bts *bts, const char *use_ref)
int codel_interval = LLC_CODEL_USE_DEFAULT; int codel_interval = LLC_CODEL_USE_DEFAULT;
LOGP(DRLCMAC, LOGL_INFO, "Creating MS object\n"); LOGP(DMS, LOGL_INFO, "Creating MS object\n");
ms->imsi[0] = '\0'; ms->imsi[0] = '\0';
osmo_timer_setup(&ms->timer, ms_release_timer_cb, ms); osmo_timer_setup(&ms->timer, ms_release_timer_cb, ms);
@ -184,7 +184,7 @@ static int ms_talloc_destructor(struct GprsMs *ms)
{ {
struct llist_item *pos, *tmp; struct llist_item *pos, *tmp;
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Destroying MS object\n"); LOGPMS(ms, DMS, LOGL_INFO, "Destroying MS object\n");
bts_stat_item_dec(ms->bts, STAT_MS_PRESENT); bts_stat_item_dec(ms->bts, STAT_MS_PRESENT);
llist_del(&ms->list); llist_del(&ms->list);
@ -240,7 +240,7 @@ static void ms_becomes_idle(struct GprsMs *ms)
return; return;
} }
LOGPMS(ms, DRLCMAC, LOGL_DEBUG, "Schedule MS release in %u secs\n", ms->delay); LOGPMS(ms, DMS, LOGL_DEBUG, "Schedule MS release in %u secs\n", ms->delay);
osmo_timer_schedule(&ms->timer, ms->delay, 0); osmo_timer_schedule(&ms->timer, ms->delay, 0);
} }
@ -249,7 +249,7 @@ static void ms_becomes_active(struct GprsMs *ms)
if (!osmo_timer_pending(&ms->timer)) if (!osmo_timer_pending(&ms->timer))
return; return;
LOGPMS(ms, DRLCMAC, LOGL_DEBUG, "Cancel scheduled MS release\n"); LOGPMS(ms, DMS, LOGL_DEBUG, "Cancel scheduled MS release\n");
osmo_timer_del(&ms->timer); osmo_timer_del(&ms->timer);
} }
@ -329,7 +329,7 @@ static bool ms_tbf_is_attached(const struct GprsMs *ms, const struct gprs_rlcmac
static void ms_attach_ul_tbf(struct GprsMs *ms, struct gprs_rlcmac_ul_tbf *tbf) static void ms_attach_ul_tbf(struct GprsMs *ms, struct gprs_rlcmac_ul_tbf *tbf)
{ {
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Attaching UL TBF: %s\n", tbf_name((struct gprs_rlcmac_tbf *)tbf)); LOGPMS(ms, DMS, LOGL_INFO, "Attaching UL TBF: %s\n", tbf_name((struct gprs_rlcmac_tbf *)tbf));
if (ms->ul_tbf) if (ms->ul_tbf)
llist_add_tail(tbf_ms_list(ul_tbf_as_tbf(ms->ul_tbf)), &ms->old_tbfs); llist_add_tail(tbf_ms_list(ul_tbf_as_tbf(ms->ul_tbf)), &ms->old_tbfs);
@ -341,7 +341,7 @@ static void ms_attach_ul_tbf(struct GprsMs *ms, struct gprs_rlcmac_ul_tbf *tbf)
static void ms_attach_dl_tbf(struct GprsMs *ms, struct gprs_rlcmac_dl_tbf *tbf) static void ms_attach_dl_tbf(struct GprsMs *ms, struct gprs_rlcmac_dl_tbf *tbf)
{ {
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Attaching DL TBF: %s\n", tbf_name((struct gprs_rlcmac_tbf *)tbf)); LOGPMS(ms, DMS, LOGL_INFO, "Attaching DL TBF: %s\n", tbf_name((struct gprs_rlcmac_tbf *)tbf));
if (ms->dl_tbf) if (ms->dl_tbf)
llist_add_tail(tbf_ms_list(dl_tbf_as_tbf(ms->dl_tbf)), &ms->old_tbfs); llist_add_tail(tbf_ms_list(dl_tbf_as_tbf(ms->dl_tbf)), &ms->old_tbfs);
@ -374,7 +374,7 @@ void ms_detach_tbf(struct GprsMs *ms, struct gprs_rlcmac_tbf *tbf)
if (!ms_tbf_is_attached(ms, tbf)) if (!ms_tbf_is_attached(ms, tbf))
return; return;
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Detaching TBF: %s\n", LOGPMS(ms, DMS, LOGL_INFO, "Detaching TBF: %s\n",
tbf_name(tbf)); tbf_name(tbf));
if (tbf == ul_tbf_as_tbf(ms->ul_tbf)) { if (tbf == ul_tbf_as_tbf(ms->ul_tbf)) {
@ -394,7 +394,7 @@ void ms_detach_tbf(struct GprsMs *ms, struct gprs_rlcmac_tbf *tbf)
ms_ref() taken to avoid use-after-free. */ ms_ref() taken to avoid use-after-free. */
void ms_reset(struct GprsMs *ms) void ms_reset(struct GprsMs *ms)
{ {
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Clearing MS object\n"); LOGPMS(ms, DMS, LOGL_INFO, "Clearing MS object\n");
struct llist_item *pos; struct llist_item *pos;
struct gprs_rlcmac_tbf *tbf; struct gprs_rlcmac_tbf *tbf;
@ -458,7 +458,7 @@ void ms_merge_and_clear_ms(struct GprsMs *ms, struct GprsMs *old_ms)
ms_name_buf(old_ms, old_ms_name, sizeof(old_ms_name)); ms_name_buf(old_ms, old_ms_name, sizeof(old_ms_name));
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Merge MS: %s\n", old_ms_name); LOGPMS(ms, DMS, LOGL_INFO, "Merge MS: %s\n", old_ms_name);
if (strlen(ms_imsi(ms)) == 0 && strlen(ms_imsi(old_ms)) != 0) if (strlen(ms_imsi(ms)) == 0 && strlen(ms_imsi(old_ms)) != 0)
osmo_strlcpy(ms->imsi, ms_imsi(old_ms), sizeof(ms->imsi)); osmo_strlcpy(ms->imsi, ms_imsi(old_ms), sizeof(ms->imsi));
@ -498,7 +498,7 @@ void ms_set_tlli(struct GprsMs *ms, uint32_t tlli)
return; return;
if (tlli != ms->new_dl_tlli) { if (tlli != ms->new_dl_tlli) {
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, UL TLLI: 0x%08x -> 0x%08x, " "Modifying MS object, UL TLLI: 0x%08x -> 0x%08x, "
"not yet confirmed\n", "not yet confirmed\n",
ms_tlli(ms), tlli); ms_tlli(ms), tlli);
@ -506,7 +506,7 @@ void ms_set_tlli(struct GprsMs *ms, uint32_t tlli)
return; return;
} }
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, TLLI: 0x%08x -> 0x%08x, " "Modifying MS object, TLLI: 0x%08x -> 0x%08x, "
"already confirmed partly\n", "already confirmed partly\n",
ms->tlli, tlli); ms->tlli, tlli);
@ -524,7 +524,7 @@ bool ms_confirm_tlli(struct GprsMs *ms, uint32_t tlli)
/* The MS has not sent a message with the new TLLI, which may /* The MS has not sent a message with the new TLLI, which may
* happen according to the spec [TODO: add reference]. */ * happen according to the spec [TODO: add reference]. */
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"The MS object cannot fully confirm an unexpected TLLI: 0x%08x, " "The MS object cannot fully confirm an unexpected TLLI: 0x%08x, "
"partly confirmed\n", tlli); "partly confirmed\n", tlli);
/* Use the network's idea of TLLI as candidate, this does not /* Use the network's idea of TLLI as candidate, this does not
@ -533,7 +533,7 @@ bool ms_confirm_tlli(struct GprsMs *ms, uint32_t tlli)
return false; return false;
} }
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, TLLI: 0x%08x confirmed\n", tlli); "Modifying MS object, TLLI: 0x%08x confirmed\n", tlli);
ms_apply_tlli_change(ms, tlli); ms_apply_tlli_change(ms, tlli);
@ -544,12 +544,12 @@ bool ms_confirm_tlli(struct GprsMs *ms, uint32_t tlli)
void ms_set_imsi(struct GprsMs *ms, const char *imsi) void ms_set_imsi(struct GprsMs *ms, const char *imsi)
{ {
if (!imsi) { if (!imsi) {
LOGP(DRLCMAC, LOGL_ERROR, "Expected IMSI!\n"); LOGP(DMS, LOGL_ERROR, "Expected IMSI!\n");
return; return;
} }
if (imsi[0] && strlen(imsi) < 3) { if (imsi[0] && strlen(imsi) < 3) {
LOGP(DRLCMAC, LOGL_ERROR, "No valid IMSI '%s'!\n", LOGP(DMS, LOGL_ERROR, "No valid IMSI '%s'!\n",
imsi); imsi);
return; return;
} }
@ -557,7 +557,7 @@ void ms_set_imsi(struct GprsMs *ms, const char *imsi)
if (strcmp(imsi, ms->imsi) == 0) if (strcmp(imsi, ms->imsi) == 0)
return; return;
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, TLLI = 0x%08x, IMSI '%s' -> '%s'\n", "Modifying MS object, TLLI = 0x%08x, IMSI '%s' -> '%s'\n",
ms_tlli(ms), ms->imsi, imsi); ms_tlli(ms), ms->imsi, imsi);
@ -570,7 +570,7 @@ void ms_set_imsi(struct GprsMs *ms, const char *imsi)
* different IMSI */ * different IMSI */
OSMO_ASSERT(old_ms != ms); OSMO_ASSERT(old_ms != ms);
LOGPMS(ms, DRLCMAC, LOGL_NOTICE, LOGPMS(ms, DMS, LOGL_NOTICE,
"IMSI '%s' was already assigned to another " "IMSI '%s' was already assigned to another "
"MS object: TLLI = 0x%08x, that IMSI will be removed\n", "MS object: TLLI = 0x%08x, that IMSI will be removed\n",
imsi, ms_tlli(old_ms)); imsi, ms_tlli(old_ms));
@ -595,12 +595,12 @@ void ms_set_ta(struct GprsMs *ms, uint8_t ta_)
return; return;
if (gsm48_ta_is_valid(ta_)) { if (gsm48_ta_is_valid(ta_)) {
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, TLLI = 0x%08x, TA %d -> %d\n", "Modifying MS object, TLLI = 0x%08x, TA %d -> %d\n",
ms_tlli(ms), ms->ta, ta_); ms_tlli(ms), ms->ta, ta_);
ms->ta = ta_; ms->ta = ta_;
} else } else
LOGP(DRLCMAC, LOGL_NOTICE, LOGP(DMS, LOGL_NOTICE,
"MS object, TLLI = 0x%08x, invalid TA %d rejected (old " "MS object, TLLI = 0x%08x, invalid TA %d rejected (old "
"value %d kept)\n", ms_tlli(ms), ta_, ms->ta); "value %d kept)\n", ms_tlli(ms), ta_, ms->ta);
} }
@ -610,7 +610,7 @@ void ms_set_ms_class(struct GprsMs *ms, uint8_t ms_class_)
if (ms_class_ == ms->ms_class) if (ms_class_ == ms->ms_class)
return; return;
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, TLLI = 0x%08x, MS class %d -> %d\n", "Modifying MS object, TLLI = 0x%08x, MS class %d -> %d\n",
ms_tlli(ms), ms->ms_class, ms_class_); ms_tlli(ms), ms->ms_class, ms_class_);
@ -622,14 +622,14 @@ void ms_set_egprs_ms_class(struct GprsMs *ms, uint8_t ms_class_)
if (ms_class_ == ms->egprs_ms_class) if (ms_class_ == ms->egprs_ms_class)
return; return;
LOGP(DRLCMAC, LOGL_INFO, LOGP(DMS, LOGL_INFO,
"Modifying MS object, TLLI = 0x%08x, EGPRS MS class %d -> %d\n", "Modifying MS object, TLLI = 0x%08x, EGPRS MS class %d -> %d\n",
ms_tlli(ms), ms->egprs_ms_class, ms_class_); ms_tlli(ms), ms->egprs_ms_class, ms_class_);
ms->egprs_ms_class = ms_class_; ms->egprs_ms_class = ms_class_;
if (!bts_max_mcs_ul(ms->bts) || !bts_max_mcs_dl(ms->bts)) { if (!bts_max_mcs_ul(ms->bts) || !bts_max_mcs_dl(ms->bts)) {
LOGPMS(ms, DRLCMAC, LOGL_DEBUG, LOGPMS(ms, DMS, LOGL_DEBUG,
"Avoid enabling EGPRS because use of MCS is disabled: ul=%u dl=%u\n", "Avoid enabling EGPRS because use of MCS is disabled: ul=%u dl=%u\n",
bts_max_mcs_ul(ms->bts), bts_max_mcs_dl(ms->bts)); bts_max_mcs_ul(ms->bts), bts_max_mcs_dl(ms->bts));
return; return;
@ -643,7 +643,7 @@ void ms_set_egprs_ms_class(struct GprsMs *ms, uint8_t ms_class_)
} else { } else {
ms_set_mode(ms, EGPRS); ms_set_mode(ms, EGPRS);
} }
LOGPMS(ms, DRLCMAC, LOGL_INFO, "Enabled EGPRS, mode %s\n", mode_name(ms_mode(ms))); LOGPMS(ms, DMS, LOGL_INFO, "Enabled EGPRS, mode %s\n", mode_name(ms_mode(ms)));
} }
void ms_update_error_rate(struct GprsMs *ms, struct gprs_rlcmac_tbf *tbf, int error_rate) void ms_update_error_rate(struct GprsMs *ms, struct gprs_rlcmac_tbf *tbf, int error_rate)
@ -882,7 +882,7 @@ enum CodingScheme ms_current_cs_dl(const struct GprsMs *ms, enum mcs_kind req_mc
} }
if (orig_cs != cs) if (orig_cs != cs)
LOGPMS(ms, DRLCMACDL, LOGL_INFO, "MS (mode=%s) suggests transmitting " LOGPMS(ms, DMS, LOGL_INFO, "MS (mode=%s) suggests transmitting "
"DL %s, downgrade to %s in order to match TBF & scheduler requirements\n", "DL %s, downgrade to %s in order to match TBF & scheduler requirements\n",
mode_name(ms_mode(ms)), mcs_name(orig_cs), mcs_name(cs)); mode_name(ms_mode(ms)), mcs_name(orig_cs), mcs_name(cs));

2
tests/app_info/AppInfoTest.cpp
View File

@ -180,7 +180,7 @@ int main(int argc, char *argv[])
log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE); log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);
log_set_print_category(osmo_stderr_target, 0); log_set_print_category(osmo_stderr_target, 0);
log_set_print_category_hex(osmo_stderr_target, 0); log_set_print_category_hex(osmo_stderr_target, 0);
log_parse_category_mask(osmo_stderr_target, "DL1IF,1:DRLCMAC,3:DRLCMACSCHED,1"); log_parse_category_mask(osmo_stderr_target, "DL1IF,1:DRLCMAC,3:DRLCMACSCHED,1:DMS,3");
the_pcu = gprs_pcu_alloc(tall_pcu_ctx); the_pcu = gprs_pcu_alloc(tall_pcu_ctx);
bts_alloc(the_pcu, 0); bts_alloc(the_pcu, 0);

2
tests/ms/MsTest.cpp
View File

@ -542,7 +542,7 @@ int main(int argc, char **argv)
log_set_log_level(osmo_stderr_target, LOGL_INFO); log_set_log_level(osmo_stderr_target, LOGL_INFO);
log_set_print_category(osmo_stderr_target, 0); log_set_print_category(osmo_stderr_target, 0);
log_set_print_category_hex(osmo_stderr_target, 0); log_set_print_category_hex(osmo_stderr_target, 0);
log_parse_category_mask(osmo_stderr_target, "DPCU,3:DRLCMAC,3"); log_parse_category_mask(osmo_stderr_target, "DPCU,3:DRLCMAC,3:DMS,3");
the_pcu = gprs_pcu_alloc(tall_pcu_ctx); the_pcu = gprs_pcu_alloc(tall_pcu_ctx);

2
tests/tbf/TbfTest.cpp
View File

@ -3470,7 +3470,7 @@ int main(int argc, char **argv)
log_set_print_category_hex(osmo_stderr_target, 0); log_set_print_category_hex(osmo_stderr_target, 0);
log_parse_category_mask(osmo_stderr_target, "DRLCMAC,1:DRLCMACDATA,3:DRLCMACDL,3:DRLCMACUL,3:" log_parse_category_mask(osmo_stderr_target, "DRLCMAC,1:DRLCMACDATA,3:DRLCMACDL,3:DRLCMACUL,3:"
"DRLCMACSCHED,1:DRLCMACMEAS,3:DNS,3:DLBSSGP,3:DPCU,5:" "DRLCMACSCHED,1:DRLCMACMEAS,3:DNS,3:DLBSSGP,3:DPCU,5:"
"DL1IF,6:DTBF,1:DTBFUL,1:DTBFDL,1:DLGLOBAL,2:"); "DL1IF,6:DMS,1:DTBF,1:DTBFUL,1:DTBFDL,1:DLGLOBAL,2:");
osmo_fsm_log_addr(false); osmo_fsm_log_addr(false);
vty_init(&pcu_vty_info); vty_init(&pcu_vty_info);
pcu_vty_init(); pcu_vty_init();

2
tests/ulc/PdchUlcTest.cpp
View File

@ -317,7 +317,7 @@ int main(int argc, char **argv)
log_set_log_level(osmo_stderr_target, LOGL_DEBUG); log_set_log_level(osmo_stderr_target, LOGL_DEBUG);
log_set_print_category_hex(osmo_stderr_target, 0); log_set_print_category_hex(osmo_stderr_target, 0);
log_set_print_category(osmo_stderr_target, 0); log_set_print_category(osmo_stderr_target, 0);
log_parse_category_mask(osmo_stderr_target, "DPCU,1:DRLCMAC,1:DRLCMACUL,1"); log_parse_category_mask(osmo_stderr_target, "DPCU,1:DRLCMAC,1:DRLCMACUL,1:DMS,1");
the_pcu = gprs_pcu_alloc(tall_pcu_ctx); the_pcu = gprs_pcu_alloc(tall_pcu_ctx);