<p>Neels Hofmeyr has uploaded this change for <strong>review</strong>.</p><p><a href="https://gerrit.osmocom.org/12987">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;">log: fsm: log timeout on state change<br><br>To not break the osmo-msc test expectations, this needs to be merged at the<br>same time as osmo-msc I621fa6ce2485149750e2062abca63d66c417998b.<br><br>Change-Id: I089b81021a1a4ada1205261470da032b82d57872<br>---<br>M include/osmocom/core/fsm.h<br>M src/fsm.c<br>M tests/fsm/fsm_test.c<br>M tests/fsm/fsm_test.err<br>4 files changed, 53 insertions(+), 12 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;">git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/87/12987/1</pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/include/osmocom/core/fsm.h b/include/osmocom/core/fsm.h</span><br><span>index df7e348..ae1c857 100644</span><br><span>--- a/include/osmocom/core/fsm.h</span><br><span>+++ b/include/osmocom/core/fsm.h</span><br><span>@@ -118,6 +118,7 @@</span><br><span> };</span><br><span> </span><br><span> void osmo_fsm_log_addr(bool log_addr);</span><br><span style="color: hsl(120, 100%, 40%);">+void osmo_fsm_log_timeouts(bool log_timeouts);</span><br><span> </span><br><span> /*! Log using FSM instance's context, on explicit logging subsystem and level.</span><br><span> * \param fi An osmo_fsm_inst.</span><br><span>diff --git a/src/fsm.c b/src/fsm.c</span><br><span>index 6e15ab7..eb457a1 100644</span><br><span>--- a/src/fsm.c</span><br><span>+++ b/src/fsm.c</span><br><span>@@ -90,6 +90,7 @@</span><br><span> </span><br><span> LLIST_HEAD(osmo_g_fsms);</span><br><span> static bool fsm_log_addr = true;</span><br><span style="color: hsl(120, 100%, 40%);">+static bool fsm_log_timeouts = false;</span><br><span> </span><br><span> /*! specify if FSM instance addresses should be logged or not</span><br><span> *</span><br><span>@@ -104,6 +105,26 @@</span><br><span> fsm_log_addr = log_addr;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+/*! Enable or disable logging of timeout values for FSM instance state changes.</span><br><span style="color: hsl(120, 100%, 40%);">+ *</span><br><span style="color: hsl(120, 100%, 40%);">+ * By default, state changes are logged by state name only, omitting the timeout. When passing true, each state change</span><br><span style="color: hsl(120, 100%, 40%);">+ * will also log the T number and the chosen timeout in seconds. osmo_fsm_inst_state_chg_keep_timer() will log remaining</span><br><span style="color: hsl(120, 100%, 40%);">+ * timeout in millisecond precision.</span><br><span style="color: hsl(120, 100%, 40%);">+ *</span><br><span style="color: hsl(120, 100%, 40%);">+ * The default for this is false to reflect legacy behavior. Since various C tests that verify logging output already</span><br><span style="color: hsl(120, 100%, 40%);">+ * existed prior to this option, keeping timeout logging off makes sure that they continue to pass. Particularly,</span><br><span style="color: hsl(120, 100%, 40%);">+ * osmo_fsm_inst_state_chg_keep_timer() may cause non-deterministic logging of remaining timeout values.</span><br><span style="color: hsl(120, 100%, 40%);">+ *</span><br><span style="color: hsl(120, 100%, 40%);">+ * For any program that does not explicitly require deterministic logging output, i.e. anything besides regression tests</span><br><span style="color: hsl(120, 100%, 40%);">+ * involving FSM instances, it is recommended to call osmo_fsm_log_timeouts(true).</span><br><span style="color: hsl(120, 100%, 40%);">+ *</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] log_timeouts Pass true to log timeouts on state transitions, false to omit timeouts.</span><br><span style="color: hsl(120, 100%, 40%);">+ */</span><br><span style="color: hsl(120, 100%, 40%);">+void osmo_fsm_log_timeouts(bool log_timeouts)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ fsm_log_timeouts = log_timeouts;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> struct osmo_fsm *osmo_fsm_find_by_name(const char *name)</span><br><span> {</span><br><span> struct osmo_fsm *fsm;</span><br><span>@@ -436,6 +457,7 @@</span><br><span> struct osmo_fsm *fsm = fi->fsm;</span><br><span> uint32_t old_state = fi->state;</span><br><span> const struct osmo_fsm_state *st = &fsm->states[fi->state];</span><br><span style="color: hsl(120, 100%, 40%);">+ struct timeval remaining;</span><br><span> </span><br><span> /* Limit to 0x7fffffff seconds as explained by</span><br><span> * _osmo_fsm_inst_state_chg()'s API doc. */</span><br><span>@@ -458,8 +480,23 @@</span><br><span> if (st->onleave)</span><br><span> st->onleave(fi, new_state);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGPFSMSRC(fi, file, line, "state_chg to %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- osmo_fsm_state_name(fsm, new_state));</span><br><span style="color: hsl(120, 100%, 40%);">+ if (fsm_log_timeouts) {</span><br><span style="color: hsl(120, 100%, 40%);">+ if (keep_timer && fi->timer.active && (osmo_timer_remaining(&fi->timer, NULL, &remaining) == 0))</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPFSMSRC(fi, file, line, "State change to %s (keeping T%d, %ld.%03lds remaining)\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fsm_state_name(fsm, new_state),</span><br><span style="color: hsl(120, 100%, 40%);">+ fi->T, remaining.tv_sec, remaining.tv_usec / 1000);</span><br><span style="color: hsl(120, 100%, 40%);">+ else if (timeout_secs && !keep_timer)</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPFSMSRC(fi, file, line, "State change to %s (T%d, %lus)\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fsm_state_name(fsm, new_state),</span><br><span style="color: hsl(120, 100%, 40%);">+ T, timeout_secs);</span><br><span style="color: hsl(120, 100%, 40%);">+ else</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPFSMSRC(fi, file, line, "State change to %s (no timeout)\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fsm_state_name(fsm, new_state));</span><br><span style="color: hsl(120, 100%, 40%);">+ } else {</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPFSMSRC(fi, file, line, "state_chg to %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fsm_state_name(fsm, new_state));</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> fi->state = new_state;</span><br><span> st = &fsm->states[new_state];</span><br><span> </span><br><span>diff --git a/tests/fsm/fsm_test.c b/tests/fsm/fsm_test.c</span><br><span>index 7aac8d3..f8ebdc7 100644</span><br><span>--- a/tests/fsm/fsm_test.c</span><br><span>+++ b/tests/fsm/fsm_test.c</span><br><span>@@ -406,6 +406,9 @@</span><br><span> </span><br><span> osmo_fsm_log_addr(false);</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ /* Using fake time to get deterministic timeout logging */</span><br><span style="color: hsl(120, 100%, 40%);">+ osmo_fsm_log_timeouts(true);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> log_init(&log_info, NULL);</span><br><span> stderr_target = log_target_create_stderr();</span><br><span> log_add_target(stderr_target);</span><br><span>diff --git a/tests/fsm/fsm_test.err b/tests/fsm/fsm_test.err</span><br><span>index bf474ab..13cbacd 100644</span><br><span>--- a/tests/fsm/fsm_test.err</span><br><span>+++ b/tests/fsm/fsm_test.err</span><br><span>@@ -3,9 +3,9 @@</span><br><span> [0;mTest_FSM(my_id){NULL}: Received Event EV_B</span><br><span> [0;mTest_FSM(my_id){NULL}: Event EV_B not permitted</span><br><span> [0;mTest_FSM(my_id){NULL}: Received Event EV_A</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM(my_id){NULL}: state_chg to ONE</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM(my_id){NULL}: State change to ONE (no timeout)</span><br><span> [0;mTest_FSM(my_id){ONE}: Received Event EV_B</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM(my_id){ONE}: state_chg to TWO</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM(my_id){ONE}: State change to TWO (T2342, 1s)</span><br><span> [0;mTest_FSM(my_id){TWO}: Timeout of T2342</span><br><span> [0;mTimer</span><br><span> [0;mTest_FSM(my_id){TWO}: Deallocated</span><br><span>@@ -83,16 +83,16 @@</span><br><span> [0;m</span><br><span> --- test_state_chg_keep_timer()</span><br><span> Test_FSM{NULL}: Allocated</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{NULL}: state_chg to ONE</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{ONE}: state_chg to TWO</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{NULL}: State change to ONE (no timeout)</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{ONE}: State change to TWO (no timeout)</span><br><span> [0;mTest_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)</span><br><span> [0;mTest_FSM{TWO}: Freeing instance</span><br><span> [0;mTest_FSM{TWO}: Deallocated</span><br><span> [0;mTotal time passed: 0.000000 s</span><br><span> Test_FSM{NULL}: Allocated</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{NULL}: state_chg to ONE</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{NULL}: State change to ONE (T10, 10s)</span><br><span> [0;mTotal time passed: 2.000342 s</span><br><span style="color: hsl(0, 100%, 40%);">-Test_FSM{ONE}: state_chg to TWO</span><br><span style="color: hsl(120, 100%, 40%);">+Test_FSM{ONE}: State change to TWO (keeping T10, 7.999s remaining)</span><br><span> [0;mTotal time passed: 2.000342 s</span><br><span> Total time passed: 9.999999 s</span><br><span> Total time passed: 10.000000 s</span><br><span>@@ -104,14 +104,14 @@</span><br><span> </span><br><span> --- test_state_chg_T()</span><br><span> Test_FSM{NULL}: Allocated</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{NULL}: state_chg to ONE</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{ONE}: state_chg to TWO</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{NULL}: State change to ONE (T42, 23s)</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{ONE}: State change to TWO (no timeout)</span><br><span> [0;mTest_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)</span><br><span> [0;mTest_FSM{TWO}: Freeing instance</span><br><span> [0;mTest_FSM{TWO}: Deallocated</span><br><span> [0;mTest_FSM{NULL}: Allocated</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{NULL}: state_chg to ONE</span><br><span style="color: hsl(0, 100%, 40%);">-[0;mTest_FSM{ONE}: state_chg to TWO</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{NULL}: State change to ONE (T42, 23s)</span><br><span style="color: hsl(120, 100%, 40%);">+[0;mTest_FSM{ONE}: State change to TWO (no timeout)</span><br><span> [0;mTest_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)</span><br><span> [0;mTest_FSM{TWO}: Freeing instance</span><br><span> [0;mTest_FSM{TWO}: Deallocated</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/12987">change 12987</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.osmocom.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.osmocom.org/12987"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: libosmocore </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-MessageType: newchange </div>
<div style="display:none"> Gerrit-Change-Id: I089b81021a1a4ada1205261470da032b82d57872 </div>
<div style="display:none"> Gerrit-Change-Number: 12987 </div>
<div style="display:none"> Gerrit-PatchSet: 1 </div>
<div style="display:none"> Gerrit-Owner: Neels Hofmeyr <nhofmeyr@sysmocom.de> </div>