example: fix expected logging output order for esp_event example

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.

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))