search

brchri / tesla-geogdo

A lightweight app that will operate your smart garage door openers (GDOs) based on the location of a defined tracker, automatically closing when you leave, and opening when you return. Supports multiple vehicles, trackers, geofence types, and smart GDO devices.
GNU General Public License v3.0
17 stars 1 forks source link

Action and state mismatch: #25

Closed ClosedBeans closed 2 weeks ago

ClosedBeans commented 2 weeks ago

Hi Team,

My ratgdo is not opening and closing garage door. Please see the log and configuration.

tesla-geogdo  | 08/24/2024 10:41:55.424 [ DBG ] Attempting to read config file: /app/config/config.yml
tesla-geogdo  | 08/24/2024 10:41:55.424 [ DBG ] Config file read successfully
tesla-geogdo  | 08/24/2024 10:41:55.425 [ DBG ] Unmarshaling yaml into config object
tesla-geogdo  | 08/24/2024 10:41:55.425 [ DBG ] Config yaml unmarshalled successfully
tesla-geogdo  | 08/24/2024 10:41:55.425 [ INF ] Config loaded successfully
tesla-geogdo  | 08/24/2024 10:41:55.426 [ DBG ] Checking garage door configs
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ] Setting MqttGdo MQTT Opts:
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  OrderMatters: false
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  KeepAlive: 30 seconds
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  PingTimeout: 10 seconds
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  AutoReconnect: true
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  Username: false (not set)
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  Password: false (not set)
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  ClientID: tesla-geogdo-ratgdo-opener
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  Protocol: TCP
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  UseTLS: false
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ]  Broker: tcp://192.168.10.150:1883
tesla-geogdo  | 08/24/2024 10:41:55.428 [ DBG ] Connecting to MqttGdo MQTT broker
tesla-geogdo  | 08/24/2024 10:41:55.430 [ INF ] ratgdo door opener connected to MQTT broker
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ] MQTT Broker Connected: true
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ] Subscribing to MqttGdo MQTT topic home/garage/ratgdo-41592/status/obstruction
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ] Subscribing to topic: home/garage/ratgdo-41592/status/obstruction
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ] Checking environment variables:
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]   DEBUG=true
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ] Setting MQTT Opts:
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  OrderMatters: false
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  KeepAlive: 30 seconds
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  PingTimeout: 10 seconds
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  AutoReconnect: true
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  Username: false (not set)
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  Password: false (not set)
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  ClientID: tesla-geogdo
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  Protocol: TCP
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  UseTLS: false
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ]  Broker: tcp://192.168.10.150:1883
tesla-geogdo  | 08/24/2024 10:41:55.430 [ DBG ] Connecting to MQTT broker
tesla-geogdo  | 08/24/2024 10:41:55.431 [ DBG ] Topic subscribed successfully: home/garage/ratgdo-41592/status/obstruction
tesla-geogdo  | 08/24/2024 10:41:55.431 [ DBG ] Subscribing to MqttGdo MQTT topic home/garage/ratgdo-41592/status/availability
tesla-geogdo  | 08/24/2024 10:41:55.431 [ DBG ] Subscribing to topic: home/garage/ratgdo-41592/status/availability
tesla-geogdo  | 08/24/2024 10:41:55.432 [ INF ] Connected to Teslamate MQTT broker
tesla-geogdo  | 08/24/2024 10:41:55.432 [ DBG ] MQTT Broker Connected: true
tesla-geogdo  | 08/24/2024 10:41:55.432 [ INF ] Subscribing to MQTT topics for tracker 1
tesla-geogdo  | 08/24/2024 10:41:55.432 [ DBG ] Subscribing to topic: teslamate/cars/1/location
tesla-geogdo  | 08/24/2024 10:41:55.433 [ DBG ] Topic subscribed successfully: teslamate/cars/1/location
tesla-geogdo  | 08/24/2024 10:41:55.433 [ INF ] Topics subscribed, listening for events...
tesla-geogdo  | 08/24/2024 10:41:55.477 [ DBG ] Received payload for complex topic teslamate/cars/1/location for tracker 1, payload:
tesla-geogdo  | {"latitude":xx.10564,"longitude":-xx.172601}
tesla-geogdo  | 08/24/2024 10:41:55.477 [ INF ] Attempting to close garage door for tracker 1 at lat xx.105640, long -xx.172601
tesla-geogdo  | 08/24/2024 10:41:55.477 [ WRN ] Action and state mismatch: garage state is not valid for executing requested action; current state: ; requested action: close
tesla-geogdo  | 08/24/2024 10:41:55.477 [ DBG ] Topic subscribed successfully: home/garage/ratgdo-41592/status/availability
tesla-geogdo  | 08/24/2024 10:41:55.477 [ DBG ] Subscribing to MqttGdo MQTT topic home/garage/ratgdo-41592/status/door
tesla-geogdo  | 08/24/2024 10:41:55.477 [ DBG ] Subscribing to topic: home/garage/ratgdo-41592/status/door
tesla-geogdo  | 08/24/2024 10:41:55.478 [ DBG ] Topic subscribed successfully: home/garage/ratgdo-41592/status/door
tesla-geogdo  | 08/24/2024 10:41:55.478 [ DBG ] MqttGdo topics subscribed, listening for events...

config:

image

image

brchri commented 2 weeks ago

It looks like these logs are just for startup, and what's happening is your tracker location is immediately being identified as "away from home" and trying to close the garage door before the garage door status topic is successfully subscribed to. This isn't necessarily bad on startup as it seems unlikely you care about immediately closing your garage when you start the application, but that's the only information that can really be gained from these logs.

It would be better if you started the application, and then either drove outside of your geofence and then back in (either waiting for your cooldown to expire or disabling the cooldown in your config), and then provided those logs. You could also simulate this by posting json payloads to your tracker location topic with simulated lat and lon values if you don't actually want to drive your car around. Either way, having some logs to look at other than the application startup logs would be more useful, as everything during the startup sequence looks fine.

ClosedBeans commented 2 weeks ago

I see lot of below in logs.

Received payload for complex topic teslamate/cars/1/location for tracker 1, payload:

brchri commented 2 weeks ago

There's nothing after the payload:? Can you connect to your MQTT broker with a tool like MQTT Explorer and confirm that there is non-empty data in that topic?

ClosedBeans commented 2 weeks ago

They have payload like this {"latitude":xx.001093,"longitude":-xx.161824}

I do not see any commands after received this payload.

image

image

brchri commented 2 weeks ago

Okay it looks like everything is working as expected, but there aren't any geofence crossing events being triggered. This likely points to a misconfigured geofence. Verify that the settings in your kml file create the polygonal geofence where and in the shape you'd expect, and confirm that the values you're seeing in the logs are moving in and out of that geofence. You can use a tool like geojson.io to assist with this, as it will let you upload your kml file, and then you can add individual points with the latitudes and longitudes your logs are generating to confirm if they're inside or outside of the geofence.

You can also simplify your test by using a circular geofence instead of a polygonal, as they are much easier to define. You just use a single latitude / longitude point and a distance radius, so the chances of misconfiguring are much smaller. Then if you're able to trigger your garage open and close events with that config, then it confirms that it's a misconfigured geofence and you can continue troubleshooting your polygonal geofence.

ClosedBeans commented 2 weeks ago

It is circular config.

If is always getting current state as empty

tesla-geogdo | 08/24/2024 23:33:18.673 [ WRN ] Action and state mismatch: garage state is not valid for executing requested action; current state: ; requested action: open

image

brchri commented 2 weeks ago

Okay great, getting geofence crossing events now. For the current state, I see from the initial logs that the current door status topic is home/garage/ratgdo-41592/status/door, can you confirm that's correct and that you can see data stored in that topic? Your earlier screenshot of the mqtt broker cut off the top-level of the status topic.

ClosedBeans commented 2 weeks ago

image

brchri commented 2 weeks ago

Strange, haven't seen this issue before. I'll have to add some more logging and have you pull a new image for testing to get more info. I'll let you know when I have a new image pushed up. Is this your first time using this or have you had this working in the past and something changed / broke recently?

ClosedBeans commented 2 weeks ago

Thank you. This is my first time setup.

brchri commented 2 weeks ago

Alright this image has additional logging, try that and let's see what we get. brchri/tesla-geogdo:add-mqtt-debug-logging

ClosedBeans commented 2 weeks ago

Surprisingly it is working with logs version.

brchri commented 2 weeks ago

Yes that is surprising, the only difference between the latest (or 2.2.1) tag and the one you just pulled is the 3 log lines...

ClosedBeans commented 2 weeks ago

Do you think it is timing issue?

And I see below strange situation in log. When I'm going away from home garage door was not closed instead it is showing requesting to open.

tesla-geogdo | 08/25/2024 14:49:03 [ WRN ] Action and state mismatch: garage state is not valid for executing requested action; current state: open; requested action: open

ClosedBeans commented 2 weeks ago

I got this issue again.

tesla-geogdo | 08/26/2024 18:36:02 [ WRN ] Action and state mismatch: garage state is not valid for executing requested action; current state: open; requested action: open

brchri commented 2 weeks ago

This happens when you're driving away from your home? Does it usually work as expected but sometimes this happens or is this what usually happens?

ClosedBeans commented 2 weeks ago

Yes. It is happening when I'm driving away from home. This is scenario:

brchri commented 2 weeks ago

Does it normally close as expected and this is a one-off, or is this always the behavior. Trying to narrow down the possibilities of bugs, misconfiguration, etc. Also are you still using a circular geofence or did you switch back to polygonal?

ClosedBeans commented 2 weeks ago

In normal scenario, It is working as expected. Polygon is not working so sticked to circular.

brchri commented 2 weeks ago

I just updated the image tagged with add-mqtt-debug-logging with some additional logging, please update your image and post debug logs the next time this happens.

ClosedBeans commented 2 weeks ago

I pulled the latest image and tried and able to replicate issue the same scenario.

please find attached logs. geogdo.log

brchri commented 2 weeks ago

There's some weirdness happening here:

tesla-geogdo  | 08/28/2024 12:41:07.480 [ DBG ] Tracker entered close geofence: Close Radius: 0.013; PreviousDistance: 2223.900867984944; CurrentDistance: 0.0025452630755786443
tesla-geogdo  | 08/28/2024 12:41:07.480 [ DBG ] Tracker entered open geofence: Open Radius: 0.035; PreviousDistance: 2223.900867984944; CurrentDistance: 0.0025452630755786443

It's showing you're going from less than 1 km away to over 2,000 km away and back again. You have the latitude and longitude values masked in the logs (understandable), but can you confirm for me that those numbers aren't changing wildly from line to line? I don't need specifics, just want to make sure things don't look wildly out of whack to validate the data integrity.

I also pushed an update to the image with a new log line to show the previous and current distances on every location update rather than just when a threshold crossing event is triggered to see if there's a pattern on the wild distance swings.

ClosedBeans commented 2 weeks ago 
tesla-geogdo  | 08/28/2024 14:52:03.929 [ DBG ] CircularGeofence Stats - PreviousDistance: 0.000000; CurrentDistance: 0.003858
tesla-geogdo  | 08/28/2024 15:16:34.594 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload opening
tesla-geogdo  | 08/28/2024 15:16:34.594 [ DBG ] Setting door status: opening
tesla-geogdo  | 08/28/2024 15:16:34.594 [ DBG ] Door status now set to: opening
tesla-geogdo  | 08/28/2024 15:16:46.743 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload open
tesla-geogdo  | 08/28/2024 15:16:46.743 [ DBG ] Setting door status: open
tesla-geogdo  | 08/28/2024 15:16:46.743 [ DBG ] Door status now set to: open
tesla-geogdo  | 08/28/2024 15:16:57.598 [ DBG ] Received payload for complex topic teslamate/cars/1/location for tracker 1, payload:
tesla-geogdo  | {
tesla-geogdo  |   "latitude": xx.105649,
tesla-geogdo  |   "longitude": -xx.172602
tesla-geogdo  | }
tesla-geogdo  | 08/28/2024 15:16:57.599 [ DBG ] CircularGeofence Stats - PreviousDistance: 0.003858; CurrentDistance: 2223.901758
tesla-geogdo  | 08/28/2024 15:16:57.599 [ DBG ] Tracker left close geofence: Close Radius: 0.013000
tesla-geogdo  | 08/28/2024 15:16:57.599 [ DBG ] Tracker left open geofence: Open Radius: 0.035000
tesla-geogdo  | 08/28/2024 15:16:57.599 [ INF ] Attempting to close garage door for tracker 1 at lat xx.105649, long -xx.172602
tesla-geogdo  | 08/28/2024 15:16:57.600 [ INF ] setting garage door close
tesla-geogdo  | 08/28/2024 15:16:57.600 [ DBG ] Reported MqttGdo availability: online
tesla-geogdo  | 08/28/2024 15:16:57.601 [ DBG ] Current opener state: open
tesla-geogdo  | 08/28/2024 15:16:58.601 [ DBG ] Current opener state: open
tesla-geogdo  | 08/28/2024 15:16:59.601 [ DBG ] Current opener state: open
tesla-geogdo  | 08/28/2024 15:16:59.674 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload closing
tesla-geogdo  | 08/28/2024 15:16:59.674 [ DBG ] Setting door status: closing
brchri commented 2 weeks ago

Okay looking at the wild swings in values, I'm guessing you're manually publishing MQTT payloads for testing, which is fine, but it explains the logs you posted earlier. Here's the sequence of events:

  1. Payload to pushed to far away location; should trigger close event; close event triggered successfully
  2. Door opened manually, not triggered by Tesla-GeoGDO, but likely but a manual button press on a remote
  3. Payload pushed to very near location; should trigger open event; receive WRN message that garage is already open and no action will be taken a. This makes sense since you opened the garage manually in step 2. When you pushed a payload to simulate returning home, the garage door would try to open but see that it already is open and therefore emit a WRN and take no action.

This is all correct behavior. Below are the logs that show the interesting events:

# event 1 - payload pushed to trigger garage close event, and garage successfully closed
tesla-geogdo  | 08/28/2024 12:37:33.435 [ DBG ] Tracker left close geofence: Close Radius: 0.013; PreviousDistance: 0.002712924583675342; CurrentDistance: 2223.900867984944
tesla-geogdo  | 08/28/2024 12:37:33.435 [ INF ] Attempting to close garage door for tracker 1 at lat xx.105641, long -xx.172610
tesla-geogdo  | 08/28/2024 12:37:33.435 [ INF ] setting garage door close
tesla-geogdo  | 08/28/2024 12:37:35.522 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload closing
tesla-geogdo  | 08/28/2024 12:37:35.522 [ DBG ] Setting door status: closing
tesla-geogdo  | 08/28/2024 12:37:35.522 [ DBG ] Door status now set to: closing
tesla-geogdo  | 08/28/2024 12:38:03.448 [ ERR ] unable to close garage door, possible reason: unknown; current state: closing
tesla-geogdo  | 08/28/2024 12:38:03.448 [ WRN ] No further attempts will be made
tesla-geogdo  | 08/28/2024 12:39:17.510 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload closed

# event 2 - garage manually opened by a remote button press, not opened by Tesla-GeoGDO
tesla-geogdo  | 08/28/2024 12:40:43.128 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload opening
tesla-geogdo  | 08/28/2024 12:40:43.128 [ DBG ] Setting door status: opening
tesla-geogdo  | 08/28/2024 12:40:43.128 [ DBG ] Door status now set to: opening
tesla-geogdo  | 08/28/2024 12:40:55.267 [ DBG ] Received message on topic home/garage/ratgdo-41592/status/door with payload open
tesla-geogdo  | 08/28/2024 12:40:55.267 [ DBG ] Setting door status: open
tesla-geogdo  | 08/28/2024 12:40:55.267 [ DBG ] Door status now set to: open

# event 3 - payload pushed to simulate return home event; garage should open; emits warning that it's already open (because of event 2)
tesla-geogdo  | 08/28/2024 12:41:07.480 [ DBG ] Tracker entered open geofence: Open Radius: 0.035; PreviousDistance: 2223.900867984944; CurrentDistance: 0.0025452630755786443
tesla-geogdo  | 08/28/2024 12:41:07.480 [ INF ] Attempting to open garage door for tracker 1 at lat xx.105641, long -xx.172614
tesla-geogdo  | 08/28/2024 12:41:07.480 [ WRN ] Action and state mismatch: garage state is not valid for executing requested action; current state: open; requested action: open
ClosedBeans commented 2 weeks ago

Correct. The normal driving scenarios working as expected. But not sure polygon is not working.

ClosedBeans commented 2 weeks ago

I see the polygon kml has wrong configuration. I have updated as per instructions. Now is working as expected.

THANKS for your quick responses and help.