Problem: wdt reset after "Sending initial information..." on "Bare minimum sketch"

e1970180 commented 6 years ago

Hello!

I try to start use homie-esp8266 as its looks great for me.

Unfortunately, I have a problem. The device continuously reset even on "Bare minimum sketch" right after it connecting to Mosquitto broker and sending initial information. (If mqtt broker is shut down no reset occur, just waiting for connection)

I use Arduino 1.6.7 with libraries: ArduinoJson ver 5.13.2 Bounce2 ver 2.52.0 ESPAsyncTCP Latest commit 7e9ed22
AsyncMqttClient ver 0.8.2 ESPAsyncWebServer ver 1.2.0

Serial log with timestamp is below.

Do you have any idears what problem is and how to fix?

Best regards, Alex

`SDK:2.2.1(cfd48f3)/Core:2.4.2/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-13-g163bb82)/BearSSL:6d1cefc

✖ /homie/config.json doesn't exist 22:45:24.808 -> Configuration invalid. Using CONFIG MODE 22:45:24.808 -> 💡 Firmware broadcast-test (1.0.0) 22:45:24.808 -> 🔌 Booting into config mode 🔌 22:45:24.808 -> Device ID is 5ccf7fa2e5d2 22:45:24.808 -> mode : sta(5c:cf:7f:a2:e5:d2) + softAP(5e:cf:7f:a2:e5:d2) 22:45:24.808 -> add if0 bcn 0 22:45:24.977 -> del if1 22:45:24.977 -> add if1 22:45:24.977 -> dhcp server start:(ip:192.168.123.1,mask:255.255.255.0,gw:192.168.123.1) 22:45:24.977 -> bcn 100 22:45:24.977 -> AP started as Homie-5ccf7fa2e5d2 with IP 192.168.123.1 22:45:25.011 -> Triggering Wi-Fi scan... scandone ✔ Wi-Fi scan completed Triggering Wi-Fi scan... scandone 22:45:47.216 -> ✔ Wi-Fi scan completed add 1 22:45:50.845 -> aid 1 22:45:50.845 -> station: b4:b6:76:01:f3:a6 join, AID = 1 Received captive portal request: Redirect: http://192.168.123.1 Received captive portal request: Redirect: http://192.168.123.1 Received captive portal request: Redirect: http://192.168.123.1 Received captive portal request: UI bundle not loaded. See Configuration API usage: http://marvinroger.github.io/homie-esp8266/ Received config request ✔ Configured ↻ Rebooting into normal mode... 22:46:05.308 -> del if0 22:46:05.308 -> station: b4:b6:76:01:f3:a6 leave, AID = 1 22:46:05.308 -> rm 1 22:46:05.308 -> bcn 0 22:46:05.308 -> del if1 22:46:05.308 -> usl

22:46:05.409 -> ets Jan 8 2013,rst cause:2, boot mode:(1,7) 22:46:05.444 ->

22:47:24.253 -> SDK:2.2.1(cfd48f3)/Core:2.4.2/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-13-g163bb82)/BearSSL:6d1cefc 22:47:24.253 -> 22:47:24.253 -> 💡 Firmware broadcast-test (1.0.0) 22:47:24.424 -> 🔌 Booting into normal mode 🔌 22:47:24.424 -> {} Stored configuration 22:47:24.424 -> • Hardware device ID: 5ccf7fa2e5d2 22:47:24.424 -> • Device ID: kitchen-light 22:47:24.424 -> • Name: The kitchen light 22:47:24.424 -> • Device Stats Interval: 60 sec 22:47:24.424 -> • Wi-Fi: 22:47:24.424 -> ◦ SSID: AirS 22:47:24.424 -> ◦ Password not shown 22:47:24.424 -> • MQTT: 22:47:24.424 -> ◦ Host: 192.168.2.100 22:47:24.424 -> ◦ Port: 1883 22:47:24.459 -> ◦ Base topic: devices/ 22:47:24.459 -> ◦ Auth? yes 22:47:24.459 -> ◦ Username: mqttDevice 22:47:24.459 -> ◦ Password not shown 22:47:24.459 -> • OTA: 22:47:24.459 -> ◦ Enabled? yes 22:47:24.459 -> ↕ Attempting to connect to Wi-Fi... 22:47:24.459 -> bcn 0 22:47:24.459 -> del if1 22:47:24.459 -> mode : sta(5c:cf:7f:a2:e5:d2) scandone state: 0 -> 2 (b0) 22:47:28.437 -> state: 2 -> 3 (0) 22:47:28.437 -> state: 3 -> 5 (10) 22:47:28.437 -> add 0 22:47:28.437 -> aid 2 22:47:28.437 -> cnt

22:47:28.472 -> connected with AirS, channel 1 dhcp client start... ip:192.168.2.12,mask:255.255.255.0,gw:192.168.2.1 22:47:29.194 -> ✔ Wi-Fi connected, IP: 192.168.2.12 22:47:29.194 -> Triggering WIFI_CONNECTED event... 22:47:29.194 -> ↕ Attempting to connect to MQTT... Sending initial information...

22:47:37.413 -> ets Jan 8 2013,rst cause:4, boot mode:(3,6) 22:47:37.447 -> 22:47:37.447 -> wdt reset 22:47:37.447 -> load 0x4010f000, len 1384, room 16 22:47:37.447 -> tail 8 22:47:37.447 -> chksum 0x2d 22:47:37.447 -> csum 0x2d 22:47:37.447 -> vbb28d4a3 22:47:37.447 -> ~ld ⸮ 22:47:37.681 -> SDK:2.2.1(cfd48f3)/Core:2.4.2/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-13-g163bb82)/BearSSL:6d1cefc 22:47:37.681 -> 22:47:37.681 -> 22:47:37.681 -> state: 2 -> 3 (0) state: 3 -> 5 (10) 22:47:37.714 -> add 0 22:47:37.714 -> aid 2 22:47:37.714 -> cnt 22:47:37.714 -> 22:47:37.714 -> connected with AirS, channel 1 dhcp client start... 💡 Firmware broadcast-test (1.0.0) 22:47:37.850 -> 🔌 Booting into normal mode 🔌 22:47:37.850 -> {} Stored configuration 22:47:37.850 -> • Hardware device ID: 5ccf7fa2e5d2 22:47:37.850 -> • Device ID: kitchen-light 22:47:37.885 -> • Name: The kitchen light 22:47:37.885 -> • Device Stats Interval: 60 sec 22:47:37.885 -> • Wi-Fi: 22:47:37.885 -> ◦ SSID: AirS 22:47:37.885 -> ◦ Password not shown 22:47:37.885 -> • MQTT: 22:47:37.885 -> ◦ Host: 192.168.2.100 22:47:37.885 -> ◦ Port: 1883 22:47:37.885 -> ◦ Base topic: devices/ 22:47:37.885 -> ◦ Auth? yes 22:47:37.885 -> ◦ Username: mqttDevice 22:47:37.885 -> ◦ Password not shown 22:47:37.885 -> • OTA: 22:47:37.885 -> ◦ Enabled? yes 22:47:37.885 -> ↕ Attempting to connect to Wi-Fi... scandone ip:192.168.2.12,mask:255.255.255.0,gw:192.168.2.1 22:47:39.689 -> ✔ Wi-Fi connected, IP: 192.168.2.12 22:47:39.689 -> Triggering WIFI_CONNECTED event... 22:47:39.689 -> ↕ Attempting to connect to MQTT... Sending initial information...`

sovcik commented 5 years ago

Same issue here :-(

bertmelis commented 5 years ago

what is the exact error message? You need to give the reset cause before we can look into the issue.

However, it is most likely caused by

faulty hardware (power?)
outdated libraries (including Arduino framework)
bad flashing
...

sovcik commented 5 years ago

Hi,

I'm trying to run it on NodeMCU connected+powered by USB. It is my usual configuration, so I'd rule power issues out. As for libraries - using Platofmio, so all were freshly installed from their repository according Homie deps. The only outdated part was the platform Espressif8266, which was at 1.8.0. Will try updating that one too.

For now it looks as follows:

 Attempting to connect to Wi-Fi...

connected with r2d2r4d4, channel 11
dhcp client start...
ip:172.16.26.122,mask:255.255.255.0,gw:172.16.26.1
✔ Wi-Fi connected, IP: 172.16.26.122
Triggering WIFI_CONNECTED event...
↕ Attempting to connect to MQTT...
Sending initial information...
Sent.

 ets Jan  8 2013,rst cause:4, boot mode:(3,7)

wdt reset
load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
vbb28d4a3
~ld
-
SDK:2.2.1(cfd48f3)/Core:2.4.2/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-13-g163bb82)/BearSSL:6d1cefc

state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt
� Firmware awesome-relay (1.0.0)
� Booting into normal mode �
{} Stored configuration
  • Hardware device ID: 18fe34cadd28
  • Device ID: z18_garaz
  • Name: Garaz
  • Device Stats Interval: 60 sec
  • Wi-Fi:
    ◦ SSID: r2d2r4d4
    ◦ Password not shown
  • MQTT:
    ◦ Host: 172.16.26.124
    ◦ Port: 1883
    ◦ Base topic: homie/
    ◦ Auth? yes
    ◦ Username: openhabian
    ◦ Password not shown
  • OTA:
    ◦ Enabled? yes
↕ Attempting to connect to Wi-Fi...

connected with r2d2r4d4, channel 11
dhcp client start...
scandone
ip:172.16.26.122,mask:255.255.255.0,gw:172.16.26.1
✔ Wi-Fi connected, IP: 172.16.26.122
Triggering WIFI_CONNECTED event...
↕ Attempting to connect to MQTT...
Sending initial information...
Sent.

 ets Jan  8 2013,rst cause:4, boot mode:(3,7)

wdt reset
load 0x4010f000, len 1384, room 16

sovcik commented 5 years ago

And after updating platform to the most current:


onnected with r2d2r4d4, channel 11
dhcp client start...
ip:172.16.26.122,mask:255.255.255.0,gw:172.16.26.1
✔ Wi-Fi connected, IP: 172.16.26.122
Triggering WIFI_CONNECTED event...
↕ Attempting to connect to MQTT...
Sending initial information...

 ets Jan  8 2013,rst cause:4, boot mode:(3,6)

wdt reset
load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
vac02aff5
~ld
�
SDK:2.2.1(cfd48f3)/Core:2.5.1=20501000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020

state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt
� Firmware awesome-relay (1.0.0)
� Booting into normal mode �
{} Stored configuration
  • Hardware device ID: 18fe34cadd28
  • Device ID: z18_garaz
  • Name: Garaz
  • Device Stats Interval: 60 sec
  • Wi-Fi:
    ◦ SSID: r2d2r4d4
    ◦ Password not shown
  • MQTT:
    ◦ Host: 172.16.26.124
    ◦ Port: 1883
    ◦ Base topic: homie/
    ◦ Auth? yes
    ◦ Username: openhabian
    ◦ Password not shown
  • OTA:
    ◦ Enabled? yes
↕ Attempting to connect to Wi-Fi...

connected with r2d2r4d4, channel 11
dhcp client start...
ip:172.16.26.122,mask:255.255.255.0,gw:172.16.26.1
✔ Wi-Fi connected, IP: 172.16.26.122
Triggering WIFI_CONNECTED event...
↕ Attempting to connect to MQTT...
Sending initial information...

 ets Jan  8 2013,rst cause:4, boot mode:(3,6)

wdt reset
load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
vac02aff5
~ld

SDK:2.2.1(cfd48f3)/Core:2.5.1=20501000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020

� Firmware awesome-relay (1.0.0)

sovcik commented 5 years ago

Tried with https://github.com/homieiot/homie-esp8266/releases/tag/v2.0.1-pre1 - so far the same result.

sovcik commented 5 years ago

Tried the same with a different mqtt host, no authentication:

↕ Attempting to connect to MQTT...
Sending initial information...

 ets Jan  8 2013,rst cause:4, boot mode:(3,6)

wdt reset
load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
vac02aff5
~ld
jj
SDK:2.2.1(cfd48f3)/Core:2.5.1=20501000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020

state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt
� Firmware awesome-relay (1.0.0)
� Booting into normal mode �
{} Stored configuration
  • Hardware device ID: 18fe34cadd28
  • Device ID: homie_test
  • Name: Test
  • Device Stats Interval: 60 sec
  • Wi-Fi:
    ◦ SSID: r2d2r4d4
    ◦ Password not shown
  • MQTT:
    ◦ Host: mqtt.eclipse.org
    ◦ Port: 1883
    ◦ Base topic: homie/
    ◦ Auth? no
  • OTA:
    ◦ Enabled? yes
↕ Attempting to connect to Wi-Fi...

connected with r2d2r4d4, channel 11
dhcp client start...
ip:172.16.26.122,mask:255.255.255.0,gw:172.16.26.1
✔ Wi-Fi connected, IP: 172.16.26.122
Triggering WIFI_CONNECTED event...
↕ Attempting to connect to MQTT...
scandone
Sending initial information...

 ets Jan  8 2013,rst cause:4, boot mode:(3,6)

wdt reset
load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
vac02aff5
~ld

SDK:2.2.1(cfd48f3)/Core:2.5.1=20501000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020

sovcik commented 5 years ago

Config file

{
  "name": "Test",
  "device_id": "homie_test",
  "device_stats_interval": 60,
  "wifi": {
    "ssid": "r2d2r4d4",
    "password": "PrettySecureI0T"
  },
  "mqtt": {
    "host": "mqtt.eclipse.org",
    "port": 1883,
    "base_topic": "homie/"
  },
  "ota": {
    "enabled": true
  },
  "settings": {
    "percentage": 55
  }
}

And code

#include <Homie.h>

const int PIN_RELAY = 4;

HomieNode lightNode("light", "switch");

bool lightOnHandler(const HomieRange& range, const String& value) {
  if (value != "true" && value != "false") return false;

  bool on = (value == "true");
  digitalWrite(PIN_RELAY, on ? HIGH : LOW);
  lightNode.setProperty("on").send(value);
  Homie.getLogger() << "Light is " << (on ? "on" : "off") << endl;

  return true;
}

void setup() {
  Serial.begin(115200);
  Serial << endl << endl;
  pinMode(PIN_RELAY, OUTPUT);
  digitalWrite(PIN_RELAY, LOW);

  Homie_setFirmware("awesome-relay", "1.0.0");

  lightNode.advertise("on").settable(lightOnHandler);

  //Homie.setHomieBootMode(HomieBootMode::NORMAL);
  Homie.setup();

}

void loop() {
  Homie.loop();
}

and platformio.ini

[env:nodemcu]
platform = espressif8266
board = nodemcu
framework = arduino
upload_speed = 921600
monitor_speed = 115200

build_flags =
    -D DEBUG_ESP_PORT=Serial
    -D PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY
    ;-Og
    ;-ggdb

lib_deps = 
    ;Homie
    https://github.com/homieiot/homie-esp8266.git#v2.0.1-pre1

kleini commented 5 years ago

Your upload speed looks way too high. I can not imagine, that the ESP is able to write the flash that fast.

-D PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY

anything with low memory never worked for me at all.

sovcik commented 5 years ago

It seems to have an issue with this part:

    case AdvertisementProgress::GlobalStep::SUB_SET:
      packetId = Interface::get().getMqttClient().subscribe(_prefixMqttTopic(PSTR("/+/+/set")), 2);
      if (packetId != 0) _advertisementProgress.globalStep = AdvertisementProgress::GlobalStep::SUB_BROADCAST;
      break;

packetId == 0 after calling that subscribe method

It tries 4x and then resets...

kleini commented 5 years ago

Yes, because of the low memory build_flag. That build flag reduces the TCP_MSS size. This is the outgoing TCP buffer. Due to async TCP traffic, outgoing TCP packets need to be placed into the outgoing TCP buffer and when this buffer is full, the whole TCP stack dies. I encounter the same issue with high memory build flag too much MQTT topics sent in the Homie.loop() methods of HomieNodes. See #515 .

sovcik commented 5 years ago

Your upload speed looks way too high. I can not imagine, that the ESP is able to write the flash that fast.

It is fine for NodeMCU. Works like magic and saves my time. Using 115200 other ESP chips.

-D PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY
anything with low memory never worked for me at all.

Only included this because it was recommended in this repo :-)

Anyway, tested slower upload speed & removed that build option too. Same result.

kleini commented 5 years ago

The whole async TCP stack works completely different compared to what is expected on normal operating systems as this is a microcontroller. This requires proper handling of TCP data down into the application code, as the interstratified frameworks (Homie, AsyncMQTT, ESPAsyncTCP, AsyncTCP) do not introduce additional buffers and just give failed returns codes. Those failures then need to be handling in the application code, which is very hard for unexperienced coders.

kleini commented 5 years ago

Use

-D PIO_FRAMEWORK_ARDUINO_LWIP2_HIGHER_BANDWIDTH

sovcik commented 5 years ago

With that PIO_FRAMEWORK_ARDUINO_LWIP2_HIGHER_BANDWIDTH got one step forward, up to

  case AdvertisementProgress::GlobalStep::SUB_BROADCAST:

Then it resets :-(

homieiot / homie-esp8266

Problem: wdt reset after "Sending initial information..." on "Bare minimum sketch" #540