[Freeipa-devel] [PATCH 53/53] ticket 2022 - modify codebase to utilize IPALogManager, obsoletes logging

[Martin Kosek]

On Thu, 2011-11-17 at 11:17 -0500, John Dennis wrote:
> On 11/16/2011 07:35 AM, Martin Kosek wrote:
> > On Tue, 2011-11-15 at 14:41 -0500, John Dennis wrote:
> >>
> >> --
> >> John Dennis<jdennis at redhat.com>
> >>
> >> Looking to carve out IT costs?
> >> www.redhat.com/carveoutcosts/
> >
> > Hi John,
> >
> > thanks for your patch, that was a fair amount of work there :-) I tested
> > them both and have few comments:
> >
> > 1) Patch 53 will need rebasing
> 
> O.K. will rebase.
> >
> > 2) Logging for install tools (ipa-server-install, ...) is now broken.
> > DEBUG level messages should get to /var/log/ipaserver-install.log even
> > when the installer is run without --debug. My
> > ipaserver-install.log/ipaserver-uninstall.log was silent when i run just
> > `ipa-server-install' without --debug flag
> 
> Yes you're right, it's supposed to always log to the file at the debug 
> level. Sorry that slipped by, it's a trivial one word fix in 
> standard_logging_setup(), done.

Ok.

> 
> > 3) Patch 53 touches most of our Python sources as it changes all
> > logging.* calls to log_mgr.root_logger.* calls. I think this may cause
> > problems (comment 1 is a good example). For example we may not be able
> > to cherry-pick most of new patches from master branch to ipa-2-1 branch
> > or other branches that do not use log_mgr.
> >
> > Additionally, typing "log_mgr.root_logger.*" whenever I want to log
> > anything seems a bit awkward to me. These issues are avoidable, however.
> > Since all our Python code use just the root_logger, can we just simply
> > export root logger in log_manager.py namespace and that import it as
> > "logging" in other modules? Then we would save *a lot* of changes across
> > all our code. Something like this:
> >
> > log_manager.py:
> > ---------------
> >   log_mgr = IPALogManager()
> >   log_mgr.configure(dict(default_level='error',
> >                          handlers=[dict(name='console',
> >                                         stream=sys.stderr)]),
> >                     configure_state='default')
> > +root_logger = log_mgr.root_logger
> >
> > ipa-server-install:
> > -------------------
> > +from ipapython.log_manager import root_logger as logginng
> >
> > ...
> > # now, all logging will work as usual:
> > logging.error('Some files have not been restored, see /var/lib/ipa/sysrestore/sysrestore.index')
> 
> Cherry picking patches between branches with out performing any editing 
> to apply the patch is a nice goal but perhaps not realistic. However 
> you're absolutely right this change introduces an extra step during 
> patch/rebase.
> 
> A larger question is should we continue to support the idea of having 
> log functions hung off a module name. Here's my thinking on that. But 
> skip to item 3 if you want a compromise solution.
> 
> 
> 1) I'm a bit concerned that co-opting or borrowing the logging module 
> name and using it for an entirely different purpose. Importing the name 
> "logging" and not have it be the Python logging module as most Python 
> programmers would be the source of needless confusion. Personally I 
> think I would be annoyed if someone had played that game because nothing 
> would be as I expect. The name "logging" implies the logging module with 
> all sorts of names, constants, objects, classes, sub-modules, etc. 
> associated with it, none of that would retain any of it's conventional 
> meaning. I much prefer clarity and to call something what it is and not 
> obfuscate for temporary expediency.
> 
> 2) The current Python logging implementation is broken IMHO and was the 
> source of some of our problems, I'm not sure I want to perpetuate that. 
> It exported a set of "convenience" functions bound to a global. It made 
> using the logging module easier to use via globals but at the expense of 
> all sorts of conflicts when more than one client of logging tried to 
> manipulate the same shared global objects.
> 
> The logging.debug(), etc. names are a bogus mapping of a top level 
> module symbol to a bound method of a specific instantiated object, an 
> object available externally only by calling a defined API to retrieve 
> that object from singleton manager by name. To my mind this is the 
> classic abuse of globals every textbook warns against. It's just bad 
> programming best avoided IMHO.
> 
> Why is it O.K. to have a global log_mgr object for IPA?
> 
>    a) Because it belongs to us, it's not shared with every piece of
>       Python code which imports the logging module.
> 
>    b) It's not abusing a top level module symbol to be a short circuit
>       reference into some other instantiated object. The root logger
>       belongs to the log_mgr instance shared by loaded IPA components.
>       Think of it as an IPA singleton.
> 
> 3) Can we have a shorter name as a compromise? Sure, I have no problems
>     with that. We already have the log_mgr as a single imported instance.
>     I don't see why we couldn't have also import the symbol
>     "root_logger" which is log_mgr.root_logger. I'm not keen on shorting
>     the name much more, for instance to "logger" because that's too
>     generic and obscures the fact it's the root logger, an important
>     distinction to maintain.
> 
>     An other option would be to have a LogManager object export the
>     debug(), info(), error(), critical(), & exception() methods where
>     they are bound to the LogManager's root_logger instance. This is
>     somewhat akin to what the standard Python logging module, except
>     they performed the binding on the module level and not on an
>     instance (the source of many problems). Those log methods *must*
>     be bound to a Logger object as such I'm not entirely keen on
>     binding them to a LogManager instance because once again you
>     end up providing an abused short cut which hides what is really
>     going on. I think it would benefit programmers if they knew they
>     were logging to a Logger and if so which one, because after all
>     once you try to customize things like "which loggers emit which
>     which messages" it would be really helpful to know you're dealing
>     with a Logger and which one it is and not obscure which one it is
>     to shorten the reference to it as a convenience via some short cut.
>     But if there is a consensus I could bend on this issue.
> 
>     That means we could have one of the two (I prefer the first)
> 
>     root_logger.debug()
> 
>     -or-
> 
>     log_mgr.debug() # Not a fan of this because it hides the important
>                     # concept of debug() being bound to the root_logger.
> 
>     As for:
> 
>     logging.debug()
> 
>     For the reasons pointed out in 1 I'd like to avoid that kind of
>     symbol abuse.
> 
> 

Ok, these are all valid arguments. I know that abusing "logging" is not
right, I was just afraid that diverging master branch from our 2.x
branch that much would do more harm (and extra effort whenever a patch
from master is backported to 2.x branch) that misusing the "logging"
name. I would like some second opinion on that before we make the call.

I think having root_logger exported to our tools and calling
root_logger.warning(...) etc. looks better than the previous version
(log_mgr.root_logger.warning()).

Martin