Log message format in KVM-Autotest

Log message format in KVM-Autotest

[Michael Goldish]

Hi Lucas,

Before the merge with Autotest we used kvm_log.py to log formatted messages.
Each message contained the current test's 'shortname' (e.g. Fedora.8.32.install), the current date and time (down to a 1 sec resolution) and the message itself. In addition, debug messages contained the name of the calling function, e.g.
remote_login: Trying to login...

What is the preferred way of obtaining this functionality using the new logging system inside Autotest? Should we define our own logging Handler for the KVM test in kvm.py, along with our own Formatter, or should we use logging.config.fileConfig(), or is there another preferred way?
I'm particularly interested in printing the name of the caller in debug messages. This feature makes debugging easier and improves overall readability of the logs. (Obviously we can manually hardcode the name of the current function into every debug message, but that doesn't seem like a good solution.)

Thanks,
Michael

Re: Log message format in KVM-Autotest

[Lucas Meneghel Rodrigues]

On Mon, 2009-06-08 at 06:35 -0400, Michael Goldish wrote: 
> Hi Lucas,
> 
> Before the merge with Autotest we used kvm_log.py to log formatted messages.
> Each message contained the current test's 'shortname' (e.g. Fedora.8.32.install), the current date and time (down to a 1 sec resolution) and the message itself. In addition, debug messages contained the name of the calling function, e.g.
> remote_login: Trying to login...
> 
> What is the preferred way of obtaining this functionality using the new logging system inside Autotest? Should we define our own logging Handler for the KVM test in kvm.py, along with our own Formatter, or should we use logging.config.fileConfig(), or is there another preferred way?
> I'm particularly interested in printing the name of the caller in debug messages. This feature makes debugging easier and improves overall readability of the logs. (Obviously we can manually hardcode the name of the current function into every debug message, but that doesn't seem like a good solution.)

The logging system can be configured to display several LogRecord
attributes, they are documented under

http://docs.python.org/library/logging.html#formatter-objects

%(funcName)s is the name of the function issuing the logging call, so
that's what we are looking to mirror the wanted functionality.

Creating a logging Handler with a formatter on its own is a possibility,
although we can propose adding the name of the function to the file
format being used by autotest. There's allways the concern that an
excess of information may clutter the logs. 

Right now, for files we use the following format:

http://autotest.kernel.org/browser/trunk/client/debug_client.ini

[formatter_file_formatter]
format=[%(asctime)s %(levelname)-5.5s %(module)s] %(message)s
datefmt=%m/%d %H:%M:%S

The formatter we're using for the logs contain a timestamp, the debug
level name and the module (source file except the .py extension). I
believe this makes debugging easy enough without cluttering too much the
logs. Do you think the caller name would be an interesting addition even
considering the above?


> Thanks,
> Michael
-- 
Lucas Meneghel Rodrigues
Software Engineer (QE)
Red Hat - Emerging Technologies

Re: [Autotest] Log message format in KVM-Autotest

[Martin Bligh]

if it's specific to one test or whatever, you could also just put it
inside the message?
Possibly with your own wrapper function around the logging?

On Mon, Jun 8, 2009 at 6:03 AM, Lucas Meneghel Rodrigues<lmr@redhat.com> wrote:
> On Mon, 2009-06-08 at 06:35 -0400, Michael Goldish wrote:
>> Hi Lucas,
>>
>> Before the merge with Autotest we used kvm_log.py to log formatted messages.
>> Each message contained the current test's 'shortname' (e.g. Fedora.8.32.install), the current date and time (down to a 1 sec resolution) and the message itself. In addition, debug messages contained the name of the calling function, e.g.
>> remote_login: Trying to login...
>>
>> What is the preferred way of obtaining this functionality using the new logging system inside Autotest? Should we define our own logging Handler for the KVM test in kvm.py, along with our own Formatter, or should we use logging.config.fileConfig(), or is there another preferred way?
>> I'm particularly interested in printing the name of the caller in debug messages. This feature makes debugging easier and improves overall readability of the logs. (Obviously we can manually hardcode the name of the current function into every debug message, but that doesn't seem like a good solution.)
>
> The logging system can be configured to display several LogRecord
> attributes, they are documented under
>
> http://docs.python.org/library/logging.html#formatter-objects
>
> %(funcName)s is the name of the function issuing the logging call, so
> that's what we are looking to mirror the wanted functionality.
>
> Creating a logging Handler with a formatter on its own is a possibility,
> although we can propose adding the name of the function to the file
> format being used by autotest. There's allways the concern that an
> excess of information may clutter the logs.
>
> Right now, for files we use the following format:
>
> http://autotest.kernel.org/browser/trunk/client/debug_client.ini
>
> [formatter_file_formatter]
> format=[%(asctime)s %(levelname)-5.5s %(module)s] %(message)s
> datefmt=%m/%d %H:%M:%S
>
> The formatter we're using for the logs contain a timestamp, the debug
> level name and the module (source file except the .py extension). I
> believe this makes debugging easy enough without cluttering too much the
> logs. Do you think the caller name would be an interesting addition even
> considering the above?
>
>
>> Thanks,
>> Michael
> --
> Lucas Meneghel Rodrigues
> Software Engineer (QE)
> Red Hat - Emerging Technologies
>
> _______________________________________________
> Autotest mailing list
> Autotest@test.kernel.org
> http://test.kernel.org/cgi-bin/mailman/listinfo/autotest
>

Re: [Autotest] Log message format in KVM-Autotest

[Lucas Meneghel Rodrigues]

On Mon, 2009-06-08 at 11:15 -0700, Martin Bligh wrote:
> if it's specific to one test or whatever, you could also just put it
> inside the message?
> Possibly with your own wrapper function around the logging?

Yes, it's a possibility, but I'd rather avoid it. IMHO the current
logging configuration is a good compromise between verbosity and the
ability to debug problems on our code.

-- 
Lucas Meneghel Rodrigues
Software Engineer (QE)
Red Hat - Emerging Technologies