ERROR - Unable to execute action.devices.commands.OpenClose for BlindXXX. Already in state

Question

ERROR - Unable to execute action.devices.commands.OpenClose for BlindXXX. Already in state

sander1988 opened this issue 3 years ago · 4 comments

sander1988 commented 3 years ago

Describe the bug:
Google sometimes fails to open the roller shutters, it reports that it's already open or closed. Most of the time it works fine.

Expected behavior:
In the requests I see a "openPercent" of 80. I would not expect a value other than 0 or 100. As the device in Domoticz is just a Venetian Blinds EU (which only supports open/close/stop). In this case it tried to close the roller shutters.

Command used to open (Dutch):
'Hey Google, sluit de rolluiken in de [KAMER NAAM]'

This translates to: 'Hey Google, close the roller shutters in the [ROOM NAME]'.

Logs:

2022-03-04 15:00:18 - DEBUG - Host: xxxxxx
Connection: Keep-Alive
Accept-Encoding: gzip
X-Forwarded-For: xxxxxx
Content-Length: 122
X-Forwarded-Proto: https
Content-Type: application/json;charset=UTF-8
Google-Assistant-API-Version: v1
Authorization: Bearer xxxxxx
User-Agent: Mozilla/5.0 (compatible; Google-Cloud-Functions/2.1; +http://www.google.com/bot.html)


2022-03-04 15:00:18 - INFO - Request {
  "inputs": [
    {
      "intent": "action.devices.QUERY",
      "payload": {
        "devices": [
          {
            "id": "Blind395"
          }
        ]
      }
    }
  ],
  "requestId": "xxxxxx"
}
2022-03-04 15:00:18 - DEBUG - Starting new HTTPS connection (1): domoticz:8443
2022-03-04 15:00:18 - DEBUG - https://domoticz:8443 "GET /json.htm?type=devices&plan=0&filter=all&used=true HTTP/1.1" 200 1004
2022-03-04 15:00:18 - DEBUG - Starting new HTTPS connection (1): domoticz:8443
2022-03-04 15:00:18 - DEBUG - https://domoticz:8443 "GET /json.htm?type=plans&order=name&used=true HTTP/1.1" 200 321
2022-03-04 15:00:18 - DEBUG - {
  "Werkkamerlamp": {
    "idx": 233,
    "type": "Light",
    "state": "Off",
    "lastupdate": "2022-03-04 08:59:24",
    "willReportState": true
  }
}
2022-03-04 15:00:18 - DEBUG - Starting new HTTPS connection (1): domoticz:8443
2022-03-04 15:00:18 - DEBUG - https://domoticz:8443 "GET /json.htm?type=plans&order=name&used=true HTTP/1.1" 200 321
2022-03-04 15:00:18 - DEBUG - {
  "Werkkamer PIR": {
    "idx": 343,
    "type": "Sensor",
    "state": "Off",
    "lastupdate": "2022-03-04 14:59:58",
    "willReportState": true
  }
}
2022-03-04 15:00:18 - DEBUG - Starting new HTTPS connection (1): domoticz:8443
2022-03-04 15:00:18 - DEBUG - https://domoticz:8443 "GET /json.htm?type=plans&order=name&used=true HTTP/1.1" 200 321
2022-03-04 15:00:18 - DEBUG - {
  "LEDstrip bureau": {
    "idx": 347,
    "type": "ColorSwitch",
    "state": "Off",
    "lastupdate": "2022-03-03 19:01:44",
    "willReportState": true
  }
}
2022-03-04 15:00:18 - DEBUG - Starting new HTTPS connection (1): domoticz:8443
2022-03-04 15:00:18 - DEBUG - https://domoticz:8443 "GET /json.htm?type=plans&order=name&used=true HTTP/1.1" 200 321
2022-03-04 15:00:18 - DEBUG - {
  "Rolluik werkkamer": {
    "idx": 395,
    "type": "Blind",
    "state": "Open",
    "lastupdate": "2022-03-04 15:00:04",
    "willReportState": true
  }
}
2022-03-04 15:00:18 - INFO - Response {
  "devices": {
    "Blind395": {
      "descriptiveCapacityRemaining": "FULL",
      "isRunning": true,
      "online": true,
      "openPercent": 100
    }
  }
}
2022-03-04 15:00:19 - DEBUG - Starting new HTTPS connection (1): accounts.google.com:443
2022-03-04 15:00:19 - DEBUG - https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
2022-03-04 15:00:19 - DEBUG - Starting new HTTPS connection (1): homegraph.googleapis.com:443
2022-03-04 15:00:19 - DEBUG - https://homegraph.googleapis.com:443 "POST /v1/devices:reportStateAndNotification HTTP/1.1" 200 None
2022-03-04 15:00:19 - DEBUG - Device state reported {
  "agentUserId": "1234",
  "payload": {
    "devices": {
      "states": {
        "Blind395": {
          "descriptiveCapacityRemaining": "FULL",
          "isRunning": true,
          "online": true,
          "openPercent": 100
        }
      }
    }
  },
  "requestId": "xxxxxx"
}
2022-03-04 15:00:19 - DEBUG - Host: xxxxxx
Connection: Keep-Alive
Accept-Encoding: gzip
X-Forwarded-For: xxxxxx
Content-Length: 477
X-Forwarded-Proto: https
Content-Type: application/json;charset=UTF-8
Google-Assistant-API-Version: v1
Authorization: Bearer xxxxxx
User-Agent: Mozilla/5.0 (compatible; Google-Cloud-Functions/2.1; +http://www.google.com/bot.html)


2022-03-04 15:00:19 - INFO - Request {
  "inputs": [
    {
      "context": {
        "locale_country": "NL",
        "locale_language": "nl"
      },
      "intent": "action.devices.EXECUTE",
      "payload": {
        "commands": [
          {
            "devices": [
              {
                "id": "Blind395"
              }
            ],
            "execution": [
              {
                "command": "action.devices.commands.OpenClose",
                "params": {
                  "followUpToken": "xxxxxx",
                  "openPercent": 80
                }
              }
            ]
          }
        ]
      }
    }
  ],
  "requestId": "xxxxxx"
}
2022-03-04 15:00:19 - ERROR - Unable to execute action.devices.commands.OpenClose for Blind395. Already in state

Desktop (please complete the following information):

Domoticz version Stable 2020.2
Dzga version v1.10.9
Python Version 3.7.3

Smartphone (please complete the following information):

Device: Google Nest Mini

Additional context, screenshot:
None

Answer 1 · 2022-03-06T14:04:56.000Z

Seeing new logs the same issue today (now opening instead of closing) I no longer think it's related to the 'openPercent' value. It seems to be DZGA/Google getting out of sync with the Domoticz state.

It tried it several times: 'Hey Google, open the roller shutters' and it failed every time with:

2022-03-06 14:51:45 - INFO - Request {
  "inputs": [
    {
      "context": {
        "locale_country": "NL",
        "locale_language": "nl"
      },
      "intent": "action.devices.EXECUTE",
      "payload": {
        "commands": [
          {
            "devices": [
              {
                "id": "Blind395"
              }
            ],
            "execution": [
              {
                "command": "action.devices.commands.OpenClose",
                "params": {
                  "followUpToken": "xxxxxx",
                  "openPercent": 100
                }
              }
            ]
          }
        ]
      }
    }
  ],
  "requestId": "xxxxxx"
}
2022-03-06 14:51:45 - ERROR - Unable to execute action.devices.commands.OpenClose for Blind395. Already in state

I don't see API requests from DZGA to Domoticz querying for the current state of the roller shutters (full debugging is enabled). Shouldn't DZGA check the state?

It works again when I ask Google to check the state first: 'Hey Google, are the rollershutter opened?'. After that the open command works again.

Answer 2 · 2022-03-08T21:16:04.000Z

Found an earlier report. Used the fix: #236 (comment)

It happens when the shutter state is changed without DZGA (e.g. directly in Domoticz).

Is there a reason why DZGA is not periodically resyncing the state from Domoticz? That would probably prevent an issue for most cases. I can implement it if aren't any reasons against it.

Answer 3 · 2022-11-11T11:56:11.000Z

#285 You are welcome to help.

Answer 4 · 2022-12-13T06:42:11.000Z

Fixed in latest beta