commit 050f2d3259bbde52eb4544ad312d5c38828cc869
author Neels Hofmeyr <neels@hofmeyr.de> Thu May 31 15:30:15 2018 +0200
committer Neels Hofmeyr <nhofmeyr@sysmocom.de> Tue Feb 26 20:57:58 2019 +0000
tree ffea9389d885e344f70ad918ba3a5335f24c7a3d
parent 047f3872f511353e894659719a6c5346249bca40

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

tests/fsm/fsm_test.err

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