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 ?