Logbook exclude not working on automations

[ntompson]

Home Assistant release with the issue: v0.73.1

Last working Home Assistant release (if known): N/A

Operating environment (Hass.io/Docker/Windows/etc.): hass.io on RasPi 3

Component/platform: logbook / mqtt automation

Description of problem: I have discovered that excludes set up against the logbook appear not to be preventing some of my automations from creating logbook entries in the recorder database. I have a number of automations that fire frequently (every 5 seconds), and I think this is leading to poor performance in the recorder database.

As a side note, I recently tried moving to a mariadb based recorder database (using the mariadb add-on) to improve performance, but this does not seem to have helped: the logbook in the GUI always times out. History graphs also take a long time to render.

I have set up excludes in the logbook to prevent unnecessary noise in the recorder database for these automations, but a recent inspection of the recorder database suggests that the entries are appearing anyway.

So I suspect something is broken in home assistant - the logbook excludes appear not to be preventing my automations causing unwanted entries in the recorder database.

For background context, I am using an MQTT based automation to handle incoming measurements from 433 MHz sensors (power by current cost and weather by acurite). I have an SDR based receiver connected to a separate RasPi, which is running RTL_433; it publishes JSON based measurements to my MQTT broker. My automations in homeassistant intercept and split the MQTT measurements; I then have MQTT sensors configured to make measurements available to home assistant.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

recorder:
  db_url: mysql://hass:<password>@core-mariadb/homeassistant
  purge_keep_days: 1

# Enables support for tracking state changes over time
history:
  exclude:
    entities:
      - sensor.time_utc
      - sensor.time__date
      - sensor.date__time
      - sensor.time
      - sensor.date
      - sensor.weather_symbol
      - sensor.forecast_symbol
    domains:
      - group
      - automation

# View all events in a logbook
logbook:
  exclude:
    entities:
      - sensor.time_utc
      - sensor.time__date
      - sensor.date__time
      - sensor.time
      - sensor.date
      - sensor.weather_symbol
      - sensor.forecast_symbol
      - automation.433_mqtt_cc__hydroheat
      - automation.433_mqtt_cc__light__power
      - automation.433_mqtt_cc__solar
      - automation.433_mqtt_acurite__outside 
      - automation.433_mqtt_acurite__inside
      - automation.433_mqtt_acurite__5n1_49
      - automation.433_mqtt_acurite__5n1_56
    domains:
      - group

Relevant automations

- id: 433_repub_cc-hh
  alias: 433 MQTT CC - Hydroheat
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "CurrentCost TX" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.dev_id == 3690 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/cc-hh"
        payload_template: '{{ trigger.payload }}'

- id: 433_repub_cc-solar
  alias: 433 MQTT CC - Solar
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "CurrentCost TX" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.dev_id == 1458 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/cc-solar"
        payload_template: '{{ trigger.payload }}'

- id: 433_repub_cc-lp
  alias: 433 MQTT CC - Light & power
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "CurrentCost TX" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.dev_id == 77 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/cc-lp"
        payload_template: '{{ trigger.payload }}'

# acurite sensor - outside temperature and humidity sensor
# {"time" : "2018-06-26 18:18:08", "model" : "Acurite tower sensor", "id" : 9158, "status" : 68, "sensor_id" : 9158, "channel" : "A", "temperature_C" : 5.900, "humidity" : 85, "battery" : 0}
- id: 433_repub_acurite_outside
  alias: 433 MQTT Acurite - Outside
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "Acurite tower sensor" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.sensor_id == 9158 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/acurite-outside"
        payload_template: '{{ trigger.payload }}'

# acurite sensor - inside temperature and humidity sensor
# {"time" : "2018-06-26 18:18:10", "model" : "Acurite tower sensor", "id" : 8411, "status" : 68, "sensor_id" : 8411, "channel" : "B", "temperature_C" : 19.600, "humidity" : 51, "battery" : 0}
- id: 433_repub_acurite_inside
  alias: 433 MQTT Acurite - Inside
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "Acurite tower sensor" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.sensor_id == 8411 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/acurite-inside"
        payload_template: '{{ trigger.payload }}'

# acurite - 5n1 sensor - message 49
- id: 433_repub_acurite_5n1_49
  alias: 433 MQTT Acurite - 5n1_49
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "Acurite 5n1 sensor" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.message_type == 49 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/acurite-5n1-49"
        payload_template: '{{ trigger.payload }}'

# acurite - 5n1 sensor - message 56
- id: 433_repub_acurite_5n1_56
  alias: 433 MQTT Acurite - 5n1_56
  initial_state: True
  trigger:
    - platform: mqtt
      topic: 'RTL_433/JSON'
  condition: 
    condition: and
    conditions:
    - condition: template
      value_template: '{{ trigger.payload_json.model == "Acurite 5n1 sensor" }}'  
    - condition: template
      value_template: '{{ trigger.payload_json.message_type == 56 }}'
  action:
    - service: mqtt.publish
      data_template:
        topic: "hass/sensor/acurite-5n1-56"
        payload_template: '{{ trigger.payload }}'

Additional information: See attached recorder database query output

[mh-daedalus]

Have you tried excluding them using the id instead of the alias?

[point-4ward]

That screenshot isn't of your logbook, what does the logbook page look like?

[ntompson]

@mh-daedalus - that's an interesting point. I thought I was doing the right thing by using the alias, rather than the id, particularly as the alias name shows up in the recorder database. But I tried just now to use the id, and was met with errors:

core-ssh:~# hassio ha check
ERROR
Testing configuration at /config
Failed config
  logbook: 
    - Invalid config for [logbook]: Entity ID automation.433_repub_cc-hh is an invalid entity id for dictionary value @ data['logbook']['exclude']['entities']. Got ['sensor.time_utc', 'sensor.time__date', 'sensor.date__time', 'sensor.time', 'sensor.date', 'sensor.weather_symbol', 'sensor.forecast_symbol', 'automation.433_repub_cc-hh', 'automation.433_repub_cc-solar', 'automation.433_repub_cc-lp', 'automation.433_repub_acurite_outside', 'automation.433_repub_acurite_inside', 'automation.433_repub_acurite_5n1_49', 'automation.433_repub_acurite_5n1_56']. (See /config/configuration.yaml, line 76). Please check the docs at https://home-assistant.io/components/logbook/

@mf-social: you're right, that's not the logbook. But the logbook isn't much to look at - it always times out and I get the following.

[amelchio]

If you do not want events recorded, exclude them via the recorder configuration: https://www.home-assistant.io/components/recorder/#exclude

[point-4ward]

Ha, that'll teach me not to read the description properly.

As @amelchio says, you're complaining that they're not excluded from the recorder, but you're not excluding them from the recorder, you're excluding them from the logbook (hence why I was confused about the screenshot)

[ntompson]

OK thanks @amelchio - that might have been the trick. Seems a little odd that exclusions set against the logbook (as documented) do not prevent entries appearing in the logbook.

It will take a day or two before old data is flushed out of the recorder database to see whether this is what was causing the logbook to time out.

I remain a little surprised at the poor performance of the recorder database. The entries table contains about 600k rows; the states table about 270k rows. These don't strike me as crazy big numbers, particularly for maridadb, and yet the logbook times out and history_graphs are very slow. Am I expecting too much?

[amelchio]

"No logbook entries found.", how do you come to the conclusion that it does not exclude?

The logbook and history are just views. They transform the recorded data but they do not each record their own data. With a lot of data, those transformations are known to be slow – even if the underlying database is actually fairly fast.

One issue is that the logbook will load all potential events from the database and then drop the ones that you have excluded. This means that excluding from the logbook does not improve speed much but just makes the output more readable.

You are not expecting too much, this is indeed dissatisfying. I think it will be improved eventually even though nobody is working on it right now.

[point-4ward]

Seems a little odd that exclusions set against the logbook (as documented) do not prevent entries appearing in the logbook.

It does. They're not appearing in your logbook, your logbook is entry according to the screenshot you posted.

You seem to be confusing the logbook and the recorder. The recorder is the component that manages the database, the logbook is a part of the UI that shows events that have happened.

[ntompson]

Thanks - I was definitely confused - the documentation could be made a little clearer. So what I think I've learnt is that exclusions set against the logbook (and history) control what is retrieved from the recorder database, whereas exclusions set against the recorder control what is stored in the recorder database in the first place.

Note that, although I posted a screenshot of an empty logbook, this is a symptom of a logbook render timeout. Every once in a while (usually earlier in the day, presumably when there are fewer items), I do get a normal looking logbook. But the far more common case is a timeout, with an empty logbook shown. I know for certain the logbook is not empty, because there are entries in the events table with event_type set to logbook_entry.

I have now reconfigured as follows. In a day or two, I am hoping that the amount of noise in the logbook will make it more functional - I will report back then.

recorder:
  db_url: mysql://hass:<password>@core-mariadb/homeassistant
  purge_keep_days: 1
  exclude:
    entities:
      - sensor.time_utc
      - sensor.time__date
      - sensor.date__time
      - sensor.time
      - sensor.date
      - sensor.weather_symbol
      - sensor.forecast_symbol
      - automation.433_mqtt_cc__hydroheat
      - automation.433_mqtt_cc__light__power
      - automation.433_mqtt_cc__solar
      - automation.433_mqtt_acurite__outside 
      - automation.433_mqtt_acurite__inside
      - automation.433_mqtt_acurite__5n1_49
      - automation.433_mqtt_acurite__5n1_56
      - automation.weather_to_watch
      - binary_sensor.saturn
      - binary_sensor.calypso
      - binary_sensor.saturn_ipmi
    domains:
      - group
      - mqtt
      - rest_command

# Enables support for tracking state changes over time
history:
  exclude:
    domains:
      - automation

# View all events in a logbook
logbook:

One thing that still surprises me, though. Although setting exclusions as above has indeed prevented those items appearing as logbook_entry, they still appear with state_changed entries, which can't be helping poor performance. Is this expected? It seems a little redundant as there is a separate state table to track state.

[amelchio]

I do not see any state_changed events for entities that you have excluded. Which event_id are you thinking of?

About the documentation, feel free to submit improvements :)

[ntompson]

Argh - I'm going cross eyed looking... I should have said call_service entries for the mqtt domain. I think the original observation is relevant, though. It seems odd that call_service entries would appear for a domain that has been excluded from recorder.

Fair point on documentation - how do I do that?

[ntompson]

I am starting to see somewhat improved performance from the logbook in the GUI. I am starting to suspect that exclusions set against the logbook are computationally expensive - sufficient to cause timeouts in the GUI. I suspect that, if I only do exclusions against recorder, GUI performance is OK, but if I also have exclusions against logbook, performance falls apart.

Will comment when the recorder database has flushed out.

[amelchio]

All documentation pages have an "Edit this page on GitHub" link in the top right corner. This way you can edit the page and submit the changes as a Pull Request (PR) right in your browser.

You are right that call_service is not excluded. This would require extra code because its data structure is different (I am not saying that this code could not be written, just acknowledging that it does not exist today).

[balloobbot]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.

Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment :+1:

[balloobbot]

This issue will be auto-closed because there hasn't been any activity for a few months. Feel free to open a new one if you still experience this problem 👍