From a0310e35d720a11e68f82b658dbd49f0ede7c3d0 Mon Sep 17 00:00:00 2001 From: Renz Christian Bagaporo Date: Wed, 13 Feb 2019 10:51:31 +0800 Subject: [PATCH] example: fix expected logging output order for esp_event example --- .../esp_event/default_event_loop/README.md | 119 +++++++++--------- .../default_event_loop/example_test.py | 27 ++-- 2 files changed, 74 insertions(+), 72 deletions(-) diff --git a/examples/system/esp_event/default_event_loop/README.md b/examples/system/esp_event/default_event_loop/README.md index bd6ee88056..f9e10c6f21 100644 --- a/examples/system/esp_event/default_event_loop/README.md +++ b/examples/system/esp_event/default_event_loop/README.md @@ -33,44 +33,45 @@ Unregistering a handler is done using `esp_event_handler_register`. Unregisterin The example flow is best explained using a sample log output. ``` -I (297) default_event_loop: setting up -I (297) default_event_loop: starting event sources -I (297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop -I (297) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 1 out of 5 -I (317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler -I (327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler -I (337) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler -I (347) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler -I (347) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 1 times -I (827) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 2 out of 5 -I (827) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler -I (827) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 2 times -I (1297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop -I (1297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler -I (1307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler -I (1317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 1 out of 3 times -I (1327) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 3 out of 5 -I (1337) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: unregistering task_iteration_handler -I (1337) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler -I (1357) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 3 times -I (1867) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 4 out of 5 -I (1867) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler -I (2297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop -I (2297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler -I (2307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler -I (2317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 2 out of 3 times -I (2367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 5 out of 5 -I (2367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler -I (3297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop -I (3297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler -I (3307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler -I (3317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop -I (3327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times -I (3337) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: all_event_handler -I (3337) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_any_handler -I (3347) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler -I (3357) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: deleted timer event source -I (3367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: deleting task event source +I (276) default_event_loop: setting up +I (276) default_event_loop: starting event sources +I (276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop +I (276) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 1 out of 5 +I (296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler +I (306) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler +I (316) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler +I (326) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 1 times +I (336) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler +I (806) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 2 out of 5 +I (806) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 2 times +I (806) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler +I (1276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop +I (1276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 1 out of 3 times +I (1286) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler +I (1296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler +I (1306) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 3 out of 5 +I (1316) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: unregistering task_iteration_handler +I (1316) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 3 times +I (1336) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler +I (1846) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 4 out of 5 +I (1846) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler +I (2276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop +I (2276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 2 out of 3 times +I (2286) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler +I (2296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler +I (2346) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 5 out of 5 +I (2346) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler +I (3276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop +I (3276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop +I (3286) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times +I (3296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler +I (3306) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler +I (3316) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler +I (3326) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: deleted timer event source +I (3326) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_any_handler +I (3336) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: all_event_handler +I (3346) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: deleting task event source + ``` ### Setting @@ -95,22 +96,22 @@ At this stage the default event loop is created, as well as the handlers for the b. ``` -I (297) default_event_loop: starting event sources -I (297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop -I (297) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 1 out of 5 +I (276) default_event_loop: starting event sources +I (276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop +I (276) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 1 out of 5 ``` The two event sources are started. The respective events are posted to the default event loop. c. ``` -I (317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler -I (327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler -I (337) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler +I (296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler +I (306) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler +I (316) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler ``` ``` -I (347) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler -I (347) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 1 times +I (326) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 1 times +I (336) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler ``` The handlers are executed for the events posted in **(b)**. In addition to event-specific handlers `timer_started_handler` and `task_iteration_handler`, the handlers `timer_any_handler` and `all_event_handler` also executed. @@ -119,13 +120,16 @@ The handler `timer_any_handler` executes for *any* timer event. It can be seen e On the other hand, `all_event_handler` executes for *any* event. This is the reason why it executes for both ``TIMER_EVENTS:TIMER_EVENT_STARTED`` and ``TASK_EVENTS:TASK_ITERATION_EVENT``. +For both the timer and task events, notice that the handlers are executed in the same order they are registered in the code. This is +a guarantee that the `esp_event` library provides. + The proceeding lines of the log follows the same pattern: the event is posted to the loop and the handlers are executed. d. ``` ... -I (1337) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: unregistering task_iteration_handler +I (1316) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: unregistering task_iteration_handler ``` At this point in the execution the handler `task_iteration_handler` is unregistered, therefore it no longer executes when the event ``TASK_EVENTS:TASK_ITERATION_EVENT`` is posted. @@ -135,28 +139,27 @@ I (1867) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler ... -I (2367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 5 out of 5 -I (2367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler +I (1846) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 4 out of 5 +I (1846) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handle ``` The iteration event continues to get posted, but only `all_event_handler` gets executed. e. ``` ... -I (3297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop -I (3297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler -I (3307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler -I (3317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop -I (3327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times -... -I (3347) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler -I (3357) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: deleted timer event source +I (3276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop +I (3276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop +I (3286) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times +I (3296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler +I (3306) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler +I (3316) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler +I (3326) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: deleted timer event source ``` When the periodic timer expiry limit is reached, the event ``TIMER_EVENTS:TIMER_EVENT_STOPPED`` is posted to the loop. The periodic timer is consequently deleted in the handler `timer_stopped_handler`. ``` ... -I (3367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: deleting task event source +I (3346) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: deleting task event source ... ``` The task containing the loop that posts iteration events also gets deleted. The example ends at this point. diff --git a/examples/system/esp_event/default_event_loop/example_test.py b/examples/system/esp_event/default_event_loop/example_test.py index 854092e656..a3cd7b8ace 100644 --- a/examples/system/esp_event/default_event_loop/example_test.py +++ b/examples/system/esp_event/default_event_loop/example_test.py @@ -39,26 +39,23 @@ def _test_timer_events(dut): dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop") print("Posted timer started event") - dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler") - dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler") dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler") + dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler") + dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler") print("Handled timer started event") for expiries in range(1, TIMER_EVENT_LIMIT + 1): dut.expect("TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop") print("Posted timer expiry event {} out of {}".format(expiries, TIMER_EVENT_LIMIT)) - if expiries < TIMER_EVENT_LIMIT: - dut.expect_all("TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler", - "TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler", - TIMER_EXPIRY_HANDLING.format(expiries)) - else: - dut.expect_all("TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop", - "TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler", - "TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler", - TIMER_EXPIRY_HANDLING.format(expiries)) + if expiries >= TIMER_EVENT_LIMIT: + dut.expect("TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop") print("Posted timer stopped event") + dut.expect(TIMER_EXPIRY_HANDLING.format(expiries)) + dut.expect("TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler") + dut.expect("TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler") + print("Handled timer expiry event {} out of {}".format(expiries, TIMER_EVENT_LIMIT)) dut.expect("TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler") @@ -79,12 +76,14 @@ def _test_iteration_events(dut): print("Posted iteration {} out of {}".format(iteration, TASK_ITERATION_LIMIT)) if iteration < TASK_UNREGISTRATION_LIMIT: - dut.expect_all("TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler", TASK_ITERATION_HANDLING.format(iteration)) + dut.expect(TASK_ITERATION_HANDLING.format(iteration)) + dut.expect("TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler") elif iteration == TASK_UNREGISTRATION_LIMIT: - dut.expect_all("TASK_EVENTS:TASK_ITERATION_EVENT: unregistering task_iteration_handler", "TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler") + dut.expect("TASK_EVENTS:TASK_ITERATION_EVENT: unregistering task_iteration_handler") + dut.expect("TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler") print("Unregistered handler at iteration {} out of {}".format(iteration, TASK_ITERATION_LIMIT)) else: - dut.expect_all("TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler") + dut.expect("TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler") print("Handled iteration {} out of {}".format(iteration, TASK_ITERATION_LIMIT)) -- 2.40.0