This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
daniel gerrit-no-reply at lists.osmocom.orgdaniel has uploaded this change for review. ( https://gerrit.osmocom.org/c/libosmocore/+/22446 )
Change subject: WIP: Tracing
......................................................................
WIP: Tracing
Change-Id: I78945ab2bde7c93e9461dc446809f7cbd6493100
---
M include/osmocom/core/fsm.h
M include/osmocom/core/logging.h
M include/osmocom/core/tdef.h
M src/fsm.c
M src/gb/gprs_ns2_vc_fsm.c
M src/logging.c
M src/tdef.c
7 files changed, 160 insertions(+), 52 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/46/22446/1
diff --git a/include/osmocom/core/fsm.h b/include/osmocom/core/fsm.h
index 77ebe7c..9ff5873 100644
--- a/include/osmocom/core/fsm.h
+++ b/include/osmocom/core/fsm.h
@@ -202,6 +202,34 @@
#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 @@
*/
#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 @@
*/
#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 @@
*/
#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 @@
* 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 @@
* 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 @@
* 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 @@
* 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 c7f89de..d27c4a3 100644
--- a/include/osmocom/core/logging.h
+++ b/include/osmocom/core/logging.h
@@ -50,10 +50,7 @@
* \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 @@
*/
#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 @@
}\
} 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 @@
#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 627ba3f..a589d43 100644
--- a/include/osmocom/core/tdef.h
+++ b/include/osmocom/core/tdef.h
@@ -159,11 +159,11 @@
*/
#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 f1dbb41..ebb9f97 100644
--- a/src/fsm.c
+++ b/src/fsm.c
@@ -319,14 +319,17 @@
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 @@
/* 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 @@
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 @@
LOGPFSM(fi, "Allocated\n");
+ TRACEPFSMEXT(fi, "status=ok");
return fi;
}
@@ -479,19 +485,20 @@
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_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 @@
LOGPFSM(fi, "Deferring deallocation\n");
/* Don't free anything yet. Exit. */
+ TRACEPFSMEXT(fi, "status=ok");
return;
}
@@ -574,6 +585,8 @@
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 @@
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 @@
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 @@
if (st->onenter)
st->onenter(fi, old_state);
+ TRACEPFSMEXTSRC(fi, file, line, func, "status=ok");
return 0;
}
@@ -743,15 +761,15 @@
*/
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 @@
* \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_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 @@
* \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 @@
}
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 @@
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 @@
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 @@
*/
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 @@
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 @@
/* 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_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 @@
/* terminate child */
_osmo_fsm_inst_term(first_child, cause, data,
- file, line);
+ file, line, func);
}
}
@@ -1028,11 +1051,11 @@
*/
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 7ee29a1..764445a 100644
--- a/src/gb/gprs_ns2_vc_fsm.c
+++ b/src/gb/gprs_ns2_vc_fsm.c
@@ -46,6 +46,7 @@
#include <osmocom/gprs/protocol/gsm_08_16.h>
#include "gprs_ns2_internal.h"
+#include "osmocom/core/logging.h"
#define S(x) (1 << (x))
@@ -477,6 +478,7 @@
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) {
@@ -521,6 +523,7 @@
}
break;
}
+ TRACEPFSMEXT(fi, "status=ok");
return 0;
}
@@ -533,8 +536,11 @@
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;
}
@@ -549,6 +555,7 @@
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 = NS_ENDPOINT_REQUEST_CHANGE;
@@ -556,6 +563,7 @@
osmo_prim_init(&nsp.oph, SAP_NS, PRIM_NS_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,
@@ -566,6 +574,8 @@
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 != NS2_VC_MODE_BLOCKRESET)
@@ -607,6 +617,8 @@
/* 7.2.1: the BLOCKED_ACK might be lost */
if (priv->accept_unitdata) {
ns2_recv_unitdata(fi, msg);
+ TRACEPFSMEXT(fi, "status=ok");
+
return;
}
@@ -618,6 +630,7 @@
case GPRS_NS2_ST_ALIVE:
case GPRS_NS2_ST_UNBLOCKED:
ns2_recv_unitdata(fi, msg);
+ TRACEPFSMEXT(fi, "status=ok");
return;
}
@@ -628,6 +641,7 @@
/* Force the NSVC back to its initial state */
osmo_fsm_inst_state_chg(fi, GPRS_NS2_ST_UNCONFIGURED, 0, 0);
osmo_fsm_inst_dispatch(fi, GPRS_NS2_EV_REQ_START, NULL);
+ TRACEPFSMEXT(fi, "status=ok");
return;
}
break;
@@ -646,6 +660,7 @@
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,
@@ -694,6 +709,8 @@
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;
@@ -701,6 +718,8 @@
osmo_timer_setup(&priv->alive.timer, alive_timeout_handler, fi);
+ TRACEPFSMEXT(fi, "status=ok");
+
return fi;
}
@@ -752,6 +771,8 @@
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 */
@@ -817,16 +838,20 @@
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 60dba64..3462112 100644
--- a/src/logging.c
+++ b/src/logging.c
@@ -263,6 +263,12 @@
.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 897a92f..3cd9696 100644
--- a/src/tdef.c
+++ b/src/tdef.c
@@ -332,29 +332,29 @@
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[] = {
--
To view, visit https://gerrit.osmocom.org/c/libosmocore/+/22446
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings
Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-Change-Id: I78945ab2bde7c93e9461dc446809f7cbd6493100
Gerrit-Change-Number: 22446
Gerrit-PatchSet: 1
Gerrit-Owner: daniel <dwillmann at sysmocom.de>
Gerrit-MessageType: newchange
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20210126/40f60de9/attachment.htm>