Thoughts on logging and mozlog

[William Lachance]

So last year Andrew Halberstadt wrote a mozbase module called mozlog
for, er, logging. You can see the documentation here:

http://mozbase.readthedocs.org/en/latest/mozlog.html

I've recently been adding better logging to eideticker to make it more
debuggable (read: replacing a random soup of print statements). I was
initially planning to just use mozlog, but had two irritations:

1. No timing/date information in the log entries. Sometimes this is key
to being able to figure out what's actually happening when something
goes wrong. Is there a reason we're not including this information by
default?

2. mozlog feels like quite a bit of syntax to go through just to log
some messages. First you have to create a logging object (and give it a
name), then you have to call it by name every time you make a log
message. I'd much rather just be able to do something like this inside
my classes:

self.log("Started capture")

.... and have it do the right thing. So I thought about it a bit, and
wrote this thing:

import datetime

class LoggingMixin(object):

@classmethod
def log(cls, msg):
datestr = datetime.datetime.now().strftime("%b %d %H:%M:%S %Z")
print "%s %s | %s" % (datestr, cls.__name__, msg)

Then I just inherit something I want to use from the class and voila,
instant datestamped and appropriately tagged log lines, like this:

May 01 16:36:08 Test | Starting capture on device 'unagi1' with
mode: 'None'
May 01 16:36:08 CaptureController | Starting capture...
May 01 16:36:08 Test | Test started callback (framenum: None)
May 01 16:36:39 Test | Test finished callback (framenum: None)
May 01 16:36:39 Test | Ending capture

Am I terrible person for doing this? It does seem a bit hacky to me, but
my oh my is it convenient. Is there maybe a non-hacky way of
accomplishing a similar goal?

Will

[Gregory Szorc]

Have you seen the [structured] logging system baked into mach?

https://github.com/indygreg/mach/blob/master/README.rst

class MyClass(LoggingMixin):
def foo(self):
self.log(logging.INFO, 'event_name', dict(duration=1.2,
name='Greg'), '{name} took {duration}')

If output is going to humans, this gets converted to "Greg took 1.2".
But, if you are writing for machines, you get a nice structured event like:

[1367469743.018413, "event_name", {"duration": 1.2, "name": "Greg"}]

By targeting both humans and machines with the same function call, you
get the best of both worlds and don't have to write parsers.

And it's all built on top of the built-in logging package which means
you can write your own appender and get access to the low-level message
parameters to write your own format as desired.

I think there is a bug somewhere to add some of this code into mozlog.

> _______________________________________________
> tools mailing list
> to...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/tools

[Andrew Halberstadt]

On 05/02/2013 12:12 AM, William Lachance wrote:
> So last year Andrew Halberstadt wrote a mozbase module called mozlog
> for, er, logging. You can see the documentation here:
>
> http://mozbase.readthedocs.org/en/latest/mozlog.html
>
> I've recently been adding better logging to eideticker to make it more
> debuggable (read: replacing a random soup of print statements). I was
> initially planning to just use mozlog, but had two irritations:
>
> 1. No timing/date information in the log entries. Sometimes this is key
> to being able to figure out what's actually happening when something
> goes wrong. Is there a reason we're not including this information by
> default?

This isn't there by default because mozharness logs all the
timestamps/dates which is what all our automation is going to be run
through.

> 2. mozlog feels like quite a bit of syntax to go through just to log
> some messages. First you have to create a logging object (and give it a
> name), then you have to call it by name every time you make a log
> message.

Not sure what you mean by "quite a bit of syntax"...

self.log = mozlog.getLogger('Foo')
self.log.info('My message')

I think there are a couple problems with your implementation.

1) There are no levels, so no easy way to have debug vs info vs error
messages.

2) No module names. By forcing module names it's easy to see at a glance
where the log is coming from. This might not seem important if you are
using it in a script, but in our automation when we have chains of
modules calling each other 10 levels deep, it's critical. E.g "Oh, this
message comes from devicemanager!"

3) Another advantage to using python's logging module is that the logger
objects are stored globally to the interpreter. So I can create a log
object in module A with custom formatting and levels, and then access
the same object from module B (by calling getLogger('ModuleName'))

> Am I terrible person for doing this? It does seem a bit hacky to me, but
> my oh my is it convenient. Is there maybe a non-hacky way of
> accomplishing a similar goal?

Yes, update mozlog! I wrote it in a couple of hours more of a
placeholder than anything else. For example, right now the format can't
be changed easily, but feel free to write a patch to make this simple.
If we want to do structured logging, feel free to write a patch to allow
mozlog to do structured logging. I don't really care how mozlog is
implemented, I just care that we don't have 20 different loggers
scattered all over the place.

Andrew

[William Lachance]

On 05/02/2013 10:35 AM, Andrew Halberstadt wrote:
> On 05/02/2013 12:12 AM, William Lachance wrote:
>> So last year Andrew Halberstadt wrote a mozbase module called mozlog
>> for, er, logging. You can see the documentation here:
>>
>> http://mozbase.readthedocs.org/en/latest/mozlog.html
>>
>> I've recently been adding better logging to eideticker to make it more
>> debuggable (read: replacing a random soup of print statements). I was
>> initially planning to just use mozlog, but had two irritations:
>>
>> 1. No timing/date information in the log entries. Sometimes this is key
>> to being able to figure out what's actually happening when something
>> goes wrong. Is there a reason we're not including this information by
>> default?
>
> This isn't there by default because mozharness logs all the
> timestamps/dates which is what all our automation is going to be run
> through.

Ok, makes sense. Have we thought at all about how to control whether the
timestamps are added to the logs, if/when we add that capability to
mozlog? For debugging stuff locally, I didn't think we wanted to use
mozharness.

>> 2. mozlog feels like quite a bit of syntax to go through just to log
>> some messages. First you have to create a logging object (and give it a
>> name), then you have to call it by name every time you make a log
>> message.
>
> Not sure what you mean by "quite a bit of syntax"...
>
> self.log = mozlog.getLogger('Foo')
> self.log.info('My message')

So it's the part where you create the logging object that's the biggest
pain. The logical place to put that in is a class's __init__ method.
This doesn't sound too bad when classes don't inherit, but it quickly
becomes a pain when you have a hierarchy of classes and you need to take
care to make sure the parent constructor is called. I'd rather not have
to worry about that, much simpler IMO to just inherit from a logging
mixin (along with whatever else) and be done with it.

> I think there are a couple problems with your implementation.
>
> 1) There are no levels, so no easy way to have debug vs info vs error
> messages.

This is true, but it would be fairly easy to add a parameter to the
method... (as is done in gps's method)

> 2) No module names. By forcing module names it's easy to see at a glance
> where the log is coming from. This might not seem important if you are
> using it in a script, but in our automation when we have chains of
> modules calling each other 10 levels deep, it's critical. E.g "Oh, this
> message comes from devicemanager!"

Actually it does. :) We get the class name to put in the log message:

print "%s %s | %s" % (datestr, cls.__name__, msg)

This translates to the messages like this:

May 01 16:36:08 Test | Starting capture on device 'unagi1' with mode:
'None'

> 3) Another advantage to using python's logging module is that the logger
> objects are stored globally to the interpreter. So I can create a log
> object in module A with custom formatting and levels, and then access
> the same object from module B (by calling getLogger('ModuleName'))

Is there a use case for this?

>> Am I terrible person for doing this? It does seem a bit hacky to me, but
>> my oh my is it convenient. Is there maybe a non-hacky way of
>> accomplishing a similar goal?
>
> Yes, update mozlog! I wrote it in a couple of hours more of a
> placeholder than anything else. For example, right now the format can't
> be changed easily, but feel free to write a patch to make this simple.
> If we want to do structured logging, feel free to write a patch to allow
> mozlog to do structured logging. I don't really care how mozlog is
> implemented, I just care that we don't have 20 different loggers
> scattered all over the place.

Well, updating mozlog to get structured logging and optional datestamps
doesn't really solve my "how do we make adding good logging *really*
easy for developers?" problem. I'd been avoiding mozlog in eideticker up
to now for that reason: I just didn't want to go through the hassle of
figuring out how to add log objects everywhere.

Anyway, thanks for the additional data. Hopefully we can make something
that will fit all our requirements and be really easy to use.

Will

[William Lachance]

On 05/02/2013 12:47 AM, Gregory Szorc wrote:
> Have you seen the [structured] logging system baked into mach?

I had not. :)

> https://github.com/indygreg/mach/blob/master/README.rst
>
> class MyClass(LoggingMixin):
> def foo(self):
> self.log(logging.INFO, 'event_name', dict(duration=1.2,
> name='Greg'), '{name} took {duration}')
>
> If output is going to humans, this gets converted to "Greg took 1.2".
> But, if you are writing for machines, you get a nice structured event like:
>
> [1367469743.018413, "event_name", {"duration": 1.2, "name": "Greg"}]
>
> By targeting both humans and machines with the same function call, you
> get the best of both worlds and don't have to write parsers.
>
> And it's all built on top of the built-in logging package which means
> you can write your own appender and get access to the low-level message
> parameters to write your own format as desired.
>
> I think there is a bug somewhere to add some of this code into mozlog.

This looks pretty cool. As Andrew just mentioned I think we might want
the module name automatically added to these logging messages for
debuggability reasons, but in general I really like the ideas here (also
it's nice to see some external validation that my logging mixin idea
isn't totally crazy).

Will

[Gregory Szorc]

On 5/2/2013 8:41 AM, William Lachance wrote:
> On 05/02/2013 12:47 AM, Gregory Szorc wrote:

>> Have you seen the [structured] logging system baked into mach?
>

> I had not. :)

>
>> https://github.com/indygreg/mach/blob/master/README.rst
>>
>> class MyClass(LoggingMixin):
>> def foo(self):
>> self.log(logging.INFO, 'event_name', dict(duration=1.2,
>> name='Greg'), '{name} took {duration}')
>>
>> If output is going to humans, this gets converted to "Greg took 1.2".
>> But, if you are writing for machines, you get a nice structured event
>> like:
>>
>> [1367469743.018413, "event_name", {"duration": 1.2, "name": "Greg"}]
>>
>> By targeting both humans and machines with the same function call, you
>> get the best of both worlds and don't have to write parsers.
>>
>> And it's all built on top of the built-in logging package which means
>> you can write your own appender and get access to the low-level message
>> parameters to write your own format as desired.
>>
>> I think there is a bug somewhere to add some of this code into mozlog.
>

> This looks pretty cool. As Andrew just mentioned I think we might want
> the module name automatically added to these logging messages for
> debuggability reasons, but in general I really like the ideas here
> (also it's nice to see some external validation that my logging mixin
> idea isn't totally crazy).

The module name is available on the low-level messages. You just need to
configure the appender to print it. Shouldn't be too much effort.

[Ed Morley]

On 02/05/2013 05:12, William Lachance wrote:
> May 01 16:36:08 Test | Starting capture on device 'unagi1' with
> mode: 'None'

> May 01 16:36:08 CaptureController | Starting capture...
> May 01 16:36:08 Test | Test started callback (framenum: None)
> May 01 16:36:39 Test | Test finished callback (framenum: None)
> May 01 16:36:39 Test | Ending capture

Whilst I'm not a great fan of our current logging format, I just want to
mention that the above won't work with the current TBPL log parsing &
will break bug suggestions unless changes are made (though since
eideticker isn't run via buildbot this is a non-issue for me at the
moment). For the format that is required by TBPL at the moment, see:
https://wiki.mozilla.org/Sheriffing/Job_Visibility_Policy#6.29_Outputs_failures_in_a_TBPL-starrable_format

Note I would very much be a fan of switching to structured logging
across the board in the future (I guess once we have treeherder and more
pluggable parsers) - I'm not attached to the current format - it's more
a case of being stuck with it for now.

Ed

[Jeff Hammel]

Too little, too late;

My main desires are two-fold:

1. as expressed by multiple folks here, it'd be nice to have an API that
was (ideally, and in order that I care about) sensible, easy to use,
evident, and conforming to python logging
2. it would be absolutely lovely to move towards a unified API
(including the log format) and ideally code across Mozilla, or at least
m-c, A*Team, releng, and other folks that touch on common code

FWIW, I've never liked the python logging module....that said, its the
standard, and it ain't that horrible :(

On 05/02/2013 08:37 AM, William Lachance wrote:
> On 05/02/2013 10:35 AM, Andrew Halberstadt wrote:

>> On 05/02/2013 12:12 AM, William Lachance wrote:
>>> So last year Andrew Halberstadt wrote a mozbase module called mozlog
>>> for, er, logging. You can see the documentation here:
>>>
>>> http://mozbase.readthedocs.org/en/latest/mozlog.html
>>>
>>> I've recently been adding better logging to eideticker to make it more
>>> debuggable (read: replacing a random soup of print statements). I was
>>> initially planning to just use mozlog, but had two irritations:
>>>
>>> 1. No timing/date information in the log entries. Sometimes this is key
>>> to being able to figure out what's actually happening when something
>>> goes wrong. Is there a reason we're not including this information by
>>> default?
>>
>> This isn't there by default because mozharness logs all the
>> timestamps/dates which is what all our automation is going to be run
>> through.
>

> Ok, makes sense. Have we thought at all about how to control whether
> the timestamps are added to the logs, if/when we add that capability
> to mozlog? For debugging stuff locally, I didn't think we wanted to
> use mozharness.
>

>>> 2. mozlog feels like quite a bit of syntax to go through just to log
>>> some messages. First you have to create a logging object (and give it a
>>> name), then you have to call it by name every time you make a log
>>> message.
>>
>> Not sure what you mean by "quite a bit of syntax"...
>>
>> self.log = mozlog.getLogger('Foo')
>> self.log.info('My message')
>

> So it's the part where you create the logging object that's the
> biggest pain. The logical place to put that in is a class's __init__
> method.
> This doesn't sound too bad when classes don't inherit, but it quickly
> becomes a pain when you have a hierarchy of classes and you need to
> take care to make sure the parent constructor is called. I'd rather
> not have to worry about that, much simpler IMO to just inherit from a
> logging mixin (along with whatever else) and be done with it.
>

>> I think there are a couple problems with your implementation.
>>
>> 1) There are no levels, so no easy way to have debug vs info vs error
>> messages.
>

> This is true, but it would be fairly easy to add a parameter to the
> method... (as is done in gps's method)
>

>> 2) No module names. By forcing module names it's easy to see at a glance
>> where the log is coming from. This might not seem important if you are
>> using it in a script, but in our automation when we have chains of
>> modules calling each other 10 levels deep, it's critical. E.g "Oh, this
>> message comes from devicemanager!"
>

> Actually it does. :) We get the class name to put in the log message:
>

> print "%s %s | %s" % (datestr, cls.__name__, msg)
>

> This translates to the messages like this:

>
> May 01 16:36:08 Test | Starting capture on device 'unagi1' with mode:
> 'None'
>

>> 3) Another advantage to using python's logging module is that the logger
>> objects are stored globally to the interpreter. So I can create a log
>> object in module A with custom formatting and levels, and then access
>> the same object from module B (by calling getLogger('ModuleName'))
>

> Is there a use case for this?
>

>>> Am I terrible person for doing this? It does seem a bit hacky to me,
>>> but
>>> my oh my is it convenient. Is there maybe a non-hacky way of
>>> accomplishing a similar goal?
>>
>> Yes, update mozlog! I wrote it in a couple of hours more of a
>> placeholder than anything else. For example, right now the format can't
>> be changed easily, but feel free to write a patch to make this simple.
>> If we want to do structured logging, feel free to write a patch to allow
>> mozlog to do structured logging. I don't really care how mozlog is
>> implemented, I just care that we don't have 20 different loggers
>> scattered all over the place.
>

> Well, updating mozlog to get structured logging and optional
> datestamps doesn't really solve my "how do we make adding good logging
> *really* easy for developers?" problem. I'd been avoiding mozlog in
> eideticker up to now for that reason: I just didn't want to go through
> the hassle of figuring out how to add log objects everywhere.
>
> Anyway, thanks for the additional data. Hopefully we can make
> something that will fit all our requirements and be really easy to use.
>
> Will

[Clint Talbert]

That's a good point, but I think we can add these kinds of capabilities
into mozlog now, and then deal with ensuring we have TBPL parseable
output (or change how TBPL parses the specific framework we are working
with) when we modify a harness to use mozlog.

-- Clint