Re: [python API] logging

On 09/15/2012 12:13 PM, Alon Bar-Lev wrote:
>
>
> ----- Original Message -----
>> From: "tim lauridsen" <[email protected]>
>> To: "Yellowdog Updater, Modified" <[email protected]>
>> Sent: Saturday, September 15, 2012 10:17:33 AM
>> Subject: Re: [Yum] [python API] logging
>>
>>
>>
>>
>>
>> On Fri, Sep 14, 2012 at 10:28 PM, Alon Bar-Lev < [email protected] >
>> wrote:
>>
>>
>>
>>
>>
>>
>> ----- Original Message -----
>>> From: "tim lauridsen" < [email protected] >
>>> To: "Yellowdog Updater, Modified" < [email protected] >
>>> Sent: Friday, September 14, 2012 8:22:17 AM
>>> Subject: Re: [Yum] [python API] logging
>>>
>>> On Wed, Sep 12, 2012 at 9:40 PM, Alon Bar-Lev < [email protected] >
>>> wrote:
>>>
>>>
>>> Hello All,
>>>
>>> I am trying to use yum via python.
>>>
>>> It is great apart of one issue I would like to discuss - logging.
>>>
>>> Going over the sources I see a lot of logs.
>>>
>>> At least:
>>>
>>> 'yum', 'yum.Depsolve', 'yum.RepoStorage', 'yum.Repos',
>>> 'yum.YumBase', 'yum.filelogging',
>>> 'yum.filelogging.RPMInstallCallback'
>>> 'yum.plugin', 'yum.verbose',
>>> 'yum.verbose.Depsolve',
>>> 'yum.verbose.ProcessTrasactionBaseCallback', 'yum.verbose.Repos',
>>> 'yum.verbose.YumPlugins', 'yum.verbose.plugin',
>>> 'yum.verbose.YumBase'
>>>
>>> Having so much logs is great, however the yum implementation lazy
>>> initialize the logs as objects are constructed. This override any
>>> setting I may have for these logs. Especially the stdout, stderr
>>> setting.
>>>
>>> My mission is to use yum pragmatically an write my own logging,
>>> thus
>>> writing even a single message to stdout/stderr breaks the entire
>>> application.
>>>
>>> Another issue is the large number of logs - as in python the log
>>> must
>>> be explicitly initialized, meaning it is not enough to initialize
>>> the 'yum' log to have effect on all the other logs.
>>> So even if explicit logs are properly initialize as application
>>> evolves it can add new logs, which will break the application.
>>>
>>> What I suggest is to add a logging object that will initialize all
>>> logging for the application at yumbase constructor, then user may
>>> override the settings as desired.
>>>
>>> The logging object will also hold a list of all available logs, so
>>> implementation can know what logs are available for configuration.
>>>
>>> Maybe I missed some feature within the library... I will be happy
>>> to
>>> know.
>>>
>>> Thoughts?
>>> Alon.
>>>
>>>
>>
>>> http://docs.python.org/library/logging.html
>>>
>>>
>>> Take a look at the propagate attribute to Logger class
>>> setting it to False, will do what you want
>>>
>>>
>>> just use 'yum' as logroot and it will get all yum logging.
>>>
>>>
>>> Check this yumex code for examples for how to create a logger there
>>> shows output in a gtk.Textview
>>
>> Hello Tim
>>
>> Thank you so much for your help!
>>
>> The propagate is good, but as root loggers set their own handlers
>> there is a need to to setup at least two: 'yum', 'rhsm'... and in
>> future any new one...
>>
>> However, even if I catch all logs, I still end up with the following
>> in stdout:
>>
>> ---
>> for l in ('yum', 'rhsm'):
>> log = logging.getLogger(l)
>> log.propagate = False
>> log.handlers = []
>> log.addHandler(miniyum._yumlogger._loghandler(this._output
>> ---
>>
>> ---
>> Loaded plugins: product-id, rhnplugin
>> Repository rhel-source is listed more than once in the configuration
>> Repository rhel-source-beta is listed more than once in the
>> configuration
>>
>> Freeing read locks for locker 0x1b: 1242/139773667890944
>> Freeing read locks for locker 0x1d: 1242/139773667890944
>> Freeing read locks for locker 0x1e: 1242/139773667890944
>> Freeing read locks for locker 0x1f: 1242/139773667890944
>> Freeing read locks for locker 0x20: 1242/139773667890944
>> Freeing read locks for locker 0x21: 1242/139773667890944
>> Freeing read locks for locker 0x22: 1242/139773667890944
>>
>> warning: rpmts_HdrFromFdno: Header V3 RSA/SHA256 Signature, key ID
>> fd431d51: NOKEY
>> Retrieving key from
>> file:///etc/pki/rpm-gpg/RPM-GPG-KEY-redhat-release
>>
>> No package matched to remove: cman
>> Package qemu-kvm-tools is obsoleted by qemu-kvm-rhev-tools, trying to
>> install 2:qemu-kvm-rhev-tools-0.12.1.2-2.295.el6_3.2.x86_64 instead
>> ---
>>
>> So I had to put my own Logger class to ignore 'yum', 'rhsm'... Not
>> sure why the propagate does not work correctly.
>>
>> ---
>> def addHandler(self, hdlr):
>> if self.name.startswith('yum') or self.name.startswith('rhsm'):
>> logging.Logger.handlers = []
>> logging.Logger.addHandler(
>> self,
>> myhandler
>> )
>> else:
>> logging.Logger.addHandler(self, hdlr)
>> ---
>>
>> Now, I left with:
>> ---
>> Freeing read locks for locker 0x1b: 1242/139773667890944
>> Freeing read locks for locker 0x1d: 1242/139773667890944
>> Freeing read locks for locker 0x1e: 1242/139773667890944
>> Freeing read locks for locker 0x1f: 1242/139773667890944
>> Freeing read locks for locker 0x20: 1242/139773667890944
>> Freeing read locks for locker 0x21: 1242/139773667890944
>> Freeing read locks for locker 0x22: 1242/139773667890944
>>
>> warning: rpmts_HdrFromFdno: Header V3 RSA/SHA256 Signature, key ID
>> fd431d51: NOKEY
>> ---
>>
>> So I had to dup /dev/null to stdout, stderr during YumBase.process()
>> to cut the above messages as well, as I could not find where these
>> are coming out from, and almost sure that there are other surprises.
>>
>> I think that like in Java, an API should not set its own handlers...
>> and make sure there is no output unless explicitly registered.
>>
>> Thanks,
>> Alon
>>
>>
>> _______________________________________________
>> Yum mailing list
>> [email protected]
>> http://lists.baseurl.org/mailman/listinfo/yum
>>
>>
>>
>>
>> You can silence the build-in yum output by setting errorlevel=0 &
>> debuglevel=0
>>
>>
>> See.
>>
>>
>> https://github.com/timlau/yum-daemon/blob/master/yumdaemon/yumdaemon#L1188
>>
>>
>> The cause that yum has automatic setup of the logger output is to
>> make it easier for API users to use it without having to setup there
>> own loggers, they don't dont normally not have the same
>> requirement as you have :)
>
> Thank you Tim!
>
> The requirement is to have log, but have full control where it goes... :)
>
> Disabling the log completely is not something I like, logs are not evil as long as I can control the output location and verbosity.
>
> Using this and propagate, I still have the following messages to stdout:
> ---
[...]
>
> Freeing read locks for locker 0x5: 1228/139804988552960
> Freeing read locks for locker 0x7: 1228/139804988552960
> Freeing read locks for locker 0x8: 1228/139804988552960
> Freeing read locks for locker 0xf: 1228/139804988552960
> Freeing read locks for locker 0x11: 1228/139804988552960
> Freeing read locks for locker 0x12: 1228/139804988552960
> Freeing read locks for locker 0x13: 1228/139804988552960
> Freeing read locks for locker 0x14: 1228/139804988552960
> Freeing read locks for locker 0x15: 1228/139804988552960
> Freeing read locks for locker 0x16: 1228/139804988552960
> Freeing read locks for locker 0x17: 1228/139804988552960
> Freeing read locks for locker 0x2f: 1228/139804988552960
> Freeing read locks for locker 0x31: 1228/139804988552960
> Freeing read locks for locker 0x32: 1228/139804988552960
> ---

Note that these "freeing locks" messages are not something you should be 
normally seeing. They indicate that a process has been forcefully 
terminated (eg kill -9'ed or crashed) while having read-locks on the rpm 
database. If you're routinely seeing them, something is wrong (in your 
software or something else on the system)

	- Panu -