toddaustin07 / rpi-st-device

Info & files needed for PI-based IOT devices connecting to Samsung SmartThings
22 stars 6 forks source link

Segmentation Fault #1

Closed Delgreco007 closed 3 years ago

Delgreco007 commented 3 years ago

Just gave your RPi onboarding a try on my RPi4 (c03112). I made it almost all the way through when I get this while trying to run the example code:

I [IoT]: _dump_device_info(664) > firmware_version: switch_example_000 I [IoT]: iot_bsp_wifi_init(142) > [rpi] iot_bsp_wifi_init E [IoT]: _initDevNames(445) > [rpi] Unexpected Ethernet device name I [IoT]: iot_bsp_wifi_init(158) > [rpi] No Ethernet I [IoT]: iot_bsp_wifi_init(168) > [rpi] Wifi station device wlan0 found I [IoT]: iot_bsp_wifi_init(221) > [rpi] Wifi Initialization Done I [IoT]: st_conn_init(1302) > stdk_version : 1.5.7 I [IoT]: st_conn_start(1771) > st_conn_start start (no-pin) I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:-1/-1 I [IoT]: _do_update_timeout(196) > Current timeout : 100000 for -1/0 I [IoT]: _do_status_report(300) > Call usr status_cb with 1/0 iot_status: 1, lv: 0 I [IoT]: _do_iot_main_command(450) > curr_main_cmd:2, curr_main_state:-1/0 E [IoT]: _iot_security_be_bsp_fs_load_from_nv(129) > iot_bsp_fs_open(./WifiProvStatus) = -1208 I [IoT]: _do_cmd_tout_check(981) > New state updated for 0 I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:0/0 I [IoT]: iot_bsp_wifi_set_mode(856) > [rpi] Requested mode SCAN I [IoT]: _perform_scan(1596) > [rpi] Running Wifi AP scan using wlan0 command failed: Device or resource busy (-16) I [IoT]: _perform_scan(1596) > [rpi] Running Wifi AP scan using wlan0 command failed: Device or resource busy (-16) I [IoT]: iot_bsp_wifi_set_mode(868) > [rpi] WiFi scan completed. 0 APs found I [IoT]: iot_bsp_wifi_get_scan_result(1552) > [rpi] Get scan result requested I [IoT]: iot_easysetup_create_ssid(101) > >> Test_Switch[ocdC] << I [IoT]: _do_update_timeout(196) > Current timeout : 300000 for 0/1 I [IoT]: _do_iot_main_command(450) > curr_main_cmd:1, curr_main_state:0/1 I [IoT]: iot_bsp_wifi_set_mode(939) > [rpi] Requested mode SoftAP Segmentation fault

I do actually have ethernet. I think the problem is that your code expects eth0 to be the first listed and docker0 is actually first listed on my system. The subsequent error I have not figured out.

toddaustin07 commented 3 years ago

Hi - thanks for leaving the info.

I've never tested in docker environment so you'll have to help me understand the environment. What O/S image are you using? Are you running without a desktop?

I'm editing my original reply after some additional thought...

Regarding your ethernet config, help me understand what it looks like under docker. That one sounds like an easy fix. Can you show me the output of ifconfig? Also, what do you have in /sys/class/net? Is docker0 there as well? What exactly is docker0?

It looks like there is a problem using the wifi to do an AP scan; two attempts were made and nothing came back. You can see in the log where it says device is busy. I have encountered device busy messages occasionally before and wonder if docker is compounding the problem. I may need to increase the retries to overcome this issue. See if you have any problem doing it manually from a terminal within docker: sudo iw wlan0 scan. (Are there any issues with running sudo commands?)

Regarding the subsequent fault:

Did you test hostapd and dnsmasq by themselves and were they going into SoftAP mode ok before you tried running the example app?

The SSID I see in your log file is not what I would expect to see. It should be made up of your device serial number, not "Test_Switch" and some garbage. This looks like the example app is picking up a default device_info.json file. Did your device serial number get correctly generated by the keygen tool and the new device_info.json copied into your example directory? All that should have been done automatically for you if you used the mastersetup script (did you, or did you set up manually?)

That shouldn't cause a segmentation fault, but maybe it is. But I'm wondering if there is something else going wrong. Can you tell me your directory structure? Anything unusual within docker environment? I'm wondering if there are extra-long path names that could be blowing a buffer.

Let me explain the sequence of events after the last log message you saw - 'Requested mode SoftAP':

  1. hostapd.conf is modified with ssid and pw based on your device serial number (this didn't look right in the log)
  2. dhcpcd is restarted in AP mode (did you notice if this happened?)
  3. hostapd & dnsmasq are started. At this point you should see the SSID based on device serial showing up on your mobile phone as a live wireless access point (did you notice if this happened?)

A couple other environmental questions: Is your wifi in regular managed mode normally? Was it connected to your router when you started? Can you tell me about your directory structure? What is the full pathname where rpi-st-device folder is located? Anything else unusual within a docker environment?

Hope you don't mind the many questions. I'm keen to help you get this working!

toddaustin07 commented 3 years ago

I've updated the wifi module to hopefully fix the ethernet issue, and I've increased the number of retries on the AP scans to hopefully get passed "device busy" errors on the wifi.

The segmentation fault still perplexes me, but I suspect is has something to do with a bad SSID, which in turn is likely from a problem with your device_info.json file. (Make sure you had copied the one that got created by the keygen tool into the example directory). The core SDK builds the SSID from the device serial number in that file.

Make sure you've downloaded the onboarding_config.json file from Developer Workspace and put it into the example directory as well.

If you haven't touched anything since the error, let me know the contents of /etc/hostapd/hostapd.conf. It would help to see if that had gotten updated prior to the segmentation fault.

One last thing to help you recover from errors: if when trying to run the example app, if an error occurs and the code can't recover (like the segmentation fault), your wifi could get left in SoftAP mode. Use the resetAP tool in the rpi-st-device directory to reset your wireless back to regular station mode in that case. For errors other than a segmentation fault that kills the process, often times the core SDK can recover, but you have to be patient and wait for it to timeout. It will usually reset the wireless back to station mode when it can and then just go to sleep. At that point you can safely Ctrl-c out of the app.

I'll wait to hear back from you with any further comments before I post the updated file.

Delgreco007 commented 3 years ago

I appreciate the suggestions, and I will give them a try and report back when I have a chance. I've had a couple of 13 hour work days, so I'm a bit exhausted at the moment.

It probably helps to know that I have not actually been trying to run it inside a docker container; I just happen to have docker installed on the pi already and docker0 is listed before eth0 in /sys/class/net.

I did the setup manually, and everything seemed to go well with the keygen. I did copy the onboarding_config.json and device_info.json (or at least I think I did; I didn't confirm that the original files were overwritten).

SoftAPConfig worked, although I think had to edit the file to add my model Pi before I could run it. testhostapd also worked fine.

I happen to have changed my home directory from /home/pi to /home/phillip on this particular pi, so I had to fix a few hard-coded references in at least one file (I think one of the c files). Everything compiled fine after I made that change though.

toddaustin07 commented 3 years ago

Ok, I'll go ahead and post the updated file tonight. Do let me know where you had to fix a directory reference so I can address that too.

When you get some rest(!), follow these steps:

cd rpi-st-device git pull origin main cp iot_bsp_wifi_rpi.c ~/st-device-sdk-c/src/port/bsp/posix/iot_bsp_wifi_rpi.c cd st-device-sdk-c make cd example rm example make

Delgreco007 commented 3 years ago

Okay, we're getting somewhere. With your changes, the eth0 problem has been fixed. Device busy has also been fixed.

The #include in iot_bsp_wifi_rpi.c has several references to /home/pi/... which obviously prevent compilation if you have a different home directory.

device-info.json and onboarding_config.json had both already been updated (by myself) as expected. However, hostapd.conf is not being updated with the device serial number when running ./example (see below). And as you noted previously, the device serial number is not being picked up in the log. Those are presumably related, although I'm not sure why it's happening.

hostapd.conf: country_code=US interface=wlan0 ssid=MyPiTestAccessPoint hw_mode=g channel=1 macaddr_acl=0 auth_algs=1 wpa=3 wpa_passphrase=11111111 wpa_key_mgmt=WPA-PSK wpa_pairwise=TKIP rsn_pairwise=CCMP

Log: I [IoT]: _dump_device_info(664) > firmware_version: switch_example_000 I [IoT]: iot_bsp_wifi_init(148) > [rpi] iot_bsp_wifi_init I [IoT]: iot_bsp_wifi_init(149) > [rpi] wifi module version 20210210 I [IoT]: iot_bsp_wifi_init(163) > [rpi] Ethernet connection available: eth0 I [IoT]: iot_bsp_wifi_init(175) > [rpi] Wifi station device wlan0 found I [IoT]: iot_bsp_wifi_init(228) > [rpi] Wifi Initialization Done I [IoT]: st_conn_init(1302) > stdk_version : 1.5.7 I [IoT]: st_conn_start(1771) > st_conn_start start (no-pin) I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:-1/-1 I [IoT]: _do_update_timeout(196) > Current timeout : 100000 for -1/0 I [IoT]: _do_status_report(300) > Call usr status_cb with 1/0 iot_status: 1, lv: 0 I [IoT]: _do_iot_main_command(450) > curr_main_cmd:2, curr_main_state:-1/0 E [IoT]: _iot_security_be_bsp_fs_load_from_nv(129) > iot_bsp_fs_open(./WifiProvStatus) = -1208 I [IoT]: _do_cmd_tout_check(981) > New state updated for 0 I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:0/0 I [IoT]: iot_bsp_wifi_set_mode(862) > [rpi] Requested mode SCAN I [IoT]: _perform_scan(1612) > [rpi] Running Wifi AP scan using wlan0 I [IoT]: iot_bsp_wifi_set_mode(880) > [rpi] WiFi scan completed. 3 APs found I [IoT]: iot_bsp_wifi_get_scan_result(1568) > [rpi] Get scan result requested I [IoT]: iot_easysetup_create_ssid(101) > >> Test_Switch[ocdC] << I [IoT]: _do_update_timeout(196) > Current timeout : 300000 for 0/1 I [IoT]: _do_iot_main_command(450) > curr_main_cmd:1, curr_main_state:0/1 I [IoT]: iot_bsp_wifi_set_mode(955) > [rpi] Requested mode SoftAP Segmentation fault

toddaustin07 commented 3 years ago

I need to search my memory; I vaguely remember seeing that strange SSD in the log during my early development.

The device_info.json file is sucked into the example app and passed to the core SDK at initialization. It's obviously making it passed that step, so it certainly doesn't seem that it is corrupted. The core SDK calls my code when it wants to go into AP mode and passes the SSID that it creates from the serial number. It - or the password, which is also passed - must be a bad string, thus causing the segmentation fault. But why........ It's crapping out before I can update hostapd.conf.

Did you notice if your wifi mode changed before the segmentation fault?

Let me step through everything again and I'll get back to you.

toddaustin07 commented 3 years ago

Three things: 1) what version of Pi O/S are you using? 2) can you post the results of sudo iw wlan0 scan? 3) can you think of anywhere you used the text "Test_Switch" ? I'm trying to figure out where that string even comes from.

A couple things to check:

Might be worthwhile to post your device_onboarding.json and device_info.json files so I can confirm everything looks right there.

Delgreco007 commented 3 years ago

I popped in a different RaspbianOS 32 - Buster sdcard I had, and I got things working without too much hassle. As for the problematic system:

  1. RaspbianOS 64 - Buster running off an SSD
  2. See below
  3. Yes, that's the name of my device in the device profile in Developer Workspace.

Both of those files were replaced and the originals were renamed.

BSS 4c:ed:fb:8f:ba:60(on wlan0) -- associated last seen: 224.885s [boottime] TSF: 0 usec (0d, 00:00:00) freq: 2457 beacon interval: 100 TUs capability: ESS Privacy ShortSlotTime RadioMeasure (0x1411) signal: -51.00 dBm last seen: 0 ms ago SSID: Harpoon Supported rates: 1.0 2.0 5.5 11.0 18.0 24.0 36.0 54.0 DS Parameter set: channel 10 TIM: DTIM Count 2 DTIM Period 3 Bitmap Control 0x0 Bitmap[0] 0x0 ERP: Barker_Preamble_Mode Extended supported rates: 6.0 9.0 12.0 48.0 RSN: * Version: 1

Delgreco007 commented 3 years ago

{ "deviceInfo": { "firmwareVersion": "switch_example_000", "privateKey": "---", "publicKey": "xyzlpl19cyBvWX8uQP0f4iNHa6C/vBk+KUIqLAlI4ws=", "serialNumber": "STD---ocdC" } }

Delgreco007 commented 3 years ago

{ "onboardingConfig": { "deviceOnboardingId": "Test_Switch", "mnId": "0--g", "setupId": "000", "vid": "ST_7d21f133-da09-41da-a4b1-2b3151532b4e", "deviceTypeId": "Switch", "ownershipValidationTypes": [ "JUSTWORKS" ], "identityType": "ED25519", "deviceIntegrationProfileKey": { "id": "c45646f0----c6dd01f84db4", "majorVersion": 0, "minorVersion": 1 }, "productId": "af0d69a4----522718ad6b34" } }

toddaustin07 commented 3 years ago

I was barking up the wrong tree looking at that ssid create-related log message. That is indeed normally your device onboarding ID. And the 4 characters in brackets is your mnid (ocdC from your log). Looks like you generated a new serial number since you had posted that original log, since your mnid in onboarding_config.json you just posted is different (OAxg). By the way, for future serial number creation, you can use a --mnid parameter to specify your assigned mnid (which you can find out by looking at your Developer Workspace profile). Then all your serial numbers can consistently contain your own mnid.

The only thing I see unusual in your scan results is on your second AP, the channel number is 149. Normally it would be a number between 1 and 11 in the U.S. Is that an outdoor AP? Looks like they use different channel numbers. Nevertheless, it's still just an integer and shouldn't cause a problem.

I'm glad you at least got it working on your other OS image, but I will continue to look at this to figure out the segmentation fault. I'll leave this issue open until I figure it out.

And I will look at that include file you said had hard-coded directory references. That's not good...thank you for finding that!

Delgreco007 commented 3 years ago

I think the 4 characters in brackets is actually the last 4 digits of the device serial number. The best I can tell, my serial numbers are STDK + 12 randomly generated digits and do not contain my mnid. I guess that's what the --mnid parameter allows. Sure would be nice if this stuff was documented somewhere by Samsung. (I tried this out, and it does indeed include my mnid as the first four digits of a serial number).

149 is a 5 MHz channel. According to my router options, channels range from 36 - 165 with variable gaps between usable channels. And 149 is indeed the channel in use by my router.

I understand what's going on better in the log now, but I guess we're back to square 1 on the segmentation fault.

toddaustin07 commented 3 years ago

I kind of glossed over something you said earlier - that you were using Raspberry Pi OS 64 bit. That's still very much in beta, isn't it? Nonetheless, I'm going to try installing it myself this weekend and test it out. I've already made some tweaks to the code that could possibly be sources of the problem, but rather than ask you to be the guinea pig again, I'll verify it's working on mine before I post the changes.

Delgreco007 commented 3 years ago

Yes, it is in beta, although I've had it running on a pi for 6+ months now, and it's been pretty rock-solid stable. In fact, it initially slipped my mind that it was 64 bit until you asked about versions. There were initially some problems with VNC Connect but those were ironed out around August. It's run any 64 bit programs that I've tried without a problem (even docker!) since then.

‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Saturday, February 13th, 2021 at 1:24 PM, Todd Austin notifications@github.com wrote:

I kind of glossed over something you said earlier - that you were using Raspberry Pi OS 64 bit. That's still very much in beta, isn't it? Nonetheless, I'm going to try installing it myself this weekend and test it out. I've already made some tweaks to the code that could possibly be sources of the problem, but rather than ask you to be the guinea pig again, I'll verify it's working on mine before I post the changes.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or unsubscribe.

Delgreco007 commented 3 years ago

I added some log entries to trace where exactly the fault is happening. It's in the setupHostapd function and seems to be on entry to this while loop:

while (getline(&readline,&len,pf)!= EOF) {

The loop does not even run once before the fault occurs.

toddaustin07 commented 3 years ago

Yes! That's where I thought things could be a problem. It's with the getline function. The len pointer wasn't initialized properly. Curious that it hasn't caused an issue previously, but the 64-bit addressing environment probably made the difference. Testing the fix now...

toddaustin07 commented 3 years ago

OK - tested on 64bit OS and no segmentation fault. So pull the updates and give it a shot when you have a chance. I should have fixed not only the segmentation fault, but also the other issues you reported, including adding the new model 4s to the SoftAPconfig script check.

I do see the device-busy on scan attempts; that seems to be more of an issue with this 64bit OS for some reason. I'll have to report that on one of the community boards.

Can I ask what mobile phone you are using? I've noted some random hangups during the provisioning process (under 32bit OS) that I've reported back to Samsung, but they've not come up with a solution yet. I'm suspecting it's during the TLS handshake, but it's hard to track down given the random nature. I've seen it using an old iPhone 6. I'm hoping it's related to the old phone with not-the-most-current IOS. If that's the case, most people may not encounter it.

So let me say that I am SO appreciative of all your assistance and patience with these problems. You've definitely improved the package. I'm sorry for the troubles, but that's why this is still beta :-) I need more kind people like you to help wring it out on different configurations.

One last thing, if you've explored docker, I'd be really interested in your thoughts on packaging this up into a container. It might simplify things a great deal and eliminate a lot of variables.

Delgreco007 commented 3 years ago

Okay, segmentation fault is definitely fixed. However, I cannot get all the way through device provisioning. On my phone (a Pixel 2 running Android 11) I get to 38-39%. This is right after I select the SSID to tell my device what to connect to when provisioning is done. I tried to run STProv as your instructions requested, but it too results in an error:

./STProv: error while loading shared libraries: libstdc++.so.6: cannot open shared object file: No such file or directory

I would think docker would be feasible. Creating a container with your dependencies already installed would be the easy part. The harder part would be the networking as well as how to add the serial number and key from the developer workspace. Maybe something like a webserver that would allow users to enter them through their browser? Some docker programs I run on my production RPi (PiHole and Google Assistant Relay) make use of this concept.

Log (picking up after the fault from before): I [IoT]: _setupHostapd(1349) > [rpi] hostapd config file updated with ssid=Test_Switch_E40Axg0006Be32ocdC, pw=1111122222, device=wlan0 I [IoT]: _SoftAPControl(1286) > [rpi] SoftAP service start issued I [IoT]: iot_bsp_wifi_set_mode(1022) > [rpi] AP Mode Started on device wlan0 I [IoT]: iot_easysetup_init(460) > IOT_STATE_PROV_ES_START I [IoT]: es_http_init(161) > http tcp init!! I [IoT]: iot_easysetup_init(490) > IOT_STATE_PROV_ES_INIT_DONE I [IoT]: _do_cmd_tout_check(981) > New state updated for 1 I [IoT]: _do_status_report(300) > Call usr status_cb with 2/1 iot_status: 2, lv: 1 I [IoT]: _iot_easysetup_gen_get_payload(150) > waiting.. response for [0] I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:1/1 I [IoT]: _do_state_updating(1567) > Notification only with IOT_STATE_PROV_CONN_MOBILE I [IoT]: _do_status_report(300) > Call usr status_cb with 2/4 iot_status: 2, lv: 4 I [IoT]: http_msg_handler(387) > get cmd[0] ok I [IoT]: _iot_easysetup_gen_post_payload(260) > waiting.. response for [1] I [IoT]: _es_keyinfo_handler(553) > master secret generation success I [IoT]: http_msg_handler(368) > post cmd[1] ok I [IoT]: _iot_easysetup_gen_post_payload(260) > waiting.. response for [2] 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 E [IoT]: st_conn_start(1829) > Can't go to PROV_CONFIRM (0x0) I [IoT]: st_conn_start(1831) > st_conn_start done (-7) I [IoT]: _es_confirm_check_manager(751) > There is no confirmation request. The check is skipped I [IoT]: http_msg_handler(368) > post cmd[2] ok 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 I [IoT]: _do_cmd_tout_check(981) > New state updated for 3 I [IoT]: _iot_easysetup_gen_get_payload(150) > waiting.. response for [4] I [IoT]: iot_bsp_wifi_set_mode(866) > [rpi] Requested mode SCAN I [IoT]: iot_bsp_wifi_set_mode(890) > [rpi] Scan not performed while in AP mode I [IoT]: iot_bsp_wifi_get_scan_result(1570) > [rpi] Get scan result requested I [IoT]: http_msg_handler(387) > get cmd[4] ok I [IoT]: _iot_easysetup_gen_post_payload(260) > waiting.. response for [5] I [IoT]: _es_wifi_prov_parse(1319) > no macAddress I [IoT]: _es_wifi_prov_parse(1343) > ssid: Harpoon I [IoT]: _es_wifi_prov_parse(1345) > mac addr: I [IoT]: _es_cloud_prov_parse(1412) > brokerUrl: mqtt-regional-useast1.api.smartthings.com:8883 I [IoT]: _es_cloud_prov_parse(1413) > deviceName : Test_Switch I [IoT]: iot_bsp_wifi_get_mac(1747) > [rpi] Mac address requested I [IoT]: iot_bsp_wifi_get_mac(1762) > [rpi] Mac=dc:a6:32:8c:78:74 E [IoT]: _iot_security_be_bsp_fs_load_from_nv(129) > iot_bsp_fs_open(./IotAPBSSID) = -1208 I [IoT]: _es_wifiprovisioninginfo_handler(1541) > provisioning success W [IoT]: _do_cmd_tout_check(968) > New state changing timeout I [IoT]: _do_iot_main_command(450) > curr_main_cmd:10, curr_main_state:3/3 W [IoT]: _do_recovery(1352) > state changing fail for 3, curr_state :3 E [IoT]: _do_recovery(1410) > Failed process [3] on time, STOP I [IoT]: _do_update_timeout(196) > Current timeout : 4294967295 for 3/-2 I [IoT]: _do_status_report(300) > Call usr status_cb with 2/3 iot_status: 2, lv: 3 I [IoT]: _do_cmd_tout_check(981) > New state updated for -2 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

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(186) > http tcp deinit complete! I [IoT]: iot_easysetup_deinit(524) > IOT_STATE_PROV_ES_DONE I [IoT]: iot_bsp_wifi_set_mode(846) > [rpi] Requested mode OFF I [IoT]: _SoftAPControl(1286) > [rpi] SoftAP service stop issued I [IoT]: _do_status_report(300) > Call usr status_cb with 1/0 iot_status: 1, lv: 0 I [IoT]: _do_update_timeout(196) > Current timeout : 4294967295 for -1/-1 I [IoT]: _do_status_report(291) > Unsupported state -1 for 0/0

toddaustin07 commented 3 years ago

One thing that doesn't look right in the log is no mac address for your Harpoon ssid. Can you do sudo iw wlan0 scan again so I can see that ssid listed? Is there anything unique or unusual about that access point? Looks like the BSS line might not be as expected. Not sure this is what's ultimately causing the onboarding error, but let's get that one figured out first.

Regarding STProv - I was wondering if you were having the provisioning problem on your 32 bit or 64 bit, but this answered my question. I got the same error running STprov on 64 bit. I recompiled it under the 64 bit OS and it works fine. I posted STProv64 to the repository so you can get it now. They must have made some changes to that library module. Funny that a simple little program like that one would have that problem..

I suspect the STProv64 output it will show a blank Mac Address and probably the Cloud Provisioning lines are complete. Device ID is usually the last thing to get written once the device registration is done with the MQTT server. Doesn't look like you got that far, though.

Can you please open a separate issue now? I'm going to close this one.