history_stats sensor displaying 'Unknown' after upgrading to 0.111.4

[joe248]

The problem

Upgraded from 0.109.6 to 0.111.4. I have a history_stats sensor that no longer works and just displays 'Unknown'.

Environment

arch | armv7l
dev | false
docker | false
hassio | false
installation_type | Home Assistant Core
os_name | Linux
os_version | 4.19.97-v7+
python_version | 3.7.3
timezone | America/Chicago
version | 0.111.4
virtualenv | true

database: postgres 11.7

• Home Assistant Core release with the issue: 0.111.0
• Last working Home Assistant Core release (if known): 0.110.7
• Operating environment (OS/Container/Supervised/Core): Core
• Integration causing this issue: history_stats
• Link to integration documentation on our website: https://www.home-assistant.io/integrations/history_stats/

Problem-relevant configuration.yaml

Config for the sensor that's NOT working:

sensor:
  - platform: history_stats
    name: HVAC On Last 24 Hrs Percentage
    entity_id: sensor.hvac_running
    state: 'on'
    type: ratio
    end: '{{ now() }}'
    duration:
      hours: 24
    scan_interval: 900

  - platform: template
    sensors:
      hvac_running:
        # Set to on if HVAC is running (cooling or heating); off otherwise
        friendly_name: "HVAC Running"
        value_template: "{% if is_state('sensor.kitchen_thermostat_hvac_state', 'off') %}off{% else %}on{% endif %}"

recorder:
  db_url: postgres://@/homeassistant
  auto_purge: False

I also have another very similar history_stats sensor that IS working. Here's that config:

sensor:
  - platform: history_stats
    name: Humidifier On Last 24 Hrs Percentage
    entity_id: binary_sensor.humidifier_state
    state: 'on'
    type: ratio
    end: '{{ now() }}'
    duration:
      hours: 24
    scan_interval: 900

binary_sensor:
  - platform: command_line
    name: 'Humidifier State'
    command: '/usr/bin/php /home/homeassistant/custom/sensors/humidifier_state_sensor.php'
    scan_interval: 300

[bdraco]

Tested ok on 0.112dev

Are there any errors in the log?

Is it possible for you to try the dev version?

[probot-home-assistant]

history_stats documentation
history_stats source
_{^{(message by IssueLinks)}}

[joe248]

There are no relevant errors in the log. I just updated to 0.112dev and still seeing the same thing. Is it possible to enable debug logging and / or see the query it's trying to run?

[bdraco]

You would need to modify recorder to echo and then use logger to put sqlalchemy in debug mode

diff --git a/homeassistant/components/recorder/__init__.py b/homeassistant/components/recorder/__init__.py
index fc3d9a5de8..8b13d4ae43 100644
--- a/homeassistant/components/recorder/__init__.py
+++ b/homeassistant/components/recorder/__init__.py
@@ -532,6 +532,7 @@ class Recorder(threading.Thread):
         if self.engine is not None:
             self.engine.dispose()
 
+        kwargs["echo"] = True
         self.engine = create_engine(self.db_url, **kwargs)
 
         sqlalchemy_event.listen(self.engine, "connect", setup_recorder_connection)

[joe248]

I enabled the logging, then rolled back to 0.109.6 and my sensor works again. Here's the two queries:

0.109.6:

2020-06-22 19:48:04 INFO (SyncWorker_12) [sqlalchemy.engine.base.Engine] SELECT states.state_id AS states_state_id, states.domain AS states_domain, states.entity_id AS states_entity_id, states.state AS states_state, states.attributes AS states_attributes, states.event_id AS states_event_id, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, states.created AS states_created, states.context_id AS states_context_id, states.context_user_id AS states_context_user_id
FROM states
WHERE states.last_updated >= %(last_updated_1)s AND states.last_updated < %(last_updated_2)s AND states.entity_id IN (%(entity_id_1)s) ORDER BY states.last_updated DESC
 LIMIT %(param_1)s
2020-06-22 19:48:04,149 INFO sqlalchemy.engine.base.Engine {'last_updated_1': datetime.datetime(2020, 6, 8, 22, 36, 42, 112327, tzinfo=psycopg2.tz.FixedOffsetTimezone(offset=-300, name=None)), 'last_updated_2': datetime.datetime(2020, 6, 22, 0, 48, 4, 14246, tzinfo=<UTC>), 'entity_id_1': 'sensor.hvac_running', 'param_1': 1}
2020-06-22 19:48:04 INFO (SyncWorker_12) [sqlalchemy.engine.base.Engine] {'last_updated_1': datetime.datetime(2020, 6, 8, 22, 36, 42, 112327, tzinfo=psycopg2.tz.FixedOffsetTimezone(offset=-300, name=None)), 'last_updated_2': datetime.datetime(2020, 6, 22, 0, 48, 4, 14246, tzinfo=<UTC>), 'entity_id_1': 'sensor.hvac_running', 'param_1': 1}

0.112dev:

2020-06-22 18:27:28,161 INFO sqlalchemy.engine.base.Engine SELECT states.domain AS states_domain, states.entity_id AS states_entity_id, states.state AS states_state, states.attributes AS states_attributes, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, states.created AS states_created, states.context_id AS states_context_id, states.context_user_id AS states_context_user_id
FROM states
WHERE states.last_changed = states.last_updated AND states.last_updated > %(last_updated_1)s AND states.last_updated < %(last_updated_2)s AND states.entity_id = %(entity_id_1)s ORDER BY states.entity_id, states.last_updated
2020-06-22 18:27:28,162 INFO sqlalchemy.engine.base.Engine {'last_updated_1': datetime.datetime(2020, 6, 21, 23, 27, 28, 122891, tzinfo=<UTC>), 'last_updated_2': datetime.datetime(2020, 6, 22, 23, 27, 28, 122891, tzinfo=<UTC>), 'entity_id_1': 'sensor.hvac_running'}

These are the differences I notice:

The new query has an additional clause: states.last_changed = states.last_updated
The new query has states.entity_id = instead of states.entity_id IN
The old query handles the timezone info for the second date parameter differently

[bdraco]

Could be caused by #35719

Also, minimal_responses was added in #35822 but history_stats shouldn't use them.

[joe248]

Is there anything else I can try or info I can provide to help debug this further?

[bdraco]

Can you try reverting #35719 on your instance and seeing if it fixes it?

[joe248]

I installed 0.110.7 and that was working. I then installed 0.111.0 and the issue was present, so it's something in the 0.111.0 changes. I reverted #35719 and that didn't fix the issue. Any other ideas?

[bdraco]

I installed 0.110.7 and that was working. I then installed 0.111.0 and the issue was present, so it's something in the 0.111.0 changes. I reverted #35719 and that didn't fix the issue. Any other ideas?

You'll have to wait 24 hours for a reversion of #35719 to have effect as it will need to generate new rows in the database

[joe248]

I've been running it with the reversion of #35719 for a few hours now. I changed my hvac_running sensor from 24 hours to 1 hour and it's still showing 'Unknown'.

[bdraco]

diff --git a/homeassistant/components/recorder/util.py b/homeassistant/components/recorder/util.py
index 883bc41e71..ae741fe7bd 100644
--- a/homeassistant/components/recorder/util.py
+++ b/homeassistant/components/recorder/util.py
@@ -59,6 +59,9 @@ def execute(qry, to_native=False, validate_entity_ids=True):
 
     This method also retries a few times in the case of stale connections.
     """
+    xstr = str(qry.statement.compile(compile_kwargs={"literal_binds": True}))
+    _LOGGER.warning("SQL Query: %s", xstr)
+
     for tryno in range(0, RETRIES):
         try:
             timer_start = time.perf_counter()

Please try the above change. This will give us raw sql queries that we can test with.

[bdraco]

Also, do you get results if you manually query the history api for sensor.hvac_running ?

https://developers.home-assistant.io/docs/api/rest/#get-apihistoryperiodtimestamp

[bdraco]

Also by chance, do you have hidden: True customized on sensor.hvac_running ?

[joe248]

Yes, I had the hvac_running sensor set to hidden under customize. I did some more testing and it appears that the state changes for that sensor are only being recorded when it's not hidden.

Here's the query output from the log:

SELECT states.state_id, states.domain, states.entity_id, states.state, states.attributes, states.event_id, states.last_changed, states.last_updated, states.created, states.context_id, states.context_user_id
FROM states
WHERE states.last_updated >= '2020-06-22 13:00:15.829401-05:00' AND states.last_updated < '2020-06-22 18:13:09.126232+00:00' AND states.entity_id IN ('sensor.hvac_running') ORDER BY states.last_updated DESC
 LIMIT 1

Using the API to fetch the data only returns data for the past hour or so, corresponding with when I had the sensor unhidden.

This is what the history data looks like for hvac_running sensor for the past 24 hours:

But it should look like this:

[joe248]

Actually, the query I just posted is probably not from the history_stats sensor because it's doing a LIMIT 1. I think this is the right query:

SELECT states.state_id, states.domain, states.entity_id, states.state, states.attributes, states.event_id, states.last_changed, states.last_updated, states.created, states.context_id, states.context_user_id
FROM states
WHERE states.last_changed = states.last_updated AND states.last_updated > '2020-06-22 18:13:09.126232+00:00' AND states.last_updated < '2020-06-23 18:13:09.126232+00:00' AND states.entity_id = 'sensor.hvac_running' ORDER BY states.entity_id, states.last_updated

[bdraco]

The Limit 1 is to get the initial state for the left side of the graph

[joe248]

So, if I use the API like this:

curl -k -X GET -H "Authorization: Bearer XXX" \
  -H "Content-Type: application/json" \
  https://XXX:8123/api/history/period/2020-06-22T14:00:00-05:00?filter_entity_id=sensor.hvac_running

I only get results from the past hour or so, corresponding with when I had the sensor unhidden.

If I run the above query in psql (modifying the time slightly):

SELECT states.state_id, states.domain, states.entity_id, states.state, states.attributes, states.event_id, states.last_changed, states.last_updated, states.created, states.context_id, states.context_user_id
FROM states
WHERE states.last_changed = states.last_updated AND states.last_updated > '2020-06-22 14:00:00-05:00' AND states.last_updated < '2020-06-23 14:00:00-05:00' AND states.entity_id = 'sensor.hvac_running' ORDER BY states.entity_id, states.last_updated

I get all of the state change results for the past 24 hours, including the period when the sensor was hidden. The attributes column for a hidden row looks like:
{"friendly_name": "HVAC Running", "hidden": true}
and for an unhidden row looks like:
{"friendly_name": "HVAC Running"}

So it appears that the state change data is being saved regardless of whether the sensor is hidden, but the history_stats sensor must be ignoring rows where the hidden attribute is set to true. Was that changed in 0.111 by design or is it a bug?

[bdraco]

The hidden check was added in #3674 for history and #3426 for logbook

When history was refactored in 0.111, some code was de-duplicated and the hidden check now works for all history apis.

We have a test to make sure history states with "hidden": True are skipped so this seems like it is working as designed.

Removing the hidden check would make things a bit faster. I'm not sure why it was added in the first place as currently only zone is using ATTR_HIDDEN which never change state from zoning and in datadog.

[bdraco]

It looks like ATTR_HIDDEN is going away anyways.

#32038 #31643 #31760 #30730 #30729 #30728 #30727

[joe248]

Ok, I guess I'll remove the hidden attribute then. Thank you for your help figuring this out!