Random provisioning hangup

[toddaustin07]

Hello and Happy New Year!

I want to report an occasional error I get during onboarding devices. After going through the onboarding process many many times, I've encountered this problem often enough that I think it is worth reporting, even though I cannot reproduce the problem every time. It seems to be a problem with the communication between the mobile app and core SDK.

After starting the provisioning process, the mobile app appears to successfully connect to the access point but then occasionally hangs at the same place, which is the highlighted line in the output below, containing "master secret generation success" and then nothing else until the core SDK eventually times out. The mobile app hangs as well. When the core SDK finally times out, it displays the lines following "master secret generation success" as seen below ("New state changing timeout").

It seems the best way to clear this problem is to terminate and restart the mobile app and try again.

My mobile device is an iPhone6 with IOS version 12.4.8 and SmartThings App version 1.6.57-463.

Onboarding...connected to mobile I [IoT]: http_msg_handler(385) > get cmd[0] ok W [IoT]: http_packet_read(103) > Connection closed I [IoT]: _iot_easysetup_gen_post_payload(258) > waiting.. response for [1] I [IoT]: _es_keyinfo_handler(553) > master secret generation success W [IoT]: _do_cmd_tout_check(967) > New state changing timeout I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:1/1 W [IoT]: _do_recovery(1349) > state changing fail for 1, curr_state :1 E [IoT]: _do_recovery(1407) > Failed process [1] on time, STOP I [IoT]: _do_update_timeout(196) > Current timeout : 4294967295 for 1/-2 I [IoT]: _do_status_report(300) > Call usr status_cb with 2/3 Onboarding...FAILED

[Kwang-Hui]

That's pretty interesting.

Could you check the time difference between below two lines?

I [IoT]: _iot_easysetup_gen_post_payload(258) > waiting.. response for [1]
I [IoT]: _es_keyinfo_handler(553) > master secret generation success

Your symptom says it takes too long time for generating master secret at your device (100 or 300 seconds timeout). The possible check point is...

• ecdh computing time
• some deadlock of IPC : iot_easysetup_request uses queue. if there is some blocking issue on queue. this could happen.

My testing result indicates ecdh computing is done within timeout even in ESP8266 (single core MCU). So I'd like to suggest you IPC problem at first. BTW, Could you let me know your test environment? (DUT's H/W, OS, etc..)

[toddaustin07]

The display output I had copied and pasted into a file doesn't have timestamps so I can't tell you the time difference.

To be clear, the master secret generation success line is displayed, and THEN it hangs up. So I thought that meant that the master secret had already been created. It was hanging up on whatever was suppose to happen NEXT.

I'm testing on a Raspberry Pi 3b, with Raspbian Buster. There's not much running at the time I'm doing the onboarding, so not sure how there could be a timeout due to CPU availability.

I have not explored the logging options for the core SDK, and I've been meaning to ask you about this. It looks like there is a debugging-level set of messages, but those are not displayed on the terminal. Is there a way to turn those on? Also, is there an option to log ALL messages to a file INSTEAD of displaying them on the screen?

I'll try to capture more info for you, for the next time it happens.

[Kwang-Hui]

Thanks for update. I think you can simply add file write and timestamp at port/XXX/iot_bsp_debug_xxx.c. and turning CONFIG_STDK_IOT_CORE_LOG_LEVEL_DEBUG config would be helpful for debugging.

[toddaustin07]

Hello - I've been able to capture a debug-level log for this issue. This same hang occurs in about 25-30% of onboarding attempts. See my prior posts for my configuration info.

Below I have two logs - the first one is when the failure occurs. The second one is a successful onboarding process with no errors. Comparing the two allows us to see exactly where the error is happening. Both logs begin with the 'master secret generation success' log message. There are no errors prior to this log message, but if you need to see that part of the log, I can post that too.

I see there are references to time/date. Please consider our earlier conversation about the problems with setting the Raspberry Pi clock. I had removed that function from the BSP system module. Is it possible that this is a clock synchronization problem? I don't understand your code enough to know what it is doing when the state changing timeout occurs, but it appears to have something to do with key generation and exchange with the mobile app.

I hope these logs can help you understand where the problem is. Thank you.

======================================================================================= FAILED LOG

I [IoT]: _es_keyinfo_handler(553) > master secret generation success D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 36@0x74701468, dst: 28@0x74701f08 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 25@0x74701f08 D [IoT]: _es_keyinfo_handler(584) > datetime = 2021-02-20T17.58.03 +0000 D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 36@0x74700e00, dst: 28@0x74701f08 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 25@0x74701f08 D [IoT]: _es_keyinfo_handler(620) > regionaldatetime = 2021-02-20T11.58.03 -0600 D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 20@0x747012b0, dst: 16@0x74700f38 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 15@0x74700f38 D [IoT]: _es_keyinfo_handler(653) > timezoneid = America/Chicago D [IoT]: iot_security_cipher_aes_encrypt(370) > input = 26@0x74701d90 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 26@0x74701d90 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x74701710 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: iot_security_cipher_get_align_size(278) > data size = 26, type = 3 D [IoT]: iot_security_cipher_get_align_size(318) > align size = 32 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x74701710 D [IoT]: iot_security_cipher_aes_encrypt(384) > output = 32@0x74701ae0 D [IoT]: iot_security_base64_encode_urlsafe(178) > src: 32@0x74701ae0, dst: 45@0x74702168 D [IoT]: iot_security_base64_encode_urlsafe(192) > done: 44@0x74702168 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 W [IoT]: _do_cmd_tout_check(968) > New state changing timeout D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:1/1 W [IoT]: _do_recovery(1352) > state changing fail for 1, curr_state :1 E [IoT]: _do_recovery(1410) > Failed process [1] on time, STOP D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x I [IoT]: _do_update_timeout(196) > Current timeout : 4294967295 for 1/-2 I [IoT]: _do_status_report(300) > Call usr status_cb with 2/3 Onboarding...FAILED D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x I [IoT]: _do_cmd_tout_check(981) > New state updated for -2 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:-2/-2 W [IoT]: _do_state_updating(1632) > Iot-core task will be stopped, needed ext-triggering

D [IoT]: iot_easysetup_deinit(500) > ENTER >>>> I [IoT]: http_cleanup_all_connection(40) > close listen socket I [IoT]: http_cleanup_all_connection(47) > close accept socket I [IoT]: es_http_deinit(187) > http tcp deinit complete! I [IoT]: iot_easysetup_deinit(524) > IOT_STATE_PROV_ES_DONE I [IoT]: iot_bsp_wifi_set_mode(836) > [rpi] Requested mode OFF I [IoT]: _SoftAPControl(1266) > [rpi] SoftAP service stop issued I [IoT]: _do_status_report(300) > Call usr status_cb with 1/0 Idle, not connected...staying D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _do_update_timeout(196) > Current timeout : 4294967295 for -1/-1 I [IoT]: _do_status_report(291) > Unsupported state -1 for 0/0 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 E [IoT]: st_conn_start(1829) > Can't go to PROV_CONFIRM (0x2) I [IoT]: st_conn_start(1831) > st_conn_start done (-7)

================================================================================= SUCCESS LOG

I [IoT]: _es_keyinfo_handler(553) > master secret generation success D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 36@0x74700d58, dst: 28@0x74701ce8 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 25@0x74701ce8 D [IoT]: _es_keyinfo_handler(584) > datetime = 2021-02-20T18.11.33 +0000 D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 36@0x74700e00, dst: 28@0x74701ce8 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 25@0x74701ce8 D [IoT]: _es_keyinfo_handler(620) > regionaldatetime = 2021-02-20T12.11.33 -0600 D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 20@0x74701148, dst: 16@0x74700f38 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 15@0x74700f38 D [IoT]: _es_keyinfo_handler(653) > timezoneid = America/Chicago D [IoT]: iot_security_cipher_aes_encrypt(370) > input = 26@0x74701d08 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 26@0x74701d08 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: iot_security_cipher_get_align_size(278) > data size = 26, type = 3 D [IoT]: iot_security_cipher_get_align_size(318) > align size = 32 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_encrypt(384) > output = 32@0x74701978 D [IoT]: iot_security_base64_encode_urlsafe(178) > src: 32@0x74701978, dst: 45@0x74702050 D [IoT]: iot_security_base64_encode_urlsafe(192) > done: 44@0x74702050 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_easysetup_gen_post_payload(280) > payload: {"message":"Jh-rQkT2XMcdkqEJdgB-uW7PDnpIjxBF_g-g2HiV74w="} I [IoT]: http_msg_handler(368) > post cmd[1] ok D [IoT]: http_msg_handler(443) > HTTP/1.1 200 OK Server: SmartThings Device SDK Connection: keep-alive Content-Type: application/json Content-Length: 58

{"message":"Jh-rQkT2XMcdkqEJdgB-uW7PDnpIjxBF_g-g2HiV74w="} W [IoT]: http_packet_read(103) > Connection closed D [IoT]: es_msg_parser(176) > payload : �otl D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _iot_easysetup_gen_post_payload(260) > waiting.. response for [2] D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1083) > request step: 2

D [IoT]: _es_json_parse_string(156) > 'message' (89): Xj_ZLADAuRSRwxv8yRZHvkSIhGk7jsDPdPZ3IWyPPVbOlLiI_cQplU6Fvi39IgCPXrRi2tFd77dDC_dkokgIXg== D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 88@0x74702190, dst: 67@0x74701790 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 64@0x74701790 D [IoT]: iot_security_cipher_aes_decrypt(408) > input = 64@0x74701790 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 64@0x74701790 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_decrypt(422) > output = 58@0x74701be0 I [IoT]: _es_confirminfo_handler(878) > otmSupportFeature = 0 I [IoT]: _es_confirm_check_manager(737) > IOT_STATE_PROV_CONFIRMING I [IoT]: iot_state_update(227) > Trigger PROV_CONFIRM D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 E [IoT]: st_conn_start(1829) > Can't go to PROV_CONFIRM (0x0) I [IoT]: st_conn_start(1831) > st_conn_start done (-7) D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _es_confirm_check_manager(751) > There is no confirmation request. The check is skipped D [IoT]: iot_security_cipher_aes_encrypt(370) > input = 2@0x74702370 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 2@0x74702370 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: iot_security_cipher_get_align_size(278) > data size = 2, type = 3 D [IoT]: iot_security_cipher_get_align_size(318) > align size = 16 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_encrypt(384) > output = 16@0x74700f20 D [IoT]: iot_security_base64_encode_urlsafe(178) > src: 16@0x74700f20, dst: 25@0x74701720 D [IoT]: iot_security_base64_encode_urlsafe(192) > done: 24@0x74701720 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: _iot_easysetup_gen_post_payload(280) > payload: {"message":"OVoMd2FcTPAM9STR-bzKMQ=="} D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 I [IoT]: http_msg_handler(368) > post cmd[2] ok D [IoT]: http_msg_handler(443) > HTTP/1.1 200 OK Server: SmartThings Device SDK Connection: keep-alive Content-Type: application/json Content-Length: 38

{"message":"OVoMd2FcTPAM9STR-bzKMQ=="} D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:1/1 I [IoT]: _do_state_updating(1573) > the state changes to IOT_STATE_PROV_CONFIRM I [IoT]: _do_update_timeout(196) > Current timeout : 100000 for 1/3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _do_cmd_tout_check(981) > New state updated for 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 W [IoT]: http_packet_read(103) > Connection closed D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _iot_easysetup_gen_get_payload(150) > waiting.. response for [4] D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1083) > request step: 4

I [IoT]: iot_bsp_wifi_set_mode(856) > [rpi] Requested mode SCAN I [IoT]: iot_bsp_wifi_set_mode(870) > [rpi] Scan not performed while in AP mode I [IoT]: iot_bsp_wifi_get_scan_result(1552) > [rpi] Get scan result requested D [IoT]: iot_security_cipher_aes_encrypt(370) > input = 299@0x747027c0 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 299@0x747027c0 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: iot_security_cipher_get_align_size(278) > data size = 299, type = 3 D [IoT]: iot_security_cipher_get_align_size(318) > align size = 304 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_encrypt(384) > output = 304@0x74702af0 D [IoT]: iot_security_base64_encode_urlsafe(178) > src: 304@0x74702af0, dst: 409@0x747036f8 D [IoT]: iot_security_base64_encode_urlsafe(192) > done: 408@0x747036f8 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_easysetup_gen_get_payload(164) > payload: {"message":"zDhg7k8uoj6HBrDzx94s916xkJDCqFvgZD9VOGVhrAotuYSdtvHdRBWxM2EC1MY-W68ZzZkmyyGnoUt8vu0tpKE0f9chOhc0-JeBTb5awzLIk_cOb2rHSv-fntLvf4zsRphmRJKU9oa_m8hIv7XpPskUJg2v-9pHrl8UwondYNMsODK9s8HF-WAz5EqLMZemCjco0aNI-SDoEDqMCmkc-gi7lbTlL30mk-L2S20iHDU5eOVwouQgswATlueTVuEfSYAnPfPAaDrrpr5GCK9ovW0pCwux5sbqXRwGdgm-vT3OA3Rlbs0LHi13-1kumbEURydMlzD17yX2Cffmc4qOH7Drlr-w8aEc60y494wLtoStAz9ROoNBa53p4roSZ0dj5zrE5ayFgsUS0HM3DJEhSw=="} I [IoT]: http_msg_handler(387) > get cmd[4] ok D [IoT]: http_msg_handler(443) > HTTP/1.1 200 OK Server: SmartThings Device SDK Connection: keep-alive Content-Type: application/json Content-Length: 422

{"message":"zDhg7k8uoj6HBrDzx94s916xkJDCqFvgZD9VOGVhrAotuYSdtvHdRBWxM2EC1MY-W68ZzZkmyyGnoUt8vu0tpKE0f9chOhc0-JeBTb5awzLIk_cOb2rHSv-fntLvf4zsRphmRJKU9oa_m8hIv7XpPskUJg2v-9pHrl8UwondYNMsODK9s8HF-WAz5EqLMZemCjco0aNI-SDoEDqMCmkc-gi7lbTlL30mk-L2S20iHDU5eOVwouQgswATlueTVuEfSYAnPfPAaDrrpr5GCK9ovW0pCwux5sbqXRwGdgm-vT3OA3Rlbs0LHi13-1kumbEURydMlzD17yX2Cffmc4qOH7Drlr- W [IoT]: http_packet_read(103) > Connection closed D [IoT]: es_msg_parser(176) > payload : �otl D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1083) > request step: 5

I [IoT]: _iot_easysetup_gen_post_payload(260) > waiting.. response for [5] D [IoT]: _es_json_parse_string(156) > 'message' (345): 5A-ZtEp5VGMHbkyptEWVQ1zVzl3K3-T8CVwYpSSPMyGVKV0zztWJdZ6H1evqR2nYoNCQeix70gQAheIyYw35PUZZW0fCXNf2jp07G0nDv99hEZB8aZqEiT5d5_EIVpAR_3pF1WlXBxHwp4EmxJFORif9WRhZ5y98DKVGghA1RW-tayINWeoEp030zLY_WleAaAZH2CAxxlaYOHLzHDFXTPUdAUwijX7huoZu1wAtOMuklzvlvYaEOWlzwEB2BpxgnUyxm7zEKrkrKFPr6FPncI0eIYoeQdghAF5YBxHEUcuvCAgU2cxUdetJKSrt6MnDYnI8Lxxz5Gch7vX7CzBE2g== D [IoT]: iot_security_base64_decode_urlsafe(221) > src: 344@0x74703ef0, dst: 259@0x74704050 D [IoT]: iot_security_base64_decode_urlsafe(252) > done: 256@0x74704050 D [IoT]: iot_security_cipher_aes_decrypt(408) > input = 256@0x74704050 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 256@0x74704050 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_decrypt(422) > output = 253@0x747042b8 D [IoT]: _decide_wifi_auth_mode(1265) > Prometheus_24GHz is type 0 D [IoT]: iot_nv_set_wifi_prov_data(460) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 1, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:1 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 1 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './WifiProvStatus' D [IoT]: iot_security_storage_write(182) > id:1 written 4@0x74701790 D [IoT]: _iot_nv_io_storage(103) > id = 2, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:2 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 2 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPSSID' D [IoT]: iot_security_storage_write(182) > id:2 written 32@0x74701790 D [IoT]: iot_nv_erase(1006) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 3, mode = 3 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_remove(191) > id:3 D [IoT]: _iot_security_be_bsp_fs_remove(309) > id = 3 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPPASS' D [IoT]: iot_bsp_fs_remove(131) > remove fail [No such file or directory] D [IoT]: iot_security_storage_remove(211) > id:3 not found D [IoT]: _iot_nv_io_storage(165) > nv '3' does not exist D [IoT]: iot_nv_erase(1014) > file does not exist D [IoT]: _iot_nv_io_storage(103) > id = 4, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:4 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 4 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPBSSID' D [IoT]: iot_security_storage_write(182) > id:4 written 17@0x74701790 D [IoT]: _iot_nv_io_storage(103) > id = 5, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:5 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 5 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPAuthType' D [IoT]: iot_security_storage_write(182) > id:5 written 1@0x74701790 D [IoT]: _iot_nv_io_storage(103) > id = 1, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:1 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 1 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './WifiProvStatus' D [IoT]: iot_security_storage_write(182) > id:1 written 4@0x74701790 I [IoT]: _es_wifi_prov_parse(1343) > ssid: Prometheus_24GHz D [IoT]: _es_wifi_prov_parse(1344) > password: I [IoT]: _es_wifi_prov_parse(1345) > mac addr: 58:6D:8F:07:72:C5 D [IoT]: _es_json_parse_string(156) > 'brokerUrl' (53): ssl://mqtt-regional-useast1.api.smartthings.com:8883 D [IoT]: _es_json_parse_string(156) > 'deviceName' (16): DSC Zone Device D [IoT]: iot_nv_set_cloud_prov_data(696) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 6, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:6 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 6 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './CloudProvStatus' D [IoT]: iot_security_storage_write(182) > id:6 written 4@0x747043c0 D [IoT]: _iot_nv_io_storage(103) > id = 7, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:7 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 7 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './ServerURL' D [IoT]: iot_security_storage_write(182) > id:7 written 41@0x74701b18 D [IoT]: _iot_nv_io_storage(103) > id = 8, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:8 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 8 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './ServerPort' D [IoT]: iot_security_storage_write(182) > id:8 written 4@0x747043c0 D [IoT]: _iot_nv_io_storage(103) > id = 9, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:9 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 9 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './Label' D [IoT]: iot_security_storage_write(182) > id:9 written 15@0x74700f38 D [IoT]: _iot_nv_io_storage(103) > id = 6, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:6 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 6 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './CloudProvStatus' D [IoT]: iot_security_storage_write(182) > id:6 written 4@0x747043c0 I [IoT]: _es_cloud_prov_parse(1412) > brokerUrl: mqtt-regional-useast1.api.smartthings.com:8883 I [IoT]: _es_cloud_prov_parse(1413) > deviceName : DSC Zone Device I [IoT]: iot_bsp_wifi_get_mac(1729) > [rpi] Mac address requested I [IoT]: iot_bsp_wifi_get_mac(1744) > [rpi] Mac=b8:27:eb:24:af:d9 D [IoT]: _es_wifiprovisioninginfo_handler(1496) > lookupid = abead058-00b9-422e-99cb-d04c2fc3efc4 D [IoT]: iot_security_cipher_aes_encrypt(370) > input = 51@0x74704050 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 51@0x74704050 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: iot_security_cipher_get_align_size(278) > data size = 51, type = 3 D [IoT]: iot_security_cipher_get_align_size(318) > align size = 64 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_encrypt(384) > output = 64@0x74701790 D [IoT]: iot_security_base64_encode_urlsafe(178) > src: 64@0x74701790, dst: 89@0x74700d28 D [IoT]: iot_security_base64_encode_urlsafe(192) > done: 88@0x74700d28 D [IoT]: iot_nv_get_prov_data(261) > >>>HIT<<< D [IoT]: iot_nv_get_wifi_prov_data(322) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 1, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:1 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 1 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 1 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './WifiProvStatus' D [IoT]: iot_security_storage_read(146) > id:1 read 4@0x747044c8 D [IoT]: _iot_nv_io_storage(103) > id = 2, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:2 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 2 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 2 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPSSID' D [IoT]: iot_security_storage_read(146) > id:2 read 32@0x747044d8 D [IoT]: _iot_nv_io_storage(103) > id = 3, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:3 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 3 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 3 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPPASS' D [IoT]: iot_bsp_fs_open(46) > file doesn't exist E [IoT]: _iot_security_be_bsp_fs_load_from_nv(129) > iot_bsp_fs_open(./IotAPPASS) = -1208 D [IoT]: iot_security_storage_read(141) > id:3 not found D [IoT]: _iot_nv_io_storage(123) > nv '3' does not exist D [IoT]: _iot_nv_io_storage(103) > id = 4, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:4 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 4 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 4 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPBSSID' D [IoT]: iot_security_storage_read(146) > id:4 read 17@0x747044d8 D [IoT]: _iot_nv_io_storage(103) > id = 5, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:5 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 5 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 5 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './IotAPAuthType' D [IoT]: iot_security_storage_read(146) > id:5 read 1@0x747044f0 D [IoT]: iot_nv_get_cloud_prov_data(587) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 6, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:6 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 6 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 6 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './CloudProvStatus' D [IoT]: iot_security_storage_read(146) > id:6 read 4@0x74704908 D [IoT]: _iot_nv_io_storage(103) > id = 7, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:7 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 7 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 7 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './ServerURL' D [IoT]: iot_security_storage_read(146) > id:7 read 41@0x74704918 D [IoT]: _iot_nv_io_storage(103) > id = 8, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:8 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 8 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 8 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './ServerPort' D [IoT]: iot_security_storage_read(146) > id:8 read 4@0x74704948 D [IoT]: _iot_nv_io_storage(103) > id = 9, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:9 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 9 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 9 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './Label' D [IoT]: iot_security_storage_read(146) > id:9 read 15@0x74704958 I [IoT]: _es_wifiprovisioninginfo_handler(1541) > provisioning success D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_easysetup_gen_post_payload(280) > payload: {"message":"yYUGLPZOSK8632EjGea3-MeiGrzuzaq7OJ8Fw0fhS9mnL7-J3niyHPh3XmIEDLJ7Ulz6mhpKgZ8o8Vg7KRUQ=="} I [IoT]: http_msg_handler(368) > post cmd[5] ok D [IoT]: http_msg_handler(443) > HTTP/1.1 200 OK Server: SmartThings Device SDK Connection: keep-alive Content-Type: application/json Content-Length: 102

{"message":"yYUGLPZOSK8632EjGea3-MeiGrzuzaq7OJ8Fw0fhS9mnL7-J3niyHPh3XmIEDLJ7Ulz6mhpKgZ8o8Vg7KRUQ=="} W [IoT]: http_packet_read(103) > Connection closed D [IoT]: es_msg_parser(176) > payload : D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _iot_easysetup_gen_post_payload(260) > waiting.. response for [6] D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1083) > request step: 6

D [IoT]: iot_security_cipher_aes_encrypt(370) > input = 2@0x747042b8 D [IoT]: _iot_security_be_software_cipher_aes(1060) > input: 2@0x747042b8 D [IoT]: _iot_security_be_software_cipher_aes(1061) > key: 32@0x747015a8 D [IoT]: _iot_security_be_software_cipher_aes(1062) > iv: 16@0x74700dc8 D [IoT]: iot_security_cipher_get_align_size(278) > data size = 2, type = 3 D [IoT]: iot_security_cipher_get_align_size(318) > align size = 16 D [IoT]: _iot_security_be_software_cipher_aes(1127) > key: 32@0x747015a8 D [IoT]: iot_security_cipher_aes_encrypt(384) > output = 16@0x74701b00 D [IoT]: iot_security_base64_encode_urlsafe(178) > src: 16@0x74701b00, dst: 25@0x74701310 D [IoT]: iot_security_base64_encode_urlsafe(192) > done: 24@0x74701310 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_easysetup_gen_post_payload(280) > payload: {"message":"OVoMd2FcTPAM9STR-bzKMQ=="} D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: http_msg_handler(368) > post cmd[6] ok D [IoT]: http_msg_handler(443) > HTTP/1.1 200 OK Server: SmartThings Device SDK Connection: keep-alive Content-Type: application/json Content-Length: 38

{"message":"OVoMd2FcTPAM9STR-bzKMQ=="} W [IoT]: http_packet_read(103) > Connection closed D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:3/3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_easysetup_deinit(500) > ENTER >>>> I [IoT]: http_cleanup_all_connection(40) > close listen socket I [IoT]: http_cleanup_all_connection(47) > close accept socket I [IoT]: es_http_deinit(187) > http tcp deinit complete! I [IoT]: iot_easysetup_deinit(524) > IOT_STATE_PROV_ES_DONE D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x I [IoT]: _do_update_timeout(196) > Current timeout : 100000 for 3/4 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 1

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:1, curr_main_state:3/4 I [IoT]: iot_bsp_wifi_set_mode(877) > [rpi] Requested mode STATION I [IoT]: _SoftAPControl(1266) > [rpi] SoftAP service stop issued Connection accepted with device manager I [IoT]: iot_bsp_wifi_set_mode(929) > [rpi] Connected to AP SSID: Prometheus_24GHz D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 3

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:3, curr_main_state:3/4 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x I [IoT]: _do_cmd_tout_check(981) > New state updated for 4 I [IoT]: _do_status_report(300) > Call usr status_cb with 2/2 Onboarding...DONE D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:4/4 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _do_state_updating(1600) > the state changes to IOT_STATE_CLOUD_REGISTERING I [IoT]: _do_update_timeout(196) > Current timeout : 900000 for 4/6 I [IoT]: _do_status_report(300) > Call usr status_cb with 8/1 Connecting to server...starting

D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 4

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:4, curr_main_state:4/6 D [IoT]: iot_nv_get_serial_number(899) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 17, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:17 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 17 D [IoT]: iot_nv_get_data_from_device_info(1072) > nv id = 17 D [IoT]: iot_security_storage_read(146) > id:17 read 16@0x747014e0 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: _iot_security_be_software_id_key2storage(112) > key id = 2 D [IoT]: _iot_security_be_software_id_key2storage(117) > storage id = 12 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 12 D [IoT]: iot_nv_get_data_from_device_info(1072) > nv id = 12 D [IoT]: iot_security_base64_decode(144) > src: 44@0x74700e40, dst: 32@0x74701978 D [IoT]: iot_security_base64_decode(152) > done: 32@0x74701978 D [IoT]: _iot_security_be_software_pk_load_ed25519_key(266) > key '2' is loaded 32@0x74701978 D [IoT]: _iot_security_be_software_id_key2storage(112) > key id = 1 D [IoT]: _iot_security_be_software_id_key2storage(117) > storage id = 13 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 13 D [IoT]: iot_nv_get_data_from_device_info(1072) > nv id = 13 D [IoT]: iot_security_base64_decode(144) > src: 44@0x74701858, dst: 32@0x74701928 D [IoT]: iot_security_base64_decode(152) > done: 32@0x74701928 D [IoT]: _iot_security_be_software_pk_load_ed25519_key(266) > key '1' is loaded 32@0x74701928 D [IoT]: _iot_security_be_software_pk_get_key_type(456) > type = 1 D [IoT]: iot_security_pk_get_key_type(131) > type = 1 D [IoT]: iot_security_base64_encode(110) > src: 94@0x74703a38, dst: 129@0x74701660 D [IoT]: iot_security_base64_encode(118) > done: 128@0x74701660 D [IoT]: iot_security_base64_encode(110) > src: 79@0x747045f8, dst: 109@0x74700f68 D [IoT]: iot_security_base64_encode(118) > done: 108@0x74700f68 D [IoT]: iot_security_pk_get_signature_len(93) > type = 1 D [IoT]: _iot_security_be_software_pk_get_key_type(456) > type = 1 D [IoT]: iot_security_pk_get_key_type(131) > type = 1 D [IoT]: iot_security_pk_sign(155) > input = 237@0x74704700 D [IoT]: _iot_security_be_software_pk_sign_ed25519(499) > input: 237@0x74704700 D [IoT]: _iot_security_be_software_pk_sign_ed25519(500) > seckey: 32@0x74701978 D [IoT]: _iot_security_be_software_pk_sign_ed25519(501) > pubkey: 32@0x74701928 D [IoT]: iot_security_pk_get_signature_len(93) > type = 1 D [IoT]: _iot_security_be_software_pk_sign_ed25519(526) > sig: 64@0x74701790 D [IoT]: iot_security_pk_sign(167) > sig = 64@0x74701790 D [IoT]: iot_security_base64_encode(110) > src: 64@0x74701790, dst: 89@0x74702190 D [IoT]: iot_security_base64_encode(118) > done: 88@0x74702190 D [IoT]: _iot_jwt_create(1026) > token: eyJhbGciOiJFZERTQSIsImt0eSI6Ik9LUCIsImNydiI6IkVkMjU1MTkiLCJ0eXAiOiJKV1QiLCJ2ZXIiOiIwLjAuMSIsImtpZCI6IlNUREtPRFZacWtXWlhvZmEifQ==.eyJpYXQiOiIxNjEzODQ0NzA2IiwianRpIjoiY2U2YmI4MTUtZWJkNy00ZTg5LTkzZjAtMjAwMzU3YzE3YWU4IiwibW5JZCI6ImZFNGIifQ==.1w9y92rZ4vGShhFUsdFVjzjkZt+6atQmNopId3Vxc/FMrZVx4QE7bQ4lOc/232t7fNweV/8spjhetsPysPC+Dg== (326) I [IoT]: iot_es_connect(990) > connect_type: registration I [IoT]: iot_bsp_wifi_get_mac(1729) > [rpi] Mac address requested I [IoT]: iot_bsp_wifi_get_mac(1744) > [rpi] Mac=b8:27:eb:24:af:d9 D [IoT]: iot_nv_get_certificate(802) > >>>HIT<<< D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_manager_get_certificate(153) > cert id = 1 D [IoT]: iot_nv_get_static_certificate(1033) > cert id = 1 I [IoT]: _iot_es_mqtt_connect(810) > url: mqtt-regional-useast1.api.smartthings.com, port: 8883 I [IoT]: _iot_es_mqtt_connect(819) > mqtt connect, id : 8b1de8b5-0685-4b9c-9234-1d62e79ccdd5 username : STDKODVZqkWZXofa password : eyJhbGciOiJFZERTQSIsImt0eSI6Ik9LUCIsImNydiI6IkVkMjU1MTkiLCJ0eXAiOiJKV1QiLCJ2ZXIiOiIwLjAuMSIsImtpZCI6IlNUREtPRFZacWtXWlhvZmEifQ==.eyJpYXQiOiIxNjEzODQ0NzA2IiwianRpIjoiY2U2YmI4MTUtZWJkNy00ZTg5LTkzZjAtMjAwMzU3YzE3YWU4IiwibW5JZCI6ImZFNGIifQ==.1w9y92rZ4vGShhFUsdFVjzjkZt+6atQmNopId3Vxc/FMrZVx4QE7bQ4lOc/232t7fNweV/8spjhetsPysPC+Dg== I [IoT]: _iot_net_tls_connect(166) > Loading the CA root certificate 1317@0x74706088 D [IoT]: _iot_net_tls_connect(184) > Connecting to mqtt-regional-useast1.api.smartthings.com:8883 D [IoT]: _iot_net_tls_connect(231) > Performing the SSL/TLS handshake D [IoT]: _iot_net_tls_connect(244) > Protocol is TLSv1.2 D [IoT]: _iot_net_tls_connect(245) > Ciphersuite is TLS-RSA-WITH-AES-128-CBC-SHA D [IoT]: _iot_net_tls_connect(247) > Verifying peer X.509 certificate D [IoT]: _iot_net_tls_write(320) > 397@0x74712ba8 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1994 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1995 D [IoT]: _iot_net_tls_read(281) > 2@0x74711e42 I [IoT]: iot_es_connect(1003) > MQTT connect success D [IoT]: iot_es_connect(1008) > noti subscribe topic : /v1/registrations/notification/STDKODVZqkWZXofa D [IoT]: _iot_net_tls_write(320) > 54@0x74701ac0 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a6c D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a6d D [IoT]: _iot_net_tls_read(281) > 3@0x7471249a D [IoT]: _iot_es_mqtt_registration(727) > publish resource payload : {"label":"DSC Zone Device","mnId":"fE4b","vid":"ST_69f2bc09-a48b-4857-84c2-06f3305a378c","deviceTypeId":"ContactSensor","lookupId":"abead058-00b9-422e-99cb-d04c2fc3efc4","serialHash":"8fjAf4O37qLm6hkdF87hRpD52riACZvSVe9BCSmss2A=","provisioningTs":1613844706,"firmwareVersion":"firmwareVersion_here","osType":"POSIX","osVersion":"200809L","stdkVersion":"1.5.5","deviceIntegrationProfileKey":{"id":"d28e1384-f875-470c-94c6-b559c6257343","majorVersion": D [IoT]: _iot_net_tls_write(320) > 494@0x74706088 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a44 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a45 D [IoT]: _iot_net_tls_read(281) > 2@0x74711e52 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _do_cmd_tout_check(981) > New state updated for 6 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1b44 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1b45 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1b46 D [IoT]: _iot_net_tls_read(281) > 972@0x747167c3 I [IoT]: mqtt_reg_sub_cb(92) > Registered MSG : {"locationId":"454d0976-1ae0-42b9-9cd7-5b4d9634d928","routingKey":"us","metadata":{"serialNumber":"STDKODVZqkWZXofa","mnId":"fE4b","vid":"ST_69f2bc09-a48b-4857-84c2-06f3305a378c","deviceTypeId":"ContactSensor","lookupId":"abead058-00b9-422e-99cb-d04c2fc3efc4","registrationPayloadType":"json","stack":"K8","serialHash":"8fjAf4O37qLm6hkdF87hRpD52riACZvSVe9BCSmss2A=","provisioningTs":1613844796866,"manufacturerName":"Individual","modelNumber":"DSC_Zone_Devi","firmwareVers D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: _iot_mqtt_registration_client_callback(237) > raw msg (len:921) : {"locationId":"454d0976-1ae0-42b9-9cd7-5b4d9634d928","routingKey":"us","metadata":{"serialNumber":"STDKODVZqkWZXofa","mnId":"fE4b","vid":"ST_69f2bc09-a48b-4857-84c2-06f3305a378c","deviceTypeId":"ContactSensor","lookupId":"abead058-00b9-422e-99cb-d04c2fc3efc4","registrationPayloadType":"json","stack":"K8","serialHash":"8fjAf4O37qLm6hkdF87hRpD52riACZvSVe9BCSmss2A=","provisioningTs":1613844796866,"manufacturerName":"Individual","modelNumber":"D D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 5

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:5, curr_main_state:6/6 D [IoT]: iot_es_disconnect(1073) > disconnect type registration D [IoT]: _iot_net_tls_write(320) > 4@0x7470fbc8 D [IoT]: _iot_net_tls_write(320) > 2@0x7470f9c0 I [IoT]: st_mqtt_disconnect(1368) > mqtt disconnect 0 I [IoT]: _iot_net_show_status(87) > [1613844797] network socket status: sockfd 36 readable 0 writable 1 sock_err 0 errno 110 D [IoT]: iot_nv_get_misc_info(941) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 11, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:11 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 11 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 11 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './MiscInfo' D [IoT]: iot_security_storage_read(146) > id:11 read 115@0x74707d90 D [IoT]: iot_misc_info_store(1249) > Store raw msic_info str : {"dip":{"id":"d28e1384-f875-470c-94c6-b559c6257343","maj":0,"min":1},"loId":"454d0976-1ae0-42b9-9cd7-5b4d9634d928"} D [IoT]: iot_misc_info_store(1258) > Same misc_info, skip NV update D [IoT]: iot_nv_get_misc_info(941) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 11, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:11 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 11 D [IoT]: _iot_security_be_bsp_fs_load_from_nv(100) > id = 11 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './MiscInfo' D [IoT]: iot_security_storage_read(146) > id:11 read 115@0x74707e08 D [IoT]: iot_misc_info_store(1249) > Store raw msic_info str : {"dip":{"id":"d28e1384-f875-470c-94c6-b559c6257343","maj":0,"min":1},"loId":"454d0976-1ae0-42b9-9cd7-5b4d9634d928"} D [IoT]: iot_misc_info_store(1258) > Same misc_info, skip NV update D [IoT]: iot_nv_set_device_id(879) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 10, mode = 2 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_write(155) > id:10 D [IoT]: _iot_security_be_bsp_fs_store(256) > id = 10 D [IoT]: iot_bsp_nv_get_data_path(24) > >>>HIT<<< D [IoT]: _iot_security_be_bsp_fs_storage_id2filename(85) > storage file = './DeviceID' D [IoT]: iot_security_storage_write(182) > id:10 written 36@0x1dc6710 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:6/6 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _do_update_timeout(196) > Current timeout : 100000 for 6/7 I [IoT]: _do_status_report(300) > Call usr status_cb with 8/6 Connecting to server...signing in D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 6

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:6, curr_main_state:6/7 D [IoT]: iot_nv_get_serial_number(899) > >>>HIT<<< D [IoT]: _iot_nv_io_storage(103) > id = 17, mode = 1 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_storage_read(114) > id:17 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 17 D [IoT]: iot_nv_get_data_from_device_info(1072) > nv id = 17 D [IoT]: iot_security_storage_read(146) > id:17 read 16@0x74712060 D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: _iot_security_be_software_id_key2storage(112) > key id = 2 D [IoT]: _iot_security_be_software_id_key2storage(117) > storage id = 12 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 12 D [IoT]: iot_nv_get_data_from_device_info(1072) > nv id = 12 D [IoT]: iot_security_base64_decode(144) > src: 44@0x74712e00, dst: 32@0x74710498 D [IoT]: iot_security_base64_decode(152) > done: 32@0x74710498 D [IoT]: _iot_security_be_software_pk_load_ed25519_key(266) > key '2' is loaded 32@0x74710498 D [IoT]: _iot_security_be_software_id_key2storage(112) > key id = 1 D [IoT]: _iot_security_be_software_id_key2storage(117) > storage id = 13 D [IoT]: _iot_security_be_bsp_fs_load(187) > id = 13 D [IoT]: iot_nv_get_data_from_device_info(1072) > nv id = 13 D [IoT]: iot_security_base64_decode(144) > src: 44@0x74700b30, dst: 32@0x74710470 D [IoT]: iot_security_base64_decode(152) > done: 32@0x74710470 D [IoT]: _iot_security_be_software_pk_load_ed25519_key(266) > key '1' is loaded 32@0x74710470 D [IoT]: _iot_security_be_software_pk_get_key_type(456) > type = 1 D [IoT]: iot_security_pk_get_key_type(131) > type = 1 D [IoT]: iot_security_base64_encode(110) > src: 94@0x747110a8, dst: 129@0x747126f8 D [IoT]: iot_security_base64_encode(118) > done: 128@0x747126f8 D [IoT]: iot_security_base64_encode(110) > src: 79@0x74710fa0, dst: 109@0x747122a8 D [IoT]: iot_security_base64_encode(118) > done: 108@0x747122a8 D [IoT]: iot_security_pk_get_signature_len(93) > type = 1 D [IoT]: _iot_security_be_software_pk_get_key_type(456) > type = 1 D [IoT]: iot_security_pk_get_key_type(131) > type = 1 D [IoT]: iot_security_pk_sign(155) > input = 237@0x74704700 D [IoT]: _iot_security_be_software_pk_sign_ed25519(499) > input: 237@0x74704700 D [IoT]: _iot_security_be_software_pk_sign_ed25519(500) > seckey: 32@0x74710498 D [IoT]: _iot_security_be_software_pk_sign_ed25519(501) > pubkey: 32@0x74710470 D [IoT]: iot_security_pk_get_signature_len(93) > type = 1 D [IoT]: _iot_security_be_software_pk_sign_ed25519(526) > sig: 64@0x74701790 D [IoT]: iot_security_pk_sign(167) > sig = 64@0x74701790 D [IoT]: iot_security_base64_encode(110) > src: 64@0x74701790, dst: 89@0x74702190 D [IoT]: iot_security_base64_encode(118) > done: 88@0x74702190 D [IoT]: _iot_jwt_create(1026) > token: eyJhbGciOiJFZERTQSIsImt0eSI6Ik9LUCIsImNydiI6IkVkMjU1MTkiLCJ0eXAiOiJKV1QiLCJ2ZXIiOiIwLjAuMSIsImtpZCI6IlNUREtPRFZacWtXWlhvZmEifQ==.eyJpYXQiOiIxNjEzODQ0Nzk3IiwianRpIjoiMzlkZTZjOGEtMWMyOC00ZWFhLWEyOTUtOTJhNjI4NTg0MTEzIiwibW5JZCI6ImZFNGIifQ==./qR3hB5DBkjPCfu5fDTSkOyg8yU9ITEiSeP7NkL4PqiMlilRjf0d6iETEUpD/WbHfNYFeaw2ZXhiEh4bxX09DA== (326) I [IoT]: iot_es_connect(936) > connect_type: log-in I [IoT]: iot_bsp_wifi_get_mac(1729) > [rpi] Mac address requested I [IoT]: iot_bsp_wifi_get_mac(1744) > [rpi] Mac=b8:27:eb:24:af:d9 D [IoT]: iot_nv_get_certificate(802) > >>>HIT<<< D [IoT]: iot_security_be_init(1830) > security backend is 'software' D [IoT]: iot_security_manager_get_certificate(153) > cert id = 1 D [IoT]: iot_nv_get_static_certificate(1033) > cert id = 1 I [IoT]: _iot_es_mqtt_connect(810) > url: mqtt-regional-useast1.api.smartthings.com, port: 8883 I [IoT]: _iot_es_mqtt_connect(819) > mqtt connect, id : 156c49ce-f03f-430d-8aad-3fd71dff8a9b username : ad05ad4d-4294-4910-bf2e-68462561f6fa password : eyJhbGciOiJFZERTQSIsImt0eSI6Ik9LUCIsImNydiI6IkVkMjU1MTkiLCJ0eXAiOiJKV1QiLCJ2ZXIiOiIwLjAuMSIsImtpZCI6IlNUREtPRFZacWtXWlhvZmEifQ==.eyJpYXQiOiIxNjEzODQ0Nzk3IiwianRpIjoiMzlkZTZjOGEtMWMyOC00ZWFhLWEyOTUtOTJhNjI4NTg0MTEzIiwibW5JZCI6ImZFNGIifQ==./qR3hB5DBkjPCfu5fDTSkOyg8yU9ITEiSeP7NkL4PqiMlilRjf0d6iETEUpD/WbHfNYFeaw2ZXhiEh4bxX09DA== I [IoT]: _iot_net_tls_connect(166) > Loading the CA root certificate 1317@0x74710878 D [IoT]: _iot_net_tls_connect(184) > Connecting to mqtt-regional-useast1.api.smartthings.com:8883 D [IoT]: _iot_net_tls_connect(231) > Performing the SSL/TLS handshake D [IoT]: _iot_net_tls_connect(244) > Protocol is TLSv1.2 D [IoT]: _iot_net_tls_connect(245) > Ciphersuite is TLS-RSA-WITH-AES-128-CBC-SHA D [IoT]: _iot_net_tls_connect(247) > Verifying peer X.509 certificate D [IoT]: _iot_net_tls_write(320) > 417@0x74703be8 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1994 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1995 D [IoT]: _iot_net_tls_read(281) > 2@0x7470fa5a I [IoT]: iot_es_connect(956) > MQTT connect success sucess/try : 1/1 D [IoT]: iot_es_connect(960) > noti subscribe topic : /v1/notifications/ad05ad4d-4294-4910-bf2e-68462561f6fa D [IoT]: _iot_net_tls_write(320) > 61@0x74701790 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a6c D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a6d D [IoT]: _iot_net_tls_read(281) > 3@0x74700f0a D [IoT]: iot_es_connect(970) > cmd subscribe topic : /v1/commands/ad05ad4d-4294-4910-bf2e-68462561f6fa D [IoT]: _iot_net_tls_write(320) > 56@0x74701ac0 D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a6c D [IoT]: _iot_net_tls_read(281) > 1@0x750b1a6d D [IoT]: _iot_net_tls_read(281) > 3@0x7470fb9a D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x I [IoT]: _do_cmd_tout_check(981) > New state updated for 7 D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 10

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:7/7 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 I [IoT]: _do_update_timeout(196) > Current timeout : 100000 for 7/8 I [IoT]: _do_status_report(300) > Call usr status_cb with 8/2 Connected to MQTT server D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: iot_os_eventgroup_wait_bits(291) > read_size = 3 D [IoT]: _iot_main_task(1058) > cmd: 0

I [IoT]: _do_iot_main_command(450) > curr_main_cmd:0, curr_main_state:7/8 I [IoT]: iot_cap_call_init_cb(1074) > Call init_cb for contactSensor capability I [IoT]: st_cap_send_attr(559) > publish event, topic : /v1/deviceEvents/ad05ad4d-4294-4910-bf2e-68462561f6fa, payload : {"deviceEvents":[{"component":"main","capability":"contactSensor","attribute":"contact","value":"closed","providerData":{"sequenceNumber":1,"timestamp":"1613844798555"}}]} D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 Sequence number return : 1 I [IoT]: iot_cap_call_init_cb(1074) > Call init_cb for partyvoice23922.contactstatus capability I [IoT]: st_cap_send_attr(559) > publish event, topic : /v1/deviceEvents/ad05ad4d-4294-4910-bf2e-68462561f6fa, payload : {"deviceEvents":[{"component":"main","capability":"partyvoice23922.contactstatus","attribute":"contactStatus","value":"Closed","providerData":{"sequenceNumber":2,"timestamp":"1613844798555"}}]} D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x Sequence number return : 2 I [IoT]: iot_cap_call_init_cb(1074) > Call init_cb for partyvoice23922.zonebypass capability I [IoT]: st_cap_send_attr(559) > publish event, topic : /v1/deviceEvents/ad05ad4d-4294-4910-bf2e-68462561f6fa, payload : {"deviceEvents":[{"component":"main","capability":"partyvoice23922.zonebypass","attribute":"zoneBypass","value":"--","providerData":{"sequenceNumber":3,"timestamp":"1613844798555"}}]} D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x Sequence number return : 3 D [IoT]: iot_os_eventgroup_set_bits(320) > write_size = 3 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x D [IoT]: _iot_net_tls_write(320) > 231@0x74700c38 I [IoT]: _do_cmd_tout_check(981) > New state updated for 8

[toddaustin07]

Hello - Do you have any new thoughts on this provisioning issue that I reported?

I am now testing on a Raspberry Pi Zero W and this hang happens every time on this platform. It looks to be a breakdown in communication between the mobile app and the core SDK during a security key exchange.

'master secret generation success' is the last non-debug message that is displayed (line 147 in log file attached below) and then it hangs for a very long time (about 4 minutes) before timing out (line 171) . The mobile app never shows an error or times out.

I am now using an iPhone 12 with IOS version 14.3. (I was hoping a new mobile phone might solve the issue, but no!) and SmartThings mobile app version 1.6.64-490

Now that I can recreate this problem every time, do you have any further recommendations on how to debug this so we can figure out the problem?

Here the latest message log: msg.log

[toddaustin07]

Hello again. I have an additional log file that might be useful to help debug this issue. This is a tcp dump of traffic captured during an attempted onboarding when the error occurs. dump3.log

I'm afraid interpreting this file is beyond my expertise, but it may be of use to someone there.

As mentioned above, I am not able to successfully onboard a device app and the error occurs in the same place every time: 'Step 1' seems to complete ok, but it appears there is no response from the mobile app to begin 'Step 2'.

I've not gotten any responses from anyone on this problem lately, so PLEASE RESPOND!! I need your expertise to help figure out this problem, and now that I can reproduce it every time, we should be able find where things are hanging up between the mobile app and core SDK.

[Kwang-Hui]

Hi @toddaustin07 ,

Sorry for late responding. Unfortunately it is not easy for me to reproduce your issue on my side. The posix version is used only for unit test purpose on my side.

I don't believe there is any protocol level issues. I suspect performance or incompatible implementation of some posix porting layer.

To get more detailed information what you have trouble now. I posted two test commits here https://github.com/SmartThingsCommunity/st-device-sdk-c/pull/85

Could you please leave your device logs once again with adding above two commits?

Thanks.

Kwang-Hui Cho

[toddaustin07]

Thank you for your reply. I will add a time stamp log. I have one in seconds but I think you probably need milliseconds precision.

I don’t understand what you want for adding ‘event group’ to the log. Can you please clarify? How do I do this?

[Kwang-Hui]

I'm suspecting that it doesn't wakeup from the http response event at https://github.com/SmartThingsCommunity/st-device-sdk-c/blob/7bad26224142381bf0e24b371e480d42bdcfa6b9/src/easysetup/http/iot_easysetup_http.c#L263

    for( ; ; ) {
        curr_event = iot_os_eventgroup_wait_bits(ctx->iot_events,
                IOT_EVENT_BIT_EASYSETUP_RESP, true, IOT_OS_MAX_DELAY);
        if (curr_event & IOT_EVENT_BIT_EASYSETUP_RESP)
            break;
    }

I hope that adding more information by https://github.com/SmartThingsCommunity/st-device-sdk-c/pull/85/commits/7bad26224142381bf0e24b371e480d42bdcfa6b9 could help to clarify the problem.

[toddaustin07]

The Pi Zero is slower hardware than the Pi model 4 so I wonder if it is a timing issue. I see this same hang occasionally on the Pi model 4 but on Pi Zero it occurs EVERY time. Both are running same version of Raspberry Pi OS (based on Debian buster).

Further info for you: I’m working with someone else who is having same problem using Android phone (mine is iPhone), so problem doesn’t appear dependent on mobile app OS version.

[Kwang-Hui]

We have 5 min timeout, But that is sufficient time even on the MCU level device - which is much slower than Pi zero. And as you described above there are unnecessary 4 min waiting.

So I suspect that the incomplete port of eventgroup API makes this trouble.

[toddaustin07]

Hello - Here is the new log file with timestamp and eventgroup info:

newdebug.log

[Kwang-Hui]

Hi @toddaustin07 , I could see something strange from your log.

03/29/21 14:46:31.494 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x08x (8)

As you can see in the code here. the EVENT_MAX is 8. So the i shouldn't be 8. I'm not sure why this happen. https://github.com/SmartThingsCommunity/st-device-sdk-c/blob/7bad26224142381bf0e24b371e480d42bdcfa6b9/src/port/os/posix/iot_os_util_posix.c#L313

And one more thing, actually I updated the log printing part like below to add missing % (fixes 0x08x --> 0x%08x) please update your code also.

@@ -312,12 +312,12 @@ int iot_os_eventgroup_set_bits(iot_os_eventgroup* eventgroup_handle,

        for (int i = 0; i < EVENT_MAX; i++) {
         if (eventgroup->group[i].id == (eventgroup->group[i].id & eventgroup->event_status)) {
-            IOT_DEBUG("already set 0x08x", eventgroup->group[i].id);
+            IOT_DEBUG("already set 0x%08x (%d)", eventgroup->group[i].id, i);
             continue;
         }

[toddaustin07]

Here is the updated log: newdebug2.log

I see what you mean about i = EVENT_MAX. That is indeed strange. Could the continue statement be causing this? Or perhaps a threading or re-entrant issue?

You'll see in this new log that i < EVENT_MAX, so it is not always happening.

One more piece of information: I mentioned earlier I'm working with someone who is seeing this exact same problem and they sent me a new TCP log which seems to confirm that the mobile does send /keyinfo request, but Pi doesn't respond:

[Kwang-Hui]

I could see understand the few things.

1. i = EVENT_MAX Actually this wasn't happen. the log print has wrong because we missed 0x%08x. The eventgroup->group[i].id has printed at (%d) instead of i

   IOT_DEBUG("already set 0x08x (%d)", eventgroup->group[i].id, i);

2. The EasySetup flow goes like below. /deviceinfo --> /keyinfo --> /confirminfo --> ... But just like you mention with TCP log, iot-core couldn't respond for /keyinfo because the iot_os_eventgroup_set_bits for the IOT_EVENT_BIT_EASYSETUP_RESP doesn't wake up.

And this log is also very strange. because I can't find where the set_bits again for IOT_EVENT_BIT_EASYSETUP_RESP after iot_os_eventgroup_wait_bits with clear_on_exit as true.

03/29/21 20:13:27.955 D [IoT]: iot_os_eventgroup_set_bits(315) > already set 0x00000008 (3)

[Kwang-Hui]

I'd like to suggest you to trace the behavior of iot_os_eventgroup_wait_bits() for IOT_EVENT_BIT_EASYSETUP_RESP on your test device. basically the posix port uses select() method to pipe handle.

[toddaustin07]

select() function can be tricky to use; I have some experience with that 🙂 so I will look closely at that and try to have more tracing info for you when you get in tomorrow.

I very much appreciate your help with this!

[toddaustin07]

Good morning - I have a new log file for you and some thoughts:

1) I saw that _iot_easysetup_gen_post_payload was calling wait_bits with timeout of max IOT time value - an unsigned int. However this number is too big for Linux time_t which is implemented with long int. I thought maybe the millisecond conversion for the timeval structure was corrupting the stack. I put in some code to check for it and pass NULL to select in that case, since that is the proper way to wait with block. Unfortunately this didn't solve our problem, but probably should be addressed in the code nevertheless.

2) Another possible issue is with fd_max list so I've added some log messages to display that info to make sure the select list is including the right fd for response.

3) I was concerned about the effects of multi-threading since the wait_bits function updates the global variable eventgroup->event_status in the case of clear_on_exit, so I added a mutex to see if that might fix the problem with the response bit being already set.

4) I tried setting the timeout value parameter from iot_easysetup_gen_post_payload to 5 seconds instead of block to force a re-invocation of wait_bits and this appears to have gotten the processing a step further as you'll see in the log. However then there was an Invalid command sequence error and an HTTP bad request error.

I'm still trying different things, but wanted to get this log posted for you to see in case you have any ideas.

newdebug5.log

[toddaustin07]

Another thought occurred to me: when I have used select() myself in other projects, I know that you have to re-initialize the fd list each time you call it because when it returns, it modifies the list you passed into it. I don't know how thread-safe select() is. Since the wait_bits routine appears to be called by multiple threads & functions, I am wondering if our resp fd is being removed from another thread or function invoking select() prior to being called by _iot_easysetup_gen_post_payload.

If this were the case then code would need to be added to restore all 'un-processed' fd's after each select() call. This is what I have had to do in my own code when using select(). However, since _iot_easysetup_gen_post_payload issues a blocking call, I don't know if the fd being added back would get picked up by that thread??

[toddaustin07]

If wait_bits times out for a RESP bit call, it returns eventgroup->event_status, which seems to have the bit still set. So event_status bit seems to not have gotten cleared from prior step.

There seem to be multiple functions setting the RESP bit. In the logs you can see the 'already set' messages, even though the last time it was cleared. That is strange.

I am having a hard time understanding the purpose of eventgroup->group[i].id vs. eventgroup->event_status. It's not clear to me how and where these two values are set and reset, but it seems to be a synchronization problem between them.

[toddaustin07]

Here is a log where I dump out eventgroup at every entry and exit of wait_bits and set_bits. The multi-threading makes it challenging to follow in places. You'll also have to scroll through all the wait_bits calls that timeout, but at least it's complete!

newdebug9.log

[Kwang-Hui]

Hi @toddaustin07 Thanks for your investigation. I'll also look into the log you attacked. It would takes some time.

[toddaustin07]

OK thanks. I think I'm getting closer to the problem.

There are synchronization issues between the set and wait functions around the event_status value. There also seems to be a problem where _iot_easysetup_gen_post_payload is expecting event_status to be set with RESP bit upon return from wait_bits call, but the wait_bits function doesn't ever update event_status with the bits value. (It only uses the NOT value to clear).

Actions I'm trying: 1) protect all of set_bits execution with a mutex 2) add eventgroup->eventstatus |= bits; to end of wait_bits function -- OR-- changing _iot_easysetup_gen_post_payload logic where it calls wait_bits to match that used in the _iot_easysetup_gen_get_payload, which doesn't use a for loop and doesn't check RESP bit upon return from wait_bits. (WHY DO THESE FUNCTIONS USE DIFFERENT LOGIC TO CALL WAIT_BITS??!)

Will keep you posted.

[toddaustin07]

Last log for today: I made progress getting to the next step but am running into a an invalid command sequence error and HTML errors, so something else must be broken still. Here's my last log for today!...

I've cut down on the log messages so you don't have to scroll through all the select() timeout cases.

newdebug15.log

[Kwang-Hui]

OK thanks. I think I'm getting closer to the problem.

There are synchronization issues between the set and wait functions around the event_status value. There also seems to be a problem where _iot_easysetup_gen_post_payload is expecting event_status to be set with RESP bit upon return from wait_bits call, but the wait_bits function doesn't ever update event_status with the bits value. (It only uses the NOT value to clear).

Actions I'm trying:

1. protect all of set_bits execution with a mutex
2. add eventgroup->eventstatus |= bits; to end of wait_bits function -- OR-- changing _iot_easysetup_gen_post_payload logic where it calls wait_bits to match that used in the _iot_easysetup_gen_get_payload, which doesn't use a for loop and doesn't check RESP bit upon return from wait_bits. (WHY DO THESE FUNCTIONS USE DIFFERENT LOGIC TO CALL WAIT_BITS??!)

Will keep you posted.

I agree with your opinion. this log indicates there is some synchronization issue between posix version of eventgroup apis. let me think how to resolve this.

[Kwang-Hui]

Could you try with this https://github.com/SmartThingsCommunity/st-device-sdk-c/pull/85/commits/25497ab73ba2277bb8166f323150c044a59bc5c4 commit?

[garrettpatterson]

Built the posix-debug branch: still appears to hang/not respond to the /keyinfo request, output log attached.

Reviewing the TCP dump - the connection appears to continue to be active with TCP keep-alive pings between the Pis AP and mobile device (I'm on an Android pixel 4a) until it resets itself back to wifi.

st-device-sdk-c-example_log_202103311122.txt

[toddaustin07]

Hi Kwang-Hui - Thanks very much for your code changes. They are similar to the mutex I had tried earlier yesterday, but unfortunately your version still produces the same result that I reported yesterday with a command sequence error after /keyinfo.

It is quite strange because the POST /keyinfo message is received OK now, but when the next message is received (line 88 in log below) it looks like the expected message, but for some reason the parser is reporting another /keyinfo uri instead of /confirminfo uri. As a result, the cmd step is not being advanced.

I added some debug messages so you can see this and also track the cur_step and ref_step values. See lines 99-102 in my log below.

mutexfix1.log

Do you have any ideas?

And thanks Garrett for commenting as well!

[Kwang-Hui]

Hi @garrettpatterson @toddaustin07 , Thanks for your updates.

The log from @garrettpatterson still shows eventgroup_wait_bits doesn't respond properly.

But the log from @toddaustin07 is different. eventgroup_wait_bits has worked. But it fails with other reasons. The iOS version of ST app still uses connection-closed method, so the socket should be closed after sending respond of /keyinfo from device just like below logs (captured from mutexfix1.log)

03/31/21 13:27:17.563 W [IoT]: http_packet_read(103) > peer connection closed
03/31/21 13:27:17.563 I [IoT]: http_cleanup_accepted_connection(59) > close accept socket

@toddaustin07 , Could you add addtional debug logs like below?

--- a/src/easysetup/http/tcp/iot_easysetup_httpd.c
+++ b/src/easysetup/http/tcp/iot_easysetup_httpd.c
@@ -24,6 +24,7 @@
 #ifdef CONFIG_STDK_IOT_CORE_EASYSETUP_HTTP_USE_SOCKET_API
 #include "iot_easysetup_http_socket.h"
 #endif
+#include "iot_util.h"

 #define RX_BUFFER_MAX    1024

@@ -68,7 +69,7 @@ static int process_accepted_connection(HTTP_CONN_H *handle)
                        }
                        return err;
                }
-
+               IOT_DEBUG(">>> %s", rx_buffer);
                content_len = 0;
                err = es_msg_parser(rx_buffer, sizeof(rx_buffer), &payload, &cmd, &type, &content_len);

@@ -84,6 +85,8 @@ static int process_accepted_connection(HTTP_CONN_H *handle)
                        payload = rx_buffer + http_request_header_len;
                }

+               iot_util_dump_mem("dump", (uint8_t*) payload, content_len);
+
                if(err != IOT_ERROR_NONE) {
                        http_msg_handler(cmd, &tx_buffer, D2D_ERROR, payload);
                }
@@ -108,6 +111,7 @@ static int process_accepted_connection(HTTP_CONN_H *handle)
                        IOT_ES_DUMP(IOT_DEBUG_LEVEL_ERROR, IOT_DUMP_EASYSETUP_SOCKET_SEND_FAIL, errno);
                        return IOT_ERROR_EASYSETUP_INTERNAL_SERVER_ERROR;
                }
+               IOT_DEBUG("http_packet_send result: %d", len);
        }
 }

[Kwang-Hui]

I updated code diff for logging

--- a/src/easysetup/http/tcp/iot_easysetup_httpd.c
+++ b/src/easysetup/http/tcp/iot_easysetup_httpd.c
@@ -24,6 +24,7 @@
 #ifdef CONFIG_STDK_IOT_CORE_EASYSETUP_HTTP_USE_SOCKET_API
 #include "iot_easysetup_http_socket.h"
 #endif
+#include "iot_util.h"

 #define RX_BUFFER_MAX    1024

@@ -68,7 +69,7 @@ static int process_accepted_connection(HTTP_CONN_H *handle)
                        }
                        return err;
                }
-
+               IOT_DEBUG(">>> %s", rx_buffer);
                content_len = 0;
                err = es_msg_parser(rx_buffer, sizeof(rx_buffer), &payload, &cmd, &type, &content_len);

@@ -84,6 +85,8 @@ static int process_accepted_connection(HTTP_CONN_H *handle)
                        payload = rx_buffer + http_request_header_len;
                }

+               iot_util_dump_mem("dump", (uint8_t*) payload, content_len);
+
                if(err != IOT_ERROR_NONE) {
                        http_msg_handler(cmd, &tx_buffer, D2D_ERROR, payload);
                }
@@ -108,6 +111,7 @@ static int process_accepted_connection(HTTP_CONN_H *handle)
                        IOT_ES_DUMP(IOT_DEBUG_LEVEL_ERROR, IOT_DUMP_EASYSETUP_SOCKET_SEND_FAIL, errno);
                        return IOT_ERROR_EASYSETUP_INTERNAL_SERVER_ERROR;
                }
+               IOT_DEBUG("http_packet_send result: %d", len);
        }
 }

[toddaustin07]

Here you go....

mutexfix2.log

Strange that there are two /keyinfo sent, but is that really the case? Are we seeing another synchronization issue?

[Kwang-Hui]

I think the mutexfix1.log , mutext2.log shows that evetgroup problem has fixed.

The multiple /keyinfo is different story. log sniff from mutexfix1.log says /keyinfo is called approx. 3 seconds period.

03/31/21 13:27:17.571 D [IoT]: es_msg_parser(83) > method=POST, uri=/keyinfo
...
03/31/21 13:27:20.901 D [IoT]: es_msg_parser(83) > method=POST, uri=/keyinfo
...
03/31/21 13:27:24.013 D [IoT]: es_msg_parser(83) > method=POST, uri=/keyinfo

Currently the iOS application repeats same http api again if the device doesn't send response packet within 3 seconds.

We could suspect that the response packet is still buffered in the device inside. (185 bytes isn't big enough to filling tcp buffer depends on system configuration) Actually to avoid this kind of buffering problem, SDK code sets TCP_NODELAY option like below https://github.com/SmartThingsCommunity/st-device-sdk-c/blob/00921d860059a6563053838a22f2c452cc72ccfc/src/easysetup/http/tcp/iot_easysetup_http_socket.c#L196

If you can analysis TCP dump like previous, we can make it clear.

[toddaustin07]

Garrett had a better TCP dump utility than mine - at least it seemed to show more readable output. Let me try running the one I have, but I'll ask Garrett what he's using.

[toddaustin07]

Here's my TCP dump:

newtcp.log

This one may be more useful, as it shows the data being transferred:

tcpdata.log

My observations:

EDIT: Well after I posted this I added some more debugging messages and I do now see the entire /keyinfo message displayed in the payload debug print. So I guess the entire message is being received, so now I don't have an explanation! . . . . . . .

The first I notice is that when the /keyinfo post is sent, it's supposed to have a content length of 324, but I don't see that data ever being sent on the initial try. I've noticed in the log files when there are retries after the initial error, in some of those retries, there was a more complete payload shown from the /keyinfo message. Here is an example of data that shows up in later retries, but not in initial receipt of /keyinfo:

03/31/21 13:27:24.013 D [IoT]: es_msg_parser(83) > method=POST, uri=/keyinfo 03/31/21 13:27:24.014 D [IoT]: es_msg_parser(178) > payload : { "timezoneid" : "QW1lcmljYS9DaGljYWdv", "spub" : "-KMSUxUQEOm1td5SQAIiIcgC4MYU_aTI3q1PduZLpxk=", "regionaldatetime" : "MjAyMS0wMy0zMVQxMy4yNy4xNyAtMDUwMA==", "datetime" : "MjAyMS0wMy0zMVQxOC4yNy4xNyArMDAwMA==", "rand" : "NDFhYTRmYzE2N2RlYTE4MzI4Yzk1OWRmNWE4ZTBlMTYyYzU2NGIyNWI5MGQ1YTM3ZDdhNWFhNGI1ZTg4N2NmNQ==" }

So this may be the problem - for some reason the Pi isn't consistently receiving the entire /keyinfo message. If you keep looking further down in the second TCP log above - when the mobile app tries to send /keyinfo again after the initial fail, that time it was able to send both parts of the message. So that's the issue, the handling on the Pi side of multi-part messages. Sounds like a TCP-level issue or some TCP configuration parameter is not working as expected... OR there is a problem with the http_packet_read_remaining function in iot_easysetup_httpd.c.

It looks to me like the Pi is sending the proper /keyinfo response back to mobile, but because the prior post didn't get sent completely, the mobile simply ignores the response and tries to resend /keyinfo message.

I noticed that none of the responses from core have a end-message delimiter on them. (\0d\0a\0d\0a) Does this matter?

[toddaustin07]

Sorry about the red herring in my prior post, I was partially fooled by printing payload before the second receive. It appears from my testing that sometimes that /keyinfo message is sent in one chunk and sometimes in two chunks.

However it still concerns me that in the TCP log I posted earlier today, it does show that the second chunk of the /keyinfo message was never sent in one case. That may be a whole other TCP-level reliability problem, because as you'll see in my updated logs below, that was not a problem in this new test. But the eventual resend of /keyinfo still occurred.

So now I'm back to thinking that maybe something is wrong with the /keyinfo response message, since the TCP log again shows a strange 'double ACK' for that message by the mobile device, and then mobile device proceeds to resend the /keyinfo message.

Here are current updates to both the TCP and core message logs (they are from the same test): mutexfix3.log tcpdump3.log

[Kwang-Hui]

Sorry about the red herring in my prior post, I was partially fooled by printing payload before the second receive. It appears from my testing that sometimes that /keyinfo message is sent in one chunk and sometimes in two chunks.

However it still concerns me that in the TCP log I posted earlier today, it does show that the second chunk of the /keyinfo message was never sent in one case. That may be a whole other TCP-level reliability problem, because as you'll see in my updated logs below, that was not a problem in this new test. But the eventual resend of /keyinfo still occurred.

So now I'm back to thinking that maybe something is wrong with the /keyinfo response message, since the TCP log again shows a strange 'double ACK' for that message by the mobile device, and then mobile device proceeds to resend the /keyinfo message.

Here are current updates to both the TCP and core message logs (they are from the same test): mutexfix3.log tcpdump3.log

Thanks for sending update. If you don't mind, Could you send me the whole pcap with tcpdump -w test.pcap from Rasp. pi W?

My observation about iOS's POST behavior was sending two chunks separated by HTTP header and body part always. That's why SDK uses http_packet_read_remaining() is exist.

I also could see something strange from tcpdata.log. The header chunk for /keyinfo is exist. but can't find the body part. but the device sent "200 OK" response with proper answer. I think something missed at the tcpdump at that time.

I'll look at newly attached logs and get back to you. (mutexfix3.log, tcpdump3.log)

[toddaustin07]

Hi again - I thought I'd post a TCP log of a WORKING provisioning session on a Pi Model 4 so we can compare.

You'll see in this one that there is no strange second ACK given by the mobile for the /keyinfo response; and things go on properly from there.

tcpworking.log

[toddaustin07]

Here is the the entire tcpdump file as you requested. I let it run until the core timed out after 4 min. I had to add the '.log' to the file name in order to be able to post it here...

test.pcap.log

[Kwang-Hui]

Thanks for the pcap log.

Could you send the iOS ST app log to us? I'll send you video tutorial how to collect ST app log.

[garrettpatterson]

So... excited to report after a fresh reboot on the PI, pull from the posix-debug branch and rebuild I had a successful device onboarding. Log attached - after onboarding I'm having some device errors which I think are just related to my device config setup and what the example project was built as but it's making requests. I'll be curious what @toddaustin07 finds.

When I stop the process and re-start it properly went back into device mode and making requests.

Reminder on my specs: Raspberry Pi Zero W, full Raspbian Buster (10) ST Mobile App in Developer mode on a Pixel 4a.

Couldn't get a TCPdump of this run.

st_device_sdk_c_log_successful_20210401.txt

[toddaustin07]

Garrett- that's fantastic! Did you happen to capture a log when you onboarded? The one you attached seems to be post-onboarding.

[toddaustin07]

Garrett - I know you may not want to mess with it now that it's working, but if you have a chance..... Are you still running with sudo to get around the time-set issue? If you are that means you are letting the core SDK set your clock. I had put in a dummy return for that request in /src/port/bsp/posix/iot_bsp_system_posix.c and I am still running that way (without sudo). I'll attach my replacement file below. I'd be curious to see if this has any effect for you. I will also re-enable that time check on my end to see if it makes a difference.

Reason I'm curious about this is that (if I understand things correctly) the master secret that gets sent back to mobile device after /keyinfo request I think gets generated partially based on the system clock. Therefore if there is anything that the mobile app doesn't like about the key, that may be causing it to re-request. Just a guess....

iot_bsp_system_rpi.c.txt

**UPDATE: Didn't seem to matter on my end unfortunately; I will try a clean slate approach like you did and see how that goes. I haven't even rebooted in quite a while!

[toddaustin07]

Kuang-Hui - I sent my mobile app log to you via email per your request.

What I see is this:

2021-04-01 01:33:34.154 [530086] [E] StdkOnboardingClient(191):sendRequest(_:with:type:isEncryptedResponse:) - [StdkOnboarding] Reqeust failed: http://192.168.2.1:8888/keyinfo, `nil`
2021-04-01 01:33:34.156 [527587] [W] StdkPresenters(510):start(dataModel:_:) - [StdkOnboarding] error: failedToSendPostKeyInfo(details: "The operation couldn’t be completed. (SmartThingsOnboarding.StdkConstants.OnboardingError error 28.)")

It doesn't say WHY the request failed, but it's probably not receiving the response for some reason - even though we know it is being sent by looking at the TCP log.

Does iOS need a '\0d\0a\0d\0a\" delimiter at the end of the response message? I noticed it has none. Does "error 28" give us any other clues?

Based on the tcpdump log, the mobile app seems to be wanting more data after the response is sent, since it doesn't close the connection right away but instead sends a generic ack again after .5 second. Could it be that there is something about the message content itself that the mobile app is rejecting?

[garrettpatterson]

EDIT/UPDATE - provisioning still works when running as sudo

Made the update that @toddaustin07 had suggested https://github.com/SmartThingsCommunity/st-device-sdk-c/issues/71#issuecomment-812091147 . The settime still appears to be an issue but we are now getting HTTP responses sent back vs just appearing to "hang" after the /keyinfo.

Should be more complete log output, and the HTTP response/requests (from 2 attempts to device onboard) for the failed onboarding:

settimeadjustlogs.pcap.txt run_log_202104011225.txt

When I run the same code as sudo the onboarding still works successfully sudosuccess.pcap.txt run_log_success_202104011256.txt

It may be my edits just didn't make it into the build... not savvy enough to troubleshoot the C-side of things.

[toddaustin07]

Hi Garrett -

Regarding the timeset issue, do this and rebuild; it's still picking up the original file:

cd ~/st-device-sdk-c/src/port/bsp/posix
mv iot_bsp_system_posix.c iot_bsp_system_posix.ORIGc
cd ~/st-device-sdk-c/build
rm stdk_iot_bsp_system_posix.o

After that you shouldn't have to use sudo since the timeset is skipped.

So I tried what you did: rebooted and did a fresh pull of the posix-debug branch. Got more than just the mods for this particular issue:

src/deps/mbedtls/Makefile
src/easysetup/http/tls/iot_easysetup_http_tls.c src/include/iot_capability.h
src/include/st_dev.h
src/include/st_dev_version.h
src/iot_api.c
src/iot_capability.c
src/port/bsp/posix/iot_bsp_debug_posix.c
src/port/net/mbedtls/iot_net_mbedtls.c
src/port/os/posix/iot_os_util_posix.c
src/port/os/tizenrt/iot_os_util_tizenrt.c
test/TC_FUNC_iot_wt.c
tools/keygen/README.md
tools/keygen/stdk-keygen.py

Unfortunately I continue to get the same error. Perhaps this narrows things down to an IOS issue!

[toddaustin07]

I found the problem! I had originally copied an existing (but unused) device_info.json file over from another Pi to use on the Pi Zero for my tests. When I remembered this today, I tried creating a fresh serial number on the Zero, added it to Developer Workspace, and it onboarded without a problem! I went back and looked at the prior keys I was using and it looks like there was a wrong digit (0 instead of O) in the public key loaded into Developer Workspace. I feel badly that I caused this problem and I apologize for the time wasted. And I will never try to re-type a key sequence again!

At least we also fixed a real problem, which was the need for a mutex in the iot_os_util_posix module. I'm very glad to now have a much more reliable onboarding experience, and I feel I can get my rpi package out of beta now! I'm also excited to be able to support Pi Zero W because it's really an ideal platform for creating device apps linked to SmartThings.

Kwang-Hui, can you please confirm that this fix will get included in an upcoming release of the SDK? We can close this issue, as well as Issue #74, which was related. I opened a new one to fix a minor debug message problem I found during all this testing.

Thanks so much for all the assistance and again, I am very sorry to be the cause of this last problem.

p.s. Registration to the SmartThings MQTT server is MUCH faster today; thank-you for that too!

[Kwang-Hui]

Good news!

Yes, the fix of posix eventgroup would be part of next release. I also realized that we need to update the log message of payload print what you mentioned at https://github.com/SmartThingsCommunity/st-device-sdk-c/issues/87.

Thanks

[Kwang-Hui]

This issue is closing now. If you need further discussion, please open new issue again.

Thanks.