Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tasmota32 9.1 on ESP32 DevKit v1 with Zigbee coord. CC2530/CC2591 goes into infinite boot loop (CORRUPT HEAP) after pairing first Zigbee end device #10121

Closed
6 of 7 tasks
tlc76 opened this issue Dec 13, 2020 · 18 comments
Assignees
Labels
bug Type - Confirmated Bug fixed Result - The work on the issue has ended

Comments

@tlc76
Copy link

tlc76 commented Dec 13, 2020

First of all, I apologize for the very long post. I tried to give as many details as possible.
Practically I am unable to use the ESP32 with attached CC2530/CC2591 zigbee coordinatoor.
Just as an FYI, a similar behavior appears also in a EspEasy setup (infinite loop after I enable the Serial Server).
I tried with multiple ESP32 boards of the same model (see below) --> same problem.

PROBLEM DESCRIPTION

HW configuration:
ESP32 (DevKit v1 30 pins) with Tasmota 9.1.0 (recompiled w/ zigbee support enabled)
Zigbee CC2530/CC2591 flashed as coordinator and wired to the ESP32 (first attempt using standard UART2 ports GPIO16 + GPIO17 and also with GPIO18 + GPIO19)
Test end device: xiaomi aqara vibration sensor

Steps performed:

  • enabled pairing until next reboot (ZbPermitJoin 99)
  • pair test device (xiaomi aqara vibration sensor)
  • reboot Tasmota (using reboot command in main menu)

here is the serial log so far:

ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac
▒00:00:00 CFG: Loaded, Count 8
00:00:00 QPC: Count 2
00:00:00 Project tasmota Tasmota Version 9.1.0(tasmota)-1_0_4
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 78:11:DC:53:10:15 in mode 11 as tasmota_851934...
00:00:03 WIF: Connected
00:00:03 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
00:00:04 MQT: Attempting connection...
00:00:04 MQT: Connected
00:00:04 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
00:00:04 MQT: tasmota/tasmota_851934/cmnd/POWER =
00:00:04 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0(tasmota)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
00:00:04 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
00:00:04 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Vbat power on reset"}
12:20:04 QPC: Reset
12:20:07 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-13T12:20:07","Uptime":"0T00:00:11","UptimeSec":11,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":38,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"78:11:DC:53:10:15","Channel":7,"RSSI":86,"Signal":-57,"LinkCount":1,"Downtime":"0T00:00:04"}}
12:20:09 ZIG: rebooting CC2530 device
12:20:10 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
12:20:10 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
12:20:11 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
12:20:11 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
12:20:11 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":1,"AssocDevicesList":["0xD74F"]}}
12:20:12 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
12:20:12 ZIG: Zigbee started
12:20:12 ZIG: No zigbee devices data in Flash
12:20:22 CMD: ZbPermitJoin 99
12:20:22 MQT: tasmota/tasmota_851934/stat/RESULT = {"ZbPermitJoin":"Done"}
12:20:22 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":22,"Message":"Enable Pairing mode until next boot"}}
12:20:34 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":34,"IEEEAddr":"0x00158D0002ABB2E5","ShortAddr":"0xD74F","ParentNetwork":"0x0000"}}
12:20:36 ZIG: Zigbee Devices Data saved (16 bytes)
12:21:12 APP: Restarting

Right after this last reboot, the ESP32 goes into an infinite loop (this is the immediate continuation of the serial log from above):

ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac
00:00:00 CFG: Loaded, Count 9
00:00:00 QPC: Count 1
00:00:00 Project tasmota Tasmota Version 9.1.0(tasmota)-1_0_4
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 78:11:DC:53:10:15 in mode 11 as tasmota_851934...
00:00:04 WIF: Connected
12:21:18 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
12:21:19 MQT: Attempting connection...
12:21:19 MQT: Connected
12:21:19 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
12:21:19 MQT: tasmota/tasmota_851934/cmnd/POWER =
12:21:19 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0(tasmota)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
12:21:19 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
12:21:19 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Software reset CPU"}
12:21:19 QPC: Reset
12:21:24 ZIG: rebooting CC2530 device
12:21:24 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-13T12:21:24","Uptime":"0T00:00:13","UptimeSec":13,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":242,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"78:11:DC:53:10:15","Channel":7,"RSSI":90,"Signal":-55,"LinkCount":1,"Downtime":"0T00:00:05"}}
12:21:26 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
12:21:26 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
12:21:26 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
12:21:27 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
12:21:27 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":1,"AssocDevicesList":["0xD74F"]}}
12:21:27 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
12:21:27 ZIG: Zigbee started
12:21:27 ZIG: No zigbee devices data in Flash
CORRUPT HEAP: Bad head at 0x3ffd32a8. Expected 0xabba1234 got 0x00000000
assertion "head != NULL" failed: file "/home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c", line 214, function: multi_heap_free
abort() was called at PC 0x40147d47 on core 1

Backtrace: 0x4008e490:0x3ffb1dd0 0x4008e6c1:0x3ffb1df0 0x40147d47:0x3ffb1e10 0x4008e095:0x3ffb1e40 0x4008698e:0x3ffb1e60 0x40086d95:0x3ffb1e80 0x4000bec7:0x3ffb1ea0 0x400f096d:0x3ffb1ec0 0x400f09d3:0x3ffb1f00 0x400fc111:0x3ffbed84

Rebooting...

and again:

ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac
00:00:00 CFG: Loaded, Count 9
00:00:00 QPC: Count 1
00:00:00 ZIG: Randomizing Zigbee parameters, please check with 'ZbConfig'
00:00:00 Project tasmota Tasmota Version 9.1.0(tasmota)-1_0_4
00:00:06 QPC: Reset
00:00:12 ZIG: rebooting CC2530 device
00:00:13 RSL: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
00:00:13 RSL: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
00:00:14 RSL: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
00:00:14 RSL: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
00:00:14 RSL: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":1,"AssocDevicesList":["0xD74F"]}}
00:00:15 RSL: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
00:00:15 ZIG: Zigbee started
00:00:15 ZIG: No zigbee devices data in Flash
CORRUPT HEAP: Bad head at 0x3ffd32a8. Expected 0xabba1234 got 0xfefefefe
assertion "head != NULL" failed: file "/home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c", line 214, function: multi_heap_free
abort() was called at PC 0x40147d47 on core 1

Backtrace: 0x4008e490:0x3ffb1dd0 0x4008e6c1:0x3ffb1df0 0x40147d47:0x3ffb1e10 0x4008e095:0x3ffb1e40 0x4008698e:0x3ffb1e60 0x40086d95:0x3ffb1e80 0x4000bec7:0x3ffb1ea0 0x400f096d:0x3ffb1ec0 0x400f09d3:0x3ffb1f00 0x400fc111:0x3ffbed84

Rebooting...

If I unplug the ESP32 the boot loop stops, I can access the Tasmota web UI but somehow the chips goes read/only: the Pinout configuration in the Module configuration menu is reset (all pins set to None) and can no longer be changed:

image

If I attempt to change the setting to match the wiring of the 2 boards (GPIO18 --> Zigbee RX and GPIO19 --> Zigbee TX) and Save configuration, the setting is lost after the reboot and again all pins are set to None:
before Save configuration:
image
after Save config. and reboot:
image

The only way to get back access to the Zigbee coordinator is to reflash the firmware.
Then I run into the same problem after I pair the first end device.

REQUESTED INFORMATION

  • Device used (e.g., Sonoff Basic): ESP32 DevKit v1 (30 pins version)
  • Tasmota binary firmware version number used: 9.1.0
    • Pre-compiled
    • Self-compiled
      • IDE / Compiler used: VSCode + PlatformIO
  • Flashing tools used: esptool with boot_app0.bin, bootloader_dout_40m.bin, partitions.bin and tasmota32.bin (command line: "c:\Program Files (x86)\Python37-32\python.exe" esptool.py --chip esp32 --port COM3 --baud 921600 --before default_reset --after hard_reset write_flash -z --flash_mode dout --flash_freq 40m --flash_size detect 0x1000 bootloader_dout_40m.bin 0x8000 partitions.bin 0xe000 boot_app0.bin 0x10000 tasmota32.bin)
  • Provide the output of command: Backlog Template; Module; GPIO 255:

..... before pairing the end device:

13:02:16 CMD: Backlog Template; Module; GPIO 255
13:02:16 MQT: tasmota/tasmota_851934/stat/RESULT = {"NAME":"ESP32-DevKit","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,1,1,1,0,1,1,1,0,0,0,0,1,1,1,1,1,0,0,1],"FLAG":0,"BASE":1}
13:02:17 MQT: tasmota/tasmota_851934/stat/RESULT = {"Module":{"1":"ESP32-DevKit"}}
13:02:17 MQT: tasmota/tasmota_851934/stat/RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"0":"None"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"},"GPIO18":{"3584":"Zigbee Rx"},"GPIO19":{"3552":"Zigbee Tx"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"0":"None"},"GPIO23":{"0":"None"},"GPIO24":{"0":"None"},"GPIO25":{"0":"None"},"GPIO26":{"0":"None"},"GPIO27":{"0":"None"},"GPIO28":{"0":"None"},"GPIO29":{"0":"None"},"GPIO30":{"0":"None"},"GPIO31":{"0":"None"},"GPIO32":{"0":"None"},"GPIO ...

..... after the device gets into read/only mode;

12:58:07 CMD: Backlog Template; Module; GPIO 255
12:58:07 MQT: tasmota/tasmota_851934/stat/RESULT = {"NAME":"ESP32-DevKit","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,1,1,1,0,1,1,1,0,0,0,0,1,1,1,1,1,0,0,1],"FLAG":0,"BASE":1}
12:58:07 MQT: tasmota/tasmota_851934/stat/RESULT = {"Module":{"1":"ESP32-DevKit"}}
12:58:08 MQT: tasmota/tasmota_851934/stat/RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"0":"None"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"},"GPIO18":{"0":"None"},"GPIO19":{"0":"None"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"0":"None"},"GPIO23":{"0":"None"},"GPIO24":{"0":"None"},"GPIO25":{"0":"None"},"GPIO26":{"0":"None"},"GPIO27":{"0":"None"},"GPIO28":{"0":"None"},"GPIO29":{"0":"None"},"GPIO30":{"0":"None"},"GPIO31":{"0":"None"},"GPIO32":{"0":"None"},"GPIO33":{"0":"None"} ...

Configuration output here:

- [ ] If using rules, provide the output of this command: `Backlog Rule1; Rule2; Rule3`:

Rules output here:

- [X] Provide the output of this command: `Status 0`:

13:22:04 CMD: status0
13:22:04 MQT: tasmota/tasmota_851934/stat/STATUS = {"Status":{"Module":1,"DeviceName":"Tasmota","FriendlyName":["Tasmota"],"Topic":"tasmota_851934","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}

- [ ] Provide the output of the Console log output when you experience your issue; if applicable:
  _(Please use_ `weblog 4` _for more debug information)_

TO REPRODUCE

  • ESP32 connected to CC2530/CC2591 with fw coordinator (3V3, GND and RX/TX connected to either UART2 GPIO16 and 17 or respectively GPIO18 and 19)
  • compile Tasmota with #define USE_ZIGBEE
  • erase flash (esptool.py)
  • write flash (esptool.py) with the bootloader and partition files - see exact details above including flash command line
  • configure module to communicate via serial protocol with the Zigbee coordinator
  • run command ZbPermitJoin 99 in console to allow end device pairing
  • pair test end device (vibration sensor)
  • reboot
  • get into an infinite boot loop (corrupt heap / backtrace)

EXPECTED BEHAVIOUR

Practically I am unable to get the ESP32 board to work with the Zigbee coordinator.
I have a similar setup with ESP8266 (and EspEasy + Zigbee2mqtt) and it works perfectly!
Has anyone managed to make it working with ESP32 boards?
If yes, can you please provide more details about the "how"?
Thanks a lot,
Cristian

SCREENSHOTS

If applicable, add screenshots to help explain your problem.

ADDITIONAL CONTEXT

Add any other context about the problem here.

(Please, remember to close the issue when the problem has been addressed)

@Jason2866
Copy link
Collaborator

Jason2866 commented Dec 13, 2020

My first impression the bug is in Arduino core Bad head at 0x3ffd32a8. Expected 0xabba1234 got 0xfefefefe assertion "head != NULL" failed: file "/home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c", line 214, function: multi_heap_free abort() was called at PC 0x40147d47 on core 1
Please compile your tasmota32 version from latest development branch with Arduino core Esp32 1.0.5-rc4. To do so, you have to rename Platformio_override_sample.ini to platformio_override.ini and uncomment line 127 to 130.
Please post your logs again.

@ascillato2 ascillato2 added awaiting feedback Action - Waiting for response or more information troubleshooting Type - Troubleshooting labels Dec 13, 2020
@tlc76
Copy link
Author

tlc76 commented Dec 13, 2020

Thanks for the tips.
I used latest devel. version (9.1.0.2) and followed the instructions (only this time I uncommented tasmota32-sensors.bin instead of tasmota32.bin). But it should make no difference.

As before, everything goes well until I reboot the ESP32:

  • I've set the GPIO18 and 19 pins to Zigbee RX/Zigbee TX
  • Saved config and rebooted
  • Entered zigbee coord. in pairing mode - nice button btw :)
  • Paired test end device - confirmation message ok:

20:12:07 ZIG: Zigbee started
20:12:07 ZIG: No Zigbee device information in Flash
20:12:25 MQT: tasmota/tasmota_851934/stat/RESULT = {"ZbPermitJoin":"Done"}
20:12:25 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":21,"Message":"Enable Pairing mode for 60 seconds"}}
20:12:32 ZIG: sending ZbMap 0x0000
20:12:32 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbMap":{"Device":"0x0000","Status":0,"StatusMessage":"SUCCESS","Total":1,"Start":1,"Map":[{"Device":"0xD74F","DeviceType":"Device","RxOnWhenIdle":false,"Relationship":"Child","PermitJoin":null,"Depth":1,"LinkQuality":170}]}}
20:12:37 ZIG: ZbMap done
20:13:05 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":34,"IEEEAddr":"0x00158D0002ABB2E5","ShortAddr":"0xD74F","ParentNetwork":"0x0000"}}
20:13:07 ZIG: Zigbee Devices Data saved in Flash (16 bytes)

  • Played a bit with the Zigbee map function (also very nice - the new sensor was displayed on the map)
    image
    ![image](https://user-images.githubusercontent.com/37828991/102020861-a8afc100-3d84-11eb-9cae-6d0e7a3f12dc.png

  • Rebooted again - it's interesting that immediately after the pairing no information from the vibration sensor is received even if I shake the sensor quite well! This device is very sensitive and should send measurements whenever you move it (X, Y, Z angles, vibration intensity etc.). So its possible that the zigbee communication is not working properly after the pairing process is carried out?

After the final reboot I get exactly the same behavior:

  • infinite loop (backtrace and CORRUPT HEAP messages)
  • if I unplug it for a while, the pinout in Module configuration is reset (all pins set to None) and zigbee is disabled
  • I am able to temporarily change the pin configuration but the new setting is lost after hitting Save (which includes a reboot).
    I did a test and changed Telemetry period from 300 to 305 seconds (this change does NOT require a reboot). After I restart the ESP32, this setting is lost (it gets back to 300 seconds).

Here is the serial output:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac
▒
00:00:00 CFG: Loaded, Count 3
00:00:00 QPC: Count 1
00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-13T20:02:42)
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 40:31:3C:9E:80:0C in mode 11n as tasmota_851934...
00:00:03 WIF: Connected
20:10:46 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
20:10:47 MQT: Attempting connection...
20:10:48 MQT: Connected
20:10:48 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
20:10:48 MQT: tasmota/tasmota_851934/cmnd/POWER =
20:10:48 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
20:10:48 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
20:10:48 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Vbat power on reset"}
20:10:49 QPC: Reset
20:10:52 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-13T20:10:52","Uptime":"0T00:00:11","UptimeSec":11,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":34,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":82,"Signal":-59,"LinkCount":1,"Downtime":"0T00:00:04"}}
20:11:46 MOD: ESP32-DevKit Module, GPIO0 0, GPIO1 0, GPIO2 0, GPIO3 0, GPIO4 0, GPIO5 0, GPIO12 0, GPIO13 0, GPIO14 0, GPIO15 0, GPIO16 0, GPIO17 0, GPIO18 3584, GPIO19 3552, GPIO21 0, GPIO22 0, GPIO23 0, GPIO25 0, GPIO26 0, GPIO27 0, GPIO32 0, GPIO33 0, GPIO34 0, GPIO35 0, GPIO36 0, GPIO39 0
20:11:47 APP: Restarting
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac

00:00:00 CFG: Loaded, Count 5
00:00:00 QPC: Count 1
00:00:00 ZIG: Randomizing Zigbee parameters, please check with 'ZbConfig'
00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-13T20:02:42)
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 40:31:3C:9E:80:0C in mode 11n as tasmota_851934...
00:00:03 WIF: Connected
00:00:04 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
20:11:54 MQT: Attempting connection...
20:11:54 MQT: Connected
20:11:54 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
20:11:54 MQT: tasmota/tasmota_851934/cmnd/POWER =
20:11:54 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
20:11:54 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
20:11:54 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Software reset CPU"}
20:11:55 QPC: Reset
20:11:58 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-13T20:11:58","Uptime":"0T00:00:11","UptimeSec":11,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":29,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":84,"Signal":-58,"LinkCount":1,"Downtime":"0T00:00:05"}}
20:12:04 ZIG: rebooting CC2530 device
20:12:05 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
20:12:05 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
20:12:06 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
20:12:06 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
20:12:06 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":1,"AssocDevicesList":["0xD74F"]}}
20:12:07 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
20:12:07 ZIG: Zigbee started
20:12:07 ZIG: No Zigbee device information in Flash
20:12:25 MQT: tasmota/tasmota_851934/stat/RESULT = {"ZbPermitJoin":"Done"}
20:12:25 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":21,"Message":"Enable Pairing mode for 60 seconds"}}
20:12:32 ZIG: sending `ZbMap 0x0000`
20:12:32 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbMap":{"Device":"0x0000","Status":0,"StatusMessage":"SUCCESS","Total":1,"Start":1,"Map":[{"Device":"0xD74F","DeviceType":"Device","RxOnWhenIdle":false,"Relationship":"Child","PermitJoin":null,"Depth":1,"LinkQuality":170}]}}
20:12:37 ZIG: ZbMap done
20:13:05 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":34,"IEEEAddr":"0x00158D0002ABB2E5","ShortAddr":"0xD74F","ParentNetwork":"0x0000"}}
20:13:07 ZIG: Zigbee Devices Data saved in Flash (16 bytes)
20:13:25 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":20,"Message":"Disable Pairing mode"}}
20:13:48 ZIG: sending `ZbMap 0x0000`
20:13:48 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbMap":{"Device":"0x0000","Status":0,"StatusMessage":"SUCCESS","Total":1,"Start":1,"Map":[{"Device":"0xD74F","DeviceType":"Device","RxOnWhenIdle":false,"Relationship":"Child","PermitJoin":null,"Depth":1,"LinkQuality":170}]}}
20:13:50 ZIG: sending `ZbMap 0xD74F`
20:13:56 ZIG: ZbMap done
20:14:08 MQT: tasmota/tasmota_851934/stat/RESULT = {"ZbRestore":"ZbRestore 0F4FD7E5B2AB02008D1500000000FF"}
20:14:09 APP: Restarting
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac

00:00:00 CFG: Loaded, Count 7
00:00:00 QPC: Count 1
00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-13T20:02:42)
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 40:31:3C:9E:80:0C in mode 11n as tasmota_851934...
00:00:04 WIF: Connected
00:00:04 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
20:14:16 MQT: Attempting connection...
20:14:16 MQT: Connected
20:14:16 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
20:14:16 MQT: tasmota/tasmota_851934/cmnd/POWER =
20:14:16 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
20:14:16 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
20:14:16 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Software reset CPU"}
20:14:17 QPC: Reset
20:14:21 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-13T20:14:21","Uptime":"0T00:00:12","UptimeSec":12,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":76,"Signal":-62,"LinkCount":1,"Downtime":"0T00:00:05"}}
20:14:26 ZIG: rebooting CC2530 device
20:14:27 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
20:14:27 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
20:14:28 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
20:14:28 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
20:14:28 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":1,"AssocDevicesList":["0xD74F"]}}
20:14:29 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
20:14:29 ZIG: Zigbee started
20:14:29 ZIG: No Zigbee device information in Flash
CORRUPT HEAP: Bad head at 0x3ffe16d0. Expected 0xabba1234 got 0x00000100
abort() was called at PC 0x40083919 on core 1

ELF file SHA256: 0000000000000000

Backtrace: 0x40090528:0x3ffd1010 0x400907a5:0x3ffd1030 0x40083919:0x3ffd1050 0x40083a45:0x3ffd1080 0x4018ca0b:0x3ffd10a0 0x401863c1:0x3ffd1360 0x40186331:0x3ffd13b0 0x400952b9:0x3ffd13e0 0x40082d62:0x3ffd1400 0x4008385d:0x3ffd1420 0x4000bec7:0x3ffd1440 0x400ff165:0x3ffd1460 0x400ff20d:0x3ffd14a0 0x40106361:0x3ffc3a1c

Rebooting...
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac

00:00:00 CFG: Loaded, Count 7
00:00:00 QPC: Count 1
00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-13T20:02:42)
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 40:31:3C:9E:80:0C in mode 11n as tasmota_851934...
00:00:03 WIF: Connected
00:00:03 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
20:14:34 MQT: Attempting connection...
20:14:35 MQT: Connected
20:14:35 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
20:14:35 MQT: tasmota/tasmota_851934/cmnd/POWER =
20:14:35 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
20:14:35 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
20:14:35 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Software reset CPU"}
20:14:36 QPC: Reset
20:14:40 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-13T20:14:40","Uptime":"0T00:00:12","UptimeSec":12,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":86,"Signal":-57,"LinkCount":1,"Downtime":"0T00:00:05"}}
20:14:45 ZIG: rebooting CC2530 device
20:14:46 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
20:14:46 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
20:14:47 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
20:14:47 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
20:14:47 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":1,"AssocDevicesList":["0xD74F"]}}
20:14:48 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
20:14:48 ZIG: Zigbee started
20:14:48 ZIG: No Zigbee device information in Flash
CORRUPT HEAP: Bad head at 0x3ffe16d0. Expected 0xabba1234 got 0x2a000045
abort() was called at PC 0x40083919 on core 1

ELF file SHA256: 0000000000000000

Backtrace: 0x40090528:0x3ffd1010 0x400907a5:0x3ffd1030 0x40083919:0x3ffd1050 0x40083a45:0x3ffd1080 0x4018ca0b:0x3ffd10a0 0x401863c1:0x3ffd1360 0x40186331:0x3ffd13b0 0x400952b9:0x3ffd13e0 0x40082d62:0x3ffd1400 0x4008385d:0x3ffd1420 0x4000bec7:0x3ffd1440 0x400ff165:0x3ffd1460 0x400ff20d:0x3ffd14a0 0x40106361:0x3ffc3a1c

Rebooting...

Should I change the GPIO pins? I tested so far with 16, 17 (RX2, TX2) and 18, 19.
Has anyone managed to make the ESP32 working in conjunction with a Zigbee coordinator via a serial connection? I tried also with EspEasy firmware and I get a similar (backtrace) issue, but during the plugin initialization phase after the reboot (the ser2net plugin is used there). Sorry for the off topic, I think it could be relevant.

Thanks for looking into this - let me know if more details are needed.
Your help is highly appreciated.

Cheers

@s-hadinger
Copy link
Collaborator

Zigbee has not really been tested with ESP32. It looks like the code to retrieve Flash.

@arendst the current code is:


  // first copy SPI buffer into ram
  uint8_t *spi_buffer = (uint8_t*) malloc(z_spi_len);
  if (!spi_buffer) {
    AddLog_P(LOG_LEVEL_ERROR, PSTR(D_LOG_ZIGBEE "Cannot allocate 4KB buffer"));
    return;
  }
  ZigbeeRead(&spi_buffer, z_spi_len);
  z_dev_start = spi_buffer;

Shouldn't it be:

ZigbeeRead(spi_buffer, z_spi_len);

I have the impression it is overwriting the stack.

@Jason2866
Copy link
Collaborator

Jason2866 commented Dec 13, 2020

@tlc76 Always use Tasmota(32) as base for customized builds.
You can run in compile issues because libs are disabled in preconfigured builds and some settings you try to do are not possible (the are reverted).
NOT the issue here. General info

@arendst arendst self-assigned this Dec 14, 2020
arendst added a commit that referenced this issue Dec 14, 2020
Fix ESP32 CC2530 heap corruption (#10121)
@arendst
Copy link
Owner

arendst commented Dec 14, 2020

Give the fix a try and report back if it solved your issue. I cannot test as my CC2530 is in production on a ESP8266.

@tlc76
Copy link
Author

tlc76 commented Dec 14, 2020

Thanks a lot @arendst, this works perfectly!
I have tested with a Temp/Humid/Pressure sensor (in addition to the vibration sensor which seems to be malfunctioning - it doesn't send telemetry data).

Reboot loop --> fixed
Corrupt heap --> fixed
All devices are kept in memory after reboot

image

However the Tasmota settings remain read-only after I enable the serial GPIOs linking the ESP32 board to the CC2530/2591 Zigbee coordinator. Any change that I make in the Tasmota configuration gets reverted after a reboot.
I have tested (unsuccesfully) with;

  • Configure Wifi / AP2 SSId
  • Configure Logging / Telemetry period

@Jason2866 : thanks for the tip, I will keep that in mind.

@arendst
Copy link
Owner

arendst commented Dec 14, 2020

However the Tasmota settings remain read-only after I enable the serial GPIOs linking the ESP32 board to the CC2530/2591 Zigbee coordinator. Any change that I make in the Tasmota configuration gets reverted after a reboot.

That could be a major issue. The zigbee devices are stored on (small)NVS as are the settings. They both need 4k contiguous space but I suspect once your first zigbee device is stored the area becomes fragmented and the 4k Tasmota settings cannot longer be saved.

I have to rethink ESP32 zigbee device storage and move it to SPIFFS/TINYFS or what ever.

This will take some time so for now treat this feature as "experimental"

@arendst arendst added Requires more research (devs) Action - Issue requires more research and removed awaiting feedback Action - Waiting for response or more information troubleshooting Type - Troubleshooting labels Dec 14, 2020
@tlc76
Copy link
Author

tlc76 commented Dec 14, 2020

@arendst that's very clear, thanks.
In the mean time let me know if I can be of any help, as an alfa/beta tester or anything else.

arendst added a commit that referenced this issue Dec 15, 2020
- Add ESP32 support for Tasmota FileSystem
- Move ESP32 Zigbee persistence from NVS to SPIFFS (#10121)
@arendst arendst added awaiting feedback Action - Waiting for response or more information and removed Requires more research (devs) Action - Issue requires more research labels Dec 15, 2020
@arendst
Copy link
Owner

arendst commented Dec 15, 2020

Pls try the latest dev. It moved the zigbee persistence from NVS to SPIFFS.

@ascillato2 ascillato2 added bug Type - Confirmated Bug fixed Result - The work on the issue has ended labels Dec 15, 2020
@tlc76
Copy link
Author

tlc76 commented Dec 15, 2020

Thanks a lot for fixing this issue!
Problem solved!
Tasmota settings can now be changed after pairing 1+ zigbee end devices.

One small concern (I'm not sure it's an issue).
Here is the use case:

  • ESP32 is erased and reflashed via serial (using the 3 bootloader/partitions files + 1 freshly built firmware file tasmota32-sensors.bin)
  • I configure the Zigbee GPIOs (then save and reboot)
  • I pair 2 end devices with the coord.
  • I get a "Zigbee Devices Data saved in Flash (XX bytes)" message in the console / serial output
  • I reboot again the ESP32
  • After the 2nd reboot I see "No Zigbee device information in Flash" message in the log (see last line, in bold) :

00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-15T22:18:14)
00:00:00 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 78:11:DC:53:10:15 in mode 11n as tasmota_851934...
00:00:04 WIF: Connected
22:45:26 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
22:45:27 MQT: Attempting connection...
22:45:28 MQT: Connected
22:45:28 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
22:45:28 MQT: tasmota/tasmota_851934/cmnd/POWER =
22:45:28 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
22:45:28 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
22:45:28 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Software reset CPU"}
22:45:28 QPC: Reset
22:45:34 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-15T22:45:34","Uptime":"0T00:00:14","UptimeSec":14,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":277,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"78:11:DC:53:10:15","Channel":7,"RSSI":80,"Signal":-60,"LinkCount":1,"Downtime":"0T00:00:05"}}
22:45:37 ZIG: rebooting CC2530 device
22:45:39 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
22:45:39 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
22:45:39 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
22:45:40 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
22:45:40 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":2,"AssocDevicesList":["0x29CC","0xDB1F"]}}
22:45:40 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
22:45:40 ZIG: Zigbee started
22:45:40 ZIG: No Zigbee device information in Flash

After the 2nd reboot, as soon as the first messages are sent out by the child devices to the coordinator (as they are already paired), the zigbee devices data are stored in the memory (see below lines in bold):

22:46:06 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraVibrationMode":"vibrate","Endpoint":1,"LinkQuality":166}}}
22:46:07 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraVibrationMode":"tilt","AqaraVibrationsOrAngle":5,"AqaraAccelerometer":"0xFC8CFFA0005B","Endpoint":1,"LinkQuality":158}}}
22:46:08 ZIG: Zigbee Devices Data saved in Flash (16 bytes)
22:46:34 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0x29CC":{"Device":"0x29CC","Temperature":26.73,"Humidity":70.15,"Pressure":1012,"PressureScale":-1,"PressureScaledValue":10123,"SeaPressure":1012,"Endpoint":1,"LinkQuality":202}}}
22:46:36 ZIG: Zigbee Devices Data saved in Flash (34 bytes)

Is this behavior normal?
Shouldn't the paired devices data be persistent in the Flash memory across reboots?

Thank you once again!

@s-hadinger
Copy link
Collaborator

Saving zigbee device data was only implemented for Zbbridge eeprom. It should not even try to save it, until I adapt the code for esp32.

Consider this feature as not implemented on esp32, yet.

@arendst
Copy link
Owner

arendst commented Dec 16, 2020

Ah I think I still have an issue. Did you ever see messages like:

  TFS: Mounting...
  TFS: Formatting...
  TFS: Mounted

I'll do some more tests.

@arendst arendst reopened this Dec 16, 2020
arendst added a commit that referenced this issue Dec 16, 2020
Fix enabling SPIFFS filesystem (#10121)
@arendst
Copy link
Owner

arendst commented Dec 16, 2020

Pls try latest dev.

@tlc76
Copy link
Author

tlc76 commented Dec 16, 2020

Ah I think I still have an issue. Did you ever see messages like:

  TFS: Mounting...
  TFS: Formatting...
  TFS: Mounted

I'll do some more tests.

I didn't notice such messages in the serial logs. I will test the new sources right away - be right back with the results.

@tlc76
Copy link
Author

tlc76 commented Dec 16, 2020

Test scenario:

  • erase_flash
  • write_flash (tasmota32-sensors.bin with newly compiled from the development branch and the 3 bootloader files)
  • configure zigbee coord. GPIOs (18-->RX, 19-->TX)
  • save/reboot
  • wait for a few minutes for incoming zigbee messages (sensors already paired)

Here is a serial log extract (after last reboot):

14:01:24 ZIG: Zigbee started
14:01:24 TFS: Mounting...
E (21280) SPIFFS: mount failed, -10025
14:01:24 TFS: Formatting...
14:01:24 TFS: Mounted
14:01:26 TFS: File not found
14:01:26 ZIG: No Zigbee device information in Flash

And the full log (with all operations after the reflash step):

ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac

00:00:00 CFG: Loaded, Count 0
00:00:00 CFG: Use defaults
00:00:00 QPC: Reset
00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-16T13:56:34)
00:00:00 WIF: Connecting to AP1 tlc3 in mode 11n as tasmota_851934...
00:00:04 WIF: Connected
14:00:25 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
14:00:26 MQT: Attempting connection...
14:00:26 MQT: Connected
14:00:26 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
14:00:26 MQT: tasmota/tasmota_851934/cmnd/POWER =
14:00:26 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
14:00:26 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
14:00:26 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Vbat power on reset"}
14:00:32 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-16T14:00:32","Uptime":"0T00:00:13","UptimeSec":13,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":258,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":96,"Signal":-52,"LinkCount":1,"Downtime":"0T00:00:05"}}
14:01:00 MOD: ESP32-DevKit Module, GPIO0 0, GPIO1 0, GPIO2 0, GPIO3 0, GPIO4 0, GPIO5 0, GPIO12 0, GPIO13 0, GPIO14 0, GPIO15 0, GPIO16 0, GPIO17 0, GPIO18 3584, GPIO19 3552, GPIO21 0, GPIO22 0, GPIO23 0, GPIO25 0, GPIO26 0, GPIO27 0, GPIO32 0, GPIO33 0, GPIO34 0, GPIO35 0, GPIO36 0, GPIO39 0
14:01:02 APP: Restarting
ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DOUT, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac

00:00:00 CFG: Loaded, Count 4
00:00:00 QPC: Count 1
00:00:00 ZIG: Randomizing Zigbee parameters, please check with 'ZbConfig'
00:00:00 Project tasmota Tasmota Version 9.1.0.2(sensors)-1_0_5_RC4(2020-12-16T13:56:34)
00:00:01 WIF: Connecting to AP1 tlc3 Channel 7 BSSId 40:31:3C:9E:80:0C in mode 11n as tasmota_851934...
00:00:04 WIF: Connected
00:00:04 HTP: Web server active on tasmota_851934 with IP address 10.0.0.42
14:01:10 MQT: Attempting connection...
14:01:10 MQT: Connected
14:01:10 MQT: tasmota/tasmota_851934/tele/LWT = Online (retained)
14:01:10 MQT: tasmota/tasmota_851934/cmnd/POWER =
14:01:10 MQT: tasmota/tasmota_851934/tele/INFO1 = {"Module":"ESP32-DevKit","Version":"9.1.0.2(sensors)","FallbackTopic":"cmnd/DVES_851934_fb/","GroupTopic":"tasmota/tasmotas/cmnd/"}
14:01:10 MQT: tasmota/tasmota_851934/tele/INFO2 = {"WebServerMode":"Admin","Hostname":"tasmota_851934","IPAddress":"10.0.0.42"}
14:01:10 MQT: tasmota/tasmota_851934/tele/INFO3 = {"RestartReason":"Software reset CPU"}
14:01:11 QPC: Reset
14:01:15 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-16T14:01:15","Uptime":"0T00:00:12","UptimeSec":12,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":92,"Signal":-54,"LinkCount":1,"Downtime":"0T00:00:05"}}
14:01:20 ZIG: rebooting CC2530 device
14:01:22 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":1,"Message":"CC2530 booted","RestartReason":"Watchdog","MajorRel":2,"MinorRel":6}}
14:01:22 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":50,"MajorRel":2,"MinorRel":6,"MaintRel":3,"Revision":20190608}}
14:01:23 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":3,"Message":"Configured, starting coordinator"}}
14:01:24 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":40,"NewState":9,"Message":"Started as coordinator"}}
14:01:24 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":51,"IEEEAddr":"0x00124B001F320808","ShortAddr":"0x0000","DeviceType":7,"DeviceState":9,"NumAssocDevices":2,"AssocDevicesList":["0x29CC","0xDB1F"]}}
14:01:24 MQT: tasmota/tasmota_851934/tele/RESULT = {"ZbState":{"Status":0,"Message":"Started"}}
14:01:24 ZIG: Zigbee started
14:01:24 TFS: Mounting...
E (21280) SPIFFS: mount failed, -10025
14:01:24 TFS: Formatting...
14:01:24 TFS: Mounted
14:01:26 TFS: File not found
14:01:26 ZIG: No Zigbee device information in Flash
14:06:16 MQT: tasmota/tasmota_851934/tele/STATE = {"Time":"2020-12-16T14:06:16","Uptime":"0T00:05:13","UptimeSec":313,"Heap":86,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Wifi":{"AP":1,"SSId":"tlc3","BSSId":"40:31:3C:9E:80:0C","Channel":7,"RSSI":74,"Signal":-63,"LinkCount":1,"Downtime":"0T00:00:05"}}
14:07:31 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraVibrationMode":"vibrate","Endpoint":1,"LinkQuality":106}}}
14:07:33 TFS: File not found
14:07:33 ZIG: Zigbee Devices Data saved in Flash (16 bytes)
14:07:38 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraVibrationMode":"tilt","AqaraVibrationsOrAngle":13,"Endpoint":1,"LinkQuality":132}}}
14:07:43 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraVibrationMode":"drop","Endpoint":1,"LinkQuality":101}}}
14:07:44 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraAccelerometer":"0x04B0FFD3000E","Endpoint":1,"LinkQuality":111}}}
14:07:57 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0x29CC":{"Device":"0x29CC","Temperature":24.87,"Humidity":58.2,"Pressure":1012,"PressureScale":-1,"PressureScaledValue":10129,"SeaPressure":1012,"Endpoint":1,"LinkQuality":111}}}
14:07:59 ZIG: Zigbee Devices Data saved in Flash (34 bytes)
14:08:07 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0x29CC":{"Device":"0x29CC","Temperature":23.91,"Humidity":88.84,"Pressure":1012,"PressureScale":-1,"PressureScaledValue":10129,"SeaPressure":1012,"Endpoint":1,"LinkQuality":111}}}

@arendst
Copy link
Owner

arendst commented Dec 16, 2020

OK. That looks better.

What happens after another reboot. You should not see the TFS: Formatting message anymore.

@tlc76
Copy link
Author

tlc76 commented Dec 16, 2020

Here is the log after another reboot (you are right, no more "formatting" message, it directly mounts the FS):

15:49:37 ZIG: Zigbee started
15:49:37 TFS: Mounting...
15:49:37 TFS: Mounted
15:49:37 TFS: File not found
15:49:37 ZIG: No Zigbee device information in Flash
15:50:09 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0x29CC":{"Device":"0x29CC","Temperature":25.25,"Humidity":86.91,"Pressure":1013,"PressureScale":-1,"PressureScaledValue":10131,"SeaPressure":1013,"Endpoint":1,"LinkQuality":119}}}
15:50:11 TFS: File not found
15:50:11 ZIG: Zigbee Devices Data saved in Flash (19 bytes)
15:50:20 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0x29CC":{"Device":"0x29CC","Temperature":24.7,"Humidity":90.53,"Pressure":1013,"PressureScale":-1,"PressureScaledValue":10131,"SeaPressure":1013,"Endpoint":1,"LinkQuality":119}}}

And after another reboot (after the 2 sensors had sent some zigbee messages to the coord.):

15:52:55 ZIG: Zigbee started
15:52:55 TFS: Mounting...
15:52:55 TFS: Mounted
15:52:55 ZIG: Zigbee device information in Flash (34 bytes)
15:54:07 MQT: tasmota/tasmota_851934/tele/SENSOR = {"ZbReceived":{"0xDB1F":{"Device":"0xDB1F","AqaraVibrationMode":"vibrate","Endpoint":1,"LinkQuality":182}}}

Could it be that the issue mentioned by @s-hadinger is gone and the zigbee device information is now persistent across reboots? That would be great :)

Saving zigbee device data was only implemented for Zbbridge eeprom. It should not even try to save it, until I adapt the code for esp32.

Consider this feature as not implemented on esp32, yet.

thanks!

@arendst
Copy link
Owner

arendst commented Dec 16, 2020

I think he was a bit confused about this as this was already present before his recent additions.

Your latest response just confirms my expectation so I think we are done here.

Thx for your cooperation. Pls close this issue.

@tlc76 tlc76 closed this as completed Dec 16, 2020
@ascillato2 ascillato2 removed the awaiting feedback Action - Waiting for response or more information label Feb 16, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Type - Confirmated Bug fixed Result - The work on the issue has ended
Projects
None yet
Development

No branches or pull requests

5 participants