Crash / wifi disconnect if Door Close Delay enabled

[jakepez]

Firmware: v3.0.5
Device: RATGDO 32
Garage Door Opener: LiftMaster ELITE Series LED Wi-Fi
Model: WLED

When Door Close Delay is enabled (3 seconds, 5 seconds, etc.):

• Trigger Door Close
• Timer starts
• Lights blink
• When Timer ends - Blinking ends
• Door does not close
• Lose Wifi connection

Connect via USB Cable, reconfigure connection to Wifi

• Able to capture logs (attached) - esp-web-tools-logs (2).txt

Crash log here:

Time of crash: 13-Jan-2025 17:20:59 PST
Crash reason: StoreProhibited
Firmware version: 3.0.5

atus - NoData: [Zero: 0x00000000, Parity: 0x8]
>>> [    168.665] ratgdo-comms: Support for GetStatus packet unimplemented. Ignoring.
>>> [    168.739] ratgdo-reader: reader completed packet
>>> [    168.742] ratgdo-packet: DECODED  00015B85 000000C0B79BE00A 4260D481
>>> [    168.746] ratgdo-packet: PACKET(0x9BE00A @ 0x15B85) Status - Status: [DoorState Opening, Parity 0xD, Obs 1, Lock 0, Light 1]
>>> [    168.759] ratgdo-comms: tgt 0 curr 2
>>> [    168.763] ratgdo-http: Current Door State changing from 1 to 2
>>> [    168.766] ratgdo-homekit: Garage door set CurrentDoorState: 2
>>> [    168.773] ratgdo-http: SSE send to client 10.0.1.116 on channel 0, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Opening", "upTime": 168763 }
>>> [    168.791] ratgdo-http: SSE send to client 10.0.1.116 on channel 1, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Opening", "upTime": 168763 }
>>> [    168.796] ratgdo-homekit: Garage door set TargetDoorState: 0
>>> [    168.806] ratgdo-http: SSE send to client 10.0.1.116 on channel 3, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Opening", "upTime": 168763 }
>>> [    168.827] ratgdo-main: Free heap dropped to 116880
>>> [    169.822] ratgdo-reader: reader completed packet
>>> [    169.825] ratgdo-packet: DECODED  00015B85 000000C0B79BE00A 4260D481
>>> [    169.829] ratgdo-packet: PACKET(0x9BE00A @ 0x15B85) Status - Status: [DoorState Opening, Parity 0xD, Obs 1, Lock 0, Light 1]
>>> [    169.843] ratgdo-comms: tgt 0 curr 2
>>> [    171.532] ratgdo-reader: reader completed packet
>>> [    171.535] ratgdo-packet: DECODED  00015B85 000000C2B79BE00A 0000E084
>>> [    171.539] ratgdo-packet: PACKET(0x9BE00A @ 0x15B85) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [    171.552] ratgdo-comms: Support for MotorOn packet unimplemented. Ignoring.
>>> [    172.590] ratgdo-http: Client 10.0.1.116 requesting: /status.json (method: HTTP_GET)
>>> [    172.690] ratgdo-http: JSON length: 1014
>>> [    176.067] ratgdo-reader: reader completed packet
>>> [    176.071] ratgdo-packet: DECODED  00015B85 000000C2B79BE00A 0000E084
>>> [    176.076] ratgdo-packet: PACKET(0x9BE00A @ 0x15B85) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [    176.089] ratgdo-comms: Support for MotorOn packet unimplemented. Ignoring.
>>> [    179.313] ratgdo-reader: reader completed packet
>>> [    179.316] ratgdo-packet: DECODED  00015B85 000000C2B79BE00A 0000E084
>>> [    179.320] ratgdo-packet: PACKET(0x9BE00A @ 0x15B85) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [    179.333] ratgdo-comms: Support for MotorOn packet unimplemented. Ignoring.
>>> [    182.343] ratgdo-reader: reader completed packet
>>> [    182.346] ratgdo-packet: DECODED  00015B86 000000C0B79BE00A 42608181
>>> [    182.350] ratgdo-packet: PACKET(0x9BE00A @ 0x15B86) Status - Status: [DoorState Open, Parity 0x8, Obs 1, Lock 0, Light 1]
>>> [    182.363] ratgdo-comms: tgt 0 curr 0
>>> [    182.367] ratgdo-http: Current Door State changing from 2 to 0
>>> [    182.374] ratgdo-homekit: Garage door set CurrentDoorState: 0


Crash in task: esp_timer, at address: 0x40082ADD
Decode backtrace with this Linux command:

addr2line -p -f -C -e homekit-ratgdo32-v3.0.5.elf \
 -a 0x40082ADD 0x4008F7FD 0x40095FBE 0x40094CC7 0x40083CDF 0x40095FF1 \
    0x4011E9D9 0x40090512 

Make sure that the ELF file matches the binary that crashed.

[dkerr64]

Thanks for reporting this. I will try and reproduce. Can you tell me if the door close request was from HomeKit or from the wall panel? The log is showing that the wall panel button is getting pressed, and I wonder if that is related or not.

Thanks

[jakepez]

The wall panel button push seems to work just fine - no delay (since it's not a remote device) - and so I think that's just getting passed through the RATGDO back to the opener.

The crash/disconnect is coming from closing the door via HomeKit (I should have included that above!).

Reseting the Door Close Delay to 0 and it closes with no delay (no lights blinking) and does not crash / disconnect the RATGDO.

[dkerr64]

Decode of the backtrace...

addr2line -p -f -C -e homekit-ratgdo32-v3.0.5.elf \
 -a 0x40082ADD 0x4008F7FD 0x40095FBE 0x40094CC7 0x40083CDF 0x40095FF1 \
    0x4011E9D9 0x40090512
0x40082add: panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:463
0x4008f7fd: esp_system_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/port/esp_system_chip.c:92
0x40095fbe: __assert_func at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/assert.c:80
0x40094cc7: multi_heap_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c:279 (discriminator 1)
0x40083cdf: heap_caps_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps_base.c:70
0x40095ff1: free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/heap.c:39
0x4011e9d9: timer_process_alarm at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_timer/src/esp_timer.c:430
0x40090512: vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139

[dkerr64]

So, I am not able to reproduce... delay close works for me. However, the backtrace shows that the crash is a free() in esp_timer which got me looking at the code. Your logs are showing both time-to-close and also "Request to boot into soft access point mode" which is strange... that should only be triggered from rapid pressing of wall panel button.

That said, I do see something suspicious in the source code... using the same timer for both door close delay, and the manual recovery to boot into access point mode. This is probably a bad idea. So I can change that. Give me a few days and I should have something for you to test.

Thanks.

[jakepez]

Thanks! I’m definitely not hitting the wall panel at the same time, but could I have wired it incorrectly?I haven’t clicked the Soft Access Point in the Settings page at all.

[dkerr64]

I found several issues with time-to-close, some of which explain why the door was not closing. Believed fixed in v3.0.6

[jakepez]

Hi - first - thanks for the quick work on this! I just tested this with Time to Close set at 5 seconds.

First close attempt - LED lights blinked for the 5 seconds and then the door closed successfully. The RATGDO stayed up and didn’t crash.

Second close attempt - LED lights blinked for the 5 seconds and then the door close hung - the HomeKit status was stuck at “Closing”. The LED light then turned on.

I waited a bit, hit the GDO icon in HomeKit and it reset the status to “Open”. I hit “close” and it successfully waited the 5 seconds and closed again.

I checked the web admin. It did not go into Soft AP mode or anything - and stayed connected to WiFi.

Server time: 17-Jan-2025 16:27:36 PST
Server uptime (secs): 268.918
Firmware version: 3.0.6
Free heap: 132800
Minimum heap: 125800

722] ratgdo-packet: PACKET(0x9BE00A @ 0x15C94) Status - Status: [DoorState Open, Parity 0x8, Obs 1, Lock 0, Light 1]
>>> [    233.677] ratgdo-http: Client 10.0.1.185 requesting: /status.json (method: HTTP_GET)
>>> [    233.771] ratgdo-http: JSON length: 1048
>>> [    234.494] ratgdo-packet: DECODED  00003B1B 000000726612E910 0000F085
>>> [    234.495] ratgdo-packet: PACKET(0x12E910 @ 0x3B1B) Motion - NoData: [Zero: 0x00000000, Parity: 0xF]
>>> [    234.506] ratgdo-comms: Motion Detected
>>> [    234.509] ratgdo-packet: ENCODING 00000217 00000000000B1539 00000080
>>> [    234.560] ratgdo-packet: DECODED  00000217 00000000000B1539 00008080
>>> [    234.561] ratgdo-packet: PACKET(0xB1539 @ 0x217) GetStatus - NoData: [Zero: 0x00000000, Parity: 0x8]
>>> [    234.646] ratgdo-packet: DECODED  00015C94 000000C0B79BE00A 42608181
>>> [    234.647] ratgdo-packet: PACKET(0x9BE00A @ 0x15C94) Status - Status: [DoorState Open, Parity 0x8, Obs 1, Lock 0, Light 1]
>>> [    235.225] ratgdo-http: Client 10.0.1.185 requesting: /index.html (HTTP_GET, type: text/html, length: 6057)
>>> [    235.311] ratgdo-http: Client 10.0.1.185 requesting: /status.json (method: HTTP_GET)
>>> [    235.405] ratgdo-http: JSON length: 1048
>>> [    235.446] ratgdo-http: Client 10.0.1.185 requesting: /rest/events/subscribe (method: HTTP_GET)
>>> [    235.448] ratgdo-http: SSE Subscription for client 535d6b68-3d17-44aa-8480-f5be16a33907 with IP 10.0.1.185: event bus location: /rest/events/1, Total subscribed: 2
>>> [    235.525] ratgdo-http: Client 10.0.1.185 listening for SSE events on channel 1
>>> [    236.089] ratgdo-http: Client 0.0.0.0 not listening, remove SSE subscription. Total subscribed: 1
>>> [    239.507] ratgdo-comms: Motion Cleared
>>> [    239.508] ratgdo-http: SSE send to client 10.0.1.185 on channel 1, data: { "garageMotion": false, "upTime": 239507 }
>>> [    250.401] ratgdo-http: Client 10.0.1.185 requesting: /auth (method: HTTP_GET)
>>> [    268.230] ratgdo-http: Client 10.0.1.185 requesting: /logs.html (HTTP_GET, type: text/html, length: 1478)
>>> [    268.413] ratgdo-http: Client 10.0.1.185 requesting: /logs.js (HTTP_GET, type: text/javascript, length: 2576)
>>> [    268.615] ratgdo-http: Client 10.0.1.185 requesting: /rest/events/subscribe (method: HTTP_GET)
>>> [    268.617] ratgdo-http: SSE Subscription for client 3af5aaf0-1416-4ebc-889f-4c085583f297 with IP 10.0.1.185: event bus location: /rest/events/0, Total subscribed: 2
>>> [    268.648] ratgdo-http: Client 10.0.1.185 requesting: /status.json (method: HTTP_GET)
>>> [    268.743] ratgdo-http: JSON length: 1049
>>> [    268.753] ratgdo-http: Client 10.0.1.185 requesting: /showrebootlog (method: HTTP_GET)
>>> [    268.756] ratgdo-logger: Print saved log
>>> [    268.771] ratgdo-http: Client 10.0.1.185 requesting: /crashlog (method: HTTP_GET)
>>> [    268.772] ratgdo-http: Request to display crash log...
>>> [    268.902] ratgdo-http: Client 10.0.1.185 listening for SSE events on channel 0
>>> [    268.911] ratgdo-http: Client 10.0.1.185 requesting: /showlog (method: HTTP_GET)
>>> [    268.902] ratgdo-http: Client 10.0.1.185 listening for SSE events on channel 0
>>> [    268.911] ratgdo-http: Client 10.0.1.185 requesting: /showlog (method: HTTP_GET) 

[dkerr64]

I'm not sure what happened with your 2nd attempt, but I am hopeful that time-to-close is now working well, but we will have to monitor it over time. If you have a syslog server, please enable that so if something does go wrong you are able to look back at the logs. If not, then no worries... just a nice-to-have.

[jakepez]

I’ll keep an eye on it. I’ll set up a syslog server next week. On Jan 19, 2025, at 11:30 AM, David Kerr ***@***.***> wrote: I'm not sure what happened with your 2nd attempt, but I am hopeful that time-to-close is now working well, but we will have to monitor it over time. If you have a syslog server, please enable that so if something does go wrong you are able to look back at the logs. If not, then no worries... just a nice-to-have. —Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you authored the thread.Message ID: ***@***.***>