Merge branch 'bugfix/default_event_loop_example_failure' into 'master'

Fix failures in running esp_event example test

Closes #64

See merge request idf/esp-idf!4252
This commit is contained in:
Ivan Grokhotkov 2019-02-15 08:50:18 +08:00
commit 91f5bb3850
3 changed files with 76 additions and 74 deletions

View file

@ -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. The example flow is best explained using a sample log output.
``` ```
I (297) default_event_loop: setting up I (276) default_event_loop: setting up
I (297) default_event_loop: starting event sources I (276) default_event_loop: starting event sources
I (297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop I (276) 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: 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 (296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler
I (327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler I (306) 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 (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 (326) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 1 times
I (347) 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 (827) 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: posting to default loop, 2 out of 5
I (827) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler I (806) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 2 times
I (827) 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 (1297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop I (1276) 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 (1276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 1 out of 3 times
I (1307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler I (1286) 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 (1296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler
I (1327) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 3 out of 5 I (1306) 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 (1316) 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 (1316) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 3 times
I (1357) 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 (1867) 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: posting to default loop, 4 out of 5
I (1867) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler I (1846) 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 (2276) 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 (2276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 2 out of 3 times
I (2307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler I (2286) 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 (2296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler
I (2367) 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: posting to default loop, 5 out of 5
I (2367) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: all_event_handler I (2346) 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 (3276) 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 (3276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop
I (3307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler I (3286) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times
I (3317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop I (3296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler
I (3327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times I (3306) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler
I (3337) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: all_event_handler I (3316) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler
I (3337) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_any_handler I (3326) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: deleted timer event source
I (3347) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler I (3326) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_any_handler
I (3357) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: deleted timer event source I (3336) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: all_event_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
``` ```
### Setting ### Setting
@ -95,22 +96,22 @@ At this stage the default event loop is created, as well as the handlers for the
b. b.
``` ```
I (297) default_event_loop: starting event sources I (276) default_event_loop: starting event sources
I (297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop I (276) 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: 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. The two event sources are started. The respective events are posted to the default event loop.
c. c.
``` ```
I (317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: all_event_handler I (296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_started_handler
I (327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STARTED: timer_any_handler I (306) 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 (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 (326) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: task_iteration_handler, executed 1 times
I (347) 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` 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. 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``. 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. The proceeding lines of the log follows the same pattern: the event is posted to the loop and the handlers are executed.
d. 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 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. 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 (1846) default_event_loop: TASK_EVENTS:TASK_ITERATION_EVENT: posting to default loop, 4 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: all_event_handle
``` ```
The iteration event continues to get posted, but only `all_event_handler` gets executed. The iteration event continues to get posted, but only `all_event_handler` gets executed.
e. e.
``` ```
... ...
I (3297) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop I (3276) 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 (3276) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop
I (3307) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler I (3286) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times
I (3317) default_event_loop: TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop I (3296) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_any_handler
I (3327) default_event_loop: TIMER_EVENTS:TIMER_EVENT_EXPIRY: timer_expiry_handler, executed 3 out of 3 times 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 (3347) 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 (3357) 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`. 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. The task containing the loop that posts iteration events also gets deleted. The example ends at this point.

View file

@ -39,26 +39,23 @@ def _test_timer_events(dut):
dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop") dut.expect("TIMER_EVENTS:TIMER_EVENT_STARTED: posting to default loop")
print("Posted timer started event") 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_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") print("Handled timer started event")
for expiries in range(1, TIMER_EVENT_LIMIT + 1): for expiries in range(1, TIMER_EVENT_LIMIT + 1):
dut.expect("TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop") dut.expect("TIMER_EVENTS:TIMER_EVENT_EXPIRY: posting to default loop")
print("Posted timer expiry event {} out of {}".format(expiries, TIMER_EVENT_LIMIT)) print("Posted timer expiry event {} out of {}".format(expiries, TIMER_EVENT_LIMIT))
if expiries < TIMER_EVENT_LIMIT: if expiries >= TIMER_EVENT_LIMIT:
dut.expect_all("TIMER_EVENTS:TIMER_EVENT_EXPIRY: all_event_handler", dut.expect("TIMER_EVENTS:TIMER_EVENT_STOPPED: posting to default loop")
"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))
print("Posted timer stopped event") 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)) print("Handled timer expiry event {} out of {}".format(expiries, TIMER_EVENT_LIMIT))
dut.expect("TIMER_EVENTS:TIMER_EVENT_STOPPED: timer_stopped_handler") 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)) print("Posted iteration {} out of {}".format(iteration, TASK_ITERATION_LIMIT))
if iteration < TASK_UNREGISTRATION_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: 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)) print("Unregistered handler at iteration {} out of {}".format(iteration, TASK_ITERATION_LIMIT))
else: 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)) print("Handled iteration {} out of {}".format(iteration, TASK_ITERATION_LIMIT))
@ -94,7 +93,7 @@ def _test_iteration_events(dut):
@IDF.idf_example_test(env_tag='Example_WIFI') @IDF.idf_example_test(env_tag='Example_WIFI')
def test_default_event_loop_example(env, extra_data): def test_default_event_loop_example(env, extra_data):
dut = env.get_dut('default_event_loop', 'examples/system/event/default_event_loop') dut = env.get_dut('default_event_loop', 'examples/system/esp_event/default_event_loop')
_test_iteration_events(dut) _test_iteration_events(dut)
_test_timer_events(dut) _test_timer_events(dut)

View file

@ -22,7 +22,7 @@ TASK_ITERATION_HANDLING = "handling TASK_EVENTS:TASK_ITERATION_EVENT from {}, it
@IDF.idf_example_test(env_tag='Example_WIFI') @IDF.idf_example_test(env_tag='Example_WIFI')
def test_user_event_loops_example(env, extra_data): def test_user_event_loops_example(env, extra_data):
dut = env.get_dut('user_event_loops', 'examples/system/event/user_event_loops') dut = env.get_dut('user_event_loops', 'examples/system/esp_event/user_event_loops')
dut.start_app() dut.start_app()