Put "choose" selections into debug log mode instead of info

mk-maddin · January 21, 2022, 9:37am

When using choose condition within script or automation and having set the logging level to “inform” for that script or automation (or the whole component), every choose decision is printed out into the log.
For me as users this unfortunately leaves no space to write my own log messages via “system_log.write” service without:

a) seeing all details of choose decision stuff OR
b) having my informational messages appear within the “log popup box” at the top of the log page if I set them to “warning”/“error”/critical level" to overcome topic a)

With this reasoning would love to see the choose decision details as part of debug level instead of info level.

petro · January 21, 2022, 1:59pm

Why not just use the traces instead of the logs? It’s much easier to debug than staring at a flat log. Just my 2c

mk-maddin · January 21, 2022, 3:44pm

Thanks for the suggestion but as said I am doing INFO messages - not Debug messages…because I do not do debugging, I want to have Information within the log.
Thats why I say I am not interested into “Automation took path X here” message…because I did not set it to DEBUG

Furthermore traces are very limited in the time they stay available.
So it is highly probable that I will miss the piont in time the INFO message I would like to have is available within the trace

petro · January 21, 2022, 3:45pm

When I said debug, it had no relation to the level in the logs. The word debug has meaning to it

mk-maddin · January 21, 2022, 4:07pm

So maybe I have a wrong interpretation of what “DEBUG” means.

As I understand DEBUG means:
the process of identifying and removing errors from computer hardware or software.
That’s where I need the information about which path my script & atuomation took and which actions were performed and thats why the log level is called “DEBUG”…

While when I am having INFO level that from my point of view is for general informational messages to the user (of non high importance and non high detail).
But unfortunately as said for me as end user I do not see a place any more where to put these because as said “choose” seems to use them wrongly for its debugging purposes… (personal opinion)

Am I having a fully wrong understanding of the debugging level here?

petro · January 21, 2022, 4:11pm

Nevermind, you don’t understand what I said. I’m moving on. You keep going back to your problem when I was talking about approaching your problem a different way.

mk-maddin · January 21, 2022, 4:59pm

Yes it seems I do not fully understand.
But I am willing to learn so please try to explain?

parautenbach · January 21, 2022, 5:06pm

OP, do I understand you correctly? You don’t actually want to debug anything. You just don’t want log messages that you think should be debug-level messages logged when your log us set to info. In other words, choose is logged with info level instead of debug level.

mk-maddin · January 21, 2022, 5:13pm

exactly
THanks

parautenbach · January 25, 2022, 7:46pm

I scanned some of the code and couldn’t spot INFO level logging of the choose code (only warnings and errors). Do you have an example log message of concern?

petro · January 25, 2022, 7:50pm

github.com

home-assistant/core/blob/2e1ac711fb4d476a40a9fd0d26ecf2debe530d9c/homeassistant/helpers/script.py#L339

    
      
              # pylint: disable=protected-access
              return await self._script._async_get_condition(config)
          
          
def _log(
              self, msg: str, *args: Any, level: int = logging.INFO, **kwargs: Any
          ) -> None:
              self._script._log(  # pylint: disable=protected-access
                  msg, *args, level=level, **kwargs
              )
          
          
def _step_log(self, default_message, timeout=None):
              self._script.last_action = self._action.get(CONF_ALIAS, default_message)
              _timeout = (
                  "" if timeout is None else f" (timeout: {timedelta(seconds=timeout)})"
              )
              self._log("Executing step %s%s", self._script.last_action, _timeout)
          
          
async def async_run(self) -> None:
              """Run script."""
              try:
                  self._log("Running %s", self._script.running_description)

mk-maddin · January 25, 2022, 8:25pm

Thanks both for your investigations.

Here is an example automation where the behavior can be validated:

  - id: test_automation
    alias: test_automation
    description: 'Any test automation'
    mode: parallel
    trigger:
      - id: 'bool_on' 
        platform: state
        entity_id: input_boolean.test_input_boolean
        to: 'on'
    action:
      - service: logger.set_level
        data:
          homeassistant.components.automation.test_automation: info       
      - service: system_log.write
        data_template:
          message: "Main - started :)"
          logger: homeassistant.components.automation.test_automation
          level: info
      - variables:
          test: true
      - choose:
          - alias: "If test is true :)"
            conditions:
              - condition: template
                value_template: "{{ test }}"
            sequence:
              - service: system_log.write
                data_template:
                  message: "Test is true :)"
                  logger: homeassistant.components.automation.test_automation
                  level: info
        default:
          - service: system_log.write
            data_template:
              message: "Test is false :)"
              logger: homeassistant.components.automation.test_automation
              level: info                
      - service: system_log.write
        data_template:
          message: "Main - completed :)"                
          logger: homeassistant.components.automation.test_automation
          level: info

And here are the log entries created from it:

2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] test_automation: Executing step call service
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] Main - started :)
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] test_automation: Executing step setting variables
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] test_automation: Choose at step 4: If test is true :): Running automation actions
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] test_automation: Choose at step 4: If test is true :): Executing step call service
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] Test is true :)
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] test_automation: Executing step call service
2022-01-25 21:20:47 INFO (MainThread) [homeassistant.components.automation.test_automation] Main - completed :)

petro · January 26, 2022, 12:34pm

The code I linked is exactly what I thought you were talking about and unfortunately, it does not distinguish between action types. So it’s everything in DEBUG or INFO. Not to mention, a change like this is more “political” in nature, and the main dev’s would need to agree. I don’t think they will as the intention of printing aliases has always been to output them to INFO.

mk-maddin · January 26, 2022, 5:07pm

oh…ok so…wow
no alias - no INFO entry - the approach behind this does make sense to me.
I was not aware my entries are coming from the aliases…

so it seems this feature request is obsolete as if the approach is understood it makes absolutely sense and I have to agree with the developers