Node data send error: Registration timeout about enigmaiot HOT 9 CLOSED

It is normal that first data send before registration fails. Node will retry after successful node hello and server hello messages.

Registration timeout happens when gateway does not reply client hello with server hello. Maybe it's a network key mismatch? It's difficult since latest code changes. And connection result in node is 3 that means authenticated successfully.

Are you using provided mqtt gateway? May you share your node code?

Compile gateway setting debug to verbose (on ide settings, not EnigmaIOTconfig.h) and check it's makes messages. You will find there if gateway does not receive client hello or it finds an error on it.

from enigmaiot.

Yes, I forgot to mention, I am using the examples from the latest release: EnigmaIOTGatewayMQTT and enigmaiot_node. I will give your suggestions a try and get back to you. Thanks!

from enigmaiot.

hmm so I am running a bit low on storage space on my board ("Sketch uses 1309897 bytes (99%) of program storage space. Maximum is 1310720 bytes.") so I couldn't go higher than debug level "Info" but this already tells us something:

[I][EnigmaIOTGateway.cpp:484] configWiFiManager(): 2704 Heap: 231296 ==== Config Portal result ====
[I][EnigmaIOTGateway.cpp:485] configWiFiManager(): 2706 Heap: 231296 Network Name: IreMarIOT
[I][EnigmaIOTGateway.cpp:486] configWiFiManager(): 2715 Heap: 231296 Network Key:
[I][EnigmaIOTGateway.cpp:487] configWiFiManager(): 2722 Heap: 231296 Channel: 6
[I][EnigmaIOTGateway.cpp:488] configWiFiManager(): 2729 Heap: 231296 Status: true
[I][EnigmaIOTGateway.cpp:489] configWiFiManager(): 2736 Heap: 231296 Save config: no
[I][GwOutput_mqtt.cpp:168] configManagerExit(): 2744 Heap: 231296 ==== Config Portal MQTTGW result ====
[I][GwOutput_mqtt.cpp:169] configManagerExit(): 2753 Heap: 231296 MQTT server: nodered.martin.notreal.ch
[I][GwOutput_mqtt.cpp:170] configManagerExit(): 2762 Heap: 231296 MQTT port: 1883
[I][GwOutput_mqtt.cpp:171] configManagerExit(): 2769 Heap: 231296 MQTT user: martin
[I][GwOutput_mqtt.cpp:172] configManagerExit(): 2777 Heap: 231296 MQTT password:
[I][GwOutput_mqtt.cpp:173] configManagerExit(): 2784 Heap: 231296 Status: true
[I][EnigmaIOTGatewayMQTT.ino:419] setup(): 3538 Heap: 230064 STA MAC Address: 30:AE:A4:74:1C:30
[I][EnigmaIOTGatewayMQTT.ino:420] setup(): 3539 Heap: 224940 AP MAC Address: 30:AE:A4:74:1C:31
[I][EnigmaIOTGatewayMQTT.ino:421] setup(): 3544 Heap: 229764 BSSID Address: 2C:3A:FD:41:45:95
[I][EnigmaIOTGatewayMQTT.ino:423] setup(): 3552 Heap: 229984 IP address: 192.168.178.34
[I][EnigmaIOTGatewayMQTT.ino:424] setup(): 3560 Heap: 229984 WiFi Channel: 6
[I][EnigmaIOTGatewayMQTT.ino:425] setup(): 3567 Heap: 229984 WiFi SSID: IreMarWifi
[I][EnigmaIOTGatewayMQTT.ino:426] setup(): 3574 Heap: 229984 Network Name: IreMarIOT
[I][GwOutput_mqtt.cpp:213] begin(): 3582 Heap: 229944 CA store set
[I][GwOutput_mqtt.cpp:216] begin(): 3588 Heap: 229944 Set MQTT server nodered.martin.notreal.ch - port 1883
[I][GwOutput_mqtt.cpp:235] reconnect(): 3597 Heap: 229844 Attempting MQTT connection...
[I][GwOutput_mqtt.cpp:445] setClock(): 3607 Heap: 228900
Waiting for NTP time sync:
.[I][GwOutput_mqtt.cpp:455] setClock(): 4113 Heap: 229288 Current time: Wed Jul 22 18:27:58 2020

[E][ssl_client.cpp:33] _handle_error(): [start_ssl_client():199]: (-80) UNKNOWN ERROR CODE (0050)
[E][WiFiClientSecure.cpp:132] connect(): start_ssl_client: -80
[E][GwOutput_mqtt.cpp:258] reconnect(): 5271 Heap: 227524 failed, rc=-1 try again in 5 seconds
[E][GwOutput_mqtt.cpp:266] reconnect(): 5278 Heap: 227524 Connect error -80: UNKNOWN ERROR CODE (0050)
[I][GwOutput_mqtt.cpp:235] reconnect(): 10287 Heap: 227556 Attempting MQTT connection...
[I][GwOutput_mqtt.cpp:445] setClock(): 10289 Heap: 227184
Waiting for NTP time sync:
[I][GwOutput_mqtt.cpp:455] setClock(): 10292 Heap: 227556 Current time: Wed Jul 22 18:28:04 2020

[E][ssl_client.cpp:33] _handle_error(): [start_ssl_client():199]: (-80) UNKNOWN ERROR CODE (0050)
[E][WiFiClientSecure.cpp:132] connect(): start_ssl_client: -80
[E][GwOutput_mqtt.cpp:258] reconnect(): 10786 Heap: 225968 failed, rc=-1 try again in 5 seconds
[E][GwOutput_mqtt.cpp:266] reconnect(): 10793 Heap: 225968 Connect error -80: UNKNOWN ERROR CODE (0050)
[I][GwOutput_mqtt.cpp:235] reconnect(): 15802 Heap: 226004 Attempting MQTT connection...
[I][GwOutput_mqtt.cpp:445] setClock(): 15804 Heap: 225636
Waiting for NTP time sync:
[I][GwOutput_mqtt.cpp:455] setClock(): 15807 Heap: 224296 Current time: Wed Jul 22 18:28:09 2020

...etc.

So it seems like an SSL error? My MQTT server isn't using SSL so I specify port 1883, could that be the issue? Anyways, I will try and see if my MQTT server is working well with another sketch first.

from enigmaiot.

You got it. To use MQTT broker without TLS and cetificate you should comment #include "dstrootca.h" on GwOutput_mqtt.h Here, and compile gateway again.

from enigmaiot.

Gateway code is indeed quite big. But you can fit it loosely by adjusting partition scheme. You should select MINIMAL SPIFFS in your IDE, what gives you 1.9MB for code + 1.9MB for OTA and 190kB for filesystem. More than needed for configuration files.

Be aware when setting debug level to debug or verbose, if your node send messages too often it may do a panic reboot due to serial buffers overflow.

from enigmaiot.

Thanks for all the helpful tips! I will try them out in the coming days and report back.

from enigmaiot.

Success! (kinda) Indeed now I get it to connect to my MQTT server successfully:

[I][GwOutput_mqtt.cpp:235] reconnect(): 5919 Heap: 232432 Attempting MQTT connection...
[W][GwOutput_mqtt.cpp:246] reconnect(): 6336 Heap: 229972 MQTT connected
[I][GwOutput_mqtt.cpp:432] publishMQTT(): 6336 Heap: 229972 Publish MQTT. IreMarIOT/gateway/status : 1

I also checked my server and it is receiving the initial message successfully. But node messages are still not getting through. Seems like now I have an encryption error:

[I][EnigmaIOTGateway.cpp:856] manageMessage(): 108648 Heap: 222432 Reveived message. Origin MAC: 3C:71:BF:5A:A9:28
[I][EnigmaIOTGateway.cpp:874] manageMessage(): 108649 Heap: 222432 <------- CLIENT HELLO
[E][cryptModule.cpp:70] decryptBuffer(): 108656 Heap: 222432 Data authentication error
[E][EnigmaIOTGateway.cpp:1509] processClientHello(): 108663 Heap: 222432 Error during decryption
[E][EnigmaIOTGateway.cpp:899] manageMessage(): 108672 Heap: 222432 Error processing client hello

[If I set the gateway's debug mode to anything higher than "Info" I get core panic crashes. That's why I'm only setting it to "info" here.]

Any ideas what I should check first to start debugging this one? I am happy to open up a separate issue for this error if you think its better. Here is my node output:

[D][EnigmaIOTNode.cpp:547] begin(): 37 Heap: 293452 Set sleepy mode: sleepy
[V][EnigmaIOTNode.cpp:124] loadRTCData(): 37 Heap: 293452. ----- Read RTCData: 52 EA A7 45 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 06 30 AE A4 74 1C 31 C3 66 68 7A AD F8 62 BD 77 6C 8F C1 8B 8E 9F 8E 20 08 97 14 85 6E E2 33 B3 90 2A 59 1D 0D 5F 29 25 49 72 65 4D 61 72 49 4F 54 00 00 00 00 00 00 00 00 00 00 00 00 01 0A 00 00 00 74 65 73 74 6E 6F 64 65 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[V][EnigmaIOTNode.cpp:982] checkCRC(): 80 Heap: 293452. CRC32 = Calc: 0x45A7EA52 Recvd: 0x45A7EA52 Length: 144
[D][EnigmaIOTNode.cpp:149] loadRTCData(): 90 Heap: 293452 Set sleepy mode
-- Node Key: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-- Node key is NOT valid
-- Node status is 0: NOT REGISTERED
-- Node name: testnode
-- Last message counter: 0
-- NodeID: 0
-- Channel: 6
-- RSSI: -61
-- Network name: IreMarIOT
-- Gateway: 30:AE:A4:74:1C:31
-- Comm errors: 0
-- Network Key: 66 68 7A AD F8 62 BD 77 6C 8F C1 8B 8E 9F 8E 20 08 97 14 85 6E E2 33 B3 90 2A 59 1D 0D 5F 29 25
-- Mode: sleepy
[D][EnigmaIOTNode.cpp:552] begin(): 138 Heap: 293452 RTC data loaded. Gateway: 30:AE:A4:74:1C:31
[D][EnigmaIOTNode.cpp:553] begin(): 146 Heap: 293452 Own address: 00:00:00:00:00:00
[D][helperFunctions.cpp:32] initWiFi(): 154 Heap: 293452 initWifi
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 2 - STA_START
[D][helperFunctions.cpp:51] initWiFi(): 200 Heap: 243144 Mode set to STA. Channel 6
[I][helperFunctions.cpp:58] initWiFi(): 206 Heap: 243144 AP MAC address of this device is 3C:71:BF:5A:A9:29
[I][helperFunctions.cpp:59] initWiFi(): 215 Heap: 243144 STA MAC address of this device is 3C:71:BF:5A:A9:28
[I][espnow_hal.cpp:70] begin(): 225 Heap: 243144 Starting ESP-NOW as node
[D][espnow_hal.cpp:72] begin(): 231 Heap: 243144 Gateway address is 30:ae:a4:74:1c:31
[I][espnow_hal.cpp:40] initComms(): 239 Heap: 243008 Gateway peer Added in channel 6. Result = ESP_OK
[D][espnow_hal.cpp:41] initComms(): 248 Heap: 243008 WIFI channel is 6
[D][EnigmaIOTNode.cpp:630] begin(): 255 Heap: 243008 Comms started. Channel 6
[D][enigmaiot_node.ino:127] setup(): 261 Heap: 243008 Node address set to 3C:71:BF:5A:A9:28
Vcc: 0.000000
Trying to send: 00 02 00 00 01 67 00 CB 02 00 7B 03 73 27 58 04 75 09 7E
---- Error sending data
Total time: 243 ms
[D][EnigmaIOTNode.cpp:1307] sleep(): 281 Heap: 242744 Sleep programmed for 10000 ms
[D][EnigmaIOTNode.cpp:898] handle(): 1789 Heap: 242780 Current node status: 0
[D][NodeList.cpp:105] reset(): 1789 Heap: 242780 Reset node
[D][NodeList.cpp:114] reset(): 1790 Heap: 242780 Reset packet rate
[I][EnigmaIOTNode.cpp:902] handle(): 1795 Heap: 242780 Random delay (1854)
[V][cryptModule.cpp:143] getDH1(): 5191 Heap: 242796. Public key: 47 7A 81 0F 9C 64 4E 3F 0D 7E 6C 01 E2 D5 5B 7E 4A 50 80 59 6C C6 BA 63 12 88 A5 E8 3E BB BE 2F
[V][cryptModule.cpp:145] getDH1(): 5195 Heap: 242796. Private key: F0 2B 92 1D 80 8C 75 25 78 D8 C8 54 53 0F 1B 40 A4 FE B1 97 6D 3F 14 18 DD D5 2E 0E 06 A1 72 73
[V][EnigmaIOTNode.cpp:1028] clientHello(): 5209 Heap: 242796. IV: EC 5D 23 7A 80 D2 95 73 A6 88 16 94
[D][EnigmaIOTNode.cpp:1039] clientHello(): 5218 Heap: 242796 Signal sleepy node
[V][EnigmaIOTNode.cpp:1047] clientHello(): 5225 Heap: 242796. Client Hello message: FF EC 5D 23 7A 80 D2 95 73 A6 88 16 94 47 7A 81 0F 9C 64 4E 3F 0D 7E 6C 01 E2 D5 5B 7E 4A 50 80 59 6C C6 BA 63 12 88 A5 E8 3E BB BE 2F B1 E2 75 90
[V][cryptModule.cpp:92] encryptBuffer(): 5245 Heap: 242796. IV: EC 5D 23 7A 80 D2 95 73 A6 88 16 94
[V][cryptModule.cpp:93] encryptBuffer(): 5254 Heap: 242796. Key: 66 68 7A AD F8 62 BD 77 6C 8F C1 8B 8E 9F 8E 20 08 97 14 85 6E E2 33 B3
[V][cryptModule.cpp:94] encryptBuffer(): 5266 Heap: 242796. AAD: FF EC 5D 23 7A 80 D2 95 73 A6 88 16 94 90 2A 59 1D 0D 5F 29 25
[V][cryptModule.cpp:103] encryptBuffer(): 5278 Heap: 242796. Tag: 69 BF 4F B1 9B 65 12 63 11 4B 92 06 C0 E9 DD 6D
[V][EnigmaIOTNode.cpp:1065] clientHello(): 5288 Heap: 242796. Encrypted Client Hello message: FF EC 5D 23 7A 80 D2 95 73 A6 88 16 94 BB 08 24 C6 53 D1 D7 EC 87 2F 97 D5 86 42 83 82 05 17 5D B0 6D 0D BE CC 58 46 BE D6 9E E2 E0 79 96 5A 91 F9 69 BF 4F B1 9B 65 12 63 11 4B 92 06 C0 E9 DD 6D
[I][EnigmaIOTNode.cpp:1070] clientHello(): 5313 Heap: 242796 -------> CLIENT HELLO
[D][espnow_hal.cpp:90] send(): 5320 Heap: 242796 ESP-NOW message to 30:AE:A4:74:1C:31
[D][espnow_hal.cpp:112] send(): 5328 Heap: 242584 esp now send result = 0
[D][EnigmaIOTNode.cpp:2235] getStatus(): 5330 Heap: 242492 SENDStatus OK
[I][EnigmaIOTNode.cpp:869] handle(): 7335 Heap: 242796 Current node status: 2
[D][NodeList.cpp:105] reset(): 7335 Heap: 242796 Reset node
[D][NodeList.cpp:114] reset(): 7336 Heap: 242796 Reset packet rate
[V][EnigmaIOTNode.cpp:303] saveRTCData(): 7342 Heap: 242796. ----- Write RTCData: 52 EA A7 45 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 06 30 AE A4 74 1C 31 C3 66 68 7A AD F8 62 BD 77 6C 8F C1 8B 8E 9F 8E 20 08 97 14 85 6E E2 33 B3 90 2A 59 1D 0D 5F 29 25 49 72 65 4D 61 72 49 4F 54 00 00 00 00 00 00 00 00 00 00 00 00 01 0A 00 00 00 74 65 73 74 6E 6F 64 65 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[I][EnigmaIOTNode.cpp:879] handle(): 7388 Heap: 242796 Registration timeout. Go to sleep for 6194 ms

from enigmaiot.

Data authentication error after HELLO MESSAGE may be caused by wrong network key. Latest version makes key selection simpler and less prone to mistakes. Test latest version, just released 0.9.4

from enigmaiot.

As it's been one month after last activity I close this. Feel free to reopen it again if needed

from enigmaiot.