From 050f2d3259bbde52eb4544ad312d5c38828cc869 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Thu, 31 May 2018 15:30:15 +0200 Subject: 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.c | 3 +++ tests/fsm/fsm_test.err | 20 ++++++++++---------- 2 files changed, 13 insertions(+), 10 deletions(-) (limited to 'tests') diff --git a/tests/fsm/fsm_test.c b/tests/fsm/fsm_test.c index 7aac8d3e..f8ebdc7b 100644 --- a/tests/fsm/fsm_test.c +++ b/tests/fsm/fsm_test.c @@ -406,6 +406,9 @@ int main(int argc, char **argv) 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 bf474aba..13cbacd9 100644 --- a/tests/fsm/fsm_test.err +++ b/tests/fsm/fsm_test.err @@ -3,9 +3,9 @@ Checking FSM allocation 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_FSM(arbitrary_id){NULL}: Terminating (cause = OSMO_FSM_TERM_REQUEST)  --- 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_FSM{TWO}: Timeout of T10 --- 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 -- cgit v1.2.3