Change in libosmocore[master]: log: fsm: log timeout on state change

[Neels Hofmeyr]

Neels Hofmeyr has uploaded this change for review. ( https://gerrit.osmocom.org/12987


Change subject: log: fsm: log timeout on state change
......................................................................

log: fsm: log timeout on state change

To not break the osmo-msc test expectations, this needs to be merged at the
same time as osmo-msc I621fa6ce2485149750e2062abca63d66c417998b.

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(-)



  git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/87/12987/1

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 = &fsm->states[fi->state];
+	struct timeval remaining;
 
 	/* Limit to 0x7fffffff 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(&fi->timer, NULL, &remaining) == 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 = &fsm->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);
+
 	log_init(&log_info, NULL);
 	stderr_target = log_target_create_stderr();
 	log_add_target(stderr_target);
diff --git a/tests/fsm/fsm_test.err b/tests/fsm/fsm_test.err
index bf474ab..13cbacd 100644
--- a/tests/fsm/fsm_test.err
+++ b/tests/fsm/fsm_test.err
@@ -3,9 +3,9 @@
 Test_FSM(my_id){NULL}: Received Event EV_B
 Test_FSM(my_id){NULL}: Event EV_B not permitted
 Test_FSM(my_id){NULL}: Received Event EV_A
-Test_FSM(my_id){NULL}: state_chg to ONE
+Test_FSM(my_id){NULL}: State change to ONE (no timeout)
 Test_FSM(my_id){ONE}: Received Event EV_B
-Test_FSM(my_id){ONE}: state_chg to TWO
+Test_FSM(my_id){ONE}: State change to TWO (T2342, 1s)
 Test_FSM(my_id){TWO}: Timeout of T2342
 Timer
 Test_FSM(my_id){TWO}: Deallocated
@@ -83,16 +83,16 @@
 
 --- test_state_chg_keep_timer()
 Test_FSM{NULL}: Allocated
-Test_FSM{NULL}: state_chg to ONE
-Test_FSM{ONE}: state_chg to TWO
+Test_FSM{NULL}: State change to ONE (no timeout)
+Test_FSM{ONE}: State change to TWO (no timeout)
 Test_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
 Test_FSM{TWO}: Freeing instance
 Test_FSM{TWO}: Deallocated
 Total time passed: 0.000000 s
 Test_FSM{NULL}: Allocated
-Test_FSM{NULL}: state_chg to ONE
+Test_FSM{NULL}: State change to ONE (T10, 10s)
 Total time passed: 2.000342 s
-Test_FSM{ONE}: state_chg to TWO
+Test_FSM{ONE}: State change to TWO (keeping T10, 7.999s remaining)
 Total time passed: 2.000342 s
 Total time passed: 9.999999 s
 Total time passed: 10.000000 s
@@ -104,14 +104,14 @@
 
 --- test_state_chg_T()
 Test_FSM{NULL}: Allocated
-Test_FSM{NULL}: state_chg to ONE
-Test_FSM{ONE}: state_chg to TWO
+Test_FSM{NULL}: State change to ONE (T42, 23s)
+Test_FSM{ONE}: State change to TWO (no timeout)
 Test_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
 Test_FSM{TWO}: Freeing instance
 Test_FSM{TWO}: Deallocated
 Test_FSM{NULL}: Allocated
-Test_FSM{NULL}: state_chg to ONE
-Test_FSM{ONE}: state_chg to TWO
+Test_FSM{NULL}: State change to ONE (T42, 23s)
+Test_FSM{ONE}: State change to TWO (no timeout)
 Test_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
 Test_FSM{TWO}: Freeing instance
 Test_FSM{TWO}: Deallocated

-- 
To view, visit https://gerrit.osmocom.org/12987
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings

Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I089b81021a1a4ada1205261470da032b82d57872
Gerrit-Change-Number: 12987
Gerrit-PatchSet: 1
Gerrit-Owner: Neels Hofmeyr <nhofmeyr at sysmocom.de>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20190221/43873d25/attachment.htm>