WIP: Tracingdaniel/tracing

Change-Id: I78945ab2bde7c93e9461dc446809f7cbd6493100

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 <osmocom/gprs/protocol/gsm_08_16.h>
 
 #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[] = {