Neels Hofmeyr has submitted this change and it was merged. (
https://gerrit.osmocom.org/12987 )
Change subject: log: fsm: allow logging the timeout on state change
..
log: fsm: allow logging the timeout on state change
Add a flag that adds timeout info to osmo_fsm_inst state change logging.
To not affect unit testing, make this an opt-in feature that is disabled by
default -- mostly because osmo_fsm_inst_state_chg_keep_timer() will produce
non-deterministic logging depending on timing (logs remaining time).
Unit tests that don't verify log output and those that use fake time may also
enable this feature. Do so in fsm_test.c.
The idea is that in due course we will add osmo_fsm_log_timeouts(true) calls to
all of our production applications' main() initialization.
Change-Id: I089b81021a1a4ada1205261470da032b82d57872
---
M include/osmocom/core/fsm.h
M src/fsm.c
M tests/fsm/fsm_test.c
M tests/fsm/fsm_test.err
4 files changed, 53 insertions(+), 12 deletions(-)
Approvals:
Neels Hofmeyr: Looks good to me, approved
Jenkins Builder: Verified
diff --git a/include/osmocom/core/fsm.h b/include/osmocom/core/fsm.h
index df7e348..ae1c857 100644
--- a/include/osmocom/core/fsm.h
+++ b/include/osmocom/core/fsm.h
@@ -118,6 +118,7 @@
};
void osmo_fsm_log_addr(bool log_addr);
+void osmo_fsm_log_timeouts(bool log_timeouts);
/*! Log using FSM instance's context, on explicit logging subsystem and level.
* \param fi An osmo_fsm_inst.
diff --git a/src/fsm.c b/src/fsm.c
index 6e15ab7..eb457a1 100644
--- a/src/fsm.c
+++ b/src/fsm.c
@@ -90,6 +90,7 @@
LLIST_HEAD(osmo_g_fsms);
static bool fsm_log_addr = true;
+static bool fsm_log_timeouts = false;
/*! specify if FSM instance addresses should be logged or not
*
@@ -104,6 +105,26 @@
fsm_log_addr = log_addr;
}
+/*! Enable or disable logging of timeout values for FSM instance state changes.
+ *
+ * By default, state changes are logged by state name only, omitting the
timeout. When passing true, each state change
+ * will also log the T number and the chosen timeout in seconds.
osmo_fsm_inst_state_chg_keep_timer() will log remaining
+ * timeout in millisecond precision.
+ *
+ * The default for this is false to reflect legacy behavior. Since various C
tests that verify logging output already
+ * existed prior to this option, keeping timeout logging off makes sure that
they continue to pass. Particularly,
+ * osmo_fsm_inst_state_chg_keep_timer() may cause non-deterministic logging of
remaining timeout values.
+ *
+ * For any program that does not explicitly require deterministic logging
output, i.e. anything besides regression tests
+ * involving FSM instances, it is recommended to call
osmo_fsm_log_timeouts(true).
+ *
+ * \param[in] log_timeouts Pass true to log timeouts on state transitions,
false to omit timeouts.
+ */
+void osmo_fsm_log_timeouts(bool log_timeouts)
+{
+ fsm_log_timeouts = log_timeouts;
+}
+
struct osmo_fsm *osmo_fsm_find_by_name(const char *name)
{
struct osmo_fsm *fsm;
@@ -436,6 +457,7 @@
struct osmo_fsm *fsm = fi->fsm;
uint32_t old_state = fi->state;
const struct osmo_fsm_state *st = >states[fi->state];
+ struct timeval remaining;
/* Limit to 0x7fff seconds as explained by
* _osmo_fsm_inst_state_chg()'s API doc. */
@@ -458,8 +480,23 @@
if (st->onleave)
st->onleave(fi, new_state);
- LOGPFSMSRC(fi, file, line, "state_chg to %s\n",
- osmo_fsm_state_name(fsm, new_state));
+ if (fsm_log_timeouts) {
+ if (keep_timer && fi->timer.active &&
(osmo_timer_remaining(>timer, NULL, ) == 0))
+ LOGPFSMSRC(fi, file, line, "State change to %s (keeping
T%d, %ld.%03lds remaining)\n",
+ osmo_fsm_state_name(fsm, new_state),
+ fi->T, remaining.tv_sec, remaining.tv_usec /
1000);
+ else if (timeout_secs && !keep_timer)
+ LOGPFSMSRC(fi, file, line, "State change to %s (T%d,
%lus)\n",
+ osmo_fsm_state_name(fsm, new_state),
+ T, timeout_secs);
+ else
+ LOGPFSMSRC(fi, file, line, "State change to %s (no
timeout)\n",
+ osmo_fsm_state_name(fsm, new_state));
+ } else {
+ LOGPFSMSRC(fi, file, line, "state_chg to %s\n",
+ osmo_fsm_state_name(fsm, new_state));
+ }
+
fi->state = new_state;
st = >states[new_state];
diff --git a/tests/fsm/fsm_test.c b/tests/fsm/fsm_test.c
index 7aac8d3..f8ebdc7 100644
--- a/tests/fsm/fsm_test.c
+++ b/tests/fsm/fsm_test.c
@@ -406,6 +406,9 @@
osmo_fsm_log_addr(false);
+ /* Using fake time to get deterministic timeout logging */
+ osmo_fsm_log_timeouts(true);
+
