golioth / golioth-zephyr-sdk

Golioth SDK For Zephyr
https://www.golioth.io
Apache License 2.0
66 stars 19 forks source link

system_client: fix flushing of events before connect attempt #338

Closed mniestroj closed 1 year ago

mniestroj commented 1 year ago

There is a race condition between getting connected and actually flushing eventfd. If some event (like scheduling new packets from client->on_connect() callback) occurred in between, then such event would be ignored.

Flush pending events notification in eventfd before attempting connect, so no events get discarded after connection was established.

Following flow triggers unwanted reconnection when using settings as a source of Golioth credentials:

This behavior is wrong, as FLAG_RECONNECT should not be respected after new connection attempt.

Fix that issue by clearing FLAG_RECONNECT in flags together with eventfd events. As a result, there is no more unwanted reconnection when using credentials from Zephyr settings.

Logs before this change

``` *** Booting Zephyr OS build v3.1.99-ncs1-3-gbf4c7b6481b3 *** I: Starting bootloader I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3 I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3 I: Boot source: none I: Swap type: none I: Bootloader chainload address offset: 0x10000 I: Jumping to the first image slot uart:~$ *** Booting Zephyr OS build v3.1.99-ncs1-3-gbf4c7b6481b3 *** [00:00:00.501,129] golioth_system: Initializing [00:00:00.507,995] fs_nvs: 2 Sectors of 4096 bytes [00:00:00.508,026] fs_nvs: alloc wra: 0, fb8 [00:00:00.508,026] fs_nvs: data wra: 0, 3c [00:00:03.309,661] golioth_dfu: main: Start DFU sample [00:00:03.309,722] golioth_samples: Waiting for interface to be up [00:00:03.309,753] golioth_system: Starting connect [00:00:04.419,799] golioth_system: Client connected! [00:00:04.765,808] golioth_dfu: golioth_desired_update: Desired a3 01 1a 63 e1 50 c4 02 78 40 34 38 64 30 65 32 |...c.P.. x@48d0e2 64 33 32 64 38 66 64 37 37 61 66 35 35 61 32 65 |d32d8fd7 7af55a2e 36 64 63 32 36 32 38 34 30 31 37 64 37 36 63 32 |6dc26284 017d76c2 37 37 61 63 36 64 66 35 37 34 37 37 35 30 63 65 |77ac6df5 747750ce 30 30 64 64 31 35 62 38 32 31 03 81 a6 01 64 6d |00dd15b8 21....dm 61 69 6e 02 65 32 2e 30 2e 30 03 78 40 30 61 36 |ain.e2.0 .0.x@0a6 64 36 61 62 66 36 36 31 35 31 62 65 66 61 39 63 |d6abf661 51befa9c 30 62 38 66 64 36 64 33 65 38 63 33 66 63 39 61 |0b8fd6d3 e8c3fc9a 37 35 34 33 35 31 63 30 38 38 38 35 32 63 62 37 |754351c0 88852cb7 37 63 34 32 32 30 36 34 39 37 39 66 31 04 1a 00 |7c422064 979f1... 04 14 08 05 70 2f 2e 75 2f 63 2f 6d 61 69 6e 40 |....p/.u /c/main@ 32 2e 30 2e 30 06 67 6d 63 75 62 6f 6f 74 |2.0.0.gm cuboot [00:00:04.766,143] golioth: Manifest sequence-number: 1675710660 [00:00:04.771,057] golioth_system: Reconnect per request [00:00:04.771,057] golioth_dfu: Error while receiving desired FW update: -110 [00:00:04.771,087] golioth_dfu: Error while receiving FW data: -110 [00:00:04.771,118] golioth: req_sync finished with error -110 [00:00:04.771,148] golioth_dfu: Failed to update to 'downloading' state: -110 [00:00:04.775,390] golioth_system: Starting connect [00:00:05.648,193] golioth_system: Client connected! [00:00:06.038,879] golioth_dfu: golioth_desired_update: Desired a3 01 1a 63 e1 50 c4 02 78 40 34 38 64 30 65 32 |...c.P.. x@48d0e2 64 33 32 64 38 66 64 37 37 61 66 35 35 61 32 65 |d32d8fd7 7af55a2e 36 64 63 32 36 32 38 34 30 31 37 64 37 36 63 32 |6dc26284 017d76c2 37 37 61 63 36 64 66 35 37 34 37 37 35 30 63 65 |77ac6df5 747750ce 30 30 64 64 31 35 62 38 32 31 03 81 a6 01 64 6d |00dd15b8 21....dm 61 69 6e 02 65 32 2e 30 2e 30 03 78 40 30 61 36 |ain.e2.0 .0.x@0a6 64 36 61 62 66 36 36 31 35 31 62 65 66 61 39 63 |d6abf661 51befa9c 30 62 38 66 64 36 64 33 65 38 63 33 66 63 39 61 |0b8fd6d3 e8c3fc9a 37 35 34 33 35 31 63 30 38 38 38 35 32 63 62 37 |754351c0 88852cb7 37 63 34 32 32 30 36 34 39 37 39 66 31 04 1a 00 |7c422064 979f1... 04 14 08 05 70 2f 2e 75 2f 63 2f 6d 61 69 6e 40 |....p/.u /c/main@ 32 2e 30 2e 30 06 67 6d 63 75 62 6f 6f 74 |2.0.0.gm cuboot [00:00:06.038,909] golioth_dfu: Ignoring new desired firmware, as downloading already started ```

Logs after this change

``` *** Booting Zephyr OS build v3.1.99-ncs1-3-gbf4c7b6481b3 *** I: Starting bootloader I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3 I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3 I: Boot source: none I: Swap type: none I: Bootloader chainload address offset: 0x10000 I: Jumping to the first image slot uart:~$ *** Booting Zephyr OS build v3.1.99-ncs1-3-gbf4c7b6481b3 *** [00:00:00.501,129] golioth_system: Initializing [00:00:00.507,843] fs_nvs: 2 Sectors of 4096 bytes [00:00:00.507,873] fs_nvs: alloc wra: 0, fb8 [00:00:00.507,873] fs_nvs: data wra: 0, 3c [00:00:03.421,997] golioth_dfu: main: Start DFU sample [00:00:03.422,058] golioth_samples: Waiting for interface to be up [00:00:03.422,088] golioth_system: Starting connect [00:00:04.534,057] golioth_system: Client connected! [00:00:04.880,218] golioth_dfu: golioth_desired_update: Desired a3 01 1a 63 e1 50 c4 02 78 40 34 38 64 30 65 32 |...c.P.. x@48d0e2 64 33 32 64 38 66 64 37 37 61 66 35 35 61 32 65 |d32d8fd7 7af55a2e 36 64 63 32 36 32 38 34 30 31 37 64 37 36 63 32 |6dc26284 017d76c2 37 37 61 63 36 64 66 35 37 34 37 37 35 30 63 65 |77ac6df5 747750ce 30 30 64 64 31 35 62 38 32 31 03 81 a6 01 64 6d |00dd15b8 21....dm 61 69 6e 02 65 32 2e 30 2e 30 03 78 40 30 61 36 |ain.e2.0 .0.x@0a6 64 36 61 62 66 36 36 31 35 31 62 65 66 61 39 63 |d6abf661 51befa9c 30 62 38 66 64 36 64 33 65 38 63 33 66 63 39 61 |0b8fd6d3 e8c3fc9a 37 35 34 33 35 31 63 30 38 38 38 35 32 63 62 37 |754351c0 88852cb7 37 63 34 32 32 30 36 34 39 37 39 66 31 04 1a 00 |7c422064 979f1... 04 14 08 05 70 2f 2e 75 2f 63 2f 6d 61 69 6e 40 |....p/.u /c/main@ 32 2e 30 2e 30 06 67 6d 63 75 62 6f 6f 74 |2.0.0.gm cuboot [00:00:04.880,523] golioth: Manifest sequence-number: 1675710660 [00:00:05.263,793] golioth_dfu: data_received: Received 1024 bytes at offset 0 [00:00:05.263,854] mcuboot_util: Swap type: none [00:00:05.263,885] golioth_dfu: swap type: none [00:00:05.902,801] golioth_dfu: data_received: Received 1024 bytes at offset 1024 [00:00:06.212,829] golioth_dfu: data_received: Received 1024 bytes at offset 2048 [00:00:06.515,808] golioth_dfu: data_received: Received 1024 bytes at offset 3072 [00:00:06.827,758] golioth_dfu: data_received: Received 1024 bytes at offset 4096 [00:00:07.452,789] golioth_dfu: data_received: Received 1024 bytes at offset 5120 [00:00:07.708,801] golioth_dfu: data_received: Received 1024 bytes at offset 6144 [00:00:08.027,832] golioth_dfu: data_received: Received 1024 bytes at offset 7168 [00:00:08.402,832] golioth_dfu: data_received: Received 1024 bytes at offset 8192 [00:00:08.746,856] golioth_dfu: data_received: Received 1024 bytes at offset 9216 [00:00:09.058,868] golioth_dfu: data_received: Received 1024 bytes at offset 10240 [00:00:09.301,879] golioth_dfu: data_received: Received 1024 bytes at offset 11264 [00:00:09.541,900] golioth_dfu: data_received: Received 1024 bytes at offset 12288 [00:00:09.939,910] golioth_dfu: data_received: Received 1024 bytes at offset 13312 [00:00:10.326,995] golioth_dfu: data_received: Received 1024 bytes at offset 14336 ```

Alternative to: #336

github-actions[bot] commented 1 year ago

Visit the preview URL for this PR (updated for commit ab06f28):

https://golioth-zephyr-sdk-doxygen-dev--pr338-fix-flush-reconn-6tiqwll8.web.app

(expires Tue, 14 Feb 2023 16:20:04 GMT)

🔥 via Firebase Hosting GitHub Action 🌎

Sign: a389eefadf4b4b68a539327b3459dd66c142cf49

mniestroj commented 1 year ago

@szczys Thanks a lot for taking time and testing it!