Illegally adding logging handlers to applications using pi3d

[codedump]

Hey there,

first off: nice work building pi3d, it's a very useful software package.

Now to the issue: I believe that either pi3d or one of its underlying libraries adds a StreamHandler to the logger when it shouldn't.

To illustrate, I have the following script -- call it test.py:

import logging
log = logging.getLogger()
print (log.handlers)
log.info("foo")

import pi3d
log.info("bar")
print (log.handlers)

And I'd expect it to have the following output:

$ python ./test.py
[]
[]

That would mean that the list of log handlers is empty, and that no other output is created (in particular no "foo" or "bar"):

However, this is the actual output:

$ python ./test.py
[]
2017-01-03 10:43:04,092 INFO: root: bar
[<logging.StreamHandler object at 0x7f8c19542d10>]

This means that pi3d is adding some kind of StreamHandler to my logger. This is extremely annoying since it messes up my application, which makes heavy of use of logging to files and terminal in various situations. In its mildest form, I get every log line displayed doubly if I create my own StreamHandler.

In its more complex form, it prevents me from properly formatting my own StreamHandler, because if I do, I will not only get every message twice, I will even have it formatted differently each time -- once by the pi3d StreamHandler, once by my own.

I've done some investigation. The current git version only has one single addHandler() call in pi3d/util/Log.py -- commenting that one out doesn't fix the issue. Maybe one of the underlying libraries is misbehaving.

Thanks & Cheers

[paddywwoof]

Hi, thanks for digging this one up. The logging features were originally added by Tom who has been tied up on other projects for the last couple of years.. So this is something I probably need to do some research into anyway. Will let you know what I find.

[paddywwoof]

OK, I've done a bit of playing around and have a little more grasp of the logging process. I don't think pi3d is doing anything unexpected in so far as it uses the logging.basicConfig() which seems to be an approved method that checks if there is a pre-existing logger set up and leaves it intact if there is. If there isn't it adds a StreamHandler with formatting etc.

However I can see that there is an issue with modules adding logging as the order of imports makes a difference. So in your example if you had done:

import logging
logging.basicConfig(format='mylog %(message)s')
log = logging.getLogger()
print (log.handlers)
log.info("foo")

import pi3d
log.info("bar")
print (log.handlers)

Your output would show the same StreamHandler in both prints and neither log.info would have printed. log.error("bar") would have produced "mylog bar" i.e. not using the pi3d default formatting. In order to change the behavior after the import I'm not sure what the approved method is. You could either just remove the handler added by pi3d's basicConfig

import logging
import pi3d
log = logging.getLogger()
log.removeHandler(log.handlers[0]) # obviously should check for None and list len etc

or modify the existing handler to suit your needs

import logging
import pi3d
log = logging.getLogger()
log.handlers[0].setFormatter(logging.Formatter('changed %(message)s'))
log.setLevel('ERROR')

I'm happy to include functionality inside pi3d.Log - let me know what you think the best approach would be given that it makes sense for the pi3d module classes to use its own logging functionality to log errors etc internally.

[codedump]

Hello paddywwoof,

thanks for taking the time to look into it.

I don't think pi3d is doing anything > unexpected in so far as it uses the logging.basicConfig() which seems to be an approved method that checks if there is a pre-existing logger set up and leaves it intact if there is. If there isn't it adds a StreamHandler with formatting etc.

I'm not sure what the "recommended" behavior is -- if you think this is how it's supposed to be, then leave it as it is.

However, this scenario seems rather odd to me. The main reason is that pi3d is a library, not an application. Addind a default StreamHandler ist practically enforcing a console output on the application using pi3d, or enforcing the burden of explicitly removing it if it doesn't want it.

I don't think that a library should make policy decisions regarding user interaction, unless the interaction an inherent function of the library scope, e.g. ncurses -- logging isn't.

Maybe the "approved method" you're refering to is something that's recommended when writing applications, as opposed to libraries?

However I can see that there is an issue with modules adding logging as the order of imports makes a difference. [...]

Yes, meanwhile that's what I thought happened: some code adds a StreamHandler if there is none, and I can remove it if I want it removed. That's what I ultimately did (slightly differend code snipped, but same effect).

I'm happy to include functionality inside pi3d.Log - let me know what you think the best approach would be given that it makes sense for the pi3d module classes to use its own logging functionality to log errors etc internally.

See above -- as I understand the logging module, it is specifically designed to provide libraries the mechanism of logging, while leaving policy to the application using the library.

I think you should just import the logger and use it, without adding handlers. (You can add StreamHandlers in the main part of the modules if you need it though, e.g. for unit testing.)

import logging

log = logging.getLogger()

def whatever():
    ## define a function, or whatever makes up our library. we can use
    ## the logger, but the message is not shown unless someone
    ## attaches a handler
    log.info ("message")

if __name__ == "__main__":
    ## we're only getting here if the module is called directly, as an
    ## application, so sounds like the correct spot to decide policy

    ## no message, because log has no handler
    whatever()

    ## now we're interested in all the noise ;-)
    hnd = logging.StreamHandler()
    fmt = logging.Formatter('%(message)s')
    hnd.setFormatter(fmt)
    log.addHandler(hnd)
    log.setLevel(logging.INFO)

    ## calling this will actually display something
    whatever()

Cheers

[paddywwoof]

@codedump Sorry for the delay, it proved messier than I thought hacking the pi3d code keeping to the existing structure. I couldn't actually get the existing code to work in the way I think it was intended to and in the end I made the functionality part of a class which holds a logging.Logger object and keeps track of a Handler etc. Unfortunately this will break existing code that used pi3d.Log - but as it didn't really work before I think this won't be noticed (famous last words!)

previously

from pi3d.util import Log
LOGGER = Log.logger(__name__)
...
Log.set_logs() #doesn't behave as expected

now

LOGGER = pi3d.Log(__name__, level='INFO', file='dump.txt', format='%(message)s')
...
LOGGER.set_logs(level='WARNING')

And I have taken all use of pi3d.Log out of the pi3d module itself, using the 'un-handled' format similar to your example

import logging
...
LOGGER = logging.getLogger(__name__)
...
LOGGER.warning(...)

in the develop branch at the moment - I will promote to live version 2.17 over the next few days. Thanks for all your help.

[rec]

Good stuff! Made a tiny comment on that commit. Just checking in, don't hesitate to ping me if you need me.

On 24 January 2017 at 17:07, paddywwoof notifications@github.com wrote:

Closed #207 https://github.com/tipam/pi3d/issues/207.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/tipam/pi3d/issues/207#event-934733677, or mute the thread https://github.com/notifications/unsubscribe-auth/AAPdshCqazppdTn59fVePLOokploGAn1ks5rViGkgaJpZM4LZe0r .

-- /t

http://radio.swirly.com - art music radio 24/7 366/1000

[paddywwoof]

Tom, yes that's much nicer. Also spotted that it needed a way to easily change the root logger level (for getting debug stuff from within the pi3d module) so patched that too.

How's Holland, cold enough to skate yet. Presumably you've seen this https://www.youtube.com/watch?v=j-xxis7hDOE ho, ho!

Paddy

On 24/01/17 16:15, Tom Swirly wrote:

Good stuff! Made a tiny comment on that commit. Just checking in, don't hesitate to ping me if you need me.

On 24 January 2017 at 17:07, paddywwoof notifications@github.com wrote:

Closed #207 https://github.com/tipam/pi3d/issues/207.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/tipam/pi3d/issues/207#event-934733677, or mute the thread

https://github.com/notifications/unsubscribe-auth/AAPdshCqazppdTn59fVePLOokploGAn1ks5rViGkgaJpZM4LZe0r .

-- /t

http://radio.swirly.com - art music radio 24/7 366/1000

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/tipam/pi3d/issues/207#issuecomment-274851163, or mute the thread https://github.com/notifications/unsubscribe-auth/AB2Xxp7L3CdH-TtJvA9qv7QieDUWfIvpks5rViOlgaJpZM4LZe0r.

[rec]

Eh, it only gets cold enough to skate every few years, and so far not this one!

It's been great so far and not really missing Brooklyn. Can't say enough good things about it to be honest. Today I actually got official residency in Amsterdam and a social security number!

I have a couple of Python projects that I'm working on here that might well be of use to pi3d - a "generic" sequencer and a "generic" expression parser (which is basically done).

At some point, I'll make a demo with the sequencer and pi3d just to keep my hand in.

On 24 January 2017 at 19:04, paddywwoof notifications@github.com wrote:

Tom, yes that's much nicer. Also spotted that it needed a way to easily change the root logger level (for getting debug stuff from within the pi3d module) so patched that too.

How's Holland, cold enough to skate yet. Presumably you've seen this https://www.youtube.com/watch?v=j-xxis7hDOE ho, ho!

Paddy

On 24/01/17 16:15, Tom Swirly wrote:

Good stuff! Made a tiny comment on that commit. Just checking in, don't hesitate to ping me if you need me.

On 24 January 2017 at 17:07, paddywwoof notifications@github.com wrote:

Closed #207 https://github.com/tipam/pi3d/issues/207.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/tipam/pi3d/issues/207#event-934733677, or mute the thread

https://github.com/notifications/unsubscribe-auth/ AAPdshCqazppdTn59fVePLOokploGAn1ks5rViGkgaJpZM4LZe0r .

-- /t

http://radio.swirly.com - art music radio 24/7 366/1000

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/tipam/pi3d/issues/207#issuecomment-274851163, or mute the thread https://github.com/notifications/unsubscribe-auth/AB2Xxp7L3CdH- TtJvA9qv7QieDUWfIvpks5rViOlgaJpZM4LZe0r.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/tipam/pi3d/issues/207#issuecomment-274885343, or mute the thread https://github.com/notifications/unsubscribe-auth/AAPdsnPze1BB8mGmgjtEFpK7c936TEASks5rVj02gaJpZM4LZe0r .

-- /t

http://radio.swirly.com - art music radio 24/7 366/1000