===== Plugin Logging - How, When, Why =====
==== Plugin Specific Logging ====
Something that we started working on in more recent Indigo 6 releases is switching our logging over to the standard Python logging module (unfortunately, we introduced a few bumps that you guys had to deal with - sorry about that!) But, you guys are gonna love this! Your plugin will now inherit some new logging functionality including a plugin specific log file.
We highly recommend you read through the [[https://docs.python.org/2/howto/logging.html#logging-basic-tutorial|Python logging module basic tutorial]] to get a basic understanding of how logging works. We've done some work for you, in terms of setting up the logging, so once you're in your plugin's ''__init__()'' method, your logger and handlers are already to go.
Your plugin will inherit a property, self.logger, which is a standard Python logger object. You can use the standard logger module methods (''self.logger.debug()'', ''self.logger.info()'', etc) to write logging information. The logger is named "Plugin" (which we'll discuss more later), and has its debug level set to ''logging.THREADDEBUG'' (which is level 5, also discussed later). This means that the logger will pass all messages level 5 or higher to all of it's handlers.
The logger has two handlers associated with it: ''self.indigo_log_handler'', which emits log data to the Indigo Event Log. This handler basically mimics the ''indigo.server.log()'' method (and the ''self.debugLog()'', ''self.errorLog()'' methods defined in the plugin base - those are now just wrappers around the standard logging ''debug()'' and ''error()'' methods). The default level of this handler is logging.INFO - meaning only informational, warning, errors, and critical errors will get written to the Indigo Log. You can, of course, change the log level of this handler to ''logging.DEBUG'' (or any level you want). In fact, we've made some under the hood changes so that if you use the defacto ''self.debug'' property to control whether debug information is written to the Indigo Log, it will now actually change the log level for ''self.indigo_log_handler'' for you, so you really don't have to change anything about how you log there.
The other handler, ''self.plugin_file_handler'', emits log data to a log file that's specific to your plugin (located in ''/Library/Application Support/Perceptive Automation/Indigo 7/Logs/your.plugin.id/plugin.log''). This is a standard ''logging.handlers.TimedRotatingFileHandler'' which rotates at midnight. It keeps 5 days worth of log files and appends the date to the end of the file name when it rolls over to a new day. The default level of this handler is ''logging.THREADDEBUG'' (level 5), so pretty much everything that's logged will get logged there. The formatter for the handler is defined like this:
pfmt = logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)s\t%(name)s.%(funcName)s:\t%(message)s', datefmt='%Y-%m-%d %H:%M:%S')
so log lines will look something like this:
2022-06-06 10:44:49.227 THREADDEBUG Plugin.ssr.Receiver.run: collecting and splitting data
2022-06-06 10:44:49.231 THREADDEBUG Plugin.ssr.Receiver.run: found 1 messages
2022-06-06 10:44:49.231 THREADDEBUG Plugin.ssr.Receiver.run: messages found in stream: 1
2022-06-06 10:44:50.177 DEBUG Plugin._processMessage: _processMessage got a reply to message: 19
2022-06-06 10:44:50.177 DEBUG Plugin._processMessage: iTunesSubscribeDict new entries: {860050058: [288403608]}
2022-06-06 10:44:50.186 DEBUG Plugin._processMessage: expectedReplies dict: {288403608: {}}
The theory here being that you can write really detailed information into your log file without it cluttering up the Indigo Event Log. When a user is having an issue, you can instruct them to send you log files which you can then examine and more quickly find issues.
In the example above, you may notice a couple of interesting things: first, **THREADDEBUG** is listed as the level. We've added our own level to the existing python logging module levels. It's called ''logging.THREADDEBUG'' and it's level 5 (lower than DEBUG). When developing threaded applications, we've found that having a lower level specifier for debugging inside the threads made it easier for us to use the logging effectively. We also added a corresponding ''self.logger.threaddebug()'' convenience method call to make it easy to log at this level. Feel free to ignore it if you like and just use the standard levels or your own levels.
The next thing you may notice is there seem to be not only logged method calls that are defined in your plugin subclass, but there appear to be some kind of name spaced log entries (i.e. ''Plugin.ssr.Receiver.run''). As you may know from reading the logging docs, you can create a logging object that's a child of a parent logger. If your plugin defines some other modules, those modules can get a new logger that's a child of the "Plugin" logger that we create for you (for instance ''logging.getLogger("Plugin.somemodule.submodule"))''. All log messages from this logger will get propagated up to the parent "Plugin" logger (as the namespace implies, it's a child) and the parent will send them to all it's handlers. The benefit is that log file entries will now have much more explicit information about where the log entry came from. It also gives you a place to do other logging if you like: you can add another type of handler to your logger (maybe a network emitter or a separate file).
You are welcome, of course, to change the log format, level, etc., so that it works better for you if you like. You can add more handlers, remove handlers, alter them as you see fit. Python logging is fairly complex, but it's also extremely flexible so you should always be able to find the right configuration for your needs. We've added a new method that will return the path to the Logs directory so you can construct the path to your plugin-specific directory:
indigo.server.getLogsFolderPath()
You can pass it an optional pluginId argument to get the path to that specific plugin's log directory:
indigo.server.getLogsFolderPath(pluginId='some.plugin.id.here')
==== Best Practices ====
== Less is More ==
When you're first developing your plugin, you'll most likely be writing a lot of information to the Indigo Event Log. However, if you choose to release your plugin to world, you'll want to consider how much information users will want to see every day.
* **Logging Levels** -- Use logging levels with your users in mind.
* Debug - Be extremely careful with debug logging. Given the repetitive nature of how some plugins can be designed, these messages can add up quickly.
* Info - Consider logging to the info level only if the information is going to be useful for the user. Does your plugin need to log changes to every device state?
* Consider only logging when something expected *doesn't* happen rather than every time it does happen.
* Warning - Consider using the warning level for things that may resolve on their own. For example, when your plugin can't reach a website due to a temporary condition.
* Critical - Consider using the critical level for catastrophic exceptions and other major conditions that require intervention.
* **On Demand** -- Consider whether information can be logged only when circumstances require it. For example, rather than logging plugin data routinely, consider added a button or menu item to log this information only when you need it.
* **Log Choice** -- Consider where the logged information will be best stored.
* **Event Log** -- The Event log is the best place to log things that the user should see during normal plugin operations. Changes to key device states--like changes to an on/off state--would be appropriate. It would probably not be appropriate in most instances to log changes to all device states in the Event Log (this obviously isn't a hard and fast rule).
* **Plugin Log** -- The plugin log is the best place to log things that the user doesn't need to see when your plugin is operating normally. For example, logging API call parameters would not be suitable for the Event Log window (unless a problem condition exists). Method calls, plugin cycle timers, Indigo object dicts would all be more suitably sent to the Plugin Log.
The goal you should be striving for is to log only what's necessary, not what's possible. Fewer log messages generally equals a greater user experience.
== Getting the Current Logging Level ==
You may be tempted to track the current logging level (i.e., Info (20), Warning (30)...) within your plugin using a global variable like ''self.log_level'' or something similar. When the logging level is changed, you would update your global variable. It is better to check the current logging level by inspecting the logger instance rather than adjusting it to what you //think// the current level is. That way you'll always be sure.# Use
logger.level
# Instead of
self.log_level