registration_helper.py fails with connection timed out/CMD prompt timed out

[sambonator]

Connection times out during registrationhelper.py. Output is: ...

Completed checking/installing package dependencies

Generating ECDSA 256-bit prime field key... Generating self-signed x.509 certificate... Successfully created x.509 certificate with expiration in 365 days... Connecting.... Changing baud rate to 921600 Changed. RAM boot... Downloading 31364 bytes at 3ffb0000... done! Downloading 456 bytes at 3ffb8f28... done! Downloading 1028 bytes at 40080000... done! Downloading 107384 bytes at 40080404... done! Downloading 4 bytes at 4009a77c... done! All segments done, executing at 40081bf0 Wait for init connection timed out CMD prompt timed out.__

Added some print() statements to serial.py wait_for_init() function to print out the lines its receiving to see what's going on. Here's the output.

_----------------------------------------- Completed checking/installing package dependencies

Generating ECDSA 256-bit prime field key... Generating self-signed x.509 certificate... Successfully created x.509 certificate with expiration in 365 days... Connecting.... Changing baud rate to 921600 Changed. RAM boot... Downloading 31364 bytes at 3ffb0000... done! Downloading 456 bytes at 3ffb8f28... done! Downloading 1028 bytes at 40080000... done! Downloading 107384 bytes at 40080404... done! Downloading 4 bytes at 4009a77c... done! All segments done, executing at 40081bf0 Wait for init waiting for line... and line reads: b'start: Single core mode\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13477) heap_init: Initializing. RAM available for dynamic allocation:\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13479) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13482) heap_init: At 3FFB90F0 len 00026F10 (155 KiB): DRAM\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13484) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13487) heap_init: At 40078000 len 00008000 (32 KiB): IRAM\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13489) heap_init: At 4009A780 len 00005880 (22 KiB): IRAM\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;32mI (13492) cpustart: Pro cpu start user code\x1b[0m\r\n' waiting for line... and line reads: b'\x1b[0;33mW (13494) clk: RTC domain not initialised by bootloader\x1b[0m\r\n' waiting for line... and line reads: b'\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x00\x00\x80\x00\x00\x80\x00\x80\x00\x00\x80\x00\x00\x80\x80\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x80\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x00\x80\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x80\x80\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x80\x00\x80\x80\x80\x00\x80\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x00\x00\x80\x00\x00\x80\x00\x80\x00\x00\x80\x00\x00\x00\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x80\x00\x00\x80\x00\x80\x80\x80\x80\x80\x00\x80\x00\x00\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x80\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x00\x80\x00\x00\x80\x00\x00\x80\x80\x80\x80\x80\x80\x80\x80\x00\x00\x00\x80\x00\x00\x80\x00\x80\x00\x00\x80\x00\x00\x00\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x80\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x80\x00\x00\x00\x00\x00\x80\x00\x80\x80\x80\x80\x80\x00\x80\x00\x00\x00\x00\x80\x80\x80\x00\x80\x00\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x00\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x80\x80\x00\x00\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x00\x00\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x00\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x80\x80\x80\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x00\x80\x80\x80\x80\x00\x80\x80\x00\x80\x00\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x00\x00\x00\x00\x00\x00\x00\x80\x00\x00\x00\x80\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x00\x00\x80\x80\x80\x80\x80\x80\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x00\x00\x00\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x00\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x80\x80\x80\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x00\x80\x80\x80\x80\x00\x80\x80\x00\x80\x00\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x00\x00\x80\x00\x00\x80\x00\x00\x80\x00\x00\x00\x00\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x80\x00\x80\x80\x80\x80\x80\x80\x80\x80\x80\x00\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x00\x00\x00\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x80\x80\x80\x80\x00\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x00\x80\x80\x80\x00\x80\x80\x00\x00\x00\x80\x80\x00\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x00\x80\x80\x80\x80\x80\x80\x80\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x00\x80\x00\x00\x00\x00\x00\x80\x80\x80\x80\x80\x00\x00\x80\x00\x00\x00\x80\x00\x00\x80\x00\x00\x80\x00\x80\x00\x00\x00\x00\x00\x80\x00\x80\x00\x00\x00\x80\x80\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x00\x80\x00\x00\x00\x80\x00\x80\x80\x80\x80\x80\x80\x80\x00\x80\x80\x80\x80\x80\x80\x80\x00\x80\x00\x00\x00\x00\x80\x00\x00\x80\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x00\x80\x00\x00\x00\x80\x00\x00\x00\x00\x00\x80\x80\x00\x80\x80\x80\x80\x00\x00\x80\x80\x80\x80\x80\x80\x00\x00\x80\x00\x80\x00\x00\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x80\x80\x00\x80\x00\x80\x80\x80\x00\x80\x80\x80\x00\x80\x80\x00\x80\x80\x00\x80\x80\x80\x00\x80\x00\x00\x80\x00\x80\x80\x80\x80\x80\x80\x80\x80\x80\x80\x80\x80\x80\x00\x80\x00\x80\x80\x00\x00\x80\x00\x00\x00\x80\x80\x80\x00\x80\x80\x00\xab\xe9 >>\n' waiting for line... and line reads: b'>>\n' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' waiting for line... and line reads: b'' connection timed out CMD prompt timed out.

This output looks suspicious: clk: RTC domain not initialised by bootloader Wondering if something is wrong with my hardware? Thanks! Sam

[rashedtalukder]

Seems like the internal clock's XTAL setting is incorrect in your bootloader. Few questions:

1) Which version of esp-idf are you on, 4.2? Run: idf.py --version 2) Did you get to compile and run the Getting Started demo? 3) Did you erase your flash after running the Getting Started demo?

[sambonator]

Hello, to answer your questions:

1. I'm on 4.2. (edukit) D:\Users\sam\Desktop\esp-idf>idf.py --version ESP-IDF v4.2-47-g2532ddd9f

2. Yes I compiled and ran the Getting started demo/Rainmaker demo, and that runs fine. I'm also able to compile, flash and run the Core2-for-AWS-IoT-EduKit-Factory-Firmware, as well as Core2-for-AWS-IoT-EduKit-Features-Demo without issue.

3. Yes I erased the flash after running the Getting Started demo. I've done that several times, always after I am done with flashing then testing.

I'm on Windows 10, running miniconda, python 3.7.3, pip 20.3.1, Visual Studio Code latest available publically, PlatformIO latest,

Interestingly, if I just comment out the code that checks for acceptable return value, the project completes without error, and the M5Stack starts senging MQTT messages to IoT Cloud, and I am able to blink the light by publishing to it.

retval = init_mfg.wait_for_init(esp._port)
'''
if retval is not True:
    print("CMD prompt timed out.")
    exit(0)
'''

I did notice when I was digging around trying different idf.py commands,, the RTC time seemed to be off... now I don't recall where I saw that... I was wondering if that was the issue. I don't know enough about the device to know how to check and set the clock.

[sambonator]

Ok it was within the output from the PlatformIO terminal, that I saw the wrong time set.
After "upload and monitor" in the Getting Started section, when I successfully add the M5Stack device using my iPhone 8, I saw the output below with the wrong time/date set.

I (171175) wifi:AP's beacon interval = 204800 us, DTIM period = 2 ␛[0;32mI (171915) app_wifi: Connected with IP Address:192.168.1.18␛[0m ␛[0;32mI (171915) esp_netif_handlers: sta ip: 192.168.1.18, mask: 255.255.255.0, gw: 192.168.1.1␛[0m ␛[0;32mI (171925) wifi_prov_mgr: STA Got IP␛[0m ␛[0;32mI (171925) app_wifi: Provisioning successful␛[0m ␛[0;32mI (171975) esp_rmaker_mqtt: Initialising MQTT␛[0m ␛[0;32mI (171975) esp_rmaker_mqtt: Connecting to a1p72mufdu6064-ats.iot.us-east-1.amazonaws.com␛[0m ␛[0;32mI (171975) esp_rmaker_mqtt: Waiting for MQTT connection. This may take time.␛[0m ␛[0;32mI (174035) esp_rmaker_mqtt: MQTT Connected␛[0m ␛[0;32mI (174035) esp_rmaker_node_config: Reporting Node Configuration␛[0m ␛[0;32mI (174045) esp_rmaker_param: Reporting params (init): {"Light":{"Name":"Light","Power":true,"Brightness":25,"Hue":100,"Saturation":100},"Temperature Sensor":{"Name":"Temperature Sensor","Temperature":45.98654},"Fan":{"Name":"Fan","Power":false,"Speed":0},"Schedule":{"Schedules":[]}}␛[0m GAP procedure initiated: stop advertising. GAP procedure initiated: stop advertising. GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19 ␛[0;32mI (174585) wifi_prov_mgr: Provisioning stopped␛[0m ␛[0;32mI (174585) wifi_prov_scheme_ble: BTDM memory released␛[0m ␛[0;32mI (181175) esp_rmaker_time_sync: SNTP Synchronised.␛[0m ␛[0;32mI (181175) esp_rmaker_time_sync: The current time is: Mon Jan 4 01:36:11 2021 +0800[CST], DST: No.␛[0m ␛[0;32mI (214595) esp_rmaker_param: Received params: {"Fan":{"Power":true}}␛[0m ␛[0;32mI (214595) FAN: Received write request via : Cloud␛[0m ␛[0;32mI (214595) FAN: Received value = true for Fan - Power␛[0m ␛[0;32mI (214605) FAN: power up, speed=0␛[0m ␛[0;32mI (214605) display: switch on␛[0m ␛[0;32mI (214615) esp_rmaker_param: Reporting params: {"Fan":{"Power":true}}␛[0m ␛[0;32mI (218685) esp_rmaker_param: Received params: {"Light":{"Power":false}}␛[0m ␛[0;32mI (218685) light: Received write request via : Cloud␛[0m ␛[0;32mI (218695) light: Received value = false for Light - Power␛[0m ␛[0;32mI (218695) display: lights off␛[0m ␛[0;32mI (218705) esp_rmaker_param: Reporting params: {"Light":{"Power":false}}␛[0m ␛[0;32mI (221995) esp_rmaker_param: Received params: {"Light":{"Power":true}}␛[0m ␛[0;32mI (221995) light: Received write request via : Cloud␛[0m ␛[0;32mI (221995) light: Received value = true for Light - Power␛[0m ␛[0;32mI (222005) esp_rmaker_param: Reporting params: {"Light":{"Power":true}}␛[0m ␛[0;32mI (224415) esp_rmaker_param: Reporting params: {"Temperature Sensor":{"Temperature":45.98815}}␛[0m ␛[0;32mI (284415) esp_rmaker_param: Reporting params: {"Temperature Sensor":{"Temperature":45.74769}}␛[0m

I'm not sure if its related to the issue with registration_helper.py...

[rashedtalukder]

This isn't related to the actual time, but the frequency of the crystal oscillator (40MHz). I'm digging into it, but haven't been able to successfully reproduce this issue yet.

[rashedtalukder]

I am not able to see the same error. The binary provided by Espressif in the esp-cryptoauth-utility should include a bootloader partition that has the same oscillator frequency that's being detected by the toolchain (see https://github.com/espressif/esp-idf/blob/release/v4.2/components/esp32/clk.c#L95).

I've tested with the same Python 3.7.3 (recommend 3.7.9) on Windows 10.

[sambonator]

I wonder if its something with my PC? I removed/reinstalled ESP-IDF, Python, Visual Studio Code, PlatformIO but the issue continues. I will try on a different PC when I get some time to set that up. All other projects appear to work without issue os far, but have a couple of more projects in the tutorial to complete.

[shahpiyushv]

@sambonator The time shown in the device logs may seem wrong because the default timezone is "Asia/Shanghai". There are various ways to change the timezone, which you can find here. However, in the context of RainMaker, this time does not really affect any functionality other than Scheduling.

[rashedtalukder]

Closing since we didn't receive any additional information. Feel free to reopen if you're still having issues.