Conflict using python logger with indigo.server.log

I can't quite figure this out but it seems to be a conflict somewhere.
I have several remote MQTT devices which send logging information to my plugin. The plugin then writes these to separate log files for each device. Here's what I'm using for instantiating the loggers (looks basic):

Code: Select all

logger = logging.getLogger(u'mqtt_' + deviceName)
logger.setLevel(int(indigo.activePlugin.pluginPrefs["loggingLevel"]))
filename = u'%s.log' % (logger.name)
filePath = os.path.join(os.path.expanduser('~'), u'Library', u'Logs', filename)
handler = logging.handlers.TimedRotatingFileHandler(filePath, when=u'midnight', backupCount=7)
formatter = logging.Formatter(u'%(asctime)s \n%(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)


This is the code that does the actual logging:

Code: Select all

indigo.server.log(u"Writing to %s log" % (deviceName))
logger.log(logLevel, u"\n" + msg.payload)
indigo.server.log(u"Done Writing")


But, if my logLevel is 40 (Errors only), I get this in the indigo log:

--- BEGIN LOG SNIPPET
MQTT Writing to T1 log
MQTT Error
t.callback cnt=105
rcv_settings.update=15720
heap=18600
MQTT Done Writing
--- END LOG SNIPPET

There's other unexplained behaviors too. If I set my logging level to 10 then none of this is in indigo error red.
Any suggestions?

Does this post - Python logging used by Indigo - help explain the situation in your case

That explains there's a conflict but I can't understand.
It still logs to indigo regardless of the logging level - if it logs to file, it logs to indigo. (If I change level to DEBUG, it logs in indigo as green.)
Why is that propagating to indigo when I explicitly log to a specific file logger?

No I don't understand that either. I think Matt / Jay will have to explain it.

Looks like some Indigo 7 preparatory code is creeping into Indigo 6 - not sure that is a good idea as these problems seem to indicate.

[jay (support)]

So, when you call logger.getLogger() from python that's executed as part of a plugin, you're getting a logger that has some customizations that we've made and includes the Indigo handler that writes to the Indigo log. We did this for a variety of reasons, but since it's our first foray into using python logging, we're open to changing it.

Try this - assuming you're calling it from inside your plugin.py, I think it will remove the Indigo log handler from your logger:

Code: Select all

logger.handlers = [h for h in logger.handlers if h is not self.indigo_log_handler]

We were on the fence about automatically adding the Indigo log handler to the default logger. We thought the majority would want it for any logging (but we could be wrong). We'll reconsider how we do that in the future.

BTW, let me know if that works...

logger.handlers = [h for h in logger.handlers if h is not self.indigo_log_handler]

See my initialization in the first post. Where would I put that in my code? I don't understand.
I see this when I indigo.server.log((str(logger.handlers)). It's the only handler listed.

Code: Select all

May 5, 2016, 6:29:39 AM
  MQTT                [<logging.handlers.TimedRotatingFileHandler instance at 0x6934738>]

[jay (support)]

Hmmm. Ok, one thing I didn't ask: how are you running this Python? Is it in a plugin or in a script that's run from an Action?

[EDIT] Sorry, reread the first post again and it's a plugin. Let me do a little more investigation. Can you zip up your plugin and send it to me? support@indigodomo.com

As mentioned in the original post - it's a plugin. Keep in mind there are MQTT registered action call backs which occur outside any specific plug-in context See https://eclipse.org/paho/clients/python/ for more information.

I've been using this for months across different versions of Indigo which I usually update to latest (currently 6.1. - eight. Everything is fine except I'm tired of the Indigo logs getting flooded with things that should go to specific log files (each log file matching a remote MQTT device and I have many which is why the indigo logs are unweildy).

[jay (support)]

Yes, I added an edit shortly after the post. Please zip up the plugin and send it to me.

Please zip up the plugin and send it to me.

I can't do that because I am not the owner of all the code in the plugin. It wouldn't work anyway because it requires several other external pieces all communicating over TCP and the plugin would throw itself out of commission.

However, all the logging code referenced is shown in the original post.

The thing that might be a conflict with indigo is paho callbacks but just to test those require several components. (Though I can't understand why as I showed you I only have a single handler in the logging handlers list - see previous post).

[jay (support)]

Well, I can't guess without actually seeing all the code in context. If your logger only has the single handler, then it's beyond me how that stuff is getting into the Indigo log.

[matt (support)]

Are you sure that the getLogger you pasted on the original post is the only time getLogger is called? Based on the log, Indigo's handler is definitely being called but based on your result of the indigo.server.log((str(logger.handlers)) call its handler is in the list which doesn't make sense unless somewhere else someone is calling getLogger().

Are you sure that the getLogger you pasted on the original post is the only time getLogger is called?

Absolutely

Based on the log, Indigo's handler is definitely being called

That's confirmed too because if I change my logger level to debug then Indigo prints my logger data as green. Likewise if I change it to Errors, the indigo displays red (as shown in first post). I don't know if this helps you but the indigo log is showing type as my plugin when it logs.

My code where the logging occurs. Note that the call "self._getLogger(remoteName)" is calling the code in the original post.

Code: Select all

     
logger = self._getLogger(remoteName)
if logger != None:
    try:
        indigo.server.log(u"Writing to %s log" % (remoteName))
        indigo.server.log(str(logger.handlers))
        logger.log(logging.DEBUG, u"\n" + msg.payload)
        indigo.server.log(u"Done Writing")
    except Exception,err:
        indigo.server.log(u"%s logger.log error: %s" + (remoteName,err), isError=True)


The indigo log:
MQTT- Writing to T1 log
MQTT- [<logging.handlers.TimedRotatingFileHandler instance at 0x692f1c0>]
MQTT- Debug
t.callback cnt=4300
rcv_settings.update=9048
heap=8640
MQTT- Done Writing

Note: Since I can't post a grab, I tried to make the colors look like the actual log

[jay (support)]

Ok, I think I've figured out what's happening. We'll get back to you once we've confirmed it.