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

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

[Michael Goldish]

----- "Lucas Meneghel Rodrigues" <lmr@redhat.com> wrote:

> 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?

No, because the test's 'shortname' contains both the test type and some
minimal information about the configuration in which it is run.
For example, scsi.smp2.Fedora.8.32.boot, is the KVM 'boot' test run with
Fedora.8.32, with 2 VCPUs and a scsi drive, and with the rest of the
parameters set to their most common values (e.g. the image format is qcow2
unless otherwise stated, the NIC is the default rtl8139...).
'boot' alone is not very informative.

> > 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.

I would very much like to see the test name, the caller name and the time
in the logs. The KVM test is much more complex than other Autotest tests
and thus requires (in my opinion) more verbose logging. This seems very
reasonable to me. I personally find the logs produced by the new logger
after the merge very difficult to read, and even more difficult to debug.

Since the logging module seems to support most or all of what we need,
I see no reason not to use our own logging config file or our own Handler
and Formatter in the KVM test. I too would rather not resort to wrapper
functions.

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