From c03208d238b0a0f8f8a6e9a7c52c2df30cad81a0 Mon Sep 17 00:00:00 2001 From: Daniel Willmann Date: Sun, 10 Jan 2021 22:14:17 +0100 Subject: WIP: Tracing Change-Id: I78945ab2bde7c93e9461dc446809f7cbd6493100 --- include/osmocom/core/fsm.h | 64 ++++++++++++++++++++++++++++------------ include/osmocom/core/logging.h | 36 +++++++++++++++++++---- include/osmocom/core/tdef.h | 4 +-- src/fsm.c | 67 ++++++++++++++++++++++++++++-------------- src/gb/gprs_ns2_vc_fsm.c | 25 ++++++++++++++++ src/logging.c | 6 ++++ src/tdef.c | 10 +++---- 7 files changed, 160 insertions(+), 52 deletions(-) diff --git a/include/osmocom/core/fsm.h b/include/osmocom/core/fsm.h index 77ebe7c1..9ff58731 100644 --- a/include/osmocom/core/fsm.h +++ b/include/osmocom/core/fsm.h @@ -202,6 +202,34 @@ void osmo_fsm_set_dealloc_ctx(void *ctx); #define OSMO_T_FMT "%c%u" #define OSMO_T_FMT_ARGS(T) ((T) >= 0 ? 'T' : 'X'), ((T) >= 0 ? T : -T) +/* FSM Tracing Macros */ +#define TRACEPFSMENTSRC(fi, file, line, func, fmt, args...) \ + TRACEPSRC((fi)->fsm->log_subsys, TRACEOP_ENTFUN, \ + file, line, func, \ + "fsminst=%p name=%s id=%s state=%s%s" fmt, fi, \ + (fi)->fsm->name, (fi)->id, \ + osmo_fsm_state_name((fi)->fsm, (fi)->state), \ + fmt[0] ? " " : "", ## args) +#define TRACEPFSMEXTSRC(fi, file, line, func, fmt, args...) \ + TRACEPSRC((fi)->fsm->log_subsys, TRACEOP_EXTFUN, \ + file, line, func, fmt, ##args) +#define TRACEPFSMATTRSRC(fi, file, line, func, fmt, args...) \ + TRACEPSRC((fi)->fsm->log_subsys, TRACEOP_ATTR, \ + file, line, func, fmt, ##args) + +#define TRACEPFSMENT(fi, fmt, args...) \ + TRACEP((fi)->fsm->log_subsys, TRACEOP_ENTFUN, \ + "fsminst=%p name=%s id=%s state=%s%s" fmt, fi, \ + (fi)->fsm->name, (fi)->id, \ + osmo_fsm_state_name((fi)->fsm, (fi)->state), \ + fmt[0] ? " " : "", ## args) + +#define TRACEPFSMEXT(fi, fmt, args...) \ + TRACEP((fi)->fsm->log_subsys, TRACEOP_EXTFUN, fmt, ##args) + +#define TRACEPFSMATTR(fi, fmt, args...) \ + TRACEP((fi)->fsm->log_subsys, TRACEOP_ATTR, fmt, ##args) + int osmo_fsm_register(struct osmo_fsm *fsm); void osmo_fsm_unregister(struct osmo_fsm *fsm); struct osmo_fsm *osmo_fsm_find_by_name(const char *name); @@ -240,17 +268,17 @@ static inline const char *osmo_fsm_inst_state_name(struct osmo_fsm_inst *fi) */ #define osmo_fsm_inst_state_chg(fi, new_state, timeout_secs, T) \ _osmo_fsm_inst_state_chg(fi, new_state, timeout_secs, T, \ - __FILE__, __LINE__) + __FILE__, __LINE__, __func__) int _osmo_fsm_inst_state_chg(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_secs, int T, - const char *file, int line); + const char *file, int line, const char *func); #define osmo_fsm_inst_state_chg_ms(fi, new_state, timeout_ms, T) \ _osmo_fsm_inst_state_chg_ms(fi, new_state, timeout_ms, T, \ - __FILE__, __LINE__) + __FILE__, __LINE__, __func__) int _osmo_fsm_inst_state_chg_ms(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_ms, int T, - const char *file, int line); + const char *file, int line, const char *func); /*! perform a state change while keeping the current timer running. * @@ -263,9 +291,9 @@ int _osmo_fsm_inst_state_chg_ms(struct osmo_fsm_inst *fi, uint32_t new_state, */ #define osmo_fsm_inst_state_chg_keep_timer(fi, new_state) \ _osmo_fsm_inst_state_chg_keep_timer(fi, new_state, \ - __FILE__, __LINE__) + __FILE__, __LINE__, __func__) int _osmo_fsm_inst_state_chg_keep_timer(struct osmo_fsm_inst *fi, uint32_t new_state, - const char *file, int line); + const char *file, int line, const char *func); /*! perform a state change while keeping the current timer if running, or starting a timer otherwise. * @@ -277,17 +305,17 @@ int _osmo_fsm_inst_state_chg_keep_timer(struct osmo_fsm_inst *fi, uint32_t new_s */ #define osmo_fsm_inst_state_chg_keep_or_start_timer(fi, new_state, timeout_secs, T) \ _osmo_fsm_inst_state_chg_keep_or_start_timer(fi, new_state, timeout_secs, T, \ - __FILE__, __LINE__) + __FILE__, __LINE__, __func__) int _osmo_fsm_inst_state_chg_keep_or_start_timer(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_secs, int T, - const char *file, int line); + const char *file, int line, const char *func); #define osmo_fsm_inst_state_chg_keep_or_start_timer_ms(fi, new_state, timeout_ms, T) \ _osmo_fsm_inst_state_chg_keep_or_start_timer_ms(fi, new_state, timeout_ms, T, \ - __FILE__, __LINE__) + __FILE__, __LINE__, __func__) int _osmo_fsm_inst_state_chg_keep_or_start_timer_ms(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_ms, int T, - const char *file, int line); + const char *file, int line, const char *func); /*! dispatch an event to an osmocom finite state machine instance @@ -297,9 +325,9 @@ int _osmo_fsm_inst_state_chg_keep_or_start_timer_ms(struct osmo_fsm_inst *fi, ui * purposes. See there for documentation. */ #define osmo_fsm_inst_dispatch(fi, event, data) \ - _osmo_fsm_inst_dispatch(fi, event, data, __FILE__, __LINE__) + _osmo_fsm_inst_dispatch(fi, event, data, __FILE__, __LINE__, __func__) int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data, - const char *file, int line); + const char *file, int line, const char *func); /*! Terminate FSM instance with given cause * @@ -308,10 +336,10 @@ int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data * See there for documentation. */ #define osmo_fsm_inst_term(fi, cause, data) \ - _osmo_fsm_inst_term(fi, cause, data, __FILE__, __LINE__) + _osmo_fsm_inst_term(fi, cause, data, __FILE__, __LINE__, __func__) void _osmo_fsm_inst_term(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause, void *data, - const char *file, int line); + const char *file, int line, const char *func); /*! Terminate all child FSM instances of an FSM instance. * @@ -320,11 +348,11 @@ void _osmo_fsm_inst_term(struct osmo_fsm_inst *fi, * purposes. See there for documentation. */ #define osmo_fsm_inst_term_children(fi, cause, data) \ - _osmo_fsm_inst_term_children(fi, cause, data, __FILE__, __LINE__) + _osmo_fsm_inst_term_children(fi, cause, data, __FILE__, __LINE__, __func__) void _osmo_fsm_inst_term_children(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause, void *data, - const char *file, int line); + const char *file, int line, const char *func); /*! dispatch an event to all children of an osmocom finite state machine instance * @@ -333,8 +361,8 @@ void _osmo_fsm_inst_term_children(struct osmo_fsm_inst *fi, * purposes. See there for documentation. */ #define osmo_fsm_inst_broadcast_children(fi, cause, data) \ - _osmo_fsm_inst_broadcast_children(fi, cause, data, __FILE__, __LINE__) + _osmo_fsm_inst_broadcast_children(fi, cause, data, __FILE__, __LINE__, __func__) void _osmo_fsm_inst_broadcast_children(struct osmo_fsm_inst *fi, uint32_t event, - void *data, const char *file, int line); + void *data, const char *file, int line, const char *func); /*! @} */ diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index c7f89dea..d27c4a3c 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -50,10 +50,7 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, * \param[in] args variable argument list */ #define LOGPC(ss, level, fmt, args...) \ - do { \ - if (log_check_level(ss, level)) \ - logp2(ss, level, __FILE__, __LINE__, 1, fmt, ##args); \ - } while(0) + LOGPSRCC(ss, level, NULL, 0, 1, fmt, ##args) /*! Log through the Osmocom logging framework with explicit source. * If caller_file is passed as NULL, __FILE__ and __LINE__ are used @@ -85,6 +82,7 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, */ #define LOGPSRCC(ss, level, caller_file, caller_line, cont, fmt, args...) \ do { \ + TRACEPEVTSRC(ss, level, caller_file, caller_line, __func__, fmt, ##args); \ if (log_check_level(ss, level)) {\ if (caller_file) \ logp2(ss, level, caller_file, caller_line, cont, fmt, ##args); \ @@ -93,6 +91,33 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, }\ } while(0) +#define TRACEOP_ENTFUN "ENTER" +#define TRACEOP_EXTFUN "EXIT" +#define TRACEOP_ATTR "ATTR" +#define TRACEOP_EVT "EVT" + +#define TRACEP(ss, oper, fmt, args...) \ + TRACEPSRC(ss, oper, NULL, 0, (const char *)NULL, fmt, ##args) +#define TRACEPSRC(ss, oper, caller_file, caller_line, caller_func, fmt, args...) \ + do { \ + if (log_check_level(DLTRACE, LOGL_DEBUG)) {\ + if (caller_file) \ + logp2(DLTRACE, LOGL_DEBUG, caller_file, caller_line, 0, "[" oper " func=%s ss=%02x]%s" fmt, caller_func, ss, fmt[0]?" ":"", ##args); \ + else \ + logp2(DLTRACE, LOGL_DEBUG, __FILE__, __LINE__, 0, "[" oper " func=%s ss=%02x]%s" fmt, __func__, ss, fmt[0]?" ":"", ##args); \ + }\ + } while(0) + +#define TRACEPENTFUN(ss, fmt, args...) \ + TRACEP(ss, TRACEOP_ENTFUN, fmt, ##args) +#define TRACEPEXTFUN(ss, fmt, args...) \ + TRACEP(ss, TRACEOP_EXTFUN, fmt, ##args) +#define TRACEPATTR(ss, fmt, args...) \ + TRACEP(ss, TRACEOP_ATTR, fmt, ##args) +#define TRACEPEVTSRC(ss, level, caller_file, caller_line, caller_func, fmt, args...) \ + TRACEPSRC(ss, TRACEOP_EVT, caller_file, caller_line, caller_func, "level=%02x " fmt, level, ##args) + + /*! different log levels */ #define LOGL_DEBUG 1 /*!< debugging information */ #define LOGL_INFO 3 /*!< general information */ @@ -122,7 +147,8 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, #define DLRSPRO -19 /*!< Osmocom Remote SIM Protocol */ #define DLNS -20 /*!< Osmocom NS layer */ #define DLBSSGP -21 /*!< Osmocom BSSGP layer */ -#define OSMO_NUM_DLIB 21 /*!< Number of logging sub-systems in libraries */ +#define DLTRACE -22 /*!< Osmocom Tracing messages (intended for GSMTAP logging) */ +#define OSMO_NUM_DLIB 22 /*!< Number of logging sub-systems in libraries */ /* Colors that can be used in log_info_cat.color */ #define OSMO_LOGCOLOR_NORMAL NULL diff --git a/include/osmocom/core/tdef.h b/include/osmocom/core/tdef.h index 627ba3f9..a589d436 100644 --- a/include/osmocom/core/tdef.h +++ b/include/osmocom/core/tdef.h @@ -159,11 +159,11 @@ const struct osmo_tdef_state_timeout *osmo_tdef_get_state_timeout(uint32_t state */ #define osmo_tdef_fsm_inst_state_chg(fi, state, timeouts_array, tdefs, default_timeout) \ _osmo_tdef_fsm_inst_state_chg(fi, state, timeouts_array, tdefs, default_timeout, \ - __FILE__, __LINE__) + __FILE__, __LINE__, __func__) int _osmo_tdef_fsm_inst_state_chg(struct osmo_fsm_inst *fi, uint32_t state, const struct osmo_tdef_state_timeout *timeouts_array, const struct osmo_tdef *tdefs, unsigned long default_timeout, - const char *file, int line); + const char *file, int line, const char *func); /*! Manage timer definitions in named groups. * This should be defined as an array with the final element kept fully zero-initialized, diff --git a/src/fsm.c b/src/fsm.c index f1dbb412..ebb9f973 100644 --- a/src/fsm.c +++ b/src/fsm.c @@ -319,14 +319,17 @@ static void fsm_tmr_cb(void *data) struct osmo_fsm *fsm = fi->fsm; int32_t T = fi->T; + TRACEPFSMENT(fi, "timer=" OSMO_T_FMT, OSMO_T_FMT_ARGS(fi->T)); LOGPFSM(fi, "Timeout of " OSMO_T_FMT "\n", OSMO_T_FMT_ARGS(fi->T)); if (fsm->timer_cb) { int rc = fsm->timer_cb(fi); - if (rc != 1) + if (rc != 1) { /* We don't actually know whether fi exists anymore. * Make sure to not access it and return right away. */ + TRACEPFSMEXT(fi, ""); return; + } /* The timer_cb told us to terminate, so we can safely assume * that fi still exists. */ LOGPFSM(fi, "timer_cb requested termination\n"); @@ -335,6 +338,7 @@ static void fsm_tmr_cb(void *data) /* if timer_cb returns 1 or there is no timer_cb */ osmo_fsm_inst_term(fi, OSMO_FSM_TERM_TIMEOUT, &T); + TRACEPFSMEXT(fi, ""); } /*! Change id of the FSM instance @@ -453,6 +457,7 @@ struct osmo_fsm_inst *osmo_fsm_inst_alloc(struct osmo_fsm *fsm, void *ctx, void fsm_free_or_steal(fi); return NULL; } + TRACEPFSMENT(fi, "fsm_alloc=1 fsm_parent=%p", ctx); INIT_LLIST_HEAD(&fi->proc.children); INIT_LLIST_HEAD(&fi->proc.child); @@ -460,6 +465,7 @@ struct osmo_fsm_inst *osmo_fsm_inst_alloc(struct osmo_fsm *fsm, void *ctx, void LOGPFSM(fi, "Allocated\n"); + TRACEPFSMEXT(fi, "status=ok"); return fi; } @@ -479,19 +485,20 @@ struct osmo_fsm_inst *osmo_fsm_inst_alloc_child(struct osmo_fsm *fsm, uint32_t parent_term_event) { struct osmo_fsm_inst *fi; + TRACEPFSMENT(parent, ""); fi = osmo_fsm_inst_alloc(fsm, parent, NULL, parent->log_level, parent->id); if (!fi) { /* indicate immediate termination to caller */ osmo_fsm_inst_dispatch(parent, parent_term_event, NULL); + TRACEPFSMEXT(fi, "status=error"); return NULL; } - LOGPFSM(fi, "is child of %s\n", osmo_fsm_inst_name(parent)); osmo_fsm_inst_change_parent(fi, parent, parent_term_event); - + TRACEPFSMEXT(fi, "status=ok"); return fi; } @@ -540,6 +547,9 @@ void osmo_fsm_inst_change_parent(struct osmo_fsm_inst *fi, */ void osmo_fsm_inst_free(struct osmo_fsm_inst *fi) { + uint32_t ss = fi->fsm->log_subsys; + TRACEPFSMENT(fi, "fsm_free=1"); + osmo_timer_del(&fi->timer); llist_del(&fi->list); @@ -554,6 +564,7 @@ void osmo_fsm_inst_free(struct osmo_fsm_inst *fi) LOGPFSM(fi, "Deferring deallocation\n"); /* Don't free anything yet. Exit. */ + TRACEPFSMEXT(fi, "status=ok"); return; } @@ -574,6 +585,8 @@ void osmo_fsm_inst_free(struct osmo_fsm_inst *fi) fsm_free_or_steal(fi); } fsm_term_safely.root_fi = NULL; + + TRACEP(ss, TRACEOP_EXTFUN, "status=ok"); } /*! get human-readable name of FSM event @@ -623,17 +636,20 @@ const char *osmo_fsm_state_name(struct osmo_fsm *fsm, uint32_t state) static int state_chg(struct osmo_fsm_inst *fi, uint32_t new_state, bool keep_timer, unsigned long timeout_ms, int T, - const char *file, int line) + const char *file, int line, const char *func) { struct osmo_fsm *fsm = fi->fsm; uint32_t old_state = fi->state; const struct osmo_fsm_state *st = &fsm->states[fi->state]; struct timeval remaining; + TRACEPFSMENTSRC(fi, file, line, func, "new_state=%s T=%u tout_ms=%lu", osmo_fsm_state_name(fsm, new_state), T, timeout_ms); + if (fi->proc.terminating) { LOGPFSMSRC(fi, file, line, "FSM instance already terminating, not changing state to %s\n", osmo_fsm_state_name(fsm, new_state)); + TRACEPFSMEXTSRC(fi, file, line, func, "status=error"); return -EINVAL; } @@ -642,6 +658,7 @@ static int state_chg(struct osmo_fsm_inst *fi, uint32_t new_state, LOGPFSMLSRC(fi, LOGL_ERROR, file, line, "transition to state %s not permitted!\n", osmo_fsm_state_name(fsm, new_state)); + TRACEPFSMEXTSRC(fi, file, line, func, "status=error Invalid transition"); return -EPERM; } @@ -698,6 +715,7 @@ static int state_chg(struct osmo_fsm_inst *fi, uint32_t new_state, if (st->onenter) st->onenter(fi, old_state); + TRACEPFSMEXTSRC(fi, file, line, func, "status=ok"); return 0; } @@ -743,15 +761,15 @@ static int state_chg(struct osmo_fsm_inst *fi, uint32_t new_state, */ int _osmo_fsm_inst_state_chg(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_secs, int T, - const char *file, int line) + const char *file, int line, const char *func) { - return state_chg(fi, new_state, false, timeout_secs*1000, T, file, line); + return state_chg(fi, new_state, false, timeout_secs*1000, T, file, line, func); } int _osmo_fsm_inst_state_chg_ms(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_ms, int T, - const char *file, int line) + const char *file, int line, const char *func) { - return state_chg(fi, new_state, false, timeout_ms, T, file, line); + return state_chg(fi, new_state, false, timeout_ms, T, file, line, func); } /*! perform a state change while keeping the current timer running. @@ -774,9 +792,9 @@ int _osmo_fsm_inst_state_chg_ms(struct osmo_fsm_inst *fi, uint32_t new_state, * \returns 0 on success; negative on error */ int _osmo_fsm_inst_state_chg_keep_timer(struct osmo_fsm_inst *fi, uint32_t new_state, - const char *file, int line) + const char *file, int line, const char *func) { - return state_chg(fi, new_state, true, 0, 0, file, line); + return state_chg(fi, new_state, true, 0, 0, file, line, func); } /*! perform a state change while keeping the current timer if running, or starting a timer otherwise. @@ -803,15 +821,15 @@ int _osmo_fsm_inst_state_chg_keep_timer(struct osmo_fsm_inst *fi, uint32_t new_s */ int _osmo_fsm_inst_state_chg_keep_or_start_timer(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_secs, int T, - const char *file, int line) + const char *file, int line, const char* func) { - return state_chg(fi, new_state, true, timeout_secs*1000, T, file, line); + return state_chg(fi, new_state, true, timeout_secs*1000, T, file, line, func); } int _osmo_fsm_inst_state_chg_keep_or_start_timer_ms(struct osmo_fsm_inst *fi, uint32_t new_state, unsigned long timeout_ms, int T, - const char *file, int line) + const char *file, int line, const char *func) { - return state_chg(fi, new_state, true, timeout_ms, T, file, line); + return state_chg(fi, new_state, true, timeout_ms, T, file, line, func); } @@ -833,7 +851,7 @@ int _osmo_fsm_inst_state_chg_keep_or_start_timer_ms(struct osmo_fsm_inst *fi, ui * \returns 0 in case of success; negative on error */ int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data, - const char *file, int line) + const char *file, int line, const char *func) { struct osmo_fsm *fsm; const struct osmo_fsm_state *fs; @@ -847,11 +865,13 @@ int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data } fsm = fi->fsm; + TRACEPFSMENTSRC(fi, file, line, func, "event=%s", osmo_fsm_event_name(fsm, event)); if (fi->proc.terminating) { LOGPFSMSRC(fi, file, line, "FSM instance already terminating, not dispatching event %s\n", osmo_fsm_event_name(fsm, event)); + TRACEPFSMEXTSRC(fi, file, line, func, "status=error"); return -EINVAL; } @@ -863,6 +883,7 @@ int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data if (((1 << event) & fsm->allstate_event_mask) && fsm->allstate_action) { fsm->allstate_action(fi, event, data); + TRACEPFSMEXTSRC(fi, file, line, func, "status=ok"); return 0; } @@ -870,12 +891,14 @@ int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data LOGPFSMLSRC(fi, LOGL_ERROR, file, line, "Event %s not permitted\n", osmo_fsm_event_name(fsm, event)); + TRACEPFSMEXTSRC(fi, file, line, func, "status=error"); return -1; } if (fs->action) fs->action(fi, event, data); + TRACEPFSMEXTSRC(fi, file, line, func, "status=ok"); return 0; } @@ -897,7 +920,7 @@ int _osmo_fsm_inst_dispatch(struct osmo_fsm_inst *fi, uint32_t event, void *data */ void _osmo_fsm_inst_term(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause, void *data, - const char *file, int line) + const char *file, int line, const char *func) { struct osmo_fsm_inst *parent; uint32_t parent_term_event = fi->proc.parent_term_event; @@ -934,7 +957,7 @@ void _osmo_fsm_inst_term(struct osmo_fsm_inst *fi, fi->fsm->pre_term(fi, cause); _osmo_fsm_inst_term_children(fi, OSMO_FSM_TERM_PARENT, NULL, - file, line); + file, line, func); /* delete ourselves from the parent */ parent = fi->proc.parent; @@ -962,7 +985,7 @@ void _osmo_fsm_inst_term(struct osmo_fsm_inst *fi, /* indicate our termination to the parent */ if (parent && cause != OSMO_FSM_TERM_PARENT) _osmo_fsm_inst_dispatch(parent, parent_term_event, data, - file, line); + file, line, func); /* Newer, safe deallocation: free only after the parent_term_event was dispatched, to catch all termination * cascades, and free all FSM instances at once. (If fsm_term_safely is enabled, depth will *always* be > 0 @@ -988,7 +1011,7 @@ void _osmo_fsm_inst_term(struct osmo_fsm_inst *fi, void _osmo_fsm_inst_term_children(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause, void *data, - const char *file, int line) + const char *file, int line, const char *func) { struct osmo_fsm_inst *first_child, *last_seen_first_child; @@ -1012,7 +1035,7 @@ void _osmo_fsm_inst_term_children(struct osmo_fsm_inst *fi, /* terminate child */ _osmo_fsm_inst_term(first_child, cause, data, - file, line); + file, line, func); } } @@ -1028,11 +1051,11 @@ void _osmo_fsm_inst_term_children(struct osmo_fsm_inst *fi, */ void _osmo_fsm_inst_broadcast_children(struct osmo_fsm_inst *fi, uint32_t event, void *data, - const char *file, int line) + const char *file, int line, const char *func) { struct osmo_fsm_inst *child, *tmp; llist_for_each_entry_safe(child, tmp, &fi->proc.children, proc.child) { - _osmo_fsm_inst_dispatch(child, event, data, file, line); + _osmo_fsm_inst_dispatch(child, event, data, file, line, func); } } diff --git a/src/gb/gprs_ns2_vc_fsm.c b/src/gb/gprs_ns2_vc_fsm.c index 66ee4505..e41e0dcd 100644 --- a/src/gb/gprs_ns2_vc_fsm.c +++ b/src/gb/gprs_ns2_vc_fsm.c @@ -46,6 +46,7 @@ #include #include "gprs_ns2_internal.h" +#include "osmocom/core/logging.h" #define S(x) (1 << (x)) @@ -491,6 +492,7 @@ static int ns2_vc_fsm_timer_cb(struct osmo_fsm_inst *fi) struct gprs_ns2_inst *nsi = ns_inst_from_fi(fi); struct gprs_ns2_vc_priv *priv = fi->priv; + TRACEPFSMENT(fi, "nsei=%05u", priv->nsvc->nse->nsei); switch (fi->state) { case GPRS_NS2_ST_RESET: if (priv->initiate_reset) { @@ -536,6 +538,7 @@ static int ns2_vc_fsm_timer_cb(struct osmo_fsm_inst *fi) } break; } + TRACEPFSMEXT(fi, "status=ok"); return 0; } @@ -548,8 +551,11 @@ static void ns2_recv_unitdata(struct osmo_fsm_inst *fi, struct osmo_gprs_ns2_prim nsp = {}; uint16_t bvci; + TRACEPFSMENT(fi, "nsei=%05u", priv->nsvc->nse->nsei); + if (msgb_l2len(msg) < sizeof(*nsh) + 3) { msgb_free(msg); + TRACEPFSMEXT(fi, "status=error Message too small"); return; } @@ -564,6 +570,7 @@ static void ns2_recv_unitdata(struct osmo_fsm_inst *fi, nsp.bvci = bvci; nsp.nsei = priv->nsvc->nse->nsei; + TRACEPATTR(DNS, "bvci=%05u", bvci); /* 10.3.9 NS SDU Control Bits */ if (nsh->data[0] & 0x1) nsp.u.unitdata.change = GPRS_NS2_ENDPOINT_REQUEST_CHANGE; @@ -571,6 +578,7 @@ static void ns2_recv_unitdata(struct osmo_fsm_inst *fi, osmo_prim_init(&nsp.oph, SAP_NS, GPRS_NS2_PRIM_UNIT_DATA, PRIM_OP_INDICATION, msg); nsi->cb(&nsp.oph, nsi->cb_data); + TRACEPFSMEXT(fi, "status=ok"); } static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi, @@ -581,6 +589,8 @@ static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi, struct gprs_ns2_inst *nsi = ns_inst_from_fi(fi); struct msgb *msg = data; + TRACEPFSMENT(fi, "nsei=%05u", priv->nsvc->nse->nsei); + switch (event) { case GPRS_NS2_EV_RX_RESET: if (priv->nsvc->mode != GPRS_NS2_VC_MODE_BLOCKRESET) @@ -622,6 +632,8 @@ static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi, /* 7.2.1: the BLOCKED_ACK might be lost */ if (priv->accept_unitdata) { ns2_recv_unitdata(fi, msg); + TRACEPFSMEXT(fi, "status=ok"); + return; } @@ -633,6 +645,7 @@ static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi, case GPRS_NS2_ST_RECOVERING: case GPRS_NS2_ST_UNBLOCKED: ns2_recv_unitdata(fi, msg); + TRACEPFSMEXT(fi, "status=ok"); return; } @@ -642,6 +655,7 @@ static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi, if (fi->state != GPRS_NS2_ST_UNCONFIGURED) { /* Force the NSVC back to its initial state */ osmo_fsm_inst_state_chg(fi, GPRS_NS2_ST_UNCONFIGURED, 0, 0); + TRACEPFSMEXT(fi, "status=ok"); return; } break; @@ -660,6 +674,7 @@ static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi, osmo_fsm_inst_state_chg(fi, GPRS_NS2_ST_BLOCKED, nsi->timeout[NS_TOUT_TNS_BLOCK], 0); break; } + TRACEPFSMEXT(fi, ""); } static void ns2_vc_fsm_clean(struct osmo_fsm_inst *fi, @@ -708,6 +723,8 @@ struct osmo_fsm_inst *ns2_vc_fsm_alloc(struct gprs_ns2_vc *nsvc, if (!fi) return fi; + TRACEPFSMENT(fi, "nsei=%05u", nsvc->nse->nsei); + nsvc->fi = fi; priv = fi->priv = talloc_zero(fi, struct gprs_ns2_vc_priv); priv->nsvc = nsvc; @@ -715,6 +732,8 @@ struct osmo_fsm_inst *ns2_vc_fsm_alloc(struct gprs_ns2_vc *nsvc, osmo_timer_setup(&priv->alive.timer, alive_timeout_handler, fi); + TRACEPFSMEXT(fi, "status=ok"); + return fi; } @@ -766,6 +785,8 @@ int ns2_vc_rx(struct gprs_ns2_vc *nsvc, struct msgb *msg, struct tlv_parsed *tp) uint8_t cause; uint16_t nsei, nsvci; + TRACEPFSMENT(fi, "nsei=%05u span.kind=server", nsvc->nse->nsei); + /* TODO: 7.2: on UNBLOCK/BLOCK: check if NS-VCI is correct, * if not answer STATUS with "NS-VC unknown" */ /* TODO: handle BLOCK/UNBLOCK/ALIVE with different VCI */ @@ -831,16 +852,20 @@ int ns2_vc_rx(struct gprs_ns2_vc *nsvc, struct msgb *msg, struct tlv_parsed *tp) case NS_PDUT_UNITDATA: /* UNITDATA have to free msg because it might send the msg layer upwards */ osmo_fsm_inst_dispatch(fi, GPRS_NS2_EV_RX_UNITDATA, msg); + TRACEPFSMEXT(fi, "status=ok"); return 0; default: LOGPFSML(fi, LOGL_ERROR, "NSEI=%u Rx unknown NS PDU type %s\n", nsvc->nse->nsei, get_value_string(gprs_ns_pdu_strings, nsh->pdu_type)); + TRACEPFSMEXT(fi, "status=error NSEI unknown"); return -EINVAL; } out: msgb_free(msg); + TRACEPFSMEXT(fi, "status=ok"); + return rc; } diff --git a/src/logging.c b/src/logging.c index a40008e9..6da36758 100644 --- a/src/logging.c +++ b/src/logging.c @@ -274,6 +274,12 @@ static const struct log_info_cat internal_cat[OSMO_NUM_DLIB] = { .enabled = 1, .loglevel = LOGL_NOTICE, .color = "\033[38;5;59m", }, + [INT2IDX(DLTRACE)] = { + .name = "DLTRACE", + .description = "Machine-parsable trace messages (for use with GSMTAP logging)", + .enabled = 0, .loglevel = LOGL_NOTICE, + .color = "", + }, }; void assert_loginfo(const char *src) diff --git a/src/tdef.c b/src/tdef.c index 897a92fd..3cd96966 100644 --- a/src/tdef.c +++ b/src/tdef.c @@ -332,29 +332,29 @@ const struct osmo_tdef_state_timeout *osmo_tdef_get_state_timeout(uint32_t state int _osmo_tdef_fsm_inst_state_chg(struct osmo_fsm_inst *fi, uint32_t state, const struct osmo_tdef_state_timeout *timeouts_array, const struct osmo_tdef *tdefs, unsigned long default_timeout, - const char *file, int line) + const char *file, int line, const char *func) { const struct osmo_tdef_state_timeout *t = osmo_tdef_get_state_timeout(state, timeouts_array); unsigned long val = 0; /* No timeout defined for this state? */ if (!t) - return _osmo_fsm_inst_state_chg(fi, state, 0, 0, file, line); + return _osmo_fsm_inst_state_chg(fi, state, 0, 0, file, line, func); if (t->T) val = osmo_tdef_get(tdefs, t->T, OSMO_TDEF_S, default_timeout); if (t->keep_timer) { if (t->T) - return _osmo_fsm_inst_state_chg_keep_or_start_timer(fi, state, val, t->T, file, line); + return _osmo_fsm_inst_state_chg_keep_or_start_timer(fi, state, val, t->T, file, line, func); else - return _osmo_fsm_inst_state_chg_keep_timer(fi, state, file, line); + return _osmo_fsm_inst_state_chg_keep_timer(fi, state, file, line, func); } /* val is always initialized here, because if t->keep_timer is false, t->T must be != 0. * Otherwise osmo_tdef_get_state_timeout() would have returned NULL. */ OSMO_ASSERT(t->T); - return _osmo_fsm_inst_state_chg(fi, state, val, t->T, file, line); + return _osmo_fsm_inst_state_chg(fi, state, val, t->T, file, line, func); } const struct value_string osmo_tdef_unit_names[] = { -- cgit v1.2.3