Improve logging/error handling

Feature Requests
1

Drastically improve logging/error handling. The current log messages are many times completely useless. Any message should have at a minimum:

  • the right level (currently some clear ERRORs are reported as DEBUG on INFO)
  • a clear reason (why that happened, what file, what line, what config statement, …)
  • a clear, actionable way to deal with it (how to fix it)

A few examples that were dismissed in other contexts, maybe this will get some attention instead of being instantly dismissed as irrelevant.

2020-10-28 11:59:23 ERROR (MainThread) [homeassistant.config] Invalid config for [automation]: not a valid value for dictionary value @ data['action'][2]['entity_id']. Got None. (See ?, line ?).

as a result, all automations are disabled. Absolutely no idea what do do about it, or where to look.

2020-09-26 10:11:12 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/template/template_entity.py", line 265, in _async_template_startup
    self.hass, template_var_tups, self._handle_results
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/event.py", line 792, in async_track_template_result
    tracker.async_setup()
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/event.py", line 518, in async_setup
    self._info[template] = template.async_render_to_info(variables)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/template.py", line 306, in async_render_to_info
    render_info._result = self.async_render(variables, **kwargs)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/template.py", line 285, in async_render
    return compiled.render(kwargs).strip()
  File "/srv/homeassistant/lib/python3.7/site-packages/jinja2/environment.py", line 1090, in render
    self.environment.handle_exception()
  File "/srv/homeassistant/lib/python3.7/site-packages/jinja2/environment.py", line 832, in handle_exception
    reraise(*rewrite_traceback_stack(source=source))
  File "/srv/homeassistant/lib/python3.7/site-packages/jinja2/_compat.py", line 28, in reraise
    raise value.with_traceback(tb)
  File "<template>", line 1, in top-level template code
ZeroDivisionError: 0.0 cannot be raised to a negative power

No idea where the error comes from. I don’t care about the backtrace in the core code, I care about the config that caused the error.

2020-09-24 20:32:38 WARNING (MainThread) [homeassistant.components.template.binary_sensor] The 'entity_id' option is deprecated, please remove it from your configuration

Where is this coming from? What config file? What line in that config?

Examples are too many to list here, it seems to be a systemic problem.

2

One more flagrant example:

2020-10-29 19:19:30 ERROR (MainThread) [homeassistant.config] Unknown error calling automation config validator
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/config.py", line 758, in async_process_component_config
    hass, config
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/automation/config.py", line 70, in async_validate_config
    for _, p_config in config_per_platform(config, DOMAIN)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/automation/config.py", line 49, in _try_async_validate_config_item
    config = await async_validate_config_item(hass, config, full_config)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/automation/config.py", line 25, in async_validate_config_item
    config = PLATFORM_SCHEMA(config)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/validators.py", line 208, in __call__
    return self._exec((Schema(val) for val in self.validators), v)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/validators.py", line 283, in _exec
    v = func(v)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 817, in validate_callable
    return schema(data)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 594, in validate_dict
    return base_validate(path, iteritems(data), out)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 386, in validate_mapping
    cval = cvalue(key_path, value)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/validators.py", line 205, in _run
    return self._exec(self._compiled, value, path)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/validators.py", line 285, in _exec
    v = func(path, v)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 635, in validate_sequence
    cval = validate(index_path, value)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 817, in validate_callable
    return schema(data)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/config_validation.py", line 882, in script_action
    return ACTION_TYPE_SCHEMAS[determine_script_action(value)](value)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/validators.py", line 205, in _run
    return self._exec(self._compiled, value, path)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/validators.py", line 250, in _exec
    return func(path, v)
  File "/srv/homeassistant/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 817, in validate_callable
    return schema(data)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/config_validation.py", line 793, in key_value_validator
    if key_value not in value_schemas:
TypeError: unhashable type: 'NodeListClass'
2020-10-29 19:19:30 ERROR (MainThread) [homeassistant.setup] Setup failed for automation: Invalid config.
3

I agree the logs really suck most times.

I believe this was a “month of WTH?” topic, too, and didn’t see any interest there. I doubt it will get much attention here either.

good luck tho.

and make sure you vote for your own feature requests. :slightly_smiling_face:

4

The tracebacks might be harder, as they come from somewhere outside of HA, but these:

should be possible to fix. The automation id or alias should be available when the error is generated, so it should be possible to add them to the error. I have tried to look in the code where they come from, and I believe this is a good start:

Did a quick test and added the following:

        _LOGGER.error(
            "Something is wrong in automation id: %s -- %s",
            config.get("id"),
            config.get("alias"),
        )

Before this line here:

And it gave me a nice

ERROR (MainThread) [homeassistant.components.automation.config] Something is wrong in automation id: 1661239687 -- New Automation 2

I’ll see if I can add a PR.