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

Fri Nov 18 21:54:00 UTC 2011

Martin Kosek wrote:
> 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()).
>

I have to agree. Patch management is going to be a pain but we knew this 
would happen sooner or later. IMHO it is worth it to get saner logging.

ACK on root_logger vs log_mgr.root_logger.xxx.

rob