Tracing

Version 5.1 adds observability to your automations via tracing and log capturing. Each time the framework interacts with your automations, a trace is created. The framework keeps track of the 50 most recent traces per automation. They are visible by clicking a "Details" button on the dashboard.

Configuring Log Capturing

In addition to tracing when the framework calls your automations, you can also capture all calls to ILogger. HaKafkaNet uses NLog to aid in log capturing. To enable this feature add the following to your programs.cs.

builder.Host.UseNLog();

It is also recommended to configure NLog so that log tracing does not become too noisy. You can configure NLog programmatically if you choose. Please see NLog documentation for details.

You can use your appsettings.json to refine which logs you want captured.

...
  "NLog":{
    "rules":[
      {
        "logger": "Microsoft.*",
        "minLevel": "Warn",
        "finalMinLevel":"Warn"
      },
      {
        "logger": "System.Net.*",
        "minLevel": "Warn",
        "finalMinLevel":"Warn"
      },
      {
        "logger": "HaKafkaNet.*",
        "minLevel": "Debug",
        "finalMinLevel": "Debug"
      }
    ]
  },
...

What is captured

HaKafkaNet will capture any log from any ILogger instance based the filtering you provide as shown above. The framework includes the following logs:

• Debug - any calls to Home Assistant API.
• Warn - any response from Home Assistant API with a status code less than 200 or greater or equal to 400.
• Info - The result of ContinuesToBeTrue for delayable automations
• Debug - When delayable automations are scheduled
• Info - If a delayable automation was running and was canceled. Usually this is caused by ContinuesToBeTrue returning false thereby cancelling the run.
• Info - Items not found in cache when accessed via IHaEntityProvider
• Error - A framework call to your automation threw an exception.
• Info - State handler initialized

The framework will also add this automation information to the scope

• "automationKey" - AutomationMetaData.GivenKey
• "automationEventType" - Event Type e.g. Trigger or Delayed-Execution
• "automationEventTime" - Time the trace was started
• "autommationName" - AutomationMetaData.Name
• "automationType" - The type of your automation
• "haContextId" - * The Home Assistant context id for a state change
• "triggerEntityId" - * The entity's state change that triggered the automation

* only if the event type is "Trigger"

Example

This code was created for demonstration purposes only. It shows how different logs appear in the UI.

        reg.Register(_factory.SimpleAutomation(["input_button.test_button"],async (sc, ct) => {
            _logger.LogDebug("this is a debug {number}", 42);
            _logger.LogWarning("this is info at: {time}", DateTime.Now);
            try
            {
                int a = 1, b = 1;
                int c = a / (a - b);            
            }
            catch (System.Exception ex)
            {
                _logger.LogError(ex, ex.Message);
                _logger.LogCritical(ex, ex.Message);
            }
        }));

Given the code above, here is an example output. The first log details have been expanded.