Better logging

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

Home assistant still logs in docker.

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.

4 Likes

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.

3 Likes

Great idea !!! Do we have any idea if this has any chance to get implemented ?

1 Like

Until the feature request is implemented there is an alternative to persist logs.
Home Assistant running in Docker makes use of the journald log driver, which means that all the Home Assistant STDOUT and STDERR output ends up in the system journal. From here rsyslog puts it in the different log files, e.g. /var/log/syslog, userlog etc. as defined in the rsyslog rules. These logs are rotated and zipped.
You can change the existing rules, and also add your own rules to e.g. put all messages received from Docker in a separate file:

$template dockerlogs,"/var/log/dockerlog"
if $syslogfacility-text == ["docker"] then -?dockerlogs

But I have a request for the opposite, namely to reduce logging. Currently Home Assistant, and in particular hassio_supervisor and hassio_audio, outputs a lot of debug statements that have no meaning, even more so if your system is stable. The Home Assistant logger filter works great for “core”, but not for these components.
Cherry on the cake is that these debug statements are all logged as errors, which means that it’s also not possible to filter them out in journald or rsyslog.

1 Like

The person that decided clearing all the logs upon reboot should find another job / hobby.
Devs keep telling us to upload log files when explaining that your system crashed. Otherwise they’re unwilling to help. But it is exactly in that situation home assistant nukes the logs, and we cannot upload the logs.

Why on earth is it not renaming all previous logs to something.log.old or similar upon reboot (possibly deleting something.log.old first)? I have 10+ years of experience with software development and server monitoring. My home assistant keep crashing every now and then and I have no way to troubleshoot it. I have never seen a system with this terrible logging setup.

Secondly, having the SSH-access only available as a web interface is a terrible option. Because exactly when one would like to use SSH to go into the system and inspect log files and/or do some analysis when the system is unresponsive; then the web interface is… well… unresponsive and there is no way to use SSH. If the system IS responsive and working, then we don’t need a hardcore SSH connection. Did someone have bad luck when thinking here as well? :slight_smile:

4 Likes

Easy to criticize folks who mostly do this in their spare time.

Maybe put your hand up to fix?

2 Likes

To be fair many SD card setups run out of disk space and I can understand to an extent why they don’t save too much by default.

But take the kodi approach and save the current log AND the one before. Or automate it (theres an idea!) Then at least you get to copy the older one off to pastebin or another computer.

SSH is not just available as a web service. I regularly ssh in from my linux box. Use the ssh and web terminal addon.

Yes, but it is not just criticism. It is constructive feedback of what to do instead to improve the product so that it becomes significantly better. It does not matter if they do it on their free time. I also do development on my free time and I always appreciate constructive feedback. It this case; a very obvious and low hanging fruit that makes the developers look really bad and ignorant if they don’t implement ASAP as many users obviously experience random crashes with no information.

Maybe if home assistant was not written in a language I am unfamiliar with. For someone that knows the language and product, it should not take more than 10 minutes to fix. To me it would take weeks just to find where to do the change.

1 Like

Plugins tend to not work when HA crashes. I want a native SSH server that starts and live independently from HA. If HA spawned it, it will most likely die with it. I will have a look next crash.

That is why I do a supervised install on debian :slight_smile:

I think the home assistant os should have this option natively (natively running an ssh server outside of the actual home assistant app), so that you don’t need to be a hacker. Or at least don’t clear the logs upon restart so that we less-hacky people can give them their logs when doing error reports.

1 Like

No it doesn’t. It carries on working. Also, not a plugin, an addon. I assume you have taken the advice to install the ssh & web terminal addon.

What are you talking about? I thought it was the ssh server you say died. Do you understand the difference between a server and a client?

I didn’t flag this post to moderators, but please mind your anger.

+1 for syslog support!

You must understand what I meant. Plugin or addon, server or client.

You have no idea if it carried on working or not as you did not inspect my instance when the HA service crashed.

Steps:

  1. Use your pc/mac to connect to home assistant running on a raspberry pi 4 on port 22 (using a client to connect to the server!).
  2. Works as expected.
  3. Wait a few days
  4. HA dies
  5. The whatever-you-call-it does not longer accept incoming requests on port 22 as it died with HA
  6. Restart by power-toggling the board physically
  7. No logs, as HA clear them upon reboot.
  8. Repeat.

I was asking for a real SSH server that is native to the OS and does not die with the main HA process.

… or make HA not clear the logs upon reboot so that I don’t have to do the SSH-thing when it crashes.

The ssh server addon does not die when the core docker container stops. I tried it before my last post.

Your setup does not appear to be the same as mine, or you stopping the core docker container is not the same thing as the crash I experience. Perhaps it is not the core docker container, perhaps it is the entire OS, or something else which is not equivalent to stopping the core docker container in a controlled manner (or is your home assistant crashing too?)

I don’t know what happens, as I am unable to investigate.

The SSH addon I use is:

This is how my Supervisor > System tab looks like:

All of this is running on a Raspberry Pi 4, and based on the above screenshot; neither CPU, RAM, or “disk” = memory card space is anywhere near any limits.

When running the top command in the terminal it is usually around 95% idle; and it is in a fan-cooled enclosure and the CPU temperature never exceeds 36*C; so no thermal throttling / emergency shutdowns to protect the hardware either. Besides; LED’s are not indicating any error on the pi board when the system crashes.

Possibly your SD card?

Well it works for a couple of days after reboot; including reading/writing from/to the SD card. So if it is the SD card it is at least mostly working. But that I guess goes for most of the hardware. If the memory or cpu or anything else is having hardware issues, it yet seems to be mostly working.

Are there any particular indications pointing towards the SD card? Is there a good way to test it command line from within the Home Assistant OS (e.g. by using ssh to connect to the board and run som fancy cd / && super-disk-checker --verify=true that comes from the OS out of the box or do I need to install something extra that can test/verify/rule out any issues with the SD card in a reliable way?