3 files changed, 196 insertions, 53 deletions

diff --git a/tests/fsm/fsm_dealloc_test.c b/tests/fsm/fsm_dealloc_test.c
index 48f80e57..246ba563 100644
--- a/tests/fsm/fsm_dealloc_test.c
+++ b/tests/fsm/fsm_dealloc_test.c
@@ -290,7 +290,7 @@ void obj_set_other(struct obj *a, struct obj *b)
 	obj_add_other(b, a);
 }
 
-static struct scene *scene_alloc()
+static struct scene *scene_alloc(void)
 {
 	struct scene *s = talloc_zero(ctx, struct scene);
 	s->use_count.talloc_object = s;
@@ -419,7 +419,7 @@ static void trigger_tests(void *loop_ctx)
 	}
 }
 
-void test_osmo_fsm_term_safely()
+void test_osmo_fsm_term_safely(void)
 {
 	fprintf(stderr, "\n\n%s()\n", __func__);
 	osmo_fsm_term_safely(true);
@@ -428,7 +428,7 @@ void test_osmo_fsm_term_safely()
 	fprintf(stderr, "\n\n%s() done\n", __func__);
 }
 
-void test_osmo_fsm_set_dealloc_ctx()
+void test_osmo_fsm_set_dealloc_ctx(void)
 {
 	fprintf(stderr, "\n\n%s()\n", __func__);
 	void *dealloc_ctx = talloc_named_const(ctx, 0, "fsm_dealloc");
@@ -443,7 +443,7 @@ int main(void)
 	ctx = talloc_named_const(NULL, 0, "main");
 	osmo_init_logging2(ctx, NULL);
 
-	log_set_print_filename(osmo_stderr_target, 0);
+	log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);
 	log_set_print_level(osmo_stderr_target, 1);
 	log_set_print_category(osmo_stderr_target, 1);
 	log_set_print_category_hex(osmo_stderr_target, 0);
diff --git a/tests/fsm/fsm_test.c b/tests/fsm/fsm_test.c
index 911aad8c..3b839412 100644
--- a/tests/fsm/fsm_test.c
+++ b/tests/fsm/fsm_test.c
@@ -41,6 +41,18 @@ static const struct value_string test_fsm_event_names[] = {
 	{ 0, NULL }
 };
 
+static void test_fsm_onenter(struct osmo_fsm_inst *fi, uint32_t prev_state)
+{
+	LOGPFSM(fi, "%s() prev_state=%s\n",
+		__func__, osmo_fsm_state_name(fi->fsm, prev_state));
+}
+
+static void test_fsm_onleave(struct osmo_fsm_inst *fi, uint32_t next_state)
+{
+	LOGPFSM(fi, "%s() next_state=%s\n",
+		__func__, osmo_fsm_state_name(fi->fsm, next_state));
+}
+
 static void test_fsm_null(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 {
 	switch (event) {
@@ -86,17 +98,23 @@ static struct osmo_fsm_state test_fsm_states[] = {
 		.out_state_mask = (1 << ST_ONE),
 		.name = "NULL",
 		.action = test_fsm_null,
+		.onenter = test_fsm_onenter,
+		.onleave = test_fsm_onleave,
 	},
 	[ST_ONE]= {
 		.in_event_mask = (1 << EV_B),
 		.out_state_mask = (1 << ST_TWO),
 		.name = "ONE",
 		.action= test_fsm_one,
+		.onenter = test_fsm_onenter,
+		.onleave = test_fsm_onleave,
 	},
 	[ST_TWO]= {
 		.in_event_mask = 0,
 		.name = "TWO",
 		.action = NULL,
+		.onenter = test_fsm_onenter,
+		.onleave = test_fsm_onleave,
 	},
 };
 
@@ -172,7 +190,7 @@ static struct osmo_fsm_inst *foo(void)
 	return fi;
 }
 
-static void test_id_api()
+static void test_id_api(void)
 {
 	struct osmo_fsm_inst *fi;
 
@@ -280,7 +298,7 @@ const struct timeval fake_time_start_time = { 123, 456 };
 	osmo_timers_update(); \
 } while (0)
 
-void fake_time_start()
+void fake_time_start(void)
 {
 	struct timespec *clock_override;
 
@@ -301,7 +319,7 @@ static int timer_cb(struct osmo_fsm_inst *fi)
 	return 0;
 }
 
-static void test_state_chg_keep_timer()
+static void test_state_chg_keep_timer(void)
 {
 	struct osmo_fsm_inst *fi;
 
@@ -349,7 +367,7 @@ static void test_state_chg_keep_timer()
 	fprintf(stderr, "--- %s() done\n", __func__);
 }
 
-static void test_state_chg_T()
+static void test_state_chg_T(void)
 {
 	struct osmo_fsm_inst *fi;
 
@@ -386,6 +404,74 @@ static void test_state_chg_T()
 	fprintf(stderr, "--- %s() done\n", __func__);
 }
 
+/* Test setting a state timeout with second granularity */
+static void test_state_chg_Ts(void)
+{
+	struct osmo_fsm_inst *fi;
+
+	fprintf(stderr, "\n--- %s()\n", __func__);
+
+	fsm.timer_cb = &timer_cb;
+	timeout_fired = -1;
+	fake_time_start();
+
+	fi = osmo_fsm_inst_alloc(&fsm, g_ctx, NULL, LOGL_DEBUG, NULL);
+	OSMO_ASSERT(fi);
+
+	osmo_fsm_inst_state_chg(fi, ST_ONE, 8, 4242);
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(3, 0); /* +3s */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(2, 500000); /* +2.5s */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(2, 500000); /* +2.5s */
+	OSMO_ASSERT(timeout_fired == 4242);
+
+	osmo_fsm_inst_term(fi, OSMO_FSM_TERM_REQUEST, NULL);
+
+	fprintf(stderr, "--- %s() done\n", __func__);
+}
+
+/* Test setting a state timeout with millisecond granularity */
+static void test_state_chg_Tms(void)
+{
+	struct osmo_fsm_inst *fi;
+
+	fprintf(stderr, "\n--- %s()\n", __func__);
+
+	fsm.timer_cb = &timer_cb;
+	timeout_fired = -1;
+	fake_time_start();
+
+	fi = osmo_fsm_inst_alloc(&fsm, g_ctx, NULL, LOGL_DEBUG, NULL);
+	OSMO_ASSERT(fi);
+
+	osmo_fsm_inst_state_chg_ms(fi, ST_ONE, 1337, 4242); /* 1s 337ms */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(0, 500000); /* +500ms, 500ms total */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(0, 250000); /* +250ms, 750ms total */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(0, 350000); /* +350ms, 1s 100ms total */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(0, 200000); /* +200ms, 1s 300ms total */
+	OSMO_ASSERT(timeout_fired == -1);
+
+	fake_time_passes(0, 37000); /* +37ms, 1s 337ms total */
+	OSMO_ASSERT(timeout_fired == 4242);
+
+	osmo_fsm_inst_term(fi, OSMO_FSM_TERM_REQUEST, NULL);
+
+	fprintf(stderr, "--- %s() done\n", __func__);
+}
+
 static const struct log_info_cat default_categories[] = {
 	[DMAIN] = {
 		.name = "DMAIN",
@@ -412,7 +498,10 @@ int main(int argc, char **argv)
 	log_init(&log_info, NULL);
 	stderr_target = log_target_create_stderr();
 	log_add_target(stderr_target);
-	log_set_print_filename(stderr_target, 0);
+	log_set_print_filename2(stderr_target, LOG_FILENAME_NONE);
+	log_set_use_color(stderr_target, 0);
+	log_set_print_category(stderr_target, 0);
+	log_set_print_category_hex(stderr_target, 0);
 	g_ctrl = ctrl_handle_alloc(NULL, NULL, NULL);
 
 	g_ctx = NULL;
@@ -431,6 +520,8 @@ int main(int argc, char **argv)
 	test_id_api();
 	test_state_chg_keep_timer();
 	test_state_chg_T();
+	test_state_chg_Ts();
+	test_state_chg_Tms();
 
 	osmo_fsm_unregister(&fsm);
 	exit(0);
diff --git a/tests/fsm/fsm_test.err b/tests/fsm/fsm_test.err
index 13cbacd9..fffb9136 100644
--- a/tests/fsm/fsm_test.err
+++ b/tests/fsm/fsm_test.err
@@ -1,18 +1,22 @@
 Checking FSM allocation
-Test_FSM(my_id){NULL}: Allocated
-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 change to ONE (no timeout)
-Test_FSM(my_id){ONE}: Received Event EV_B
-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
-
+Test_FSM(my_id){NULL}: Allocated
+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}: test_fsm_onleave() next_state=ONE
+Test_FSM(my_id){NULL}: State change to ONE (no timeout)
+Test_FSM(my_id){ONE}: test_fsm_onenter() prev_state=NULL
+Test_FSM(my_id){ONE}: Received Event EV_B
+Test_FSM(my_id){ONE}: test_fsm_onleave() next_state=TWO
+Test_FSM(my_id){ONE}: State change to TWO (T2342, 1s)
+Test_FSM(my_id){TWO}: test_fsm_onenter() prev_state=ONE
+Test_FSM(my_id){TWO}: Timeout of T2342
+Timer
+Test_FSM(my_id){TWO}: Deallocated
+
 --- test_id_api()
 Test_FSM{NULL}: Allocated
-  osmo_fsm_inst_name() == "Test_FSM"
+  osmo_fsm_inst_name() == "Test_FSM"
   osmo_fsm_inst_find_by_name("Test_FSM") == fi
 osmo_fsm_inst_update_id("my_id")
     rc == 0, ok
@@ -39,23 +43,23 @@ osmo_fsm_inst_update_id("arbitrary_id")
   osmo_fsm_inst_find_by_id("arbitrary_id") == fi
 osmo_fsm_inst_update_id("")
 Attempting to set illegal id for FSM instance of type 'Test_FSM': ""
-    rc == -22, ok
+    rc == -22, ok
   osmo_fsm_inst_name() == "Test_FSM(arbitrary_id)"
   osmo_fsm_inst_find_by_name("Test_FSM(arbitrary_id)") == fi
 osmo_fsm_inst_update_id("invalid.id")
 Attempting to set illegal id for FSM instance of type 'Test_FSM': "invalid.id"
-    rc == -22, ok
+    rc == -22, ok
   osmo_fsm_inst_name() == "Test_FSM(arbitrary_id)"
   osmo_fsm_inst_find_by_name("Test_FSM(arbitrary_id)") == fi
 --- id format tests...
 osmo_fsm_inst_update_id_f("format%cid", '.')
 Attempting to set illegal id for FSM instance of type 'Test_FSM': "format.id"
-    rc == -22, ok
+    rc == -22, ok
   osmo_fsm_inst_name() == "Test_FSM(arbitrary_id)"
   osmo_fsm_inst_find_by_name("Test_FSM(arbitrary_id)") == fi
 osmo_fsm_inst_update_id_f("%s", "")
 Attempting to set illegal id for FSM instance of type 'Test_FSM': ""
-    rc == -22, ok
+    rc == -22, ok
   osmo_fsm_inst_name() == "Test_FSM(arbitrary_id)"
   osmo_fsm_inst_find_by_name("Test_FSM(arbitrary_id)") == fi
 osmo_fsm_inst_update_id_f("format%xid%d", 0x23, 42)
@@ -78,41 +82,89 @@ osmo_fsm_inst_update_id_f("%s%c%s", "arbitrary", '_', "id")
 --- test_id_api() done
 
 Test_FSM(arbitrary_id){NULL}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
-Test_FSM(arbitrary_id){NULL}: Freeing instance
-Test_FSM(arbitrary_id){NULL}: Deallocated
-
+Test_FSM(arbitrary_id){NULL}: Freeing instance
+Test_FSM(arbitrary_id){NULL}: Deallocated
+
 --- test_state_chg_keep_timer()
 Test_FSM{NULL}: Allocated
-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}: test_fsm_onleave() next_state=ONE
+Test_FSM{NULL}: State change to ONE (no timeout)
+Test_FSM{ONE}: test_fsm_onenter() prev_state=NULL
+Test_FSM{ONE}: test_fsm_onleave() next_state=TWO
+Test_FSM{ONE}: State change to TWO (no timeout)
+Test_FSM{TWO}: test_fsm_onenter() prev_state=ONE
+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 change to ONE (T10, 10s)
-Total time passed: 2.000342 s
+Test_FSM{NULL}: test_fsm_onleave() next_state=ONE
+Test_FSM{NULL}: State change to ONE (T10, 10s)
+Test_FSM{ONE}: test_fsm_onenter() prev_state=NULL
+Total time passed: 2.000342 s
+Test_FSM{ONE}: test_fsm_onleave() next_state=TWO
 Test_FSM{ONE}: State change to TWO (keeping T10, 7.999s remaining)
-Total time passed: 2.000342 s
+Test_FSM{TWO}: test_fsm_onenter() prev_state=ONE
+Total time passed: 2.000342 s
 Total time passed: 9.999999 s
 Total time passed: 10.000000 s
 Test_FSM{TWO}: Timeout of T10
-Test_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
-Test_FSM{TWO}: Freeing instance
-Test_FSM{TWO}: Deallocated
---- test_state_chg_keep_timer() done
+Test_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
+Test_FSM{TWO}: Freeing instance
+Test_FSM{TWO}: Deallocated
+--- test_state_chg_keep_timer() done
 
 --- test_state_chg_T()
 Test_FSM{NULL}: Allocated
-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 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_state_chg_T() done
+Test_FSM{NULL}: test_fsm_onleave() next_state=ONE
+Test_FSM{NULL}: State change to ONE (T42, 23s)
+Test_FSM{ONE}: test_fsm_onenter() prev_state=NULL
+Test_FSM{ONE}: test_fsm_onleave() next_state=TWO
+Test_FSM{ONE}: State change to TWO (no timeout)
+Test_FSM{TWO}: test_fsm_onenter() prev_state=ONE
+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}: test_fsm_onleave() next_state=ONE
+Test_FSM{NULL}: State change to ONE (T42, 23s)
+Test_FSM{ONE}: test_fsm_onenter() prev_state=NULL
+Test_FSM{ONE}: test_fsm_onleave() next_state=TWO
+Test_FSM{ONE}: State change to TWO (no timeout)
+Test_FSM{TWO}: test_fsm_onenter() prev_state=ONE
+Test_FSM{TWO}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
+Test_FSM{TWO}: Freeing instance
+Test_FSM{TWO}: Deallocated
+--- test_state_chg_T() done
+
+--- test_state_chg_Ts()
+Total time passed: 0.000000 s
+Test_FSM{NULL}: Allocated
+Test_FSM{NULL}: test_fsm_onleave() next_state=ONE
+Test_FSM{NULL}: State change to ONE (T4242, 8s)
+Test_FSM{ONE}: test_fsm_onenter() prev_state=NULL
+Total time passed: 3.000000 s
+Total time passed: 5.500000 s
+Total time passed: 8.000000 s
+Test_FSM{ONE}: Timeout of T4242
+Test_FSM{ONE}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
+Test_FSM{ONE}: Freeing instance
+Test_FSM{ONE}: Deallocated
+--- test_state_chg_Ts() done
+
+--- test_state_chg_Tms()
+Total time passed: 0.000000 s
+Test_FSM{NULL}: Allocated
+Test_FSM{NULL}: test_fsm_onleave() next_state=ONE
+Test_FSM{NULL}: State change to ONE (T4242, 1337ms)
+Test_FSM{ONE}: test_fsm_onenter() prev_state=NULL
+Total time passed: 0.500000 s
+Total time passed: 0.750000 s
+Total time passed: 1.100000 s
+Total time passed: 1.300000 s
+Total time passed: 1.337000 s
+Test_FSM{ONE}: Timeout of T4242
+Test_FSM{ONE}: Terminating (cause = OSMO_FSM_TERM_REQUEST)
+Test_FSM{ONE}: Freeing instance
+Test_FSM{ONE}: Deallocated
+--- test_state_chg_Tms() done