Limit Plugin Logging

Posted on
Thu Jan 03, 2019 8:46 pm
DaveL17 offline
User avatar
Posts: 6743
Joined: Aug 20, 2013
Location: Chicago, IL, USA

Limit Plugin Logging

I'm on a jag to improve logging within my plugins.

Now, regardless of the logging level set with:

Code: Select all
self.indigo_log_handler.setLevel(debug_level)
all calls to self.logger.xxxxxx are written to the log file at 'com.plugin.indigoPlugin.whatever'. If I want to optimize logging to the plugin's log file -- that is, only write to the log file when it's actually needed -- the only way I've found to do that is conditional evaluation:

Code: Select all
debug_level = int(self.pluginPrefs.get('debugLevel', '30'))

if debug_level <= 20:
    self.logger.debug('foo')
or
Code: Select all
verbose_logging = self.pluginPrefs.get('verboseLogging', False)

if verbose_logging:
    self.logger.debug('foo')
Under normal operation, there's plenty of stuff that doesn't need to be logged (like valuesDicts and whatnot) that I might want to invoke under certain conditions. I guess the best way to describe what I'm after is to have the plugin log handler work the same way as the Indigo Event log handler--in other words, it would be like taking the Indigo Event log and filtering for only my plugin's messages (then, I could use threaddebug to write messages that only the plugin log file would get.) Does that make sense?

Is there a better mousetrap?

I came here to drink milk and kick ass....and I've just finished my milk.

[My Plugins] - [My Forums]

Posted on
Thu Jan 03, 2019 10:58 pm
kw123 offline
User avatar
Posts: 8333
Joined: May 12, 2013
Location: Dallas, TX

Re: Limit Plugin Logging

I am trying to have 3 dimensions in logging

1. Severity : info, warning error critical.
2. area : eg comm, logic, update .. etc what every your plugin does
3. reports: nicely formatted data print outs. Created when requested by user

For info, warning, error, reports... I like to have different formats
Error, critical should get the full treatment
Timestamp, method, line number, message
Info... does not need the items

It looks as if the current logger only allows one format at a time for each log file.

Question. Could we get some examples from the gurus how to do some of these things like in the sdk for other functions

That would help me

Currently I am doing this “manually” in my own logger methods .. but I can not get the method included in the message automatically. Rest is ok

Would like to switch but I have >> 3000 lines of logging across my plugins ...changing everything manually is not an option.

Karl






Sent from my iPhone using Tapatalk

Posted on
Fri Jan 04, 2019 10:23 am
RogueProeliator offline
User avatar
Posts: 2501
Joined: Nov 13, 2012
Location: Baton Rouge, LA

Re: Limit Plugin Logging

Is there a better mousetrap?

I think there are multiple ways of doing this, but I wouldn't put the conditional in there... I'm almost positive that the only things written to the "private" log that you reference are done because they meet the logging level threshold of threaddebug (Jay posted somewhere the value of it, I can't find it off hand). Instead of using those helper functions, you can use the generic .log() call for sending messages. It requires passing in the level as the first argument.

SO, if you have a variable that is already storing the logging level set by the user, just pass that in to the log function. If you want to log super-debug stuff only sometimes, set the variable to a value that won't be caught by the thread debug level. When the enhanced logging is turned on by the user, simply update that class/global/whatever variable and when the .log() gets called it will magically match and be logged.

At least, that is my understanding -- Jay or other Python experts can jump in if I got any of that wrong.

Adam

Posted on
Fri Jan 04, 2019 11:46 am
kw123 offline
User avatar
Posts: 8333
Joined: May 12, 2013
Location: Dallas, TX

Re: Limit Plugin Logging

yes the


Code: Select all
logformat = logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-12s\t%(name)s.%(funcName)-25s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S')
self.plugin_file_handler.setFormatter(logformat)
self.mylogger = logging.getLogger("Plugin") 
self.mylogger.setLevel(logging.THREADDEBUG)
self.mylogger.log(50,"---text-50--")
self.mylogger.log(10,"---text-10--")

prints :

2019-01-04 11:41:13.044   CRITICAL       Plugin.startup                    -- text 50 --
2019-01-04 11:41:13.044   DEBUG          Plugin.startup                    -- text 10 --
to the private logfile

now I like to change the format for different logging levels, info and critical don't need the same detailed info ..

==> how to use >1 format for the same logger for different levels
or how do i define another logger that points to the same file?


Karl

ps

sys._getframe(1).f_code.co_name
returns the name of the calling function. -- one of my issues.

Posted on
Fri Jan 04, 2019 12:38 pm
DaveL17 offline
User avatar
Posts: 6743
Joined: Aug 20, 2013
Location: Chicago, IL, USA

Re: Limit Plugin Logging

RogueProeliator wrote:
I'm almost positive that the only things written to the "private" log that you reference are done because they meet the logging level threshold of threaddebug (Jay posted somewhere the value of it, I can't find it off hand).

You're the second person to say that. Maybe I'm initiating the logging helper functions improperly.

With the following in __init__:
Code: Select all
        # ========================= Initialize Logger =========================
        self.plugin_file_handler.setFormatter(logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-10s\t%(name)s.%(funcName)-28s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S'))
        self.debug      = True
        self.debugLevel = int(self.pluginPrefs.get('showDebugLevel', '30'))  # plugin pref set to 30
        self.indigo_log_handler.setLevel(self.debugLevel)
        self.logger.debug('Foo')

I get this in the personal log file (I like that name):
Code: Select all
2019-01-04 12:29:07.437   DEBUG        Plugin.__init__                     Foo


With this (leaves out self.debug):
Code: Select all
        # ========================= Initialize Logger =========================
        self.plugin_file_handler.setFormatter(logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-10s\t%(name)s.%(funcName)-28s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S'))
        # self.debug      = True
        self.debugLevel = int(self.pluginPrefs.get('showDebugLevel', '30'))  # again, 30
        self.indigo_log_handler.setLevel(self.debugLevel)
        self.logger.debug('Foo')

I get this in the personal log file:
Code: Select all
2019-01-04 12:31:54.246   DEBUG        Plugin.__init__                     Foo

And with a pause:
Code: Select all
        # ========================= Initialize Logger =========================
        self.plugin_file_handler.setFormatter(logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-10s\t%(name)s.%(funcName)-28s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S'))
        # self.debug      = True
        self.debugLevel = int(self.pluginPrefs.get('showDebugLevel', '30'))
        self.indigo_log_handler.setLevel(self.debugLevel)
        self.sleep(5)
        self.logger.debug('Foo')

I get:
Code: Select all
2019-01-04 12:31:54.246   DEBUG        Plugin.__init__                     Foo

What am I not seeing?

I came here to drink milk and kick ass....and I've just finished my milk.

[My Plugins] - [My Forums]

Posted on
Fri Jan 04, 2019 12:43 pm
DaveL17 offline
User avatar
Posts: 6743
Joined: Aug 20, 2013
Location: Chicago, IL, USA

Re: Limit Plugin Logging

Reread your note:
I'm almost positive that the only things written to the "private" log that you reference are done because they meet the logging level threshold of threaddebug (Jay posted somewhere the value of it, I can't find it off hand).

I think that might be my disconnect.

If everything that meets the level of threaddebug will be posted to the private log file -- regardless of the plugin debug level (options are 10-50) -- then that's consistent with what I'm seeing.

I came here to drink milk and kick ass....and I've just finished my milk.

[My Plugins] - [My Forums]

Posted on
Fri Jan 04, 2019 1:07 pm
kw123 offline
User avatar
Posts: 8333
Joined: May 12, 2013
Location: Dallas, TX

Re: Limit Plugin Logging

this seems to work = create 2. stream into the plugin logger file "Library/Application Support/Perceptive Automation/Indigo 7.2/Logs/<<pluginid>>/plugin.log"

Code: Select all
      logformatERROR = logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-12s\t%(name)s.%(funcName)-25s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S')
      logformatINFO  = logging.Formatter('%(asctime)s    %(msg)s', datefmt='%Y-%m-%d %H:%M:%S')

      self.plugin_file_handler.setFormatter(logformatERROR)
      self.methodTracer = logging.getLogger("Plugin") 
      self.methodTracer.setLevel(logging.THREADDEBUG)
      self.methodTracer.threaddebug(u"CLASS: Plugin")
      self.methodTracer.info(u"startup  .... ")
      self.methodTracer.log(50,u" -- text 50 -- ")
      self.methodTracer.log(10,u" -- text 10 -- ")

      self.myLogger = logging.getLogger()
      fh = logging.FileHandler(self.PluginLogFile, 'a')
      fh.setFormatter(logformatINFO)
      self.myLogger.addHandler(fh)
      self.myLogger.setLevel(logging.WARNING)
      self.myLogger.log(10," myLogger 10")
      self.myLogger.log(20," myLogger 20")
      self.myLogger.log(30," myLogger 30")
      self.myLogger.log(40," myLogger 40")
      self.myLogger.log(50," myLogger 50")
does:
Code: Select all
2019-01-04 13:05:53.548   THREADDEBUG    Plugin.startup                   CLASS: Plugin
2019-01-04 13:05:53.548   INFO           Plugin.startup                   startup  ....
2019-01-04 13:05:53.548   CRITICAL       Plugin.startup                    -- text 50 --
2019-01-04 13:05:53.548   DEBUG          Plugin.startup                    -- text 10 --
2019-01-04 13:05:53     myLogger 30
2019-01-04 13:05:53     myLogger 40
2019-01-04 13:05:53     myLogger 50


independently of the indigo plugin logger, but puts the lines into the indigo plugin logfile

Posted on
Fri Jan 04, 2019 1:31 pm
RogueProeliator offline
User avatar
Posts: 2501
Joined: Nov 13, 2012
Location: Baton Rouge, LA

Re: Limit Plugin Logging

If everything that meets the level of threaddebug will be posted to the private log file -- regardless of the plugin debug level (options are 10-50) -- then that's consistent with what I'm seeing.

It looks like the following property is being set:
logging.THREADDEBUG = 5

So that is capturing all logging with a level above 5. All of your calls are using logger.debug() which is logging at a level of 10 I believe.

Try:
Code: Select all
self.logger.log(4, u'Test... should not capture anywhere!')
self.logger.log(5, u'Captured only in private plugin log')
self.logger.log(10, u'Captured to indigo log if you set the logging level to 10, but not if set to INFO (20)')

Note that here you are setting the log handler of the Indigo Log, but not the one that goes to the private plugin log:
Code: Select all
self.indigo_log_handler.setLevel(self.debugLevel)

To set the level for the plugin-specific log (not sure why you would want to, but can...)
Code: Select all
self.plugin_file_handler.setLevel(logging.DEBUG)


Does that make more sense?
Adam

Posted on
Fri Jan 04, 2019 2:22 pm
DaveL17 offline
User avatar
Posts: 6743
Joined: Aug 20, 2013
Location: Chicago, IL, USA

Re: Limit Plugin Logging

Does that make more sense?

Crystal. Thanks Adam!

I'm not in a position to test at the moment, but I *think* you've given me my answer.

Code: Select all
def closedPrefsConfigUi(self, valuesDict, userCancelled):
    if self.pluginPrefs['verbose']:
        self.plugin_file_handler.setLevel(logging.THREADDEBUG)
    else:
        self.plugin_file_handler.setLevel(logging.DEBUG)

    # will only be written to private log if self.pluginPrefs['verbose'] is set to True
    self.logger.threaddebug(u"pluginPrefs = {0}".format(dict(valuesDict)))

I came here to drink milk and kick ass....and I've just finished my milk.

[My Plugins] - [My Forums]

Posted on
Fri Jan 04, 2019 2:30 pm
jay (support) offline
Site Admin
User avatar
Posts: 18200
Joined: Mar 19, 2008
Location: Austin, Texas

Re: Limit Plugin Logging

Here are some clarifications (which may or may not have been mentioned in the thread above:

  • self.debugLevel isn't implemented so has no effect on logging (all levels should be set either on the logger itself or the handler)
  • Levels cascade - so if you set self.logger to a higher level, nothing will get down to the handler. The handler is the more granular place to set levels.
  • self.indigo_log_handler is the handler that directs to the Event Log window and is set by default to INFO
  • setting self.debug is just a shortcut for setting the indigo_log_handler to DEBUG (I wouldn't use it or self.debugLog since those were just there to help convert from the old logging)
  • self.logger.debug, self.logger.warn, self.logger.info aren't Indigo shortcuts, they are implemented in the logger module itself so there's really no advantage to using the raw self.logger.log command with the level as the first parameter (IMO) .
  • logger.THREADDEBUG = 5 # this is the default level for self.logger and self.plugin_file_handler
  • I added self.logger.threaddebug as a shortcut synonymous to the ones built into the logger module if you're using the defined logger.THREADDEBUG level.
  • THREADDEBUG was added because I thought that it would be nice to have an even deeper debug option for multi-threaded plugins where you might not want to see detailed debugging from threads but debugging from other areas.

Any other questions I missed?

Jay (Indigo Support)
Twitter | Facebook | LinkedIn

Posted on
Fri Jan 04, 2019 5:18 pm
DaveL17 offline
User avatar
Posts: 6743
Joined: Aug 20, 2013
Location: Chicago, IL, USA

Re: Limit Plugin Logging

Thanks Jay. Nothing for me. You also cleared up a couple other things for me too, so thanks for that.

For the future, this seems to work well for my use case:

Code: Select all
    def __init__(self, pluginId, pluginDisplayName, pluginVersion, pluginPrefs):

       # ========================= Initialize Logger =========================
        self.plugin_file_handler.setFormatter(logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-10s\t%(name)s.%(funcName)-28s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S'))
        self.debug_level = int(self.pluginPrefs.get('showDebugLevel', '30'))
        self.indigo_log_handler.setLevel(self.debug_level)
        self.plugin_file_handler.setLevel(10)

    def closedPrefsConfigUi(self, valuesDict, userCancelled):

        if valuesDict['verbose']:
            self.plugin_file_handler.setLevel(5)
        else:
            self.plugin_file_handler.setLevel(10)

        return True

    self.logger.threaddebug(u"Foo")  # will only log to the private log file if valuesDict['verbose'] is True


I came here to drink milk and kick ass....and I've just finished my milk.

[My Plugins] - [My Forums]

Posted on
Sun Jan 06, 2019 2:34 pm
jay (support) offline
Site Admin
User avatar
Posts: 18200
Joined: Mar 19, 2008
Location: Austin, Texas

Re: Limit Plugin Logging

FYI, using the constants (logging.DEBUG, logging.INFO, etc.) is more future proof since those constants are defined in the python logging module. And we'll make sure that logging.THREADDEBUG always works in the context of a plugin as well. And, at least to me, it's clearer to read than the raw numbers that they represent.

Jay (Indigo Support)
Twitter | Facebook | LinkedIn

Posted on
Tue Sep 10, 2019 3:11 am
berkinet offline
User avatar
Posts: 3290
Joined: Nov 18, 2008
Location: Berkeley, CA, USA & Mougins, France

Re: Limit Plugin Logging

DaveL17 wrote:
...
Code: Select all
      # ========================= Initialize Logger =========================
        self.plugin_file_handler.setFormatter(logging.Formatter('%(asctime)s.%(msecs)03d\t%(levelname)-10s\t%(name)s.%(funcName)-28s %(msg)s', datefmt='%Y-%m-%d %H:%M:%S'))
...

I have been working on getting my logging better organized and trying to get up to date with recent, and not so recent, changes in Indigo logging support. In the past, I have used this little snippet to allow me to easily add debugging type logging to a plugin:
Code: Select all
func = inspect.stack()[0][3]
      self.logger.debug(u"%s: called for: %s, %s, %s." % (func, typeId, devId, valuesDict))
Which produces something like:
Code: Select all
MyPlugin           somePluginMethod: myPluginDeviceType, 123456, ...
Looking at your post above, it seemed I could define a format string for messages sent to the server log but with only a subset of the elements you are using in a log file. Indeed:
Code: Select all
self.indigo_log_handler.setFormatter(logging.Formatter('%(funcName)s: %(msg)s'))
does what I wanted. The only problem is, this formats all log messages in this manner and I just wanted to format debugging messages. At the moment I am unable to wrap my feeble brain around how to do that. Any brilliant suggestions would be most welcome.

Posted on
Tue Sep 10, 2019 6:04 am
DaveL17 offline
User avatar
Posts: 6743
Joined: Aug 20, 2013
Location: Chicago, IL, USA

Re: Limit Plugin Logging

I'm not 100% sure I understand, but let's try. :D

As you found, you can set the logging format handler anytime you want. If it were me, I think I'd set the initial logging formatter in __init__ and then I'd wrap the rest of my logging in a method and call that as needed..

Code: Select all
self.log_me(error_state=False, level=20, msg="something important")

Then you could select the proper logging formatter in the call to the method by setting error_state. Based on my very quick tests, this will adjust the output to the private debug log, but leave Indigo's Event Log unchanged.

Is that even close?

I do something similar when I pass log messages between threads or subprocesses and the main Plugin class. I throw everything in a dict, put the dict in the queue, and do the logging from the Plugin class.

I came here to drink milk and kick ass....and I've just finished my milk.

[My Plugins] - [My Forums]

Posted on
Tue Sep 10, 2019 6:31 am
berkinet offline
User avatar
Posts: 3290
Joined: Nov 18, 2008
Location: Berkeley, CA, USA & Mougins, France

Re: Limit Plugin Logging

DaveL17 wrote:
I'm not 100% sure I understand, but let's try. :D ...

Hmmm. Let me try again. As you note, I can set the format handler in __INIT__ to
Code: Select all
self.indigo_log_handler.setFormatter(logging.Formatter('%(funcName)s: %(msg)s'))
Now, later on I have two log messages
Code: Select all
self.logger.info(u"Something very normal happened to {}'.format(dev.name))
self.logger.debug(u"Here is the complete device {}".format(dev))
I would like the debug message to follow the format set in __INIT__ but I want the info message to be printed exactly as coded. I.e. no formatting. BTW, I am not, yet, interested in writing to the private log file, just Indigo's log.
Last edited by berkinet on Tue Sep 10, 2019 6:56 am, edited 1 time in total.

Who is online

Users browsing this forum: No registered users and 1 guest