Better logging

Feature Requests
#1

Coming from the perspective of a long time linux user, I find logging in home assistant a bit in need of improvement. No criticism, I suspect the current system probably arose out of small SD card and not wanting to over fill the thing.

The problem I perceive is that the log disappears on each start of home assistant. So valuable information that might help debugging is lost.

Proposal 1

I propose that there be a user configurable number of logs to keep. On restart of home assistant the homeassistant.log is renamed to homeassistant.log.1, homeassistant.log.1 is renamed to homeassistant.log.2, and so on up to the maximum set in your configuration.

Optionally the older files could be zipped to save space.

logger:
  keep_max:
  zip:

Proposal 2

Include pastebinit by default in home assistant core images, and a service to use pastebinit to post your logs to a paste site and return a url to it. This can probably be done easily by a user via command_line.

Proposal 3

Proper logging over a network via syslog.

Now many people, including me, often say in response to requests like this “get coding” or “where is your PR?”. I am not a serious coder, but willing to help and test.

Save log files when restarting
How to redirect Home Assistant log from Docker to /var/log
#2

This :100:! I’d love a rolling log system like that.

#3

very true.
thanks for raising it.

from the perspective of a casual linux user and HA user not sure Proposal 2 would appeal to many (just a gut feeling) and Proposal 3 sounds a bit techy, don’t know what it means exactly.
Proposal 1 sounds reasonable, I’d add moving historic logs to <config>/logs folder (leaving the current one in <config> to avoid questions like “Where’s my log”?)
Actually, instead of number of logs number of days could be even better, especially in cases when one restarts HA frequently during testing or whatever else. And it should be even easier to code :wink:

#4

I’m starting hass in a venv with:

hass --log-rotate-days 4

(hass) homeassi:~$ hass --help
usage: hass [-h] [--version] [-c path_to_config_dir] [--safe-mode] [--debug]
            [--open-ui] [--skip-pip] [-v] [--pid-file path_to_pid_file]
            [--log-rotate-days LOG_ROTATE_DAYS] [--log-file LOG_FILE]
            [--log-no-color] [--runner] [--script ...] [--daemon]

Home Assistant: Observe, Control, Automate.

optional arguments:
  -h, --help            show this help message and exit
  --version             show program's version number and exit
  -c path_to_config_dir, --config path_to_config_dir
                        Directory that contains the Home Assistant
                        configuration
  --safe-mode           Start Home Assistant in safe mode
  --debug               Start Home Assistant in debug mode
  --open-ui             Open the webinterface in a browser
  --skip-pip            Skips pip install of required packages on startup
  -v, --verbose         Enable verbose logging to file.
  --pid-file path_to_pid_file
                        Path to PID file useful for running as daemon
  --log-rotate-days LOG_ROTATE_DAYS
                        Enables daily log rotation and keeps up to the
                        specified days
  --log-file LOG_FILE   Log file to write to. If not set, CONFIG/home-
                        assistant.log is used
  --log-no-color        Disable color logs
  --runner              On restart exit with code 100
  --script ...          Run one of the embedded scripts
  --daemon              Run Home Assistant as daemon
#5

I’m running what used to be Hass.io and I’m not sure if it’s possible to do something like that…

#6

In a docker and or k8s setup you do not want any file based logging but stdout and stderr logging.

#7

I’m running under venv on ubuntu 16.04 LTS, as a service

I get logging to home-assistant.log as per everyone else plus way more to /var/log/syslog (with the default logger: - nothing is set in configuration.yaml):

[email protected]:~$ grep hass /var/log/syslog|tail -10
Apr 12 10:57:38 JonLabNUC hass[21381]: 2020-04-12 10:57:38 INFO (MainThread) [homeassistant.components.mqtt] Updating component: sensor.motion_sensor_158d000221a1ad_battery
Apr 12 10:57:38 JonLabNUC hass[21381]: 2020-04-12 10:57:38 INFO (MainThread) [homeassistant.components.automation] battery_sensor_from_attributes: Executing step call service
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.automation] Executing battery_sensor_from_attributes
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.automation] battery_sensor_from_attributes: Running script
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.automation] battery_sensor_from_attributes: Executing step call service
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor plug_158d0002431039_battery, sending update
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.automation] battery_sensor_from_attributes: Executing step call service
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.mqtt] Got update for entity with hash: ('sensor', 'plug_158d0002431039_battery') '{'name': 'WashingMachine Battery', 'state_topic': 'homeassistant/sensor/plug_158d0002431039_battery/state', 'value_template': '{{ value_json.value | int }}', 'unit_of_measurement': '%', 'device_class': 'battery', 'unique_id': 'plug_158d0002431039_battery', 'json_attributes_topic': 'homeassistant/sensor/plug_158d0002431039_battery/attributes', 'platform': 'mqtt'}'
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.mqtt] Updating component: sensor.washingmachine_battery
Apr 12 10:57:40 JonLabNUC hass[21381]: 2020-04-12 10:57:40 INFO (MainThread) [homeassistant.components.automation] battery_sensor_from_attributes: Executing step call service
#8

in case of what used to be Hass.io that folder is empty anyway

#9

Well spotted. Of course as many people are running in docker this needs to be configurable in $CONFIG

#10

Home assistant still logs in docker.

#11

Create your own custom logs. You can log as much or little as you like. See here: https://www.home-assistant.io/integrations/file/

Here are some excerpts from my configs:
In Notify:

- platform: file
  name: hvaclog
  filename: hvaclog.csv
  timestamp: true
- platform: file
  name: eventlog
  filename: eventlog.csv
  timestamp: true

In an automation:

  action:
  - service: notify.hvaclog
    data_template: 
      message: "Automation - At {{now().strftime('%m/%d %H:%M:%S')}} <hvac_mode1_changed> triggered by {{ trigger.entity_id }}."

and in a script:

  - service: notify.hvaclog
    data_template: 
      message: >-
        Set - T-Stat1 set point now at {{ states.input_number.t1_set_point.state | int }} degrees by {{ states('input_text.hvac_trigger') }}.

Its incredibly easy to set up, completely controlled by you and can be toggled on/off with a simple input_boolean (assuming you place the notify_xxx AFTER the relevant code block.

Finally, here is a small bit of the data logged today:

Home Assistant notifications (Log started: 2020-04-08T14:34:51.008347+00:00)
--------------------------------------------------------------------------------
2020-04-12T04:00:05.016090+00:00 ================== 04/12/2020 ==================
2020-04-12T08:41:50.008183+00:00 Automation - At 04/12 04:41:50 <hvac_set_mode_2> triggered by sensor.tstat2_actual_temp to 77.
2020-04-12T08:41:50.026784+00:00 Automation - At 04/12 04:41:50 <hvac_mode2_changed> triggered by input_select.thermostat_mode_2.
2020-04-12T08:41:50.037949+00:00 Action - HVAC-2 Mode: Heat at 78.0℉
2020-04-12T08:41:50.047637+00:00 Script - At 04/12 04:41:50 <update_tstat_mode_2> started.
2020-04-12T08:41:51.230585+00:00 Automation - At 04/12 04:41:51 <hvac_set_mode_2> triggered by sensor.tstat2_currentsetpoint to 78.
2020-04-12T08:41:51.242928+00:00 Action - HVAC-2 Mode: Heat at 78.0℉
2020-04-12T08:41:56.006867+00:00 Set - T-Stat2 to heat mode by auto.hvac_set_mode_2.
2020-04-12T08:42:01.027156+00:00 Script - At 04/12 04:42:01 <update_tstat_temp_2> started.
2020-04-12T08:42:01.035220+00:00 Get - T2 set point was at 79.

For clarity I use a simple nomenclature scheme;
Automations are prefixed as Automation -
Triggered events in automations are prefixed as Action -
Script initiations are prefixed as Script -
and service actions are either Set - or Get -

Makes reading the log a bit easier to follow especially if there are built in Delays or Waits.
Each day it writes a new Day Header.

Hope this helps someone.

3 Likes
#12

This is a great idea. It’s so good that I independently suggested it here https://github.com/home-assistant/core/issues/43155#issuecomment-752305609 :grin: to try to solve a recent problem with HA regularly crashing but leaving no clue as to why. Surely a simple solution like the existing log is renamed HA.old.log and a new log is created for this new session should be easy to implement and prevent a lot of frustration when trying to diagnose the cause of crashes in Home Assistant.
Oh and I am talking about Home Assistant system logs, not the integrations log that kartcon is talking about above.

2 Likes