SmartThingsCommunity / st-device-sdk-c

SmartThings SDK for Direct Connected Devices for C
Other
118 stars 126 forks source link

Direct Connect using TAustin's RPi solution failing device registration #110

Open kubycsolutions opened 1 year ago

kubycsolutions commented 1 year ago

I've been working with Todd to try to get my Raspberry Pi Zero W running as a SmartThings device, using his rpi-st-device package, following the build sequence driven by his mastersetup script. As far as I know, I'm operating each of the stages correctly. But when I get to the final step of actually starting the application and having the android SmartThings app try to register it, the app fails to do so and reports error code 04-100 or 07-003. (I'm not sure which one I got most recently; I'll check.) I've wiped out the rpi-st-device and st-device-sdk-c directories and restarted the build-and-register process from scratch several times, and keep failing at that same point.

Todd has said that at this point he is running out of debugging ideas to try, and suggested I report the problem here and ask for assistance. Any suggestions on how we can debug this and determine what I'm doing differently from past users of Todd's code would be greatly appreciated.

The following is a console log from running mastersetup and selecting option 8, which should be the registration.

e[97mInstall and configure Raspberry Pi support for
    Samsung SmartThings direct-connected device applicationse[0m
    Version .20210406

    e[4mCHECKING YOUR SYSTEM:e[0m
    e[92mModel: Raspberry Pi Zero W Rev 1.1... OK
    e[92mO/S: "Raspbian GNU/Linux 11 (bullseye)"... OK
    e[92mPython 3.9.2... OK
e[0m
e[0m
    =======================================================
                             e[1me[97mMENUe[0m
    =======================================================
     1. Install Pi enablement package       e[92m[done]e[0m
     2. Install software dependencies       e[92m[done]e[0m
     3. Install Core SDK                e[92m[done]e[0m
     4. Build Core SDK              e[92m[done]e[0m
     5. Register devices in Developer Workspace     e[92m[done]e[0m
     6. Build example device app            e[92m[done]e[0m
     7. Configure Pi for SoftAP             e[92m[done]e[0m
     8. On-board example device app         e[92m[done]e[0m
    =======================================================

    e[95mEnter a step number or q to quit:e[0m  

    e[93mAre you sure you want to repeat this step? (y/n):e[0m y

    e[97mPrepare to onboard your device!e[0m

    Open the SmartThings mobile app and begin the 'e[97mAdd Devicee[0m' process

    e[95mPress any key once you have tapped 'e[97mScan QR codee[0m' 

    e[97mStarting example application...e[0m

e[0mGoodbye

e[32mI (1670774357:958) [IoT]: _dump_device_info(706) > firmware_version: switch_example_001
e[0me[32mI (1670774357:958) [IoT]: iot_bsp_wifi_init(149) > [rpi] iot_bsp_wifi_init
e[0me[32mI (1670774357:958) [IoT]: iot_bsp_wifi_init(150) > [rpi] wifi module version 20210405
e[0me[33mW (1670774358:72) [IoT]: _initDevNames(461) > [rpi] eth0 not found
e[0me[32mI (1670774358:135) [IoT]: iot_bsp_wifi_init(166) > [rpi] No Ethernet
e[0me[32mI (1670774358:135) [IoT]: iot_bsp_wifi_init(176) > [rpi] Wifi station device wlan0 found
e[0me[32mI (1670774358:139) [IoT]: iot_bsp_wifi_init(230) > [rpi] Wifi Initialization Done
e[0me[32mI (1670774358:140) [IoT]: st_conn_init(1372) > previous error code[]
e[0me[32mI (1670774358:140) [IoT]: st_conn_init(1380) > stdk_version : 1.7.5
e[0me[32mI (1670774358:140) [IoT]: st_conn_start(1850) > st_conn_start start (no-pin)
e[0me[32mI (1670774358:155) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:-1/-1
e[0me[32mI (1670774358:155) [IoT]: _do_update_timeout(199) > Current timeout : 100000 for -1/0
e[0me[32mI (1670774358:155) [IoT]: _do_status_report(304) > Call usr status_cb with 1/0
e[0miot_status: 1, lv: 0
e[32mI (1670774358:155) [IoT]: _do_iot_main_command(498) > curr_main_cmd:2, curr_main_state:-1/0
e[0me[31mE (1670774358:162) [IoT]: _iot_security_be_bsp_fs_load_from_nv(129) > iot_bsp_fs_open(./WifiProvStatus) = -1208
e[0me[32mI (1670774358:162) [IoT]: _do_cmd_tout_check(1041) > New state updated for 0
e[0me[32mI (1670774358:162) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:0/0
e[0me[32mI (1670774358:162) [IoT]: iot_bsp_wifi_set_mode(871) > [rpi] Requested mode SCAN
e[0me[32mI (1670774358:162) [IoT]: _perform_scan(1613) > [rpi] Running Wifi AP scan using wlan0
e[0me[32mI (1670774359:382) [IoT]: iot_bsp_wifi_set_mode(889) > [rpi] WiFi scan completed. 5 APs found
e[0me[32mI (1670774359:382) [IoT]: iot_bsp_wifi_get_scan_result(1587) > [rpi] Get scan result requested; 5 available
e[0me[32mI (1670774359:389) [IoT]: iot_easysetup_create_ssid(89) > >> Pi-based IR i[6oiI] <<
e[0me[32mI (1670774359:390) [IoT]: _do_update_timeout(199) > Current timeout : 300000 for 0/1
e[0me[32mI (1670774359:390) [IoT]: _do_iot_main_command(498) > curr_main_cmd:1, curr_main_state:0/1
e[0me[32mI (1670774359:390) [IoT]: iot_bsp_wifi_set_mode(964) > [rpi] Requested mode SoftAP
e[0me[32mI (1670774366:825) [IoT]: _SoftAPControl(1282) > [rpi] SoftAP service start issued
e[0me[32mI (1670774372:463) [IoT]: iot_bsp_wifi_set_mode(1028) > [rpi] AP Mode Started on device wlan0
e[0me[32mI (1670774372:463) [IoT]: iot_easysetup_init(494) > IOT_STATE_PROV_ES_START
e[0me[32mI (1670774372:463) [IoT]: es_http_init(159) > http tcp init!!
e[0me[32mI (1670774372:463) [IoT]: iot_easysetup_init(530) > IOT_STATE_PROV_ES_INIT_DONE
e[0me[32mI (1670774372:464) [IoT]: _do_cmd_tout_check(1041) > New state updated for 1
e[0me[32mI (1670774372:464) [IoT]: _do_status_report(304) > Call usr status_cb with 2/1
e[0miot_status: 2, lv: 1
e[33mW (1670774659:481) [IoT]: _do_cmd_tout_check(1028) > New state changing timeout
e[0me[32mI (1670774659:482) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:1/1
e[0me[33mW (1670774659:482) [IoT]: _do_recovery(1429) > state changing fail for 1, curr_state :1
e[0me[31mE (1670774659:482) [IoT]: _do_recovery(1488) > Failed process [1] on time, STOP
e[0me[32mI (1670774659:482) [IoT]: _do_update_timeout(199) > Current timeout : 4294967295 for 1/-2
e[0me[32mI (1670774659:482) [IoT]: _do_status_report(304) > Call usr status_cb with 2/3
e[0miot_status: 2, lv: 3
e[32mI (1670774659:482) [IoT]: _do_cmd_tout_check(1041) > New state updated for -2
e[0me[32mI (1670774659:482) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:-2/-2
e[0me[33mW (1670774659:482) [IoT]: _do_state_updating(1711) > Iot-core task will be stopped, needed ext-triggering

e[0me[32mI (1670774659:482) [IoT]: http_cleanup_all_connection(39) > close listen socket
e[0me[32mI (1670774659:489) [IoT]: es_http_deinit(184) > http tcp deinit complete!
e[0me[32mI (1670774659:490) [IoT]: iot_eas

Apologies for the terminal-coloring escape sequences; I think you should be able to read past them, but if not I can edit this down to remove them.

I am presuming that there was something following that final iot_eas but that it got stuck in the redirection buffers; I haven't yet explored whether there's a way of flushing those to get a more complete log.

If there's a debug bit I can turn on when compiling st-device-sdk-c, or when running this code, I'd be glad to make that change and pull further logs. Ditto any other experiments which might help resolve this.

The only thing that I know is different from past users of Todd's code is that I'm on the Raspberry Pi Zero W, which has a somewhat slower processor... and that I've usually been doing the previous stages of building the device code via ssh connection rather than via keyboard and screen hooked directly to the Pi. For step 8, registration, I've tried both letting the ssh connection be brought down by SoftAP and snapping the QR code from a copy kept on my laptop, and switching to actually working on the Pi's native screen and keyboard, and get the same failure either way.

Presumably there is something I'm doing wrong or have out of synch, or some subtle (timing?) issue that's appearing only on the Pi Zero W. But it looks like I need deeper assistance in finding it than Todd can provide.

Help?

(Ultimate goal is for these RPis to act as IR transceivers to bring a Mitsubishi minisplit HVAC system under SmartThings control. Various pieces of this have existed, but I haven't found a complete solution so I'm homebrewing. Hopefully when I get it working it'll be clean enough to be worth sharing.)

kubycsolutions commented 1 year ago

I should note that I am running a Cisco firewall between my home-automation network and the public WAN. That hasn't interfered with running other SmartThings registrations, but if there's something unusual about DirectConnect that might require my opening additional protocols or allowing incoming connections from the WAN please let me know.

Kwang-Hui commented 1 year ago

Hi @kubycsolutions , The linux port for RPi isn't part of our official release. So it is hard to comment about it. But I could see there is timeout for the SoftAP activation. (the SDK wait for 5 min - please refer here) How about try to onboard device within 5 min after it booted up?

Mostly commercial product with this SDK provides method of reactive setup mode (softap) by pressing buttons on it.

Thank you.

Kwang-Hui commented 1 year ago
e[0me[32mI (1670774372:463) [IoT]: iot_easysetup_init(494) > IOT_STATE_PROV_ES_START
...
e[33mW (1670774659:481) [IoT]: _do_cmd_tout_check(1028) > New state changing timeout
toddaustin07 commented 1 year ago

Hi Kwang-Hui- to add to the above problem description, I have successfully run this on a Raspberry Pi Zero W without a problem. I suspect there may be a configuration issue here but because the mobile app and SDK error messages are not particularly helpful, we can’t figure this out. Could you please help us diagnose this? If he provides you a debug-level log, would that provide a more specific reason for the onboarding failure?

Kwang-Hui commented 1 year ago

Hi @toddaustin07 @kubycsolutions ,

The log indicates device is just waiting for ST app to connect its soft-ap. Could you double check the ip address of SoftAP? If the mobile device got an ip address from dhcp server (from soft-ap device) as A.B.C.D, ST app expect the device's ip address as A.B.C.1 with implied protocol.

toddaustin07 commented 1 year ago

@kubycsolutions - I remember you were not using 192.168.2.1 for your AP address, but rather another address. In your latest testing, what IP address are you configuring the Pi's AP for? Is it possible to try 192.168.2.1 or is that not available? Kwang-Hui points out that the mobile app will look for x.x.x.1, so we need to make sure that is what your AP is configured to use.

kubycsolutions commented 1 year ago

My "site" convention is 192.170.x.x. The pi is normally at 192.170.3.13; ..3. is my home-automation subnet and is where the SmartThings hub is attached.

I've been setting up the Pi's access point configuration as 192.170.254.1, telling it to issue addresses in the range 192.170.254.2 thru .10. I can certainly try a 100% vanilla install and see it it's any happier.

Question: How quickly should the AP be available after displaying the QR code, and how long should it remain available before timing out and restoring my "normal" address for the pi? I'm wondering whether I'm scanning the QR too soon. (It's definitely not too late; I've usually started trying to register immediately after the system says the example has been started, less than a minute.)

toddaustin07 commented 1 year ago

As long as the Pi AP itself is at 192.170.254.1, then you should be OK

I'd recommend re-reading the onboarding instructions in my documentation - starting on page 17. It gives you a detailed step-by-step walkthrough of the process so you can be clear on the order and timing of all the steps.

Some additional things to check that are pointed out there:

Can you also share for Kwang-Hui exactly what step you are getting to on your mobile app and any messages you are seeing there? For example, if you're not eventually being presented with a list of your network SSIDs to choose from, then that says the phone never even successfully connected to the Pi's AP.

kubycsolutions commented 1 year ago

It is failing before asking me which network SSID to connect to. Developer mode is enabled.

I don't know whether it matters, but in the Developer's Workspace I'm defining the Direct Connect device configuration as an individual rather than Enrolling As An Organization. The screens I'm showing are slightly different from those in the document; I've been presuming that the document just referred to a previous version of the workspace but could this be where we're diverging?

kubycsolutions commented 1 year ago

I was hoping that using mastersetup would spare me all the reading -- I started looking at going through it manually, then decided I'd rather get running first and look at the details later. If I need to go back to full manual mode, I can...

mastersetup does not make the timing of step 8 completely clear. It tells us to hit a key after we've said we're ready to scan the QR code, then pops that up on screen. There's no hint about whether we should wait a bit before scanning it, so I've been assuming that the example should be ready to respond to the app's request fairly quickly. I was wondering whether I should give it more time. If that isn't the problem, fine.

kubycsolutions commented 1 year ago

News:

I went back and tried to run mastersetup EXACTLY as the instructions requested, from using 192.168.2.1 to calling it Switch Example.

The good news is that I did get farther.

So something about the setup is depending on exact details of the instructions which I departed from previously. Possibly the AP address, possibly something else. But there's clearly a second problem once I get past that.

OK, stop Example, clean up, put the phone on the home-automation access point, restart mastersetup step 8, scan QR again.

Two things wrong with this...

So this seems to be a problem of the registration process being overly picky.

I can (and will) try turning off 5GHz support in that access point temporarily and see if that lets us complete registration... but that really should not be necessary.

Pi console log from that last attempt follows:

        Install and configure Raspberry Pi support for
        Samsung SmartThings direct-connected device applications
        Version .20210406

        CHECKING YOUR SYSTEM:
        Model: Raspberry Pi Zero W Rev 1.1... OK
        O/S: "Raspbian GNU/Linux 11 (bullseye)"... OK
        Python 3.9.2... OK

        =======================================================
                                 MENU
        =======================================================
         1. Install Pi enablement package               [done]
         2. Install software dependencies               [done]
         3. Install Core SDK                            [done]
         4. Build Core SDK                              [done]
         5. Register devices in Developer Workspace     [done]
         6. Build example device app                    [done]
         7. Configure Pi for SoftAP                     [done]
         8. On-board example device app                 [done]
        =======================================================

        Enter a step number or q to quit: 8

        Are you sure you want to repeat this step? (y/n): y

        Prepare to onboard your device!

        Open the SmartThings mobile app and begin the 'Add Device' process

        Press any key once you have tapped 'Scan QR code'

        Starting example application...

Goodbye

I (1670956100:276) [IoT]: _dump_device_info(706) > firmware_version: switch_example_001
I (1670956100:277) [IoT]: iot_bsp_wifi_init(149) > [rpi] iot_bsp_wifi_init
I (1670956100:277) [IoT]: iot_bsp_wifi_init(150) > [rpi] wifi module version 20210405
W (1670956100:427) [IoT]: _initDevNames(461) > [rpi] eth0 not found
I (1670956100:488) [IoT]: iot_bsp_wifi_init(166) > [rpi] No Ethernet
I (1670956100:488) [IoT]: iot_bsp_wifi_init(176) > [rpi] Wifi station device wlan0 found
I (1670956100:488) [IoT]: iot_bsp_wifi_init(230) > [rpi] Wifi Initialization Done
I (1670956100:489) [IoT]: st_conn_init(1372) > previous error code[]
I (1670956100:489) [IoT]: st_conn_init(1380) > stdk_version : 1.7.5
I (1670956100:490) [IoT]: st_conn_start(1850) > st_conn_start start (no-pin)
I (1670956100:492) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:-1/-1
I (1670956100:492) [IoT]: _do_update_timeout(199) > Current timeout : 100000 for -1/0
I (1670956100:492) [IoT]: _do_status_report(304) > Call usr status_cb with 1/0
iot_status: 1, lv: 0
I (1670956100:492) [IoT]: _do_iot_main_command(498) > curr_main_cmd:2, curr_main_state:-1/0
E (1670956100:493) [IoT]: _iot_security_be_bsp_fs_load_from_nv(129) > iot_bsp_fs_open(./WifiProvStatus) = -1208
I (1670956100:493) [IoT]: _do_cmd_tout_check(1041) > New state updated for 0
I (1670956100:493) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:0/0
I (1670956100:493) [IoT]: iot_bsp_wifi_set_mode(871) > [rpi] Requested mode SCAN
I (1670956100:493) [IoT]: _perform_scan(1613) > [rpi] Running Wifi AP scan using wlan0
I (1670956101:553) [IoT]: iot_bsp_wifi_set_mode(889) > [rpi] WiFi scan completed. 10 APs found
I (1670956101:553) [IoT]: iot_bsp_wifi_get_scan_result(1587) > [rpi] Get scan result requested; 10 available
I (1670956101:553) [IoT]: iot_easysetup_create_ssid(89) > >> Switch Exampl[5Kb7] <<
I (1670956101:554) [IoT]: _do_update_timeout(199) > Current timeout : 300000 for 0/1
I (1670956101:554) [IoT]: _do_iot_main_command(498) > curr_main_cmd:1, curr_main_state:0/1
I (1670956101:554) [IoT]: iot_bsp_wifi_set_mode(964) > [rpi] Requested mode SoftAP
I (1670956107:800) [IoT]: _SoftAPControl(1282) > [rpi] SoftAP service start issued
I (1670956109:99) [IoT]: iot_bsp_wifi_set_mode(1028) > [rpi] AP Mode Started on device wlan0
I (1670956109:99) [IoT]: iot_easysetup_init(494) > IOT_STATE_PROV_ES_START
I (1670956109:99) [IoT]: es_http_init(159) > http tcp init!!
I (1670956109:100) [IoT]: iot_easysetup_init(530) > IOT_STATE_PROV_ES_INIT_DONE
I (1670956109:100) [IoT]: _do_cmd_tout_check(1041) > New state updated for 1
I (1670956109:100) [IoT]: _do_status_report(304) > Call usr status_cb with 2/1
iot_status: 2, lv: 1
I (1670956140:619) [IoT]: _iot_easysetup_gen_get_payload(177) > waiting.. response for [0]
I (1670956140:619) [IoT]: _do_iot_main_command(498) > curr_main_cmd:10, curr_main_state:1/1
I (1670956140:619) [IoT]: _do_state_updating(1646) > Notification only with IOT_STATE_PROV_CONN_MOBILE
I (1670956140:619) [IoT]: _do_status_report(304) > Call usr status_cb with 2/4
iot_status: 2, lv: 4
I (1670956140:620) [IoT]: http_msg_handler(421) > get cmd[0] ok
I (1670956140:648) [IoT]: _iot_easysetup_gen_post_payload(292) > waiting.. response for [1]
I (1670956140:785) [IoT]: _es_keyinfo_handler(560) > master secret generation success
I (1670956140:786) [IoT]: http_msg_handler(402) > post cmd[1] ok
I (1670956140:805) [IoT]: _iot_easysetup_gen_post_payload(292) > waiting.. response for [2]
I (1670956140:806) [IoT]: _es_confirminfo_handler(856) > otmSupportFeature = 0
I (1670956140:806) [IoT]: _es_confirm_check_manager(726) > IOT_STATE_PROV_CONFIRMING
I (1670956140:806) [IoT]: iot_state_update(229)
kubycsolutions commented 1 year ago

I'm not sure why the SmartThings code would even care what speed the device's or phone's connection to the access point runs at...?

(Yes, home automation can generally be run adequately at the lower speed. But I'd really rather not have to force that in the access point, so I can take advantage of 5GHz when devices do support it.)

kubycsolutions commented 1 year ago

As Todd said, if it would help I'm quite willing to try running with debug builds of the ST API and send you logs from that -- or turn on logging in the Android app, if that's possible and would be helpful. It's in everyone's interest to make ST device development as easy and robust as possible.

toddaustin07 commented 1 year ago

Yes, it is true that it only supports 2.4Ghz for some reason. I never really understood why.

What did you configure on the Pi that had it connecting at 5GHz? I've never done anything explicitly to affect that, that I can think of...

toddaustin07 commented 1 year ago

Kuang Hui,

I'm trying to understand what you meant when you said this:

If the mobile device got an ip address from dhcp server (from soft-ap device) as A.B.C.D, ST app expect the device's ip address as A.B.C.1 with implied protocol.

In our case the AP itself would be at address A.B.C.1, and it would assign addresses from A.B.C.2 to A.B.C.10, for example. This is OK?

kubycsolutions commented 1 year ago

The Pi Zero W does not support 5GHz WiFi. (Rechecked the specs.) But it is perfectly happy connecting to an access point that is configured to run at both speeds. The fact that the phone happens to be connected at 5GHz should not prevent setting up the device at 2.4GHz...?

toddaustin07 commented 1 year ago

That's what I would think.

kubycsolutions commented 1 year ago

So, update: I have finally been able to connect. But it's ugly.

1) Go into router/AP configuration, turn off the 5GHz radio. 2) Reconnect Android phone to that network, confirm phone is now running at 2.4GHz 3) Start the device registration process. 4) When it asks me which network to connect to, and lists those available, this router/AP is listed among those NOT supported, presumably because the phone remembers that it was set up for both radio frequencies. (Also, FYI, you display only the first word of the SSID -- rather than "Casa delGato" you display "Casa". That's not always going to be enough, if multiple SSIDs with the same prefix are in range.) 5) Manually re-enter the AP's SSID, password, and security setting. 6) Let the process finish. 7) Test that the "switch" device turns on and off as expected. 8) Go back to the router/AP configuration, turn on 5GHz again. 9) Unfortunately, the phone still insists on connecting to that AP only at 2.4GHz. Tried several ways to fix that, "forgetting" and rediscovering that SSID, rebooting the phone, rebooting the router... It finally recovered; I don't know what did the trick (or if I just had to wait for the phone to time out a lease and rescan?)... but things seem to be where they should be. 10) And toggling the "switch" still works as expected.

This dance REALLY shouldn't be necessary, should it?

kubycsolutions commented 1 year ago

My router uses the same SSID for both 2.4GHz and 5GHz. It looks as if iot_bsp_wifi_get_freq only tells us that 5GHz is available, so Todd's code tells me I can't register the device using that SSID.

As a workaround, I can turn off 5GHz while I register the devices.

But I haven't had this problem with other devices. Are they just not asking the speed before trying to connect, or is there something else we can change so it works as expected?

toddaustin07 commented 1 year ago

Correction: the SDK limits the return of the iot_bsp_wifi_get_freq function to 2.4GHz (not 5)