search

ratgdo / homekit-ratgdo

A native HomeKit implementation of a Security+ 2.0 garage door controller based on ratgdo hardware
https://ratgdo.github.io/homekit-ratgdo/
GNU General Public License v3.0
215 stars 21 forks source link

Crash on 1.6.0 #214

Closed colinrblake closed 3 months ago

colinrblake commented 4 months ago

Got my first crash since installing 1.6.0. In case you want to take a look. Feel free to close if nothing interesting.

Crash information recovered from EEPROM
Crash # 1 at -2072118327 ms
Restart reason: 3
Exception (4):
epc1=0x402687de epc2=0x00000000 epc3=0x00000000 excvaddr=0x40107a4e depc=0x00000000
>>>stack>>>

ctx: sys

sp: 3fffff40 end: 3fffffb0
3fffff40: 4026a08c 3fff60cc 3fff2dcc 60000600 
3fffff50: 00000000 3ffeaf38 00000000 00000000 
3fffff60: 402685f4 3ffeaf38 3fff03c0 60000600 
3fffff70: 4026e5ed 3ffeaf38 3fff03c0 8bf149eb 
3fffff80: 4026e632 3fffdab0 00000000 3fffdcb0 
3fffff90: 3fff03e0 3fffdad0 3fff20dc 40233ece 
3fffffa0: 40000f49 3fffdab0 ffffff01 40000f49 
<<<stack<<<

EEPROM space available: 0x036b bytes

Flash CRC OK
Firmware Version: 1.6.0

> [-2072140619] HomeKit: [Client 1073705188] Got characteristic 1.12 change event
>>> [-2072139704] RATGDO: Current Door State changing from 2 to 0
>>> [-2072138109] RATGDO: Obstruction Detected
>>> [-2072138109] HomeKit: [Client 1073705188] Got characteristic 1.13 change event
>>> [-2072137200] RATGDO: Obstruction Clear
>>> [-2072137200] HomeKit: [Client 1073705188] Got characteristic 1.13 change event
>>> [-2072136289] HomeKit: [Client 1073705188] Get Characteristics
!!! [-2072134480] HomeKit: [Client 1073705188] socket.write, data_size=23, write_size=7
>>> [-2072134478] HomeKit: [Client 1073705188] Disconnected!
>>> [-2072134477] HomeKit: [Client 1073705188] Closing client connection
>>> [-2072132353] RATGDO: reader completed packet
>>> [-2072132352] RATGDO: DECODED  000020F2 0000000213D6990C 0000F085
>>> [-2072132351] RATGDO: PACKET(0xD6990C @ 0x20F2) Motion - NoData: [Zero: 0x00000000, Parity: 0xF]
>>> [-2072132344] RATGDO: Motion Detected
>>> [-2072132338] RATGDO: ENCODING 00002B43 00000000001D2539 00000080
>>> [-2072132304] RATGDO: writing 11076 to file rolling
>>> [-2072132238] RATGDO: reader completed packet
>>> [-2072132237] RATGDO: DECODED  000062CB 00000040BB99C0D6 0260C181
>>> [-2072132236] RATGDO: PACKET(0x99C0D6 @ 0x62CB) Status - Status: [DoorState Open, Parity 0xC, Obs 1, Lock 0, Light 1]
>>> [-2072132227] RATGDO: tgt 0 curr 0
>>> [-2072127388] RATGDO: reader completed packet
>>> [-2072127388] RATGDO: DECODED  000020F2 0000000213D6990C 0000F085
>>> [-2072127387] RATGDO: PACKET(0xD6990C @ 0x20F2) Motion - NoData: [Zero: 0x00000000, Parity: 0xF]
>>> [-2072127380] RATGDO: Motion Detected
>>> [-2072127374] RATGDO: ENCODING 00002B44 00000000001D2539 00000080
>>> [-2072127275] RATGDO: reader completed packet
>>> [-2072127275] RATGDO: DECODED  000062CB 00000040BB99C0D6 0260C181
>>> [-2072127274] RATGDO: PACKET(0x99C0D6 @ 0x62CB) Status - Status: [DoorState Open, Parity 0xC, Obs 1, Lock 0, Light 1]
>>> [-2072127265] RATGDO: tgt 0 curr 0
>>> [-2072122375] RATGDO: Motion Cleared
dkerr64 commented 4 months ago

Stack trace decodes as...

Exception Cause: 4 [Level1Interrupt: Level-1 interrupt as indicated by set level-1 bits in the INTERRUPT register]

0x402687de: pm_send_nullfunc at ??:?
0x40107a4e: ?? ??:0
0x4026a08c: ppRecycleRxPkt at ??:?
0x402685f4: pm_keep_active_enable at ??:?
0x4026e5ed: ets_timer_handler_isr at ??:?
0x4026e632: ets_timer_handler_isr at ??:?
0x40233ece: loop_task(ETSEventTag*) at core_esp8266_main.cpp:?
0x40000f49: ?? ??:0
0x40000f49: ?? ??:0
dkerr64 commented 4 months ago

And it's interesting that the timestamp is negative. Looking at log.h I see we are using format specifier of %7d which is signed integer type. millis() is returning unsigned long, so we should change the format specifier to %7lu

dkerr64 commented 4 months ago

I've not seen this crash before. The log suggests that the HomeKit hub is somehow disconnected, and we have seen crashes when events occur and the ratgdo server tries to notify the hub when there is no connection to HomeKit. So perhaps that is the reason.

dkerr64 commented 4 months ago

And it's interesting that the timestamp is negative. Looking at log.h I see we are using format specifier of %7d which is signed integer type. millis() is returning unsigned long, so we should change the format specifier to %7lu

Just opened PR #216 which includes this fix.

We also need to update Arduino HomeKit server logging to unsigned long as well. I have done this in the log_char_update branch, but we need to decide when to merge that to main and update our platform.ini to point to it.

dkerr64 commented 3 months ago

Implemented in v1.7