GDO light does not auto-off after close, and turns back on automatically after manually engaging switch

mgrimace commented 3 months ago

Hello, I'm on 1.6.1 and the following has been happening:

the actual garage door light is staying on indefinitely after an open/close cycle. Obstruction and Motion are both reading false (e.g., the motion isn't being triggered with the door closed).
If I turn the light off at the wall switch, it turns back on after a 10s count. Turning it off a second time seems to stay off.
the issue is not fixed with reboot
there are no crash logs in my homekit-ratgdo webui

dkerr64 commented 3 months ago

Weird. Are you Sec+ 2.0 or 1.0? And can you run the viewlog script to capture logs while this happens?

Thanks.

mgrimace commented 3 months ago

Sec+ 2.0. Ok, I captured the logs and it did do as I described above. For reference, when the log first says that the light is turned off, when I checked it was in fact still on. I turned the light off at the switch, came down and looked at the logs, went back up, and it was automatically turned back on again (roughly 20-30seconds):

Firmware Version: 1.6.1
Flash CRC: 0xFD684C66
Flash Length: 605440
Free heap: 19208
Max malloc size: 18216
Fragmentation pct: 6

GDO: get target door state: 1
>>> [7363585] RATGDO: get obstruction: 0
>>> [7363587] RATGDO: get current lock state: 0
>>> [7363588] RATGDO: get target lock state: 0
>>> [7363894] RATGDO: get light state: On
>>> [7365263] HomeKit: [Client 1073697220] Get Characteristics
>>> [7365552] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366600] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366719] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366738] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366807] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366830] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366860] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366909] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366926] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366945] HomeKit: [Client 1073697220] Update Characteristics
>>> [7366984] HomeKit: [Client 1073697220] Update Characteristics
>>> [7367011] HomeKit: [Client 1073697220] Get Characteristics
>>> [7367044] HomeKit: [Client 1073697220] Get Characteristics
>>> [7367138] HomeKit: [Client 1073697220] Get Characteristics
>>> [7367223] HomeKit: [Client 1073697220] Get Characteristics
>>> [7367273] HomeKit: [Client 1073697220] Get Characteristics
>>> [7367328] HomeKit: [Client 1073697220] Get Characteristics
>>> [7367533] HomeKit: [Client 1073697220] Get Characteristics
>>> [7368038] HomeKit: [Client 1073697220] Get Characteristics
>>> [7368888] HomeKit: [Client 1073697220] Get Characteristics
>>> [7368990] HomeKit: [Client 1073697220] Get Characteristics
>>> [7369093] HomeKit: [Client 1073697220] Get Characteristics
>>> [7382059] RATGDO: Client 192.168.68.50 requesting: /rest/events/subscribe (method: HTTP_GET)
>>> [7382060] RATGDO: SSE Subscription for client F7C9A95A-A0DB-4D11-9D47-0FCDB8300AB5 with IP 192.168.68.50: event bus location: /rest/events/0, Total subscribed: 1
>>> [7382707] RATGDO: Client 192.168.68.50 requesting: /showlog (method: HTTP_GET)
>>> [7383622] RATGDO: Client 192.168.68.50 listening for SSE events on channel 0
>>> [7392830] HomeKit: [Client 1073697220] Get Characteristics
>>> [7393226] RATGDO: get light state: On
>>> [7393361] HomeKit: [Client 1073697220] Update Characteristics
>>> [7393665] RATGDO: set light: On
>>> [7393968] RATGDO: Light already On
>>> [7395437] RATGDO: Minimum free heap dropped to 15656
>>> [7396437] RATGDO: Minimum free heap dropped to 14992
>>> [7398999] HomeKit: [Client 1073697220] Disconnected!
>>> [7399062] HomeKit: [Client 1073697220] Closing client connection
>>> [7401299] RATGDO: reader completed packet
>>> [7401431] RATGDO: DECODED  00001797 000000D20D00C8A0 01018280
>>> [7401734] RATGDO: PACKET(0xC8A0 @ 0x1797) DoorAction - DoorAction: [DoorAction Toggle, Pressed 1, Id 01]
>>> [7402128] RATGDO: Support for DoorAction packet unimplemented. Ignoring.
>>> [7403040] RATGDO: reader completed packet
>>> [7403584] RATGDO: DECODED  00001797 000000D20D00C8A0 01009280
>>> [7403887] RATGDO: PACKET(0xC8A0 @ 0x1797) DoorAction - DoorAction: [DoorAction Toggle, Pressed 0, Id 01]
>>> [7404189] RATGDO: Support for DoorAction packet unimplemented. Ignoring.
>>> [7405100] RATGDO: reader completed packet
>>> [7405321] RATGDO: DECODED  000107D7 000000706698400A 4260D481
>>> [7405332] RATGDO: PACKET(0x98400A @ 0x107D7) Status - Status: [DoorState Opening, Parity 0xD, Obs 1, Lock 0, Light 1]
>>> [7405340] RATGDO: tgt 0 curr 2
>>> [7405378] RATGDO: Current Door State changing from 1 to 2
>>> [7405403] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Opening", "upTime": 7405378 }
>>> [7406431] RATGDO: reader completed packet
>>> [7406509] RATGDO: DECODED  000107D7 000000726698400A 0000E084
>>> [7406811] RATGDO: PACKET(0x98400A @ 0x107D7) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7407113] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7408097] RATGDO: reader completed packet
>>> [7408400] RATGDO: DECODED  000107D7 000000726698400A 0000E084
>>> [7408790] RATGDO: PACKET(0x98400A @ 0x107D7) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7409302] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7409853] RATGDO: reader completed packet
>>> [7410155] RATGDO: DECODED  000107D7 000000726698400A 0000E084
>>> [7410457] RATGDO: PACKET(0x98400A @ 0x107D7) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7410759] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7412272] RATGDO: reader completed packet
>>> [7412575] RATGDO: DECODED  000107D7 000000726698400A 0000E084
>>> [7412877] RATGDO: PACKET(0x98400A @ 0x107D7) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7413012] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7413929] RATGDO: reader completed packet
>>> [7414224] RATGDO: DECODED  000107D8 000000706698400A 42608181
>>> [7414526] RATGDO: PACKET(0x98400A @ 0x107D8) Status - Status: [DoorState Open, Parity 0x8, Obs 1, Lock 0, Light 1]
>>> [7414623] RATGDO: tgt 0 curr 0
>>> [7414736] RATGDO: Current Door State changing from 2 to 0
>>> [7414804] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Open", "upTime": 7414736 }
>>> [7415039] RATGDO: reader completed packet
>>> [7415047] RATGDO: DECODED  00001798 000000D20D00C8A0 01018280
>>> [7415059] RATGDO: PACKET(0xC8A0 @ 0x1798) DoorAction - DoorAction: [DoorAction Toggle, Pressed 1, Id 01]
>>> [7415068] RATGDO: Support for DoorAction packet unimplemented. Ignoring.
>>> [7415138] RATGDO: reader completed packet
>>> [7415148] RATGDO: DECODED  00001798 000000D20D00C8A0 01009280
>>> [7415161] RATGDO: PACKET(0xC8A0 @ 0x1798) DoorAction - DoorAction: [DoorAction Toggle, Pressed 0, Id 01]
>>> [7415171] RATGDO: Support for DoorAction packet unimplemented. Ignoring.
>>> [7415326] RATGDO: reader completed packet
>>> [7415344] RATGDO: DECODED  000107D8 000000726698400A 0000E084
>>> [7415369] RATGDO: PACKET(0x98400A @ 0x107D8) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7415671] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7415761] RATGDO: reader completed packet
>>> [7416064] RATGDO: DECODED  000107D9 000000706698400A 4260C581
>>> [7416366] RATGDO: PACKET(0x98400A @ 0x107D9) Status - Status: [DoorState Closing, Parity 0xC, Obs 1, Lock 0, Light 1]
>>> [7416391] RATGDO: tgt 1 curr 3
>>> [7416401] RATGDO: Current Door State changing from 0 to 3
>>> [7416470] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Closing", "upTime": 7416400 }
>>> [7417929] RATGDO: reader completed packet
>>> [7417959] RATGDO: DECODED  000107D9 000000726698400A 0000E084
>>> [7417999] RATGDO: PACKET(0x98400A @ 0x107D9) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7418010] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7421873] RATGDO: reader completed packet
>>> [7422175] RATGDO: DECODED  000107D9 000000726698400A 0000E084
>>> [7422422] RATGDO: PACKET(0x98400A @ 0x107D9) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7422724] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7425020] RATGDO: reader completed packet
>>> [7425204] RATGDO: DECODED  000107D9 000000726698400A 0000E084
>>> [7425391] RATGDO: PACKET(0x98400A @ 0x107D9) MotorOn - NoData: [Zero: 0x00000000, Parity: 0xE]
>>> [7425499] RATGDO: Support for MotorOn packet unimplemented. Ignoring.
>>> [7426915] RATGDO: reader completed packet
>>> [7427134] RATGDO: DECODED  000107DA 000000706698400A 4260B281
>>> [7427437] RATGDO: PACKET(0x98400A @ 0x107DA) Status - Status: [DoorState Closed, Parity 0xB, Obs 1, Lock 0, Light 1]
>>> [7427666] RATGDO: tgt 1 curr 1
>>> [7427969] HomeKit: Got new client 1073697220: local 192.168.68.64:5556, remote 192.168.68.70:51492
>>> [7428346] HomeKit: Setting Timeout to 500ms
>>> [7428452] HomeKit: [Client 1073697220] Pair Verify Step 1/2
>>> [7429338] HomeKit: Free heap: 18936
>>> [7429486] RATGDO: Current Door State changing from 3 to 1
>>> [7429788] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "lastDoorUpdateAt": 0, "garageDoorState": "Closed", "upTime": 7429486 }
>>> [7431146] HomeKit: [Client 1073697220] Pair Verify Step 2/2
>>> [7431450] HomeKit: [Client 1073697220] Found pairing with B24B08D0-C5BC-40AD-809E-042145DE059F
>>> [7431942] HomeKit: [Client 1073697220] Verification successful, secure session established
>>> [7432245] HomeKit: Free heap: 15712
>>> [7432851] RATGDO: Minimum free heap dropped to 14504
>>> [7433595] RATGDO: Minimum free heap dropped to 14168
>>> [7433897] RATGDO: Maximum malloc block size dropped to 12872 (10% fragmented)
>>> [7435208] HomeKit: [Client 1073697220] Get Accessories
>>> [7435317] RATGDO: get active: 1
>>> [7435336] RATGDO: get current door state: 1
>>> [7435348] RATGDO: get target door state: 1
>>> [7435775] RATGDO: get obstruction: 0
>>> [7436078] RATGDO: get current lock state: 0
>>> [7436382] RATGDO: get target lock state: 0
>>> [7436988] RATGDO: get light state: On
>>> [7437283] RATGDO: Maximum malloc block size dropped to 11352 (33% fragmented)
>>> [7438267] HomeKit: [Client 1073697220] Get Characteristics
>>> [7438912] HomeKit: [Client 1073697220] Get Characteristics
>>> [7439027] HomeKit: [Client 1073697220] Update Characteristics
>>> [7439095] HomeKit: [Client 1073697220] Update Characteristics
>>> [7439125] HomeKit: [Client 1073697220] Update Characteristics
>>> [7439198] HomeKit: [Client 1073697220] Update Characteristics
>>> [7439230] HomeKit: [Client 1073697220] Update Characteristics
>>> [7439307] HomeKit: [Client 1073697220] Update Characteristics
>>> [7439340] HomeKit: [Client 1073697220] Update Characteristics
>>> [7441123] HomeKit: [Client 1073697220] Update Characteristics
>>> [7441928] HomeKit: [Client 1073697220] Update Characteristics
>>> [7444848] HomeKit: [Client 1073697220] Update Characteristics
>>> [7444944] HomeKit: [Client 1073697220] Update Characteristics
>>> [7444972] HomeKit: [Client 1073697220] Get Characteristics
>>> [7445064] HomeKit: [Client 1073697220] Get Characteristics
>>> [7445166] HomeKit: [Client 1073697220] Get Characteristics
>>> [7445250] HomeKit: [Client 1073697220] Get Characteristics
>>> [7445894] HomeKit: [Client 1073697220] Get Characteristics
>>> [7446476] HomeKit: [Client 1073697220] Get Characteristics
>>> [7446583] HomeKit: [Client 1073697220] Get Characteristics
>>> [7446696] HomeKit: [Client 1073697220] Get Characteristics
>>> [7446788] HomeKit: [Client 1073697220] Get Characteristics
>>> [7446899] HomeKit: [Client 1073697220] Get Characteristics
>>> [7446996] HomeKit: [Client 1073697220] Get Characteristics
>>> [7486096] HomeKit: [Client 1073697220] Get Characteristics
>>> [7486729] HomeKit: [Client 1073697220] Get Characteristics
>>> [7486747] RATGDO: get light state: On
>>> [7486834] HomeKit: [Client 1073697220] Update Characteristics
>>> [7486847] RATGDO: set light: On
>>> [7486894] RATGDO: Light already On
>>> [7520381] HomeKit: [Client 1073697220] Get Characteristics
>>> [7520441] RATGDO: get light state: On
>>> [7520519] HomeKit: [Client 1073697220] Update Characteristics
>>> [7520535] RATGDO: set light: On
>>> [7520565] RATGDO: Light already On
>>> [7545982] HomeKit: [Client 1073697220] Get Characteristics
>>> [7562735] HomeKit: [Client 1073697220] Get Characteristics
>>> [7562875] RATGDO: get light state: On
>>> [7563031] HomeKit: [Client 1073697220] Update Characteristics
>>> [7563126] RATGDO: set light: On
>>> [7563142] RATGDO: Light already On
>>> [7602849] HomeKit: [Client 1073697220] Get Characteristics
>>> [7603216] RATGDO: get light state: On
>>> [7603531] HomeKit: [Client 1073697220] Update Characteristics
>>> [7603776] RATGDO: set light: On
>>> [7603791] RATGDO: Light already On
>>> [7608175] HomeKit: [Client 1073697220] Get Characteristics
>>> [7669066] HomeKit: [Client 1073697220] Get Characteristics
>>> [7682277] HomeKit: [Client 1073697220] Get Characteristics
>>> [7682315] RATGDO: get light state: On
>>> [7682402] HomeKit: [Client 1073697220] Update Characteristics
>>> [7682431] RATGDO: set light: On
>>> [7682440] RATGDO: Light already On
>>> [7718466] RATGDO: reader completed packet
>>> [7718486] RATGDO: DECODED  000107DB 000000706698400A 40609281
>>> [7718567] RATGDO: PACKET(0x98400A @ 0x107DB) Status - Status: [DoorState Closed, Parity 0x9, Obs 1, Lock 0, Light 0]
>>> [7718581] RATGDO: tgt 1 curr 1
>>> [7718653] RATGDO: Light Status Off
>>> [7718666] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "garageLightOn": false, "upTime": 7718665 }
>>> [7726767] HomeKit: [Client 1073697220] Get Characteristics
>>> [7726845] RATGDO: get light state: Off
>>> [7726922] HomeKit: [Client 1073697220] Update Characteristics
>>> [7726958] RATGDO: set light: On
>>> [7727007] RATGDO: ENCODING 000006FF 00000002005E7539 00000181
>>> [7727073] RATGDO: ENCODING 00000700 00000000005E7539 00000080
>>> [7727252] RATGDO: reader completed packet
>>> [7727263] RATGDO: DECODED  000107DC 000000706698400A 4260B281
>>> [7727271] RATGDO: PACKET(0x98400A @ 0x107DC) Status - Status: [DoorState Closed, Parity 0xB, Obs 1, Lock 0, Light 1]
>>> [7727287] RATGDO: tgt 1 curr 1
>>> [7727307] RATGDO: Light Status On
>>> [7727330] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "garageLightOn": true, "upTime": 7727330 }
>>> [7730235] HomeKit: [Client 1073697220] Get Characteristics
>>> [7743757] RATGDO: reader completed packet
>>> [7743777] RATGDO: DECODED  00001799 000000D20D00C8A0 00009281
>>> [7743857] RATGDO: PACKET(0xC8A0 @ 0x1799) Light - Light: [LightState Toggle]
>>> [7743959] RATGDO: Light Cmd Off
>>> [7744128] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "garageLightOn": false, "upTime": 7744127 }
>>> [7744353] RATGDO: ENCODING 00000701 00000000005E7539 00000080
>>> [7744494] RATGDO: reader completed packet
>>> [7744516] RATGDO: DECODED  000107DD 000000706698400A 40609281
>>> [7744561] RATGDO: PACKET(0x98400A @ 0x107DD) Status - Status: [DoorState Closed, Parity 0x9, Obs 1, Lock 0, Light 0]
>>> [7744571] RATGDO: tgt 1 curr 1
>>> [7744585] RATGDO: reader completed packet
>>> [7744593] RATGDO: DECODED  000107DD 000000706698400A 40609281
>>> [7744637] RATGDO: PACKET(0x98400A @ 0x107DD) Status - Status: [DoorState Closed, Parity 0x9, Obs 1, Lock 0, Light 0]
>>> [7744668] RATGDO: tgt 1 curr 1
>>> [7790784] HomeKit: [Client 1073697220] Get Characteristics
>>> [7792725] HomeKit: [Client 1073697220] Get Characteristics
>>> [7792805] RATGDO: get light state: Off
>>> [7792887] HomeKit: [Client 1073697220] Update Characteristics
>>> [7792905] RATGDO: set light: On
>>> [7792933] RATGDO: ENCODING 00000702 00000002005E7539 00000181
>>> [7792995] RATGDO: ENCODING 00000703 00000000005E7539 00000080
>>> [7793172] RATGDO: reader completed packet
>>> [7793210] RATGDO: DECODED  000107DE 000000706698400A 4260B281
>>> [7793222] RATGDO: PACKET(0x98400A @ 0x107DE) Status - Status: [DoorState Closed, Parity 0xB, Obs 1, Lock 0, Light 1]
>>> [7793233] RATGDO: tgt 1 curr 1
>>> [7793277] RATGDO: Light Status On
>>> [7793300] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "garageLightOn": true, "upTime": 7793299 }
>>> [7793344] RATGDO: reader completed packet
>>> [7793647] RATGDO: DECODED  000107DE 000000706698400A 4260B281
>>> [7793837] RATGDO: PACKET(0x98400A @ 0x107DE) Status - Status: [DoorState Closed, Parity 0xB, Obs 1, Lock 0, Light 1]
>>> [7794140] RATGDO: tgt 1 curr 1

In case it isn't clear, here's exactly what I did:

open garage at switch
close garage at switch
wait 5 mins, until log says 'light off'
check, light is on
turn light off
wait 30 s
check, light is back on

dkerr64 commented 3 months ago

I will try and see if it does the same for me. In step 5, do you turn light off using ratgdo web page, apple home app, or wall panel?

Thanks

mgrimace commented 3 months ago

I will try and see if it does the same for me. In step 5, do you turn light off using ratgdo web page, apple home app, or wall panel?

Thanks

In Step 5 I turned off the light at the wall panel (nothing above is via siri or the webui). Now, checking again a few hours later the light is back on - I haven't touched anything.

dkerr64 commented 3 months ago

Do you have any homekit automations that could be influencing this?

I tested with my door and it worked as expected. Looking at your log I see quite a lot of communication with HomeKit and there are several places that HomeKit requests the status of the light, we return off (or sometimes on), and then HomeKit immediately comes back and asks to turn the light on.

>>> [7790784] HomeKit: [Client 1073697220] Get Characteristics
>>> [7792725] HomeKit: [Client 1073697220] Get Characteristics
>>> [7792805] RATGDO: get light state: Off
>>> [7792887] HomeKit: [Client 1073697220] Update Characteristics
>>> [7792905] RATGDO: set light: On

Here is the part of the log where the light turns off (after door close) and then 8 seconds later HomeKit requests status and then immediately does an Update request to turn the light on...

>>> [7718466] RATGDO: reader completed packet
>>> [7718486] RATGDO: DECODED  000107DB 000000706698400A 40609281
>>> [7718567] RATGDO: PACKET(0x98400A @ 0x107DB) Status - Status: [DoorState Closed, Parity 0x9, Obs 1, Lock 0, Light 0]
>>> [7718581] RATGDO: tgt 1 curr 1
>>> [7718653] RATGDO: Light Status Off
>>> [7718666] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "garageLightOn": false, "upTime": 7718665 }
*** Idle for ~8 seconds***
>>> [7726767] HomeKit: [Client 1073697220] Get Characteristics
>>> [7726845] RATGDO: get light state: Off
>>> [7726922] HomeKit: [Client 1073697220] Update Characteristics
>>> [7726958] RATGDO: set light: On
>>> [7727007] RATGDO: ENCODING 000006FF 00000002005E7539 00000181
>>> [7727073] RATGDO: ENCODING 00000700 00000000005E7539 00000080
>>> [7727252] RATGDO: reader completed packet
>>> [7727263] RATGDO: DECODED  000107DC 000000706698400A 4260B281
>>> [7727271] RATGDO: PACKET(0x98400A @ 0x107DC) Status - Status: [DoorState Closed, Parity 0xB, Obs 1, Lock 0, Light 1]
>>> [7727287] RATGDO: tgt 1 curr 1
>>> [7727307] RATGDO: Light Status On
>>> [7727330] RATGDO: SSE send to client 192.168.68.50 on channel 0, data: { "garageLightOn": true, "upTime": 7727330 }

So this looks to me like something inside HomeKit that is forcing the light on.

mgrimace commented 3 months ago

So this looks to me like something inside HomeKit that is forcing the light on.

I think that was it, we don't use automations but when I checked the home app it looks like one of the in-built ones was toggled on (turn on light when motion is detected at front entry). Odd, but it must be that. Thanks so much, and I'm glad it's not a bug or anything. My apologies for not thinking to check that before-hand, we honestly don't use too much other than 'hey siri'.

ratgdo / homekit-ratgdo

GDO light does not auto-off after close, and turns back on automatically after manually engaging switch #226