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

Expiring callbacks and defer sending during status handling #189

Open
wants to merge 8 commits into
base: main
Choose a base branch
from

Conversation

mariusmuja
Copy link
Collaborator

Added expiring callbacks that will only be called within a certain time.

Defer sending operations in status handling methods.

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Getting a somewhat reliable crash after an open/close cycle completes

[14:46:30][D][api:102]: Accepted 192.168.107.8
[14:46:30][D][api.connection:1121]: Home Assistant 2024.2.0.dev0 (192.168.107.8): Connected successfully
[14:46:31][D][time:044]: Synchronized time: 2024-01-20 14:46:31
[14:46:37][D][cover:076]: 'Door' - Setting
[14:46:37][D][cover:084]:   Position: 49%
[14:46:37][D][ratgdo:522]: Moving to position 0.49 in 8.0s
[14:46:37][D][number:012]: 'Rolling code counter': Sending state 1494.000000
[14:46:38][D][ratgdo:233]: Motor: state=OFF
[14:46:38][D][binary_sensor:036]: 'Motor': Sending state ON
[14:46:38][D][ratgdo:095]: Door state=OPENING
[14:46:38][D][ratgdo:209]: Light state=ON
[14:46:38][D][ratgdo:215]: Lock state=UNLOCKED
[14:46:38][D][ratgdo:194]: Learn state=INACTIVE
[14:46:38][D][cover:170]: 'Door' - Publishing:
[14:46:38][D][cover:173]:   Position: 0%
[14:46:38][D][cover:186]:   Current Operation: OPENING
[14:46:39][D][cover:170]: 'Door' - Publishing:
[14:46:39][D][cover:173]:   Position: 3%
[14:46:39][D][cover:186]:   Current Operation: OPENING
[14:46:39][D][cover:170]: 'Door' - Publishing:
[14:46:39][D][cover:173]:   Position: 6%
[14:46:39][D][cover:186]:   Current Operation: OPENING
[14:46:40][D][cover:170]: 'Door' - Publishing:
[14:46:40][D][cover:173]:   Position: 9%
[14:46:40][D][cover:186]:   Current Operation: OPENING
[14:46:40][D][esp8266.preferences:238]: Saving preferences to flash...
[14:46:40][D][cover:170]: 'Door' - Publishing:
[14:46:40][D][cover:173]:   Position: 12%
[14:46:40][D][cover:186]:   Current Operation: OPENING
[14:46:41][D][cover:170]: 'Door' - Publishing:
[14:46:41][D][cover:173]:   Position: 15%
[14:46:41][D][cover:186]:   Current Operation: OPENING
[14:46:41][D][cover:170]: 'Door' - Publishing:
[14:46:41][D][cover:173]:   Position: 18%
[14:46:41][D][cover:186]:   Current Operation: OPENING
[14:46:42][D][cover:170]: 'Door' - Publishing:
[14:46:42][D][cover:173]:   Position: 22%
[14:46:42][D][cover:186]:   Current Operation: OPENING
[14:46:42][D][cover:170]: 'Door' - Publishing:
[14:46:42][D][cover:173]:   Position: 25%
[14:46:42][D][cover:186]:   Current Operation: OPENING
[14:46:43][D][cover:170]: 'Door' - Publishing:
[14:46:43][D][cover:173]:   Position: 28%
[14:46:43][D][cover:186]:   Current Operation: OPENING
[14:46:43][D][cover:170]: 'Door' - Publishing:
[14:46:43][D][cover:173]:   Position: 31%
[14:46:43][D][cover:186]:   Current Operation: OPENING
[14:46:44][D][cover:170]: 'Door' - Publishing:
[14:46:44][D][cover:173]:   Position: 34%
[14:46:44][D][cover:186]:   Current Operation: OPENING
[14:46:44][W][ratgdo_secplus2:309]: Discard incomplete packet, length: 18
[14:46:44][D][cover:170]: 'Door' - Publishing:
[14:46:44][D][cover:173]:   Position: 37%
[14:46:44][D][cover:186]:   Current Operation: OPENING
[14:46:45][D][cover:170]: 'Door' - Publishing:
[14:46:45][D][cover:173]:   Position: 40%
[14:46:45][D][cover:186]:   Current Operation: OPENING
[14:46:45][D][cover:170]: 'Door' - Publishing:
[14:46:45][D][cover:173]:   Position: 43%
[14:46:45][D][cover:186]:   Current Operation: OPENING
[14:46:45][D][number:012]: 'Rolling code counter': Sending state 1495.000000
[14:46:46][D][cover:170]: 'Door' - Publishing:
[14:46:46][D][cover:173]:   Position: 46%
[14:46:46][D][cover:186]:   Current Operation: OPENING
[14:46:46][D][ratgdo:095]: Door state=STOPPED
[14:46:46][D][ratgdo:533]: Cancelling position callbacks
[14:46:46][D][ratgdo:209]: Light state=ON
[14:46:46][D][ratgdo:215]: Lock state=UNLOCKED
[14:46:46][D][ratgdo:194]: Learn state=INACTIVE
[14:46:46][D][binary_sensor:036]: 'Motor': Sending state OFF
[14:46:46][D][cover:170]: 'Door' - Publishing:
[14:46:46][D][cover:173]:   Position: 49%
[14:46:46][D][cover:186]:   Current Operation: IDLE
[14:46:50][D][esp8266.preferences:238]: Saving preferences to flash...
[14:46:51][D][cover:076]: 'Door' - Setting
[14:46:51][D][cover:084]:   Position: 0%
[14:46:52][D][number:012]: 'Rolling code counter': Sending state 1496.000000
[14:46:53][D][ratgdo:095]: Door state=CLOSING
[14:46:53][D][ratgdo:209]: Light state=ON
[14:46:53][D][ratgdo:215]: Lock state=UNLOCKED
[14:46:53][D][ratgdo:194]: Learn state=INACTIVE
[14:46:53][D][cover:170]: 'Door' - Publishing:
[14:46:53][D][cover:173]:   Position: 49%
[14:46:53][D][cover:186]:   Current Operation: CLOSING
[14:46:53][D][cover:170]: 'Door' - Publishing:
[14:46:53][D][cover:173]:   Position: 46%
[14:46:53][D][cover:186]:   Current Operation: CLOSING
[14:46:54][D][cover:170]: 'Door' - Publishing:
[14:46:54][D][cover:173]:   Position: 43%
[14:46:54][D][cover:186]:   Current Operation: CLOSING
[14:46:54][D][cover:170]: 'Door' - Publishing:
[14:46:54][D][cover:173]:   Position: 40%
[14:46:54][D][cover:186]:   Current Operation: CLOSING
[14:46:54][D][ratgdo:233]: Motor: state=OFF
[14:46:54][D][binary_sensor:036]: 'Motor': Sending state ON
[14:46:55][D][cover:170]: 'Door' - Publishing:
[14:46:55][D][cover:173]:   Position: 37%
[14:46:55][D][cover:186]:   Current Operation: CLOSING
[14:46:55][D][cover:170]: 'Door' - Publishing:
[14:46:55][D][cover:173]:   Position: 35%
[14:46:55][D][cover:186]:   Current Operation: CLOSING
[14:46:55][D][esp8266.preferences:238]: Saving preferences to flash...
[14:46:56][D][cover:170]: 'Door' - Publishing:
[14:46:56][D][cover:173]:   Position: 32%
[14:46:56][D][cover:186]:   Current Operation: CLOSING
[14:46:56][D][cover:170]: 'Door' - Publishing:
[14:46:56][D][cover:173]:   Position: 29%
[14:46:56][D][cover:186]:   Current Operation: CLOSING
[14:46:57][D][cover:170]: 'Door' - Publishing:
[14:46:57][D][cover:173]:   Position: 26%
[14:46:57][D][cover:186]:   Current Operation: CLOSING
[14:46:57][D][cover:170]: 'Door' - Publishing:
[14:46:57][D][cover:173]:   Position: 23%
[14:46:57][D][cover:186]:   Current Operation: CLOSING
[14:46:58][D][cover:170]: 'Door' - Publishing:
[14:46:58][D][cover:173]:   Position: 20%
[14:46:58][D][cover:186]:   Current Operation: CLOSING
[14:46:58][D][cover:170]: 'Door' - Publishing:
[14:46:58][D][cover:173]:   Position: 17%
[14:46:58][D][cover:186]:   Current Operation: CLOSING
[14:46:59][D][cover:170]: 'Door' - Publishing:
[14:46:59][D][cover:173]:   Position: 14%
[14:46:59][D][cover:186]:   Current Operation: CLOSING
[14:46:59][D][cover:170]: 'Door' - Publishing:
[14:46:59][D][cover:173]:   Position: 11%
[14:46:59][D][cover:186]:   Current Operation: CLOSING
[14:47:00][D][cover:170]: 'Door' - Publishing:
[14:47:00][D][cover:173]:   Position: 9%
[14:47:00][D][cover:186]:   Current Operation: CLOSING
[14:47:00][D][cover:170]: 'Door' - Publishing:
[14:47:00][D][cover:173]:   Position: 6%
[14:47:00][D][cover:186]:   Current Operation: CLOSING
[14:47:01][D][cover:170]: 'Door' - Publishing:
[14:47:01][D][cover:173]:   Position: 3%
[14:47:01][D][cover:186]:   Current Operation: CLOSING
[14:47:01][D][cover:170]: 'Door' - Publishing:
[14:47:01][D][cover:173]:   Position: 0%
[14:47:01][D][cover:186]:   Current Operation: CLOSING
[14:47:01][D][switch:016]: 'Status door' Turning OFF.
[14:47:03][D][ratgdo:233]: Motor: state=ON
[14:47:04][D][ratgdo:095]: Door state=CLOSED
[14:47:04][D][ratgdo:533]: Cancelling position callbacks
[14:47:04][D][ratgdo:209]: Light state=ON
[14:47:04][D][ratgdo:215]: Lock state=UNLOCKED
[14:47:04][D][ratgdo:194]: Learn state=INACTIVE
[14:47:04][D][binary_sensor:036]: 'Motor': Sending state OFF
[14:47:04][D][cover:170]: 'Door' - Publishing:
[14:47:04][D][cover:173]:   Position: 0%
[14:47:04][D][cover:186]:   Current Operation: IDLE
[14:47:04][D][switch:016]: 'Status door' Turning OFF.
[14:47:04][D][number:012]: 'Rolling code counter': Sending state 1497.000000
[14:47:04][D][ratgdo:275]: Openings: 2417
[14:47:04][D][sensor:093]: 'Openings': Sending state 2417.00000 openings with 0 decimals of accuracy
[14:47:05][D][esp8266.preferences:238]: Saving preferences to flash...
WARNING midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
WARNING Disconnected from API
INFO Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.047s
INFO Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.181s
[14:47:40][C][web_server:168]: Web Server:
[14:47:40][C][web_server:169]:   Address: midgarageratgdo.local:80
[14:47:40][C][mdns:115]: mDNS:
[14:47:40][C][mdns:116]:   Hostname: midgarageratgdo
[14:47:40][C][ota:097]: Over-The-Air Updates:
[14:47:40][C][ota:098]:   Address: midgarageratgdo.local:8266
[14:47:40][W][ota:106]: Last Boot was an unhandled reset, will proceed to safe mode in 8 restarts
[14:47:40][C][api:139]: API Server:
[14:47:40][C][api:140]:   Address: midgarageratgdo.local:6053
[14:47:40][C][api:144]:   Using noise encryption: NO
[14:47:42][D][api:102]: Accepted 192.168.106.56
[14:47:42][D][api.connection:1121]: aioesphomeapi (192.168.106.56): Connected successfully
[14:47:42][D][time:044]: Synchronized time: 2024-01-20 14:47:42
[14:47:44][D][api:102]: Accepted 192.168.107.8
[14:47:44][D][api.connection:1121]: Home Assistant 2024.2.0.dev0 (192.168.107.8): Connected successfully
[14:47:44][D][time:044]: Synchronized time: 2024-01-20 14:47:44

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

seems to be getting stuck at 95% somehow

[14:48:32][D][binary_sensor:036]: 'Motor': Sending state OFF
[14:48:32][D][cover:170]: 'Door' - Publishing:
[14:48:32][D][cover:173]:   Position: 56%
[14:48:32][D][cover:186]:   Current Operation: IDLE
[14:48:32][D][esp8266.preferences:238]: Saving preferences to flash...
[14:48:47][D][cover:076]: 'Door' - Setting
[14:48:47][D][cover:084]:   Position: 0%
[14:48:47][D][number:012]: 'Rolling code counter': Sending state 1514.000000
[14:48:47][D][esp8266.preferences:238]: Saving preferences to flash...
[14:48:48][D][ratgdo:095]: Door state=CLOSING
[14:48:48][D][ratgdo:209]: Light state=ON
[14:48:48][D][ratgdo:215]: Lock state=UNLOCKED
[14:48:48][D][ratgdo:194]: Learn state=INACTIVE
[14:48:48][D][cover:170]: 'Door' - Publishing:
[14:48:48][D][cover:173]:   Position: 56%
[14:48:48][D][cover:186]:   Current Operation: CLOSING
[14:48:48][D][cover:170]: 'Door' - Publishing:
[14:48:48][D][cover:173]:   Position: 53%
[14:48:48][D][cover:186]:   Current Operation: CLOSING
[14:48:49][D][cover:170]: 'Door' - Publishing:
[14:48:49][D][cover:173]:   Position: 50%
[14:48:49][D][cover:186]:   Current Operation: CLOSING
[14:48:49][D][cover:170]: 'Door' - Publishing:
[14:48:49][D][cover:173]:   Position: 47%
[14:48:49][D][cover:186]:   Current Operation: CLOSING
[14:48:50][D][cover:170]: 'Door' - Publishing:
[14:48:50][D][cover:173]:   Position: 44%
[14:48:50][D][cover:186]:   Current Operation: CLOSING
[14:48:50][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 41%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:53][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 38%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:53][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 36%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:53][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 33%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:53][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 30%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:53][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 27%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:53][D][cover:170]: 'Door' - Publishing:
[14:48:53][D][cover:173]:   Position: 24%
[14:48:53][D][cover:186]:   Current Operation: CLOSING
[14:48:54][D][cover:170]: 'Door' - Publishing:
[14:48:54][D][cover:173]:   Position: 21%
[14:48:54][D][cover:186]:   Current Operation: CLOSING
[14:48:54][D][cover:170]: 'Door' - Publishing:
[14:48:54][D][cover:173]:   Position: 18%
[14:48:54][D][cover:186]:   Current Operation: CLOSING
[14:48:55][D][cover:170]: 'Door' - Publishing:
[14:48:55][D][cover:173]:   Position: 15%
[14:48:55][D][cover:186]:   Current Operation: CLOSING
[14:48:55][D][ratgdo:233]: Motor: state=OFF
[14:48:55][D][binary_sensor:036]: 'Motor': Sending state ON
[14:48:55][D][cover:170]: 'Door' - Publishing:
[14:48:55][D][cover:173]:   Position: 12%
[14:48:55][D][cover:186]:   Current Operation: CLOSING
[14:48:56][D][cover:170]: 'Door' - Publishing:
[14:48:56][D][cover:173]:   Position: 10%
[14:48:56][D][cover:186]:   Current Operation: CLOSING
[14:48:56][D][cover:170]: 'Door' - Publishing:
[14:48:56][D][cover:173]:   Position: 7%
[14:48:56][D][cover:186]:   Current Operation: CLOSING
[14:48:56][D][ratgdo:095]: Door state=CLOSED
[14:48:56][D][ratgdo:533]: Cancelling position callbacks
[14:48:56][D][ratgdo:209]: Light state=ON
[14:48:56][D][ratgdo:215]: Lock state=UNLOCKED
[14:48:56][D][ratgdo:194]: Learn state=INACTIVE
[14:48:56][D][binary_sensor:036]: 'Motor': Sending state OFF
[14:48:56][D][cover:170]: 'Door' - Publishing:
[14:48:56][D][cover:173]:   Position: 0%
[14:48:56][D][cover:186]:   Current Operation: IDLE
[14:48:56][D][switch:016]: 'Status door' Tu

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

[14:51:42][D][cover:084]:   Position: 20%
[14:51:42][D][number:012]: 'Rolling code counter': Sending state 1536.000000
[14:51:42][D][esp8266.preferences:238]: Saving preferences to flash...
[14:51:43][D][cover:076]: 'Door' - Setting
[14:51:43][D][cover:084]:   Position: 61%
[14:51:43][D][number:012]: 'Rolling code counter': Sending state 1537.000000
[14:51:47][D][esp8266.preferences:238]: Saving preferences to flash...
[14:51:51][D][cover:076]: 'Door' - Setting
[14:51:51][D][cover:084]:   Position: 32%
[14:51:51][D][number:012]: 'Rolling code counter': Sending state 1538.000000
[14:51:52][D][cover:076]: 'Door' - Setting
[14:51:52][D][cover:084]:   Position: 58%
[14:51:52][D][number:012]: 'Rolling code counter': Sending state 1539.000000
[14:51:52][D][cover:076]: 'Door' - Setting
[14:51:52][D][cover:084]:   Position: 74%
[14:51:52][D][number:012]: 'Rolling code counter': Sending state 1540.000000
[14:51:52][D][esp8266.preferences:238]: Saving preferences to flash...
WARNING midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
WARNING Disconnected from API
INFO Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.009s
INFO Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.047s
[14:52:22][D][api:102]: Accepted 192.168.106.56
[14:52:23][D][api.connection:1121]: aioesphomeapi (192.168.106.56): Connected successfully
[14:52:23][D][time:044]: Synchronized time: 2024-01-20 14:52:22
[14:52:24][D][api:102]: Accepted 192.168.107.8
[14:52:24][D][api.connection:1121]: Home Assistant 2024.2.0.dev0 (192.168.107.8): Connected successfully
[14:52:24][D][time:044]: Synchronized time: 2024-01-20 14:52:24

Eventually it crashed

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I reverted back to main and its stable again.

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I don't see anything obviously wrong here that would explain the crashes.....

@mariusmuja
Copy link
Collaborator Author

mariusmuja commented Jan 21, 2024

No idea why the crashes happen, I can't replicate them on my GDO. I'll think about it.

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I've been testing a lot on this one ...maybe I've worn out the flash....

@mariusmuja
Copy link
Collaborator Author

I've been testing a lot on this one ...maybe I've worn out the flash....

If that's the case it would crash on main too.

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

maybe its bad flash and when I OTA I hit the other side....

anyways

#190

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Let me flash twice and see if its stable

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I flashed a different one and the problem happens there as well so not the chip

[15:15:50][D][ratgdo:194]: Learn state=INACTIVE
[15:15:50][D][binary_sensor:036]: 'Motor': Sending state OFF
[15:15:50][D][cover:170]: 'Door' - Publishing:
[15:15:50][D][cover:173]:   Position: 0%
[15:15:50][D][cover:186]:   Current Operation: IDLE
[15:15:50][D][switch:016]: 'Status door' Turning OFF.
[15:15:50][D][number:012]: 'Rolling code counter': Sending state 1878.000000
[15:15:50][D][ratgdo:275]: Openings: 7316
[15:15:50][D][sensor:093]: 'Openings': Sending state 7316.00000 openings with 0 decimals of accuracy
[15:15:52][D][esp8266.preferences:238]: Saving preferences to flash...
[15:15:53][D][cover:076]: 'Door' - Setting
[15:15:53][D][cover:080]:   Command: STOP
[15:15:53][W][ratgdo:478]: The door is not moving.
[15:15:54][D][cover:076]: 'Door' - Setting
[15:15:54][D][cover:084]:   Position: 100%
[15:15:54][D][number:012]: 'Rolling code counter': Sending state 1879.000000
[15:15:55][D][ratgdo:095]: Door state=OPENING
[15:15:56][D][ratgdo:209]: Light state=ON
[15:15:56][D][ratgdo:215]: Lock state=UNLOCKED
[15:15:56][D][ratgdo:194]: Learn state=INACTIVE
[15:15:56][D][cover:170]: 'Door' - Publishing:
[15:15:56][D][cover:173]:   Position: 0%
[15:15:56][D][cover:186]:   Current Operation: OPENING
[15:15:56][D][cover:170]: 'Door' - Publishing:
[15:15:56][D][cover:173]:   Position: 4%
[15:15:56][D][cover:186]:   Current Operation: OPENING
[15:15:56][D][cover:170]: 'Door' - Publishing:
[15:15:56][D][cover:173]:   Position: 8%
[15:15:56][D][cover:186]:   Current Operation: OPENING
[15:15:56][D][cover:170]: 'Door' - Publishing:
[15:15:56][D][cover:173]:   Position: 12%
[15:15:56][D][cover:186]:   Current Operation: OPENING
[15:15:56][D][ratgdo:233]: Motor: state=OFF
[15:15:57][D][binary_sensor:036]: 'Motor': Sending state ON
[15:15:57][D][esp8266.preferences:238]: Saving preferences to flash...
[15:15:57][D][cover:170]: 'Door' - Publishing:
[15:15:57][D][cover:173]:   Position: 16%
[15:15:57][D][cover:186]:   Current Operation: OPENING
[15:15:57][D][cover:170]: 'Door' - Publishing:
[15:15:58][D][cover:173]:   Position: 19%
[15:15:58][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 23%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 27%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 31%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 35%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 39%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 43%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][ratgdo:233]: Motor: state=ON
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 47%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:01][D][cover:170]: 'Door' - Publishing:
[15:16:01][D][cover:173]:   Position: 50%
[15:16:01][D][cover:186]:   Current Operation: OPENING
[15:16:02][D][cover:170]: 'Door' - Publishing:
[15:16:03][D][cover:173]:   Position: 54%
[15:16:03][D][cover:186]:   Current Operation: OPENING
[15:16:03][D][cover:170]: 'Door' - Publishing:
[15:16:03][D][cover:173]:   Position: 58%
[15:16:03][D][cover:186]:   Current Operation: OPENING
[15:16:03][D][cover:170]: 'Door' - Publishing:
[15:16:03][D][cover:173]:   Position: 62%
[15:16:03][D][cover:186]:   Current Operation: OPENING
[15:16:03][D][cover:170]: 'Door' - Publishing:
[15:16:03][D][cover:173]:   Position: 66%
[15:16:03][D][cover:186]:   Current Operation: OPENING
[15:16:04][D][ratgdo:233]: Motor: state=ON
[15:16:04][D][cover:170]: 'Door' - Publishing:
[15:16:04][D][cover:173]:   Position: 70%
[15:16:04][D][cover:186]:   Current Operation: OPENING
[15:16:04][D][cover:170]: 'Door' - Publishing:
[15:16:04][D][cover:173]:   Position: 74%
[15:16:04][D][cover:186]:   Current Operation: OPENING
[15:16:05][D][cover:170]: 'Door' - Publishing:
[15:16:05][D][cover:173]:   Position: 78%
[15:16:05][D][cover:186]:   Current Operation: OPENING
[15:16:05][D][cover:170]: 'Door' - Publishing:
[15:16:05][D][cover:173]:   Position: 81%
[15:16:05][D][cover:186]:   Current Operation: OPENING
[15:16:06][D][cover:170]: 'Door' - Publishing:
[15:16:06][D][cover:173]:   Position: 85%
[15:16:06][D][cover:186]:   Current Operation: OPENING
[15:16:06][D][cover:170]: 'Door' - Publishing:
[15:16:06][D][cover:173]:   Position: 89%
[15:16:06][D][cover:186]:   Current Operation: OPENING
[15:16:07][D][cover:170]: 'Door' - Publishing:
[15:16:07][D][cover:173]:   Position: 93%
[15:16:07][D][cover:186]:   Current Operation: OPENING
[15:16:07][D][cover:170]: 'Door' - Publishing:
[15:16:07][D][cover:173]:   Position: 97%
[15:16:07][D][cover:186]:   Current Operation: OPENING
[15:16:08][D][ratgdo:095]: Door state=OPEN
[15:16:08][D][ratgdo:533]: Cancelling position callbacks
[15:16:08][D][binary_sensor:036]: 'Motor': Sending state OFF
[15:16:08][D][cover:170]: 'Door' - Publishing:
[15:16:08][D][cover:173]:   Position: 100%
[15:16:08][D][cover:186]:   Current Operation: IDLE
[15:16:08][D][switch:012]: 'Status door' Turning ON.
[15:16:08][D][switch:055]: 'Status door': Sending state ON
[15:16:08][D][number:012]: 'Rolling code counter': Sending state 1880.000000
[15:16:08][D][ratgdo:095]: Door state=OPEN
[15:16:08][D][ratgdo:209]: Light state=ON
[15:16:08][D][ratgdo:215]: Lock state=UNLOCKED
[15:16:08][D][ratgdo:194]: Learn state=INACTIVE
[15:16:08][D][ratgdo:095]: Door state=OPEN
[15:16:08][D][ratgdo:209]: Light state=ON
[15:16:08][D][ratgdo:215]: Lock state=UNLOCKED
[15:16:08][D][ratgdo:194]: Learn state=INACTIVE
[15:16:08][D][cover:076]: 'Door' - Setting
[15:16:08][D][cover:080]:   Command: STOP
[15:16:08][W][ratgdo:478]: The door is not moving.
[15:16:10][D][cover:076]: 'Door' - Setting
WARNING fargarageratgdo @ 192.168.107.50: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for fargarageratgdo @ 192.168.107.50
WARNING Disconnected from API
INFO Successfully connected to fargarageratgdo @ 192.168.107.50 in 0.005s
INFO Successful handshake with fargarageratgdo @ 192.168.107.50 in 0.055s

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

tried a third one

same behavior

[15:23:39][C][api:139]: API Server:
[15:23:39][C][api:140]:   Address: fargarageratgdo12.local:6053
[15:23:39][C][api:144]:   Using noise encryption: NO
[15:23:41][D][light:036]: 'Light' Setting:
[15:23:41][D][light:047]:   State: OFF
[15:23:41][D][number:012]: 'Rolling code counter': Sending state 344.000000
[15:23:45][D][cover:076]: 'Door' - Setting
[15:23:45][D][cover:084]:   Position: 31%
[15:23:45][D][ratgdo:522]: Moving to position 0.31 in 4.2s
[15:23:45][D][number:012]: 'Rolling code counter': Sending state 345.000000
[15:23:46][D][ratgdo:095]: Door state=OPENING
[15:23:46][D][ratgdo:209]: Light state=ON
[15:23:46][D][ratgdo:215]: Lock state=UNLOCKED
[15:23:46][D][ratgdo:194]: Learn state=INACTIVE
[15:23:46][D][cover:170]: 'Door' - Publishing:
[15:23:46][D][cover:173]:   Position: 0%
[15:23:46][D][cover:186]:   Current Operation: OPENING
[15:23:46][D][esp8266.preferences:238]: Saving preferences to flash...
[15:23:46][D][cover:170]: 'Door' - Publishing:
[15:23:46][D][cover:173]:   Position: 4%
[15:23:46][D][cover:186]:   Current Operation: OPENING
[15:23:47][D][cover:170]: 'Door' - Publishing:
[15:23:47][D][cover:173]:   Position: 8%
[15:23:47][D][cover:186]:   Current Operation: OPENING
[15:23:47][W][ratgdo_secplus2:309]: Discard incomplete packet, length: 18
[15:23:47][D][cover:170]: 'Door' - Publishing:
[15:23:47][D][cover:173]:   Position: 11%
[15:23:47][D][cover:186]:   Current Operation: OPENING
[15:23:48][D][cover:170]: 'Door' - Publishing:
[15:23:48][D][cover:173]:   Position: 15%
[15:23:48][D][cover:186]:   Current Operation: OPENING
[15:23:48][D][cover:170]: 'Door' - Publishing:
[15:23:48][D][cover:173]:   Position: 19%
[15:23:48][D][cover:186]:   Current Operation: OPENING
[15:23:49][D][cover:170]: 'Door' - Publishing:
[15:23:49][D][cover:173]:   Position: 22%
[15:23:49][D][cover:186]:   Current Operation: OPENING
[15:23:49][D][number:012]: 'Rolling code counter': Sending state 346.000000
[15:23:50][D][cover:170]: 'Door' - Publishing:
[15:23:50][D][cover:173]:   Position: 26%
[15:23:50][D][cover:186]:   Current Operation: OPENING
[15:23:50][D][cover:170]: 'Door' - Publishing:
[15:23:50][D][cover:173]:   Position: 30%
[15:23:50][D][cover:186]:   Current Operation: OPENING
[15:23:50][D][ratgdo:095]: Door state=STOPPED
[15:23:50][D][ratgdo:533]: Cancelling position callbacks
[15:23:50][D][ratgdo:209]: Light state=ON
[15:23:50][D][ratgdo:215]: Lock state=UNLOCKED
[15:23:50][D][ratgdo:194]: Learn state=INACTIVE
[15:23:50][D][cover:170]: 'Door' - Publishing:
[15:23:50][D][cover:173]:   Position: 31%
[15:23:50][D][cover:186]:   Current Operation: IDLE
[15:23:53][D][cover:076]: 'Door' - Setting
[15:23:53][D][cover:084]:   Position: 63%
[15:23:53][D][ratgdo:522]: Moving to position 0.63 in 4.3s
[15:23:53][D][number:012]: 'Rolling code counter': Sending state 347.000000
[15:23:54][D][ratgdo:095]: Door state=OPENING
[15:23:54][D][ratgdo:209]: Light state=ON
[15:23:54][D][ratgdo:215]: Lock state=UNLOCKED
[15:23:54][D][ratgdo:194]: Learn state=INACTIVE
[15:23:54][D][cover:170]: 'Door' - Publishing:
[15:23:54][D][cover:173]:   Position: 31%
[15:23:54][D][cover:186]:   Current Operation: OPENING
[15:23:54][D][cover:170]: 'Door' - Publishing:
[15:23:54][D][cover:173]:   Position: 35%
[15:23:54][D][cover:186]:   Current Operation: OPENING
[15:23:55][D][cover:170]: 'Door' - Publishing:
[15:23:55][D][cover:173]:   Position: 39%
[15:23:55][D][cover:186]:   Current Operation: OPENING
[15:23:55][D][cover:170]: 'Door' - Publishing:
[15:23:55][D][cover:173]:   Position: 43%
[15:23:55][D][cover:186]:   Current Operation: OPENING
[15:23:56][D][cover:170]: 'Door' - Publishing:
[15:23:56][D][cover:173]:   Position: 46%
[15:23:56][D][cover:186]:   Current Operation: OPENING
[15:23:56][D][cover:170]: 'Door' - Publishing:
[15:23:56][D][cover:173]:   Position: 50%
[15:23:56][D][cover:186]:   Current Operation: OPENING
[15:23:56][D][ratgdo:233]: Motor: state=OFF
[15:23:56][D][binary_sensor:036]: 'Motor': Sending state ON
[15:23:57][D][cover:170]: 'Door' - Publishing:
[15:23:57][D][cover:173]:   Position: 54%
[15:23:57][D][cover:186]:   Current Operation: OPENING
[15:23:57][D][number:012]: 'Rolling code counter': Sending state 348.000000
[15:23:57][D][cover:170]: 'Door' - Publishing:
[15:23:57][D][cover:173]:   Position: 57%
[15:23:57][D][cover:186]:   Current Operation: OPENING
[15:23:58][D][cover:170]: 'Door' - Publishing:
[15:23:58][D][cover:173]:   Position: 61%
[15:23:58][D][cover:186]:   Current Operation: OPENING
[15:23:58][D][ratgdo:095]: Door state=STOPPED
[15:23:58][D][ratgdo:533]: Cancelling position callbacks
[15:23:58][D][ratgdo:209]: Light state=ON
[15:23:58][D][ratgdo:215]: Lock state=UNLOCKED
[15:23:58][D][ratgdo:194]: Learn state=INACTIVE
[15:23:58][D][binary_sensor:036]: 'Motor': Sending state OFF
[15:23:58][D][cover:170]: 'Door' - Publishing:
[15:23:58][D][cover:173]:   Position: 63%
[15:23:58][D][cover:186]:   Current Operation: IDLE
WARNING fargarageratgdo12 @ 192.168.110.150: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for fargarageratgdo12 @ 192.168.110.150
WARNING Disconnected from API
INFO Successfully connected to fargarageratgdo12 @ 192.168.110.150 in 0.006s
INFO Successful handshake with fargarageratgdo12 @ 192.168.110.150 in 0.036s
[15:24:26][D][api:102]: Accepted 192.168.111.11
[15:24:26][D][api.connection:1121]: Home Assistant 2024.1.4 (192.168.111.11): Connected successfully
[15:24:26][D][time:044]: Synchronized time: 2024-01-20 15:24:26

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I can build a new box and do a fresh HA install with ESPHome and link one of them if you want to play around with it

@mariusmuja
Copy link
Collaborator Author

I can build a new box and do a fresh HA install with ESPHome and link one of them if you want to play around with it

That sounds like too much work and I wouldn't see much more than what you've already posted here. It's very strange, I cannot get it to crash on mine... Maybe try with verbose logging to get more clues (update ESP_LOG1 and ESP_LOG1 in common.h).

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Crash with more logging

[15:43:59][C][safe_mode.button:022]: Safe Mode Button 'Safe mode boot'
[15:43:59][C][safe_mode.button:022]:   Icon: 'mdi:restart-alert'
[15:43:59][C][homeassistant.time:010]: Home Assistant Time:
[15:43:59][C][homeassistant.time:011]:   Timezone: 'HST10'
[15:43:59][C][web_server:168]: Web Server:
[15:43:59][C][web_server:169]:   Address: midgarageratgdo.local:80
[15:43:59][C][mdns:115]: mDNS:
[15:43:59][C][mdns:116]:   Hostname: midgarageratgdo
[15:43:59][C][ota:097]: Over-The-Air Updates:
[15:43:59][C][ota:098]:   Address: midgarageratgdo.local:8266
[15:43:59][C][api:139]: API Server:
[15:43:59][C][api:140]:   Address: midgarageratgdo.local:6053
[15:43:59][C][api:144]:   Using noise encryption: NO
[15:44:01][D][api:102]: Accepted 192.168.107.196
[15:44:01][D][api.connection:1121]: aioesphomeapi (192.168.107.196): Connected successfully
[15:44:01][D][time:044]: Synchronized time: 2024-01-20 15:44:01
[15:44:02][D][api:102]: Accepted 192.168.107.8
[15:44:02][D][api.connection:1121]: Home Assistant 2024.2.0.dev0 (192.168.107.8): Connected successfully
[15:44:02][D][time:044]: Synchronized time: 2024-01-20 15:44:02
[15:44:19][D][cover:076]: 'Door' - Setting
[15:44:19][D][cover:084]:   Position: 56%
[15:44:19][D][ratgdo:522]: Moving to position 0.56 in 9.2s
[15:44:19][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010101
[15:44:19][D][ratgdo_secplus2:450]: [36932] Encode for transmit rolling=0000695 fixed=020064d539 data=01010180
[15:44:19][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 19 00 12 04 4C 00 48 07 4A 28 BC 03 AA 1E 4F 7C]
[15:44:19][W][component:214]: Component api took a long time for an operation (0.05 s).
[15:44:19][W][component:215]: Components should block for at most 20-30ms.
[15:44:19][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010001
[15:44:19][D][ratgdo_secplus2:450]: [37123] Encode for transmit rolling=0000695 fixed=020064d539 data=01000180
[15:44:19][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 19 00 12 04 4C 00 48 06 4A 28 BC 03 AA 1E 5F 7C]
[15:44:19][D][number:012]: 'Rolling code counter': Sending state 1686.000000
[15:44:19][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:19][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 80 10 43 62 B5 9B 6D B6 11 02 18 20 5A 20 64 D6]
[15:44:19][D][ratgdo_secplus2:358]: [37582] received rolling=0025bb4 fixed=027ccab006 data=00000084
[15:44:19][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[15:44:19][D][ratgdo_secplus2:373]: [37595] Handle command: MOTOR_ON
[15:44:19][D][ratgdo:233]: Motor: state=OFF
[15:44:19][D][ratgdo_secplus2:415]: [37605] Done handle command: MOTOR_ON
[15:44:19][D][binary_sensor:036]: 'Motor': Sending state ON
[15:44:20][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:20][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 6A 3F FE D7 E8 A9 D3 45 02 29 E6 9B 83 94 D3 58]
[15:44:20][D][ratgdo_secplus2:358]: [38067] received rolling=0025bb5 fixed=007ccab006 data=42600481
[15:44:20][D][ratgdo_secplus2:366]: cmd=081 (STATUS) byte2=42 byte1=60 nibble=4
[15:44:20][D][ratgdo_secplus2:373]: [38081] Handle command: STATUS
[15:44:20][D][ratgdo:095]: Door state=OPENING
[15:44:20][D][ratgdo:310]: Schedule position sync: delta 0.560000, start position: 0.000000, start moving: 38091
[15:44:20][D][ratgdo:209]: Light state=ON
[15:44:20][D][ratgdo:215]: Lock state=UNLOCKED
[15:44:20][D][ratgdo:194]: Learn state=INACTIVE
[15:44:20][D][ratgdo_secplus2:415]: [38113] Done handle command: STATUS
[15:44:20][W][component:214]: Component ratgdo took a long time for an operation (0.06 s).
[15:44:20][W][component:215]: Components should block for at most 20-30ms.
[15:44:20][D][ratgdo:335]: [38152] Position update: 0.003720
[15:44:20][D][cover:170]: 'Door' - Publishing:
[15:44:20][D][cover:173]:   Position: 0%
[15:44:20][D][cover:186]:   Current Operation: OPENING
[15:44:20][D][ratgdo:335]: [38657] Position update: 0.034512
[15:44:20][D][cover:170]: 'Door' - Publishing:
[15:44:20][D][cover:173]:   Position: 3%
[15:44:20][D][cover:186]:   Current Operation: OPENING
[15:44:21][D][ratgdo:335]: [39165] Position update: 0.065488
[15:44:21][D][cover:170]: 'Door' - Publishing:
[15:44:21][D][cover:173]:   Position: 7%
[15:44:21][D][cover:186]:   Current Operation: OPENING
[15:44:21][D][ratgdo:335]: [39673] Position update: 0.096463
[15:44:21][D][cover:170]: 'Door' - Publishing:
[15:44:21][D][cover:173]:   Position: 10%
[15:44:21][D][cover:186]:   Current Operation: OPENING
[15:44:22][D][ratgdo:335]: [40177] Position update: 0.127195
[15:44:22][D][cover:170]: 'Door' - Publishing:
[15:44:22][D][cover:173]:   Position: 13%
[15:44:22][D][cover:186]:   Current Operation: OPENING
[15:44:22][D][ratgdo:335]: [40681] Position update: 0.157927
[15:44:22][D][cover:170]: 'Door' - Publishing:
[15:44:22][D][cover:173]:   Position: 16%
[15:44:22][D][cover:186]:   Current Operation: OPENING
[15:44:23][D][ratgdo:335]: [41186] Position update: 0.188720
[15:44:23][D][cover:170]: 'Door' - Publishing:
[15:44:23][D][cover:173]:   Position: 19%
[15:44:23][D][cover:186]:   Current Operation: OPENING
[15:44:23][D][ratgdo:335]: [41690] Position update: 0.219451
[15:44:23][D][cover:170]: 'Door' - Publishing:
[15:44:23][D][cover:173]:   Position: 22%
[15:44:23][D][cover:186]:   Current Operation: OPENING
[15:44:24][D][ratgdo:335]: [42197] Position update: 0.250366
[15:44:25][D][cover:170]: 'Door' - Publishing:
[15:44:25][D][cover:173]:   Position: 25%
[15:44:25][D][cover:186]:   Current Operation: OPENING
[15:44:25][D][ratgdo:335]: [42706] Position update: 0.281402
[15:44:25][D][cover:170]: 'Door' - Publishing:
[15:44:25][D][cover:173]:   Position: 28%
[15:44:25][D][cover:186]:   Current Operation: OPENING
[15:44:25][D][ratgdo:335]: [43210] Position update: 0.312134
[15:44:25][D][cover:170]: 'Door' - Publishing:
[15:44:25][D][cover:173]:   Position: 31%
[15:44:25][D][cover:186]:   Current Operation: OPENING
[15:44:25][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:25][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 6A 3F FE D5 E8 A4 D3 4D 02 29 E6 9B 83 96 92 19]
[15:44:25][D][ratgdo_secplus2:358]: [43561] received rolling=0025bb5 fixed=027ccab006 data=00000084
[15:44:25][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[15:44:25][D][ratgdo_secplus2:373]: [43575] Handle command: MOTOR_ON
[15:44:25][D][ratgdo:233]: Motor: state=ON
[15:44:25][D][ratgdo_secplus2:415]: [43585] Done handle command: MOTOR_ON
[15:44:25][D][ratgdo:335]: [43716] Position update: 0.342988
[15:44:25][D][cover:170]: 'Door' - Publishing:
[15:44:25][D][cover:173]:   Position: 34%
[15:44:25][D][cover:186]:   Current Operation: OPENING
[15:44:26][D][ratgdo:335]: [44220] Position update: 0.373720
[15:44:26][D][cover:170]: 'Door' - Publishing:
[15:44:26][D][cover:173]:   Position: 37%
[15:44:26][D][cover:186]:   Current Operation: OPENING
[15:44:26][D][ratgdo:335]: [44724] Position update: 0.404451
[15:44:26][D][cover:170]: 'Door' - Publishing:
[15:44:26][D][cover:173]:   Position: 40%
[15:44:26][D][cover:186]:   Current Operation: OPENING
[15:44:27][D][ratgdo:335]: [45228] Position update: 0.435183
[15:44:28][D][cover:170]: 'Door' - Publishing:
[15:44:28][D][cover:173]:   Position: 44%
[15:44:28][D][cover:186]:   Current Operation: OPENING
[15:44:28][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:28][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 6A 3F FE D5 E8 A4 D3 4D 02 29 E6 9B 83 96 92 19]
[15:44:28][D][ratgdo_secplus2:358]: [45533] received rolling=0025bb5 fixed=027ccab006 data=00000084
[15:44:28][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[15:44:28][D][ratgdo_secplus2:373]: [45547] Handle command: MOTOR_ON
[15:44:28][D][ratgdo:233]: Motor: state=ON
[15:44:28][D][ratgdo_secplus2:415]: [45557] Done handle command: MOTOR_ON
[15:44:28][D][ratgdo:335]: [45737] Position update: 0.466220
[15:44:28][D][cover:170]: 'Door' - Publishing:
[15:44:28][D][cover:173]:   Position: 47%
[15:44:28][D][cover:186]:   Current Operation: OPENING
[15:44:28][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010103
[15:44:28][D][ratgdo_secplus2:450]: [46158] Encode for transmit rolling=0000696 fixed=020064d539 data=01010380
[15:44:28][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 84 2F BF FC 4F BF FF 7A A9 07 23 65 06 E0 C2 25]
[15:44:28][D][ratgdo:335]: [46239] Position update: 0.496829
[15:44:28][D][cover:170]: 'Door' - Publishing:
[15:44:28][D][cover:173]:   Position: 50%
[15:44:28][D][cover:186]:   Current Operation: OPENING
[15:44:28][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010003
[15:44:28][D][ratgdo_secplus2:450]: [46347] Encode for transmit rolling=0000696 fixed=020064d539 data=01000380
[15:44:28][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 84 2F BF FC 4F BF FF 7E A9 07 23 65 06 E0 82 25]
[15:44:28][D][number:012]: 'Rolling code counter': Sending state 1687.000000
[15:44:28][D][esp8266.preferences:238]: Saving preferences to flash...
[15:44:28][D][ratgdo:335]: [46742] Position update: 0.527500
[15:44:29][D][cover:170]: 'Door' - Publishing:
[15:44:29][D][cover:173]:   Position: 53%
[15:44:29][D][cover:186]:   Current Operation: OPENING
[15:44:29][D][ratgdo:335]: [47250] Position update: 0.558476
[15:44:29][D][cover:170]: 'Door' - Publishing:
[15:44:29][D][cover:173]:   Position: 56%
[15:44:29][D][cover:186]:   Current Operation: OPENING
[15:44:29][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:29][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 15 04 90 D9 0F BA 1A 79 62 21 04 10 99 56 12 62]
[15:44:29][D][ratgdo_secplus2:358]: [47298] received rolling=0025bb6 fixed=007ccab006 data=42600381
[15:44:29][D][ratgdo_secplus2:366]: cmd=081 (STATUS) byte2=42 byte1=60 nibble=3
[15:44:29][D][ratgdo_secplus2:373]: [47313] Handle command: STATUS
[15:44:29][D][ratgdo:095]: Door state=STOPPED
[15:44:29][D][ratgdo:335]: [47323] Position update: 0.562927
[15:44:29][D][ratgdo:533]: Cancelling position callbacks
[15:44:29][D][ratgdo:209]: Light state=ON
[15:44:29][D][ratgdo:215]: Lock state=UNLOCKED
[15:44:29][D][ratgdo:194]: Learn state=INACTIVE
[15:44:29][D][ratgdo_secplus2:415]: [47346] Done handle command: STATUS
[15:44:29][W][component:214]: Component ratgdo took a long time for an operation (0.06 s).
[15:44:29][W][component:215]: Components should block for at most 20-30ms.
[15:44:30][D][binary_sensor:036]: 'Motor': Sending state OFF
[15:44:30][D][cover:170]: 'Door' - Publishing:
[15:44:30][D][cover:173]:   Position: 56%
[15:44:30][D][cover:186]:   Current Operation: IDLE
[15:44:32][D][cover:076]: 'Door' - Setting
[15:44:32][D][cover:084]:   Position: 27%
[15:44:32][D][ratgdo:522]: Moving to position 0.27 in 5.1s
[15:44:32][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010100
[15:44:32][D][ratgdo_secplus2:450]: [50515] Encode for transmit rolling=0000697 fixed=020064d539 data=01010080
[15:44:32][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 82 0B 2C 91 F9 64 92 5C 9A 0E B7 6E 2A 56 13 4D]
[15:44:32][W][component:214]: Component api took a long time for an operation (0.05 s).
[15:44:32][W][component:215]: Components should block for at most 20-30ms.
[15:44:32][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010000
[15:44:32][D][ratgdo_secplus2:450]: [50711] Encode for transmit rolling=0000697 fixed=020064d539 data=01000080
[15:44:32][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 82 0B 2C 91 F9 64 92 58 9A 0E B7 6E 2A 56 03 4D]
[15:44:32][D][number:012]: 'Rolling code counter': Sending state 1688.000000
[15:44:33][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:33][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 14 36 59 FD 9D F3 3E EF 54 27 BA FA 1E 33 EF 39]
[15:44:33][D][ratgdo_secplus2:358]: [51672] received rolling=0025bb7 fixed=007ccab006 data=42600581
[15:44:33][D][ratgdo_secplus2:366]: cmd=081 (STATUS) byte2=42 byte1=60 nibble=5
[15:44:33][D][ratgdo_secplus2:373]: [51686] Handle command: STATUS
[15:44:33][D][ratgdo:095]: Door state=CLOSING
[15:44:33][D][ratgdo:310]: Schedule position sync: delta -0.292927, start position: 0.562927, start moving: 51696
[15:44:33][D][ratgdo:209]: Light state=ON
[15:44:33][D][ratgdo:215]: Lock state=UNLOCKED
[15:44:33][D][ratgdo:194]: Learn state=INACTIVE
[15:44:33][D][ratgdo_secplus2:415]: [51718] Done handle command: STATUS
[15:44:33][W][component:214]: Component ratgdo took a long time for an operation (0.06 s).
[15:44:33][W][component:215]: Components should block for at most 20-30ms.
[15:44:33][D][ratgdo:335]: [51758] Position update: 0.559364
[15:44:33][D][cover:170]: 'Door' - Publishing:
[15:44:33][D][cover:173]:   Position: 56%
[15:44:33][D][cover:186]:   Current Operation: CLOSING
[15:44:34][D][ratgdo:335]: [52261] Position update: 0.530456
[15:44:34][D][cover:170]: 'Door' - Publishing:
[15:44:34][D][cover:173]:   Position: 53%
[15:44:34][D][cover:186]:   Current Operation: CLOSING
[15:44:34][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:34][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 14 36 59 F9 9D FF BE FF 54 27 BA FA 1E 32 EE BF]
[15:44:34][D][ratgdo_secplus2:358]: [52380] received rolling=0025bb7 fixed=027ccab006 data=00000084
[15:44:34][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[15:44:34][D][ratgdo_secplus2:373]: [52393] Handle command: MOTOR_ON
[15:44:34][D][ratgdo:233]: Motor: state=OFF
[15:44:34][D][ratgdo_secplus2:415]: [52404] Done handle command: MOTOR_ON
[15:44:34][D][binary_sensor:036]: 'Motor': Sending state ON
[15:44:34][D][ratgdo:335]: [52768] Position update: 0.501318
[15:44:34][D][cover:170]: 'Door' - Publishing:
[15:44:34][D][cover:173]:   Position: 50%
[15:44:34][D][cover:186]:   Current Operation: CLOSING
[15:44:35][D][ratgdo:335]: [53272] Position update: 0.472352
[15:44:35][D][cover:170]: 'Door' - Publishing:
[15:44:35][D][cover:173]:   Position: 47%
[15:44:35][D][cover:186]:   Current Operation: CLOSING
[15:44:35][D][ratgdo:335]: [53779] Position update: 0.443214
[15:44:35][D][cover:170]: 'Door' - Publishing:
[15:44:35][D][cover:173]:   Position: 44%
[15:44:35][D][cover:186]:   Current Operation: CLOSING
[15:44:36][D][ratgdo:335]: [54283] Position update: 0.414249
[15:44:36][D][cover:170]: 'Door' - Publishing:
[15:44:36][D][cover:173]:   Position: 41%
[15:44:36][D][cover:186]:   Current Operation: CLOSING
[15:44:36][D][ratgdo:335]: [54787] Position update: 0.385283
[15:44:36][D][cover:170]: 'Door' - Publishing:
[15:44:36][D][cover:173]:   Position: 39%
[15:44:36][D][cover:186]:   Current Operation: CLOSING
[15:44:37][D][ratgdo_secplus2:279]: Baud: 9708
[15:44:37][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 14 36 59 F9 9D FF BE FF 54 27 BA FA 1E 32 EE BF]
[15:44:37][D][ratgdo_secplus2:358]: [55015] received rolling=0025bb7 fixed=027ccab006 data=00000084
[15:44:37][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[15:44:37][D][ratgdo_secplus2:373]: [55028] Handle command: MOTOR_ON
[15:44:37][D][ratgdo:233]: Motor: state=ON
[15:44:37][D][ratgdo_secplus2:415]: [55038] Done handle command: MOTOR_ON
[15:44:37][D][ratgdo:335]: [55291] Position update: 0.356318
[15:44:37][D][cover:170]: 'Door' - Publishing:
[15:44:37][D][cover:173]:   Position: 36%
[15:44:37][D][cover:186]:   Current Operation: CLOSING
[15:44:37][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010103
[15:44:37][D][ratgdo_secplus2:450]: [55658] Encode for transmit rolling=0000698 fixed=020064d539 data=01010380
[15:44:37][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 09 00 00 2C 48 00 04 07 49 07 42 FC 45 A8 14 0B]
[15:44:37][D][ratgdo:335]: [55802] Position update: 0.326950
[15:44:37][D][cover:170]: 'Door' - Publishing:
[15:44:37][D][cover:173]:   Position: 33%
[15:44:37][D][cover:186]:   Current Operation: CLOSING
WARNING midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
WARNING Disconnected from API
INFO Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.004s
INFO Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.034s
[15:45:01][D][api:102]: Accepted 192.168.107.196
[15:45:01][D][api.connection:1121]: aioesphomeapi (192.168.107.196): Connected successfully
[15:45:01][D][time:044]: Synchronized time: 2024-01-20 15:45:01
[15:45:03][D][api:102]: Accepted 192.168.107.8
[15:45:03][D][api.connection:1121]: Home Assistant 2024.2.0.dev0 (192.168.107.8): Connected successfully
[15:45:04][D][time:044]: Synchronized time: 2024-01-20 15:45:04

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Let me know if I should pull out the car and get the ladder to get a serial console trace

@mariusmuja
Copy link
Collaborator Author

mariusmuja commented Jan 21, 2024

Sorry, I had to step away from the computer for a while.

I pushed two branches, expiring_callbacks_1 (reverts defer calls in status message handling) and expiring_callbacks_2 (reverts expiring callbacks change). We can try to isolate the change that causes the crash that way.

Also what version of esphome/platformio/gcc are you using?

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Sorry, I had to step away from the computer for a while.

I pushed two branches, expiring_callbacks_1 (reverts defer calls in status message handling) and expiring_callbacks_2 (reverts expiring callbacks change). We can try to isolate the change that causes the crash that way.

Also what version of esphome/platformio/gcc are you using?

I'm installing with the latest stable addon from HA. It's whatever Debian bookworm provides. Esphome 2023.12.8. I can check the gcc and platform IO versions when I get back home.

I'll have to test tomorrow as I won't be back home until late

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

[09:54:54][D][ratgdo:275]: Openings: 5957
[09:54:54][D][ratgdo_secplus2:415]: [123434] Done handle command: OPENINGS
[09:54:54][D][sensor:093]: 'Openings': Sending state 5957.00000 openings with 0 decimals of accuracy
[09:55:04][D][cover:076]: 'Door' - Setting
[09:55:04][D][cover:084]:   Position: 100%
[09:55:04][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010101
[09:55:04][D][ratgdo_secplus2:450]: [133259] Encode for transmit rolling=0000bf3 fixed=020000e539 data=01010180
[09:55:04][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 41 12 49 22 82 41 24 95 55 29 B5 A5 6A 73 EB 2E]
[09:55:04][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010001
[09:55:04][D][ratgdo_secplus2:450]: [133458] Encode for transmit rolling=0000bf3 fixed=020000e539 data=01000180
[09:55:04][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 41 12 49 22 82 41 24 91 55 29 B5 A5 6A 73 CB 2E]
[09:55:04][D][number:012]: 'Rolling code counter': Sending state 3060.000000
[09:55:05][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:05][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 56 09 E5 7B D1 69 A6 93 99 08 22 90 94 E4 C8 84]
[09:55:05][D][ratgdo_secplus2:358]: [133938] received rolling=0031a0b fixed=d249cac006 data=00000084
[09:55:05][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[09:55:05][D][ratgdo_secplus2:373]: [133953] Handle command: MOTOR_ON
[09:55:05][D][ratgdo:233]: Motor: state=OFF
[09:55:05][D][ratgdo_secplus2:415]: [133963] Done handle command: MOTOR_ON
[09:55:05][D][binary_sensor:036]: 'Motor': Sending state ON
[09:55:05][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:05][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 25 08 E6 EF A8 AF 5B 0C 88 2C BA FC 04 76 5D 60]
[09:55:05][D][ratgdo_secplus2:358]: [134418] received rolling=0031a0c fixed=d049cac006 data=42600481
[09:55:05][D][ratgdo_secplus2:366]: cmd=081 (STATUS) byte2=42 byte1=60 nibble=4
[09:55:05][D][ratgdo_secplus2:373]: [134432] Handle command: STATUS
[09:55:05][D][ratgdo:095]: Door state=OPENING
[09:55:05][D][ratgdo:310]: Schedule position sync: delta 1.000000, start position: 0.000000, start moving: 134443
[09:55:05][D][ratgdo:209]: Light state=ON
[09:55:05][D][ratgdo:215]: Lock state=UNLOCKED
[09:55:05][D][ratgdo:194]: Learn state=INACTIVE
[09:55:05][D][ratgdo_secplus2:415]: [134465] Done handle command: STATUS
[09:55:05][W][component:214]: Component ratgdo took a long time for an operation (0.06 s).
[09:55:05][W][component:215]: Components should block for at most 20-30ms.
[09:55:05][D][ratgdo:335]: [134503] Position update: 0.004762
[09:55:06][D][cover:170]: 'Door' - Publishing:
[09:55:06][D][cover:173]:   Position: 0%
[09:55:06][D][cover:186]:   Current Operation: OPENING
[09:55:06][D][ratgdo:335]: [135004] Position update: 0.044524
[09:55:06][D][cover:170]: 'Door' - Publishing:
[09:55:06][D][cover:173]:   Position: 4%
[09:55:06][D][cover:186]:   Current Operation: OPENING
[09:55:06][D][ratgdo:335]: [135506] Position update: 0.084365
[09:55:07][D][cover:170]: 'Door' - Publishing:
[09:55:07][D][cover:173]:   Position: 8%
[09:55:07][D][cover:186]:   Current Operation: OPENING
[09:55:07][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:07][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 25 08 E6 E7 A8 B6 5B 2C 88 2C BA FC 04 76 CC 24]
[09:55:07][D][ratgdo_secplus2:358]: [135921] received rolling=0031a0c fixed=d249cac006 data=00000084
[09:55:07][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[09:55:07][D][ratgdo_secplus2:373]: [135936] Handle command: MOTOR_ON
[09:55:07][D][ratgdo:233]: Motor: state=ON
[09:55:07][D][ratgdo_secplus2:415]: [135946] Done handle command: MOTOR_ON
[09:55:07][D][ratgdo:335]: [136011] Position update: 0.124444
[09:55:07][D][cover:170]: 'Door' - Publishing:
[09:55:07][D][cover:173]:   Position: 12%
[09:55:07][D][cover:186]:   Current Operation: OPENING
[09:55:08][D][ratgdo:335]: [136516] Position update: 0.164524
[09:55:08][D][cover:170]: 'Door' - Publishing:
[09:55:08][D][cover:173]:   Position: 16%
[09:55:08][D][cover:186]:   Current Operation: OPENING
[09:55:08][D][ratgdo:335]: [137018] Position update: 0.204365
[09:55:08][D][cover:170]: 'Door' - Publishing:
[09:55:08][D][cover:173]:   Position: 20%
[09:55:08][D][cover:186]:   Current Operation: OPENING
[09:55:09][D][ratgdo:335]: [137521] Position update: 0.244286
[09:55:09][D][cover:170]: 'Door' - Publishing:
[09:55:09][D][cover:173]:   Position: 24%
[09:55:09][D][cover:186]:   Current Operation: OPENING
[09:55:09][D][ratgdo:335]: [138024] Position update: 0.284206
[09:55:09][D][cover:170]: 'Door' - Publishing:
[09:55:09][D][cover:173]:   Position: 28%
[09:55:09][D][cover:186]:   Current Operation: OPENING
[09:55:10][D][ratgdo:335]: [138526] Position update: 0.324048
[09:55:10][D][cover:170]: 'Door' - Publishing:
[09:55:10][D][cover:173]:   Position: 32%
[09:55:10][D][cover:186]:   Current Operation: OPENING
[09:55:10][D][ratgdo:335]: [139030] Position update: 0.364048
[09:55:10][D][cover:170]: 'Door' - Publishing:
[09:55:10][D][cover:173]:   Position: 36%
[09:55:10][D][cover:186]:   Current Operation: OPENING
[09:55:10][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:11][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 25 08 E6 E7 A8 B6 5B 2C 88 2C BA FC 04 76 CC 24]
[09:55:11][D][ratgdo_secplus2:358]: [139521] received rolling=0031a0c fixed=d249cac006 data=00000084
[09:55:11][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[09:55:11][D][ratgdo_secplus2:373]: [139536] Handle command: MOTOR_ON
[09:55:11][D][ratgdo:233]: Motor: state=ON
[09:55:11][D][ratgdo_secplus2:415]: [139546] Done handle command: MOTOR_ON
[09:55:11][D][ratgdo:335]: [139562] Position update: 0.406270
[09:55:11][D][cover:170]: 'Door' - Publishing:
[09:55:11][D][cover:173]:   Position: 41%
[09:55:11][D][cover:186]:   Current Operation: OPENING
[09:55:11][D][ratgdo:335]: [140063] Position update: 0.446032
[09:55:11][D][cover:170]: 'Door' - Publishing:
[09:55:11][D][cover:173]:   Position: 45%
[09:55:11][D][cover:186]:   Current Operation: OPENING
[09:55:12][D][ratgdo:335]: [140565] Position update: 0.485873
[09:55:12][D][cover:170]: 'Door' - Publishing:
[09:55:12][D][cover:173]:   Position: 49%
[09:55:12][D][cover:186]:   Current Operation: OPENING
[09:55:12][D][ratgdo:335]: [141071] Position update: 0.526032
[09:55:12][D][cover:170]: 'Door' - Publishing:
[09:55:12][D][cover:173]:   Position: 53%
[09:55:12][D][cover:186]:   Current Operation: OPENING
[09:55:13][D][ratgdo:335]: [141576] Position update: 0.566111
[09:55:13][D][cover:170]: 'Door' - Publishing:
[09:55:13][D][cover:173]:   Position: 57%
[09:55:13][D][cover:186]:   Current Operation: OPENING
[09:55:13][D][ratgdo:335]: [142079] Position update: 0.606032
[09:55:13][D][cover:170]: 'Door' - Publishing:
[09:55:13][D][cover:173]:   Position: 61%
[09:55:13][D][cover:186]:   Current Operation: OPENING
[09:55:14][D][ratgdo:335]: [142581] Position update: 0.645873
[09:55:14][D][cover:170]: 'Door' - Publishing:
[09:55:14][D][cover:173]:   Position: 65%
[09:55:14][D][cover:186]:   Current Operation: OPENING
[09:55:14][D][ratgdo:335]: [143084] Position update: 0.685794
[09:55:14][D][cover:170]: 'Door' - Publishing:
[09:55:14][D][cover:173]:   Position: 69%
[09:55:14][D][cover:186]:   Current Operation: OPENING
[09:55:15][D][ratgdo:335]: [143586] Position update: 0.725635
[09:55:15][D][cover:170]: 'Door' - Publishing:
[09:55:15][D][cover:173]:   Position: 73%
[09:55:15][D][cover:186]:   Current Operation: OPENING
[09:55:15][D][ratgdo:335]: [144091] Position update: 0.765714
[09:55:15][D][cover:170]: 'Door' - Publishing:
[09:55:15][D][cover:173]:   Position: 77%
[09:55:15][D][cover:186]:   Current Operation: OPENING
[09:55:15][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:15][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 25 08 E6 E7 A8 B6 5B 2C 88 2C BA FC 04 76 CC 24]
[09:55:15][D][ratgdo_secplus2:358]: [144349] received rolling=0031a0c fixed=d249cac006 data=00000084
[09:55:15][D][ratgdo_secplus2:366]: cmd=284 (MOTOR_ON) byte2=00 byte1=00 nibble=0
[09:55:15][D][ratgdo_secplus2:373]: [144364] Handle command: MOTOR_ON
[09:55:15][D][ratgdo:233]: Motor: state=ON
[09:55:15][D][ratgdo_secplus2:415]: [144374] Done handle command: MOTOR_ON
[09:55:16][D][ratgdo:335]: [144593] Position update: 0.805556
[09:55:16][D][cover:170]: 'Door' - Publishing:
[09:55:16][D][cover:173]:   Position: 81%
[09:55:16][D][cover:186]:   Current Operation: OPENING
[09:55:16][D][ratgdo:335]: [145095] Position update: 0.845397
[09:55:16][D][cover:170]: 'Door' - Publishing:
[09:55:16][D][cover:173]:   Position: 85%
[09:55:16][D][cover:186]:   Current Operation: OPENING
[09:55:16][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:16][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 25 08 E6 AF A8 A6 13 3C 88 2C BA FC 04 D2 45 05]
[09:55:16][D][ratgdo_secplus2:358]: [145469] received rolling=0031a0c fixed=d449cac006 data=5802010a
[09:55:16][D][ratgdo_secplus2:366]: cmd=40a (TTC) byte2=58 byte1=02 nibble=1
[09:55:16][D][ratgdo_secplus2:373]: [145484] Handle command: TTC
[09:55:16][D][ratgdo_secplus2:415]: [145490] Done handle command: TTC
[09:55:17][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:17][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 24 13 8F CB 3A FF 7F BF 69 08 A0 D8 94 73 98 05]
[09:55:17][D][ratgdo_secplus2:358]: [145548] received rolling=0031a0d fixed=d049cac006 data=000001a0
[09:55:17][D][ratgdo_secplus2:366]: cmd=0a0 (PAIR_3) byte2=00 byte1=00 nibble=1
[09:55:17][D][ratgdo_secplus2:373]: [145563] Handle command: PAIR_3
[09:55:17][D][ratgdo_secplus2:415]: [145569] Done handle command: PAIR_3
[09:55:17][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:17][D][ratgdo:335]: [145601] Position update: 0.885556
[09:55:17][D][cover:170]: 'Door' - Publishing:
[09:55:17][D][cover:173]:   Position: 89%
[09:55:17][D][cover:186]:   Current Operation: OPENING
[09:55:17][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 8A 34 32 92 7C F6 DF 5D 18 14 D3 21 6C F2 81 27]
[09:55:17][D][ratgdo_secplus2:358]: [145620] received rolling=0031a0e fixed=d049cac006 data=000201a1
[09:55:17][D][ratgdo_secplus2:366]: cmd=0a1 (PAIR_3_RESP) byte2=00 byte1=02 nibble=1
[09:55:17][D][ratgdo_secplus2:373]: [145640] Handle command: PAIR_3_RESP
[09:55:17][D][ratgdo_secplus2:415]: [145644] Done handle command: PAIR_3_RESP
[09:55:17][D][ratgdo_secplus2:279]: Baud: 9900
[09:55:17][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 A6 38 54 12 5D 4D 36 91 61 38 79 A0 DE 3A B4 95]
[09:55:17][D][ratgdo_secplus2:358]: [145689] received rolling=00096d9 fixed=9057da9908 data=000101a1
[09:55:17][D][ratgdo_secplus2:366]: cmd=0a1 (PAIR_3_RESP) byte2=00 byte1=01 nibble=1
[09:55:17][D][ratgdo_secplus2:373]: [145705] Handle command: PAIR_3_RESP
[09:55:17][D][ratgdo_secplus2:415]: [145712] Done handle command: PAIR_3_RESP
[09:55:17][D][ratgdo:335]: [146103] Position update: 0.925397
[09:55:17][D][cover:170]: 'Door' - Publishing:
[09:55:17][D][cover:173]:   Position: 93%
[09:55:17][D][cover:186]:   Current Operation: OPENING
[09:55:17][D][ratgdo_secplus2:279]: Baud: 9615
[09:55:18][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 89 09 C4 49 11 56 04 0A 09 30 8B 40 4A A0 04 07]
[09:55:18][D][ratgdo_secplus2:358]: [146509] received rolling=0031a0f fixed=d049cac006 data=42600181
[09:55:18][D][ratgdo_secplus2:366]: cmd=081 (STATUS) byte2=42 byte1=60 nibble=1
[09:55:18][D][ratgdo_secplus2:373]: [146524] Handle command: STATUS
[09:55:18][D][ratgdo:095]: Door state=OPEN
[09:55:18][D][ratgdo:533]: Cancelling position callbacks
[09:55:18][D][ratgdo:209]: Light state=ON
[09:55:18][D][ratgdo:215]: Lock state=UNLOCKED
[09:55:18][D][ratgdo:194]: Learn state=INACTIVE
[09:55:18][D][ratgdo_secplus2:415]: [146551] Done handle command: STATUS
[09:55:18][D][binary_sensor:036]: 'Motor': Sending state OFF
[09:55:18][D][cover:170]: 'Door' - Publishing:
[09:55:18][D][cover:173]:   Position: 100%
[09:55:18][D][cover:186]:   Current Operation: IDLE
[09:55:18][D][switch:012]: 'Status door' Turning ON.
[09:55:18][D][switch:055]: 'Status door': Sending state ON
[09:55:36]
[09:55:36]--------------- CUT HERE FOR EXCEPTION DECODER ---------------
[09:55:36]
[09:55:36]Soft WDT reset
[09:55:36]
[09:55:36]>>>stack>>>
WARNING Found stack trace! Trying to decode it
[09:55:36]
[09:55:36]ctx: sys
[09:55:36]sp: 3fffed40 end: 3fffffb0 offset: 01a0
[09:55:36]3fffeee0:  3ffe9fe0 3ffe9fe8 000007c6 00000002  
[09:55:36]3fffeef0:  00000018 00012e0d 00000000 4024888b  
WARNING Decoded 0x4024888b: ethernet_output at /home/earle/src/esp-quick-toolchain/arduino/tools/sdk/lwip2/builder/lwip2-src/src/netif/ethernet.c:304
[09:55:36]3fffef00:  40276174 3fff2994 3fff4af4 402487e5  
WARNING Decoded 0x40276174: chip_v6_unset_chanfreq
WARNING Decoded 0x402487e5: ethernet_input_LWIP2 at /home/earle/src/esp-quick-toolchain/arduino/tools/sdk/lwip2/builder/lwip2-src/src/netif/ethernet.c:166
[09:55:36]3fffef10:  00000000 3ffea598 00000000 00000000  
[09:55:36]3fffef20:  40269c54 3ffea598 3ffefa20 40100ab0  
WARNING Decoded 0x40269c54: LightSleepWakedCbSetFunc
WARNING Decoded 0x40100ab0: ets_post
[09:55:36]3fffef30:  4026fc61 3ffea598 3ffefa20 09b1ae76  
WARNING Decoded 0x4026fc61: eagle_lwip_if_free
[09:55:36]3fffef40:  4026fca6 3fffdab0 00000000 3fffdcb0  
WARNING Decoded 0x4026fca6: eagle_lwip_if_free
[09:55:36]3fffef50:  3ffefa40 3fffdad0 3fff047c 402344a6  
WARNING Decoded 0x402344a6: operator new(unsigned int, std::nothrow_t const&)
[09:55:36]3fffef60:  40000f49 3fffdab0 3fffdab0 40000f49  
[09:55:36]3fffef70:  40000e19 00083821 00000000 00000005  
[09:55:36]3fffef80:  60000600 aa55aa55 000000f6 40105d95  
WARNING Decoded 0x40105d95: call_user_start_local
[09:55:36]3fffef90:  40105d9b 00000000 00000005 6d005849  
WARNING Decoded 0x40105d9b: call_user_start_local
[09:55:36]3fffefa0:  4010000d 00000000 00083821 401000ab  
WARNING Decoded 0x4010000d: call_user_start
WARNING Decoded 0x401000ab: app_entry_redefinable
[09:55:36]3fffefb0:  4025fed8 3fffef4c 4025fe89 3fffff48  
WARNING Decoded 0x4025fed8: eloop_register_timeout
WARNING Decoded 0x4025fe89: eloop_register_timeout
[09:55:36]3fffefc0:  3fffffd0 00000000 00000000 feefeffe  
[09:55:36]3fffefd0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3fffefe0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3fffeff0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff000:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff010:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff020:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff030:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff040:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff050:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff060:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff070:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff080:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff090:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff0a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff0b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff0c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff0d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff0e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff0f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff100:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff110:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff120:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff130:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff140:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff150:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff160:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff170:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff180:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff190:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff1a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff1b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff1c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff1d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff1e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff1f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff200:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff210:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff220:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff230:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff240:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff250:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff260:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff270:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff280:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff290:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff2a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff2b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff2c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff2d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff2e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff2f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff300:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff310:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff320:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff330:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff340:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff350:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff360:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff370:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff380:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff390:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff3a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff3b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff3c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff3d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff3e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff3f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff400:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff410:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff420:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff430:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff440:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff450:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff460:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff470:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff480:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff490:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff4a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff4b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff4c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff4d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff4e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff4f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff500:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff510:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff520:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff530:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff540:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff550:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff560:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff570:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff580:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff590:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff5a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff5b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff5c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff5d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff5e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff5f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff600:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff610:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff620:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff630:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff640:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff650:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff660:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff670:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff680:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff690:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff6a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff6b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff6c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff6d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff6e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff6f0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff700:  feefeffe feefeffe feefeffe feefeffe  
[09:55:36]3ffff710:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff720:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff730:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff740:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff750:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff760:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff770:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff780:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff790:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff7a0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff7b0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff7c0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff7d0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff7e0:  feefeffe feefeffe feefeffe feefeffe  
[09:55:37]3ffff7f0:  40100d10 feefeffe feefeffe feefeffe  
WARNING Decoded 0x40100d10: interrupt_handler
[09:55:37]3ffff800:  00000020 feefeffe feefeffe feefeffe  
[09:55:37]3ffff810:  feefeffe feefeffe feefeffe 00000022  
[09:55:37]3ffff820:  4000050c 40100cd8 3fffc258 4000050c  
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffff830:  4000e23d 00000030 0000001d ffffffff  
[09:55:37]3ffff840:  4000da01 00000002 00020000 00000002  
[09:55:37]3ffff850:  0000000d 00012000 40275df1 00000010  
WARNING Decoded 0x40275df1: chip_v6_unset_chanfreq
[09:55:37]3ffff860:  00000000 00000000 3ffffa73 00052000  
[09:55:37]3ffff870:  20000000 20000000 80000000 00000030  
[09:55:37]3ffff880:  40100d10 3fff1439 3ffffa63 00000000  
WARNING Decoded 0x40100d10: interrupt_handler
[09:55:37]3ffff890:  00000000 00000000 00000000 00000022  
[09:55:37]3ffff8a0:  40100d10 40100cd8 3fffc258 00000022  
WARNING Decoded 0x40100d10: interrupt_handler
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffff8b0:  00000020 00000000 0000000a 00000000  
[09:55:37]3ffff8c0:  00000003 00000000 0000000a 00000022  
[09:55:37]3ffff8d0:  4000050c 40100cd8 3fffc258 4000050c  
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffff8e0:  00000003 00000000 0000000a 00000000  
[09:55:37]3ffff8f0:  00000003 00000000 0000000a 00000000  
[09:55:37]3ffff900:  40100d10 00000001 40105be1 3ffeea18  
WARNING Decoded 0x40100d10: interrupt_handler
WARNING Decoded 0x40105be1: lmacTxFrame
[09:55:37]3ffff910:  00000000 a0000000 00000000 0000001c  
[09:55:37]3ffff920:  00000002 00000000 00000010 00000000  
[09:55:37]3ffff930:  00000002 00000000 00000010 00000000  
[09:55:37]3ffff940:  3ffffa30 3ffffa33 00000000 ffffffff  
[09:55:37]3ffff950:  00000001 3fff20f8 11567ecb 40100674  
WARNING Decoded 0x40100674: EspSoftwareSerial::UARTBase::rxBitISR(EspSoftwareSerial::UARTBase*)
[09:55:37]3ffff960:  00000001 3fff20f8 115b6f71 40100674  
WARNING Decoded 0x40100674: EspSoftwareSerial::UARTBase::rxBitISR(EspSoftwareSerial::UARTBase*)
[09:55:37]3ffff970:  115b6f71 00000004 3ffffae0 40243ab0  
WARNING Decoded 0x40243ab0: __copybits at /workdir/repo/newlib/newlib/libc/stdlib/mprec.c:1000
[09:55:37]3ffff980:  00000031 3fff20f8 115b2747 40100674  
WARNING Decoded 0x40100674: EspSoftwareSerial::UARTBase::rxBitISR(EspSoftwareSerial::UARTBase*)
[09:55:37]3ffff990:  40100d10 00000001 00000004 00037011  
WARNING Decoded 0x40100d10: interrupt_handler
[09:55:37]3ffff9a0:  00000020 00000001 00000004 40100d9c  
WARNING Decoded 0x40100d9c: interrupt_handler
[09:55:37]3ffff9b0:  00000020 3ffffa71 00000002 00000022  
[09:55:37]3ffff9c0:  4000050c 40100cd8 3fffc258 4000050c  
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffff9d0:  4021895d 00000030 00000010 ffffffff  
WARNING Decoded 0x4021895d: esphome::socket::LWIPRawImpl::~LWIPRawImpl()
[09:55:37]3ffff9e0:  402105f2 3fff555c 3fff555c 3ffffb10  
WARNING Decoded 0x402105f2: esphome::ota::OTAComponent::handle_()
[09:55:37]3ffff9f0:  3fffff28 4021892c 3ffeff48 fffffffe  
WARNING Decoded 0x4021892c: esphome::socket::LWIPRawImpl::~LWIPRawImpl()
[09:55:37]3ffffa00:  00000450 3fffc6fc 00000000 3fff54ec  
[09:55:37]3ffffa10:  3fffff10 3fff5764 3ffffb10 00000030  
[09:55:37]3ffffa20:  40100d10 7ff00000 7fc1c298 00000039  
WARNING Decoded 0x40100d10: interrupt_handler
[09:55:37]3ffffa30:  00000020 00000401 85300000 00000006  
[09:55:37]3ffffa40:  3fff3302 3fff3301 3ffe83c4 00000022  
[09:55:37]3ffffa50:  4000050c 40100cd8 3fffc258 4000050c  
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffffa60:  40241a48 00000030 0000001e ffffffff  
WARNING Decoded 0x40241a48: _dtoa_r at /workdir/repo/newlib/newlib/libc/stdlib/dtoa.c:340 (discriminator 1)
[09:55:37]3ffffa70:  402419cc 00000009 00000003 00000003  
WARNING Decoded 0x402419cc: _dtoa_r at /workdir/repo/newlib/newlib/libc/stdlib/dtoa.c:278
[09:55:37]3ffffa80:  40590000 00000000 00000000 20000000  
[09:55:37]3ffffa90:  e0000000 a7e90d1b 61c80000 ffffffff  
[09:55:37]3ffffaa0:  00000001 00000006 3ffe83c4 00000030  
[09:55:37]3ffffab0:  11593854 bfffffff 00000005 401029fc  
WARNING Decoded 0x401029fc: pp_post
[09:55:37]3ffffac0:  3ffea855 40105c93 3ffee2e0 40100d9c  
WARNING Decoded 0x40105c93: lmacRxDone
WARNING Decoded 0x40100d9c: interrupt_handler
[09:55:37]3ffffad0:  3fffff28 3fff20f8 117683a9 40100674  
WARNING Decoded 0x40100674: EspSoftwareSerial::UARTBase::rxBitISR(EspSoftwareSerial::UARTBase*)
[09:55:37]3ffffae0:  117683a9 00000003 3ffeeb74 3fff19bc  
[09:55:37]3ffffaf0:  00000000 3fffff10 3fff19bc 402105f2  
WARNING Decoded 0x402105f2: esphome::ota::OTAComponent::handle_()
[09:55:37]3ffffb00:  00000001 7fc1c298 40103c1e 00037011  
WARNING Decoded 0x40103c1e: wDev_ProcessFiq
[09:55:37]3ffffb10:  3ffffb60 40590000 00000000 402437da  
WARNING Decoded 0x402437da: __mdiff at /workdir/repo/newlib/newlib/libc/stdlib/mprec.c:599
[09:55:37]3ffffb20:  00000000 00000000 0000001f 40100ab0  
WARNING Decoded 0x40100ab0: ets_post
[09:55:37]3ffffb30:  3ffffb64 00000000 3fffc228 4010652d  
WARNING Decoded 0x4010652d: ets_timer_disarm
[09:55:37]3ffffb40:  00000005 00000000 0000000a 00000000  
[09:55:37]3ffffb50:  00000005 00000000 0000000a 00000000  
[09:55:37]3ffffb60:  40000fa0 00000531 00000531 3fffc200  
[09:55:37]3ffffb70:  3ffffc6a a0000000 00000000 0000001c  
[09:55:37]3ffffb80:  00005000 3fffc6fc 00005000 3ffe83c4  
[09:55:37]3ffffb90:  00000001 00000001 3ffffd00 40243ab0  
WARNING Decoded 0x40243ab0: __copybits at /workdir/repo/newlib/newlib/libc/stdlib/mprec.c:1000
[09:55:37]3ffffba0:  3ffffc91 3ffffc6a 00000001 40243ab0  
WARNING Decoded 0x40243ab0: __copybits at /workdir/repo/newlib/newlib/libc/stdlib/mprec.c:1000
[09:55:37]3ffffbb0:  3ffffca1 00000000 4023eaa1 3ffe83c4  
WARNING Decoded 0x4023eaa1: _printf_i at /workdir/repo/newlib/newlib/libc/stdio/nano-vfprintf_i.c:120 (discriminator 16)
[09:55:37]3ffffbc0:  00000002 00000000 3ffffd00 3ffe83c4  
[09:55:37]3ffffbd0:  00000000 00000000 3ffffd40 40243ab0  
WARNING Decoded 0x40243ab0: __copybits at /workdir/repo/newlib/newlib/libc/stdlib/mprec.c:1000
[09:55:37]3ffffbe0:  3ffe90d6 3ffffcd3 00000000 3ffffd00  
[09:55:37]3ffffbf0:  3ffe8ca2 00000000 3ffffc50 3ffe83c4  
[09:55:37]3ffffc00:  00000005 00000000 00000020 40100ab0  
WARNING Decoded 0x40100ab0: ets_post
[09:55:37]3ffffc10:  40100d10 3ffe90d6 00000005 401029fc  
WARNING Decoded 0x40100d10: interrupt_handler
WARNING Decoded 0x401029fc: pp_post
[09:55:37]3ffffc20:  3ffea855 40105c93 3ffee2b8 3ffffd40  
WARNING Decoded 0x40105c93: lmacRxDone
[09:55:37]3ffffc30:  40103587 3ffee2b8 3ffffc90 00000022  
WARNING Decoded 0x40103587: rcReachRetryLimit
[09:55:37]3ffffc40:  00000001 099ed364 3ffeeb74 40103764  
WARNING Decoded 0x40103764: rcReachRetryLimit
[09:55:37]3ffffc50:  3ffeb0e8 00000000 00000000 ffffffff  
[09:55:37]3ffffc60:  00000001 099ed364 40103c1e 00000100  
WARNING Decoded 0x40103c1e: wDev_ProcessFiq
[09:55:37]3ffffc70:  3ffeb0e8 7fffffff 00002200 00000001  
[09:55:37]3ffffc80:  40100d10 00006208 00000000 3fff590c  
WARNING Decoded 0x40100d10: interrupt_handler
[09:55:37]3ffffc90:  00000020 3fff6d2c 3fff1a1c 099ed364  
[09:55:37]3ffffca0:  3ffeb0dc 2c9f0300 4000050c 00000022  
[09:55:37]3ffffcb0:  40100d10 40100cd8 3fffc258 4000050c  
WARNING Decoded 0x40100d10: interrupt_handler
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffffcc0:  40271497 00000030 00000010 ffffffff  
WARNING Decoded 0x40271497: wifi_softap_dhcps_stop
[09:55:37]3ffffcd0:  40271516 00000001 40275810 00000022  
WARNING Decoded 0x40271516: wifi_station_dhcpc_start
WARNING Decoded 0x40275810: chip_v6_unset_chanfreq
[09:55:37]3ffffce0:  4000050c 40100cd8 3fffc258 4000050c  
WARNING Decoded 0x40100cd8: interrupt_handler
[09:55:37]3ffffcf0:  402217e1 00000030 00000010 ffffffff  
WARNING Decoded 0x402217e1: esphome::PollingComponent::start_poller()
[09:55:37]3ffffd00:  4020258e 40221a0c 402217e4 00000001  
WARNING Decoded 0x4020258e: esphome::api::APIConnection::loop()
WARNING Decoded 0x40221a0c: esphome::ComponentIterator::advance()
WARNING Decoded 0x402217e4: esphome::PollingComponent::start_poller()
[09:55:37]3ffffd10:  402182cc 4021892c 3ffeff48 3ffffb10  
WARNING Decoded 0x402182cc: esphome::socket::LWIPRawImpl::close()
WARNING Decoded 0x4021892c: esphome::socket::LWIPRawImpl::~LWIPRawImpl()
[09:55:37]3ffffd20:  4021d27c 3fffc6fc 00000000 3fff6d0c  
WARNING Decoded 0x4021d27c: esphome::wifi::WiFiComponent::WiFiComponent()
[09:55:37]3ffffd30:  000003e9 3fff54e8 3fff1a1c 00000030  
[09:55:37]3ffffd40:  00000005 00000000 00000020 40100ab0  
WARNING Decoded 0x40100ab0: ets_post
[09:55:37]3ffffd50:  00000000 00000000 00000005 401029fc  
WARNING Decoded 0x401029fc: pp_post
[09:55:37]3ffffd60:  3ffea855 40105c93 3ffee2b8 3fff1a1c  
WARNING Decoded 0x40105c93: lmacRxDone
[09:55:37]3ffffd70:  3fff6d2c 3fff6d4c 3fff6d2c 402045c5  
WARNING Decoded 0x402045c5: _ZN7esphome3api23APIPlaintextFrameHelper15try_read_frame_EPNS1_11ParsedFrameE$part$0 at api_frame_helper.cpp
[09:55:37]3ffffd80:  00000003 09b06982 3ffeeb74 40103764  
WARNING Decoded 0x40103764: rcReachRetryLimit
[09:55:37]3ffffd90:  3ffeb0dc 00000000 00000000 00000001  
[09:55:37]3ffffda0:  00000003 09b06982 40103c1e 00000100  
WARNING Decoded 0x40103c1e: wDev_ProcessFiq
[09:55:37]3ffffdb0:  3ffffde0 3fff1774 3fff54e8 00000001  
[09:55:37]3ffffdc0:  40272703 00006208 3ffee2b8 3fff1a1c  
WARNING Decoded 0x40272703: wifi_station_connect
[09:55:37]3ffffdd0:  00000000 00027b4f b3333333 02de9427  
[09:55:37]3ffffde0:  00000000 00000000 00000000 3fff1a1c  
[09:55:37]3ffffdf0:  3fff54e8 000003e9 3fff6c74 4020259d  
WARNING Decoded 0x4020259d: esphome::api::APIConnection::loop()
[09:55:37]3ffffe00:  40100b90 00000030 00000010 ffffffff  
WARNING Decoded 0x40100b90: millis
[09:55:37]3ffffe10:  40100b76 09b06fb8 4bc6a7f0 00000002  
WARNING Decoded 0x40100b76: millis
[09:55:37]3ffffe20:  00004bc6 00000000 3ffeff48 fffffffe  
[09:55:37]3ffffe30:  4022da7c 3fffc6fc 00000000 00000000  
WARNING Decoded 0x4022da7c: esp8266::MDNSImplementation::MDNSResponder::_updateProbeStatus()
[09:55:37]3ffffe40:  09b06fb8 00000000 00000000 00000000  
[09:55:37]3ffffe50:  00000000 00027b4f b4395810 02de9428  
[09:55:37]3ffffe60:  3ffeff44 3fffdad0 3fff047c 3fff1a1c  
[09:55:37]3ffffe70:  3fff54e8 3fff54e8 3fff1a1c 40208fd3  
WARNING Decoded 0x40208fd3: esphome::api::APIServer::loop()
[09:55:37]3ffffe80:  4021fc3a 00000030 00000010 ffffffff  
WARNING Decoded 0x4021fc3a: esphome::wifi::WiFiComponent::wifi_scan_done_callback_(void*, STATUS)
[09:55:37]3ffffe90:  4021fc3a 000dbba0 00027afd fffffeff  
WARNING Decoded 0x4021fc3a: esphome::wifi::WiFiComponent::wifi_scan_done_callback_(void*, STATUS)
[09:55:37]3ffffea0:  00004bc6 00000000 3ffeff48 fffffffe  
[09:55:37]3ffffeb0:  3fff3598 3fffc6fc 00000000 3ffeff44  
[09:55:37]3ffffec0:  00000000 3fff4f34 3fff1774 00000000  
[09:55:37]3ffffed0:  00000000 3fff20f8 3fff20f8 40231399  
WARNING Decoded 0x40231399: EspSoftwareSerial::UARTBase::rxBits(unsigned int)
[09:55:37]3ffffee0:  00000000 0000001c 7f7ced91 3fff20ac  
[09:55:37]3ffffef0:  00000000 00027b4f a3958106 02de9415  
[09:55:37]3fffff00:  3fffdad0 3ffeff1c 3fff20f8 00000001  
[09:55:37]3fffff10:  00000000 3fff025c 3fff5020 4022d4f8  
WARNING Decoded 0x4022d4f8: esp8266::MDNSImplementation::MDNSResponder::_parseQuery(esp8266::MDNSImplementation::MDNSResponder::stcMDNS_MsgHeader const&)
[09:55:37]3fffff20:  00000000 00027b4f ba9fbe76 02de942f  
[09:55:37]3fffff30:  40106671 02f07202 3fff04e4 00000000  
WARNING Decoded 0x40106671: ets_timer_arm_new
[09:55:37]3fffff40:  3ffefa20 3fff04e4 00000010 3fff04e4  
[09:55:37]3fffff50:  00027b4f 3fff1a1c 40234525 3fffefb0  
WARNING Decoded 0x40234525: cont_init
[09:55:37]3fffff60:  3fff04e4 00027b4f 3fff1a1c 40234c4d  
WARNING Decoded 0x40234c4d: __unhandled_exception
[09:55:37]3fffff70:  3fff4f5c 00000010 3ffeff44 4021fcb3  
WARNING Decoded 0x4021fcb3: _ZZN7esphome11Application5setupEvENKUlPNS_9ComponentES2_E0_clES2_S2_$constprop$0 at application.cpp
[09:55:37]3fffff80:  3fff4f01 000021bf 3fff4300 3fff047c  
[09:55:37]3fffff90:  3fff4f5c 3fff30d4 3ffeff78 3fff047c  
[09:55:37]3fffffa0:  3fffdad0 00000000 3fff0468 3fff047c  
[09:55:37]<<<stack<<<
[09:55:37]
[09:55:37]--------------- CUT HERE FOR EXCEPTION DECODER ---------------
[09:55:37]
[09:55:37] ets Jan  8 2013,rst cause:2, boot mode:(3,0)
[09:55:37]
[09:55:37]load 0x4010f000, len 3460, room 16 
[09:55:37]tail 4
[09:55:37]chksum 0xcc
[09:55:37]load 0x3fff20b8, len 40, room 4 
[09:55:37]tail 4
[09:55:37]chksum 0xc9
[09:55:37]csum 0xc9
[09:55:37]v00083830
[09:55:37]~ld
[09:55:37][I][logger:351]: Log initialized
[09:55:37][C][ota:473]: There have been 1 suspected unsuccessful boot attempts.
[09:55:37][I][app:029]: Running through setup()...
[09:55:37][D][number:012]: 'Rolling code counter': Sending state 3058.000000
[09:55:37][D][ratgdo:340]: Set opening duration: 12.6s
[09:55:37][D][number:012]: 'Opening duration': Sending state 12.600000
[09:55:37][D][ratgdo:346]: Set closing duration: 16.3s
[09:55:37][D][number:012]: 'Closing duration': Sending state 16.299999
[09:55:37][D][number:012]: 'Client ID': Sending state 58681.000000
[09:55:37][C][switch.gpio:011]: Setting up GPIO Switch 'Status door'...

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I hooked up a serial console.

trace is above

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

The trace is from the near garage door

Testing expiring_callbacks_1 now on the mid garage door

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Confirmed crash still happens with expiring_callbacks_1 on mid garage door (console not attached as I'd have to pull out the other car but can if needed)

[10:10:13][D][cover:173]:   Position: 46%
[10:10:13][D][cover:186]:   Current Operation: CLOSING
[10:10:13][D][cover:076]: 'Door' - Setting
[10:10:13][D][cover:080]:   Command: STOP
[10:10:13][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010103
[10:10:13][D][ratgdo_secplus2:450]: [47629] Encode for transmit rolling=00006c6 fixed=020064d539 data=01010380
[10:10:13][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 48 24 93 4A 14 9A 4D 21 06 1C 6E 65 5E CD F6 6F]
[10:10:13][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010003
[10:10:13][D][ratgdo_secplus2:450]: [47831] Encode for transmit rolling=00006c6 fixed=020064d539 data=01000380
[10:10:13][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 48 24 93 4A 14 9A 4D 25 06 1C 6E 65 5E CD B6 6F]
[10:10:13][D][number:012]: 'Rolling code counter': Sending state 1735.000000
[10:10:13][D][cover:076]: 'Door' - Setting


WARNING midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 54] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
WARNING Disconnected from API
INFO Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.106s
INFO Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.067s


Trying _2 now

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

expiring_callbacks_2

crashed with this one as well

[10:12:30][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010100
[10:12:30][D][ratgdo_secplus2:450]: [58084] Encode for transmit rolling=00006de fixed=020064d539 data=01010080
[10:12:30][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 64 3B FD FC 6F ED FE FC 86 1E 6F 6E 9C 8D 36 4B]
[10:12:31][D][ratgdo_secplus2:279]: Baud: 9708
[10:12:31][D][ratgdo_secplus2:320]: Received packet: : [55 01 00 0A 34 D2 D9 29 B6 DD 3D 5A 3D F3 5C CC 39 C9 63]
[10:12:31][D][ratgdo_secplus2:358]: [58249] received rolling=0025c21 fixed=007ccab006 data=000c01a1
[10:12:31][D][ratgdo_secplus2:366]: cmd=0a1 (PAIR_3_RESP) byte2=00 byte1=0c nibble=1
[10:12:31][D][ratgdo_secplus2:373]: [58263] Handle command: PAIR_3_RESP
[10:12:31][D][ratgdo_secplus2:415]: [58270] Done handle command: PAIR_3_RESP
[10:12:31][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010000
[10:12:31][D][ratgdo_secplus2:450]: [58287] Encode for transmit rolling=00006de fixed=020064d539 data=01000080
[10:12:31][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 64 3B FD FC 6F ED FE FE 86 1E 6F 6E 9C 8D 26 4B]


WARNING midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 54] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
WARNING Disconnected from API
INFO Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.152s
INFO Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.042s

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

retesting as I realized the refs need to be changed in the branches

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

adjusted refs 5cb97a7 8a5af03
437beaa

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

retesting with expiring_callbacks_1 now ...

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Crashing with _1 bad test.. was watching the wrong GDO 🤦

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

expiring_callbacks_2 appears to be stable... testing more

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

spoke too soon

_2 crashed

[10:23:27.860][D][cover:084]:   Position: 100%
[10:23:27.860][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010101
[10:23:27.860][D][ratgdo_secplus2:450]: [179888] Encode for transmit rolling=000070f fixed=020064d539 data=01010180
[10:23:27.860][D][ratgdo_secplus2:320]: Sending packet: [55 01 00 06 1B 2D 9E 83 6D B6 4E 59 0E 07 E8 C7 C5 32 03]
[10:23:28.004][D][ratgdo_secplus2:420]: Send command: DOOR_ACTION, data: 010001


2024-01-21 10:24:18.167 WARNING  midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 54] Connection reset by peer
2024-01-21 10:24:18.168 INFO     Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
2024-01-21 10:24:18.168 WARNING  Disconnected from API
2024-01-21 10:24:18.377 INFO     Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.209s
2024-01-21 10:24:18.626 INFO     Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.249s

Now properly testing _1

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

Summary

expiring_callbacks crashes with trace in #189 (comment)
expiring_callbacks_1 appears more stable than _2 but still crashes
expiring_callbacks_2 crashes

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

I just realized I'm getting crashes on main as well so something must have changed in the last round of merges and this change makes it more likely to trigger somehow

[10:31:44.409][D][number:012]: 'Rolling code counter': Sending state 1910.000000
[10:31:44.409][D][cover:170]: 'Door' - Publishing:
[10:31:44.409][D][cover:173]:   Position: 0%
[10:31:44.409][D][cover:186]:   Current Operation: IDLE
[10:31:44.409][D][switch:016]: 'Status door' Turning OFF.
[10:31:44.464][D][ratgdo:270]: Openings: 2432
[10:31:44.503][D][sensor:093]: 'Openings': Sending state 2432.00000 openings with 0 decimals of accuracy



2024-01-21 10:32:17.171 WARNING  midgarageratgdo @ 192.168.106.58: Connection error occurred: [Errno 54] Connection reset by peer
2024-01-21 10:32:17.171 INFO     Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
2024-01-21 10:32:17.172 WARNING  Disconnected from API
2024-01-21 10:32:17.327 INFO     Successfully connected to midgarageratgdo @ 192.168.106.58 in 0.155s
2024-01-21 10:32:17.546 INFO     Successful handshake with midgarageratgdo @ 192.168.106.58 in 0.219s
[10:32:18.707][D][api:102]: Accepted 192.168.107.8
[10:32:18.875][D][api.connection:1121]: Home Assistant 2024.2.0.dev0 (192.168.107.8): Connected successfully
[10:32:18.883][D][time:044]: Synchronized time: 2024-01-21 10:32:18

@bdraco
Copy link
Member

bdraco commented Jan 21, 2024

The best way I have found to trigger the crash is to open and close a few times and stop the door at various points in the open/close phase and than restart the open/close

@mariusmuja
Copy link
Collaborator Author

Thanks for all the testing!

I just realized I'm getting crashes on main as well so something must have changed in the last round of merges and this change makes it more likely to trigger somehow

Ok, that at least makes a bit more sense, since it was a large refactoring... I couldn't see what would cause it in this latest change. Still strange that it didn't happen for me at all, I'll have some time later today to look at it and test some more.

@mariusmuja
Copy link
Collaborator Author

@bdraco

I saw in the stack-trace that the crash was a WDT reset and looking though the code it seems that esphome does not feed the WDT in between scheduler tasks. I pushed a change that feeds the WDT after each defer task in the ratgdo component, when you have a chance, can you see if it fixes the crashes?

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

I re-flashed. Sorry to report the behavior is the same

[14:16:37.423][D][cover:186]:   Current Operation: CLOSING
[14:16:37.562][D][ratgdo:335]: [50139] Position update: 0.316606
[14:16:37.562][D][cover:170]: 'Door' - Publishing:
[14:16:37.562][D][cover:173]:   Position: 32%
[14:16:37.562][D][cover:186]:   Current Operation: CLOSING
[14:16:37.981][D][ratgdo:335]: [50647] Position update: 0.287411


2024-01-22 14:17:37.034 WARNING  midgarageratgdo @ 192.168.106.58: Connection error occurred: Ping response not received after 45.0 seconds
2024-01-22 14:17:37.035 INFO     Processing unexpected disconnect from ESPHome API for midgarageratgdo @ 192.168.106.58
2024-01-22 14:17:37.035 WARNING  Disconnected from API

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

Let me know if you want a full trace and I'll hook up the console again

@mariusmuja
Copy link
Collaborator Author

Try again with the latest?

If the same, another trace might give some additional clues... frustrating to not be able to reproduce it, I've been opening/closing the door lots of times and nothing...

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

I have a feeling its 8266 only....

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

Its hard crashed and not coming back so I have to get the ladder back out anyways

@mariusmuja
Copy link
Collaborator Author

I have a feeling its 8266 only....

I'm using an 8266...

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

Thats super frustrating for sure considering how many different GDOs I can replicate on

@mariusmuja
Copy link
Collaborator Author

Thats super frustrating for sure considering how many different GDOs I can replicate on

Send me a binary, I'll flash it on mine, at least narrow down to HW or build environment.

@mariusmuja
Copy link
Collaborator Author

mariusmuja commented Jan 23, 2024

Its hard crashed and not coming back so I have to get the ladder back out anyways

Not even ping/OTA? I've always been able to OTA even if HA was not connecting (ESP went into safe mode boot).

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

I have wifi creds hard coded into it.

Can you find me on discord (same handle), and I'll compile one for you.

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

pings but no OTA

@bdraco
Copy link
Member

bdraco commented Jan 23, 2024

Last push appears to have fixed it

15 cycles and no crash.

Couldn't get past 2 before

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants