Better Logging for AppDaemon Apps

As I briefly mentioned in my last post, IP Camera, Home Security and Automation Update, I’ve begun using the HomeAssistant project for home automation and also to act as the brain for my DIY alarm system. The logic behind some of this is somewhat complex, so rather than try to use HomeAssistant’s YAML-based automation configuration for all of it, I’ve implemented the alarm logic using AppDaemon. AppDaemon is a Python daemon that integrates with HomeAssistant’s API and message/event bus, and allows standalone Python classes (“apps”) to operate like HomeAssistant automations - be triggered by events or state change, access internal state and attributes, call services, and control anything that HomeAssistant can control. For someone with at least a basic working knowledge of Python, this makes it much easier to write complex conditional logic than attempting to use YAML.

However, when I wrote my first AppDaemon app, I was quite frustrated by the built-in logging system. The documentation explains that AppDaemon uses two log files by default, “general” and “error”, and that each AppDaemon app (subclass of appdaemon.plugins.hass.hassapi.Hass) can log to them using self.log() and self.error() convenience methods. So far this sounds fine. However, looking at the API documentation for these log() and error() methods, it becomes apparent that the only arguments they take are a string message and a log level that defaults to INFO. Unlike the ubiquitous logging methods of the Python standard library, they don’t accept a message with percent-formatting placeholders and a list of arguments, meaning that the message string needs to be formatted in the logging call itself.

Another annoyance is the fixed logging format that includes only the timestamp, log level, app name, and message; when I’m developing and debugging code I often find it useful to include at least the source module and line number in the log message. At first I tried to alter the logging formatter in use by AppDaemon, but that gave some strange results because it turns out that AppDaemon doesn’t actually use a logging format, but rather in the appdaemon.utils.log() function interpolates the timestamp, level and app name directly into the message and passes that to logging.

Furthermore, and even more bothersome during development, there’s no way to enable debug-level logging on a per-app basis. Logging level is controlled by a command line flag (-D) to appdaemon itself, which means that debug logging is all-or-nothing for both AppDaemon itself and all apps. I found a forum thread complaining about this and also a closed GitHub issue looking for a better solution.

So, I came up with my own solution to this in the form of my sane_app_logging.py module and the SaneAppLogging mixin class in it. All I need to do is add SaneAppLogging to the list of classes my app inherits from and add a call to self._setup_logging(self.__class__.__name__, False) at the beginning of the initialize() method. What this gets me is:

• self._log.(debug|info|warning|error|critical|log) methods that pass directly through to the standard library logging methods, including args and kwargs (and therefore support for log messages with percent-formatting of args).
• Log message formatting for all of AppDaemon that includes the filename, line number and function name ("[%(levelname)s %(filename)s:%(lineno)s - %(name)s.%(funcName)s() ] %(message)s"). A large portion of the code in my sane_app_logging.py module is dedicated to finding the proper stack frame so that source location is correct even with the wrapper in place.
• Runtime toggling of “debug-as-info” logging. To get around AppDaemon’s global log levels and the requirement of enabling debugging at AppDaemon start and for all running code, apps using SaneAppLogging listen for a LOGWRAPPER_SET_DEBUG event from HomeAssistant. When received this event toggles a specific app class to log all .debug() messages at INFO level instead, allowing me to selectively turn on and off debug logging on a single app at runtime.

The event payloads for debug-as-info toggling are quite simple, a dictionary with two keys: app_class and debug_value. app_class should be set to the name of the class (App) we want to change, and debug_value a boolean. When True, any messages logged via self._log.debug() will actually be logged via self._log.info().

So far this seems to be working quite well for me, and allowing me to have a much better experience with developing, debugging and testing AppDaemon apps. Perhaps it will be useful to someone else as well.