Bazaar

Merge lp:~eric97/bzr/mutter-pid into lp:bzr

mutter-pid
Merge into bzr.dev

Proposed by Eric Siegerman on 2011-01-08

Status:	Work in progress
Proposed branch:	lp:~eric97/bzr/mutter-pid
Merge into:	lp:bzr
Diff against target:	123 lines (+45/-7) 3 files modified bzrlib/tests/test_selftest.py (+2/-1) bzrlib/tests/test_trace.py (+29/-4) bzrlib/trace.py (+14/-2)
To merge this branch:	bzr merge lp:~eric97/bzr/mutter-pid
Related bugs:	Link a bug report

Reviewer	Review Type	Date Requested	Status
bzr-core		2011-01-08	Pending
Review via email: mp+45595@code.launchpad.net

Commit message

Make mutter() output look more like other .bzr.log entries, by adding PID, absolute date/time, and a pseudo-log-level of "MUTTER".

Description of the change

Make mutter() output look more like other .bzr.log entries, by adding PID, absolute date/time, and a pseudo-log-level of "MUTTER".

Before:

Fri 2011-01-07 23:56:35 -0500
0.053 bazaar version: 2.3.0dev5
0.053 bzr arguments: [u'rocks']
[...]
0.271 encoding stdout as sys.stdout encoding 'UTF-8'
0.271 Transferred: 0kB (0.0kB/s r:0kB w:0kB)
0.271 return code 0
[ 782] 2011-01-07 23:56:35.885 WARNING: bzr: warning: some compiled extensions could not be loaded; see <https://answers.launchpad.net/bzr/+faq/703>

After:

Fri 2011-01-07 23:56:46 -0500
[ 786] 2011-01-07 23:56:46.978 MUTTER: 0.049 bazaar version: 2.3.0dev5
[ 786] 2011-01-07 23:56:46.978 MUTTER: 0.049 bzr arguments: [u'rocks']
[...]
[ 786] 2011-01-07 23:56:47.172 MUTTER: 0.244 encoding stdout as sys.stdout encoding 'UTF-8'
[ 786] 2011-01-07 23:56:47.173 MUTTER: 0.244 Transferred: 0kB (0.0kB/s r:0kB w:0kB)
[ 786] 2011-01-07 23:56:47.173 MUTTER: 0.245 return code 0
[ 786] 2011-01-07 23:56:47.173 WARNING: bzr: warning: some compiled extensions could not be loaded; see <https://answers.launchpad.net/bzr/+faq/703>

(N.B.: I've purposely avoided compiling extensions, in order to force bzr to emit a WARNING.)

lp:~eric97/bzr/mutter-pid updated on 2011-01-08

5589. By Eric Siegerman <email address hidden> on 2011-01-08: TestTrace._mutter_prefix now accepts any PID.
We used to require this process's PID, but that would fail should we
ever be asked to match against lines written by a subprocess.
5590. By Eric Siegerman <email address hidden> on 2011-01-08: Make test_trace.mutter_prefix global.
Adapt test_selftest.TestRunner.test_unicode_test_output_on_ascii_stream()
to the new mutter() format.

Revision history for this message

Martin Pool (mbp) wrote on 2011-01-08:

Logging the pid would certainly be useful.

This format makes thing pretty wide, which might be a concern for ease
of reading the file. Of course in a good editor you can scroll but
not in a bug tracker, and not in everyones' mail client.

So if you could shrink it a bit that would be good. Ideally it would
have more in common with how other thing are logged, not less.

--
Martin

Revision history for this message

Eric Siegerman (eric97) wrote on 2011-01-08:

> So if you could [make the output narrower] that would be good. Ideally it would
> have more in common with how other thing are logged, not less.

Note that the non-mutter() lines are no wider than they were before; I haven't touched those, but only made the mutter() lines more closely resemble them.

The only remaining difference is that mutter() still prints the elapsed time (that's the number that was printed before my changes; it now follows "MUTTER:"). Removing the elapsed time would save a few characters (and one could get away with it now that the absolute date/time is included), but I assume that the it's there because it's useful, and so would be missed if it were to go away.

To reiterate, the status quo ante is format #1:
    1.234 Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

and this patch, as it stands, produces format #2:
    [21703] 2011-01-07 19:07:18.974 MUTTER: 1.234 Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

If I did remove the elapsed time, the output would look like format #3:
    [21703] 2011-01-07 19:07:18.974 MUTTER: Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is totally unified, but doesn't save all that many characters. Is it enough of an improvement to be worth sacrificing the elapsed-time field?

On the other hand, I could back part-way out, and add *only* the PID to mutter() lines. That would produce format #4:
    [21703] 1.234 Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is shorter, but violates your "more in common" request.

One could change the non-mutter() lines too, e.g. to include *only* elapsed times (format #5):
    [21703] 1.234 MUTTER: Plugin name launchpad already loaded
    [21703] 1.236 WARNING: bzr: warning: blah

But the non-mutter() lines are written by the Python logging subsystem, and hacking that might be beyond my current level of Python- and bzr-fu -- especially under Python 2.4, because the logging module's "extra" feature for adding custom fields only appeared in 2.5. I can look into doing that, but it'd take me a while. It might be better to land this branch, or a minor variant of it, and do the more extensive format changes as a follow-on branch if people feel they're warranted.

> So if you could [make the output narrower] that would be good.  Ideally it would
> have more in common with how other thing are logged, not less.

Note that the non-mutter() lines are no wider than they were before; I haven't touched those, but only made the mutter() lines more closely resemble them.

The only remaining difference is that mutter() still prints the elapsed time (that's the number that was printed before my changes; it now follows "MUTTER:").  Removing the elapsed time would save a few characters (and one could get away with it now that the absolute date/time is included), but I assume that the it's there because it's useful, and so would be missed if it were to go away.

To reiterate, the status quo ante is format #1:
&nbsp;&nbsp;&nbsp;&nbsp;1.234  Plugin name launchpad already loaded
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

and this patch, as it stands, produces format #2:
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 2011-01-07 19:07:18.974 MUTTER: 1.234  Plugin name launchpad already loaded
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

If I did remove the elapsed time, the output would look like format #3:
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 2011-01-07 19:07:18.974 MUTTER: Plugin name launchpad already loaded
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is totally unified, but doesn't save all that many characters.  Is it enough of an improvement to be worth sacrificing the elapsed-time field?

On the other hand, I could back part-way out, and add *only* the PID to mutter() lines.  That would produce format #4:
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 1.234  Plugin name launchpad already loaded
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is shorter, but violates your "more in common" request.

One could change the non-mutter() lines too, e.g. to include *only* elapsed times (format #5):
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 1.234 MUTTER: Plugin name launchpad already loaded
&nbsp;&nbsp;&nbsp;&nbsp;[21703] 1.236 WARNING: bzr: warning: blah

But the non-mutter() lines are written by the Python logging subsystem, and hacking that might be beyond my current level of Python- and bzr-fu -- especially under Python 2.4, because the logging module's "extra" feature for adding custom fields only appeared in 2.5.  I can look into doing that, but it'd take me a while.  It might be better to land this branch, or a minor variant of it, and do the more extensive format changes as a follow-on branch if people feel they're warranted.

Revision history for this message

Eric Siegerman (eric97) wrote on 2011-01-08:

Sigh: let's try that again without the  's. No other changes...

> So if you could [make the output narrower] that would be good. Ideally it would
> have more in common with how other thing are logged, not less.

Note that the non-mutter() lines are no wider than they were before; I haven't touched those, but only made the mutter() lines more closely resemble them.

To reiterate, the status quo ante is format #1:
1.234 Plugin name launchpad already loaded
[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

and this patch, as it stands, produces format #2:
[21703] 2011-01-07 19:07:18.974 MUTTER: 1.234 Plugin name launchpad already loaded
[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

If I did remove the elapsed time, the output would look like format #3:
[21703] 2011-01-07 19:07:18.974 MUTTER: Plugin name launchpad already loaded
[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is totally unified, but doesn't save all that many characters. Is it enough of an improvement to be worth sacrificing the elapsed-time field?

On the other hand, I could back part-way out, and add *only* the PID to mutter() lines. That would produce format #4:
[21703] 1.234 Plugin name launchpad already loaded
[21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is shorter, but violates your "more in common" request.

One could change the non-mutter() lines too, e.g. to include *only* elapsed times (format #5):
[21703] 1.234 MUTTER: Plugin name launchpad already loaded
[21703] 1.236 WARNING: bzr: warning: blah

Sigh: let's try that again without the &nbsp;'s.  No other changes...

> So if you could [make the output narrower] that would be good.  Ideally it would
> have more in common with how other thing are logged, not less.

Note that the non-mutter() lines are no wider than they were before; I haven't touched those, but only made the mutter() lines more closely resemble them.

The only remaining difference is that mutter() still prints the elapsed time (that's the number that was printed before my changes; it now follows "MUTTER:").  Removing the elapsed time would save a few characters (and one could get away with it now that the absolute date/time is included), but I assume that the it's there because it's useful, and so would be missed if it were to go away.

To reiterate, the status quo ante is format #1:
    1.234  Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

and this patch, as it stands, produces format #2:
    [21703] 2011-01-07 19:07:18.974 MUTTER: 1.234  Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

If I did remove the elapsed time, the output would look like format #3:
    [21703] 2011-01-07 19:07:18.974 MUTTER: Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is totally unified, but doesn't save all that many characters.  Is it enough of an improvement to be worth sacrificing the elapsed-time field?

On the other hand, I could back part-way out, and add *only* the PID to mutter() lines.  That would produce format #4:
    [21703] 1.234  Plugin name launchpad already loaded
    [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah

which is shorter, but violates your "more in common" request.

One could change the non-mutter() lines too, e.g. to include *only* elapsed times (format #5):
    [21703] 1.234 MUTTER: Plugin name launchpad already loaded
    [21703] 1.236 WARNING: bzr: warning: blah

But the non-mutter() lines are written by the Python logging subsystem, and hacking that might be beyond my current level of Python- and bzr-fu -- especially under Python 2.4, because the logging module's "extra" feature for adding custom fields only appeared in 2.5.  I can look into doing that, but it'd take me a while.  It might be better to land this branch, or a minor variant of it, and do the more extensive format changes as a follow-on branch if people feel they're warranted.

lp:~eric97/bzr/mutter-pid updated on 2011-01-08

5591. By Eric Siegerman <email address hidden> on 2011-01-08: Doc fix.

Revision history for this message

John A Meinel (jameinel) wrote on 2011-01-08:

Download full text (3.2 KiB)

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 1/8/2011 3:03 AM, Eric Siegerman wrote:
> Sigh: let's try that again without the  's. No other changes...
>
>> So if you could [make the output narrower] that would be good. Ideally it would
>> have more in common with how other thing are logged, not less.
>
> Note that the non-mutter() lines are no wider than they were before; I haven't touched those, but only made the mutter() lines more closely resemble them.
>
> The only remaining difference is that mutter() still prints the elapsed time (that's the number that was printed before my changes; it now follows "MUTTER:"). Removing the elapsed time would save a few characters (and one could get away with it now that the absolute date/time is included), but I assume that the it's there because it's useful, and so would be missed if it were to go away.
>
> To reiterate, the status quo ante is format #1:
> 1.234 Plugin name launchpad already loaded
> [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
>
> and this patch, as it stands, produces format #2:
> [21703] 2011-01-07 19:07:18.974 MUTTER: 1.234 Plugin name launchpad already loaded
> [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
>
> If I did remove the elapsed time, the output would look like format #3:
> [21703] 2011-01-07 19:07:18.974 MUTTER: Plugin name launchpad already loaded
> [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
>
> which is totally unified, but doesn't save all that many characters. Is it enough of an improvement to be worth sacrificing the elapsed-time field?
>
> On the other hand, I could back part-way out, and add *only* the PID to mutter() lines. That would produce format #4:
> [21703] 1.234 Plugin name launchpad already loaded
> [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
>
> which is shorter, but violates your "more in common" request.

^- This is my personal favorite. mutter lines are far more common than
warning/error lines.

I don't find the absolute date-time to be very useful, when with
pid+elapsed time+log at startup time you can get it if you need to.

[PID] has some real use cases for sorting out which lines belonged to
which process. So I'm in favor of adding it.

John
=:->

>
> One could change the non-mutter() lines too, e.g. to include *only* elapsed times (format #5):
> [21703] 1.234 MUTTER: Plugin name launchpad already loaded
> [21703] 1.236 WARNING: bzr: warning: blah
>
> But the non-mutter() lines are written by the Python logging subsystem, and hacking that might be beyond my current level of Python- and bzr-fu -- especially under Python 2.4, because the logging module's "extra" feature for adding custom fields only appeared in 2.5. I can look into doing that, but it'd take me a while. It might be better to land this branch, or a minor variant of it, and do the more extensive format changes as a follow-on branch if people feel they're warranted.
>
>
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk0ogMgACgkQJdeBCYSNAAMZngCgnP1V6ofK4nk9YJ+cetGt...

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 1/8/2011 3:03 AM, Eric Siegerman wrote:
> Sigh: let's try that again without the &nbsp;'s.  No other changes...
> 
>> So if you could [make the output narrower] that would be good.  Ideally it would
>> have more in common with how other thing are logged, not less.
> 
> Note that the non-mutter() lines are no wider than they were before; I haven't touched those, but only made the mutter() lines more closely resemble them.
> 
> The only remaining difference is that mutter() still prints the elapsed time (that's the number that was printed before my changes; it now follows "MUTTER:").  Removing the elapsed time would save a few characters (and one could get away with it now that the absolute date/time is included), but I assume that the it's there because it's useful, and so would be missed if it were to go away.
> 
> To reiterate, the status quo ante is format #1:
>     1.234  Plugin name launchpad already loaded
>     [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
> 
> and this patch, as it stands, produces format #2:
>     [21703] 2011-01-07 19:07:18.974 MUTTER: 1.234  Plugin name launchpad already loaded
>     [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
> 
> If I did remove the elapsed time, the output would look like format #3:
>     [21703] 2011-01-07 19:07:18.974 MUTTER: Plugin name launchpad already loaded
>     [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
> 
> which is totally unified, but doesn't save all that many characters.  Is it enough of an improvement to be worth sacrificing the elapsed-time field?
> 
> On the other hand, I could back part-way out, and add *only* the PID to mutter() lines.  That would produce format #4:
>     [21703] 1.234  Plugin name launchpad already loaded
>     [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
> 
> which is shorter, but violates your "more in common" request.

^- This is my personal favorite. mutter lines are far more common than
warning/error lines.

I don't find the absolute date-time to be very useful, when with
pid+elapsed time+log at startup time you can get it if you need to.

[PID] has some real use cases for sorting out which lines belonged to
which process. So I'm in favor of adding it.

John
=:->

> 
> One could change the non-mutter() lines too, e.g. to include *only* elapsed times (format #5):
>     [21703] 1.234 MUTTER: Plugin name launchpad already loaded
>     [21703] 1.236 WARNING: bzr: warning: blah
> 
> But the non-mutter() lines are written by the Python logging subsystem, and hacking that might be beyond my current level of Python- and bzr-fu -- especially under Python 2.4, because the logging module's "extra" feature for adding custom fields only appeared in 2.5.  I can look into doing that, but it'd take me a while.  It might be better to land this branch, or a minor variant of it, and do the more extensive format changes as a follow-on branch if people feel they're warranted.
> 
> 
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk0ogMgACgkQJdeBCYSNAAMZngCgnP1V6ofK4nk9YJ+cetGt1BqS
Q0UAnRlI9/SFC3ipdj0U9sfksakvXDDV
=cqga
-----END PGP SIGNATURE-----

Revision history for this message

Martin Pool (mbp) wrote on 2011-01-09:

On 8 January 2011 09:26, John A Meinel <email address hidden> wrote:
>> On the other hand, I could back part-way out, and add *only* the PID to mutter() lines. That would produce format #4:
>> [21703] 1.234 Plugin name launchpad already loaded
>> [21703] 2011-01-07 19:07:18.974 WARNING: bzr: warning: blah
>>
>> which is shorter, but violates your "more in common" request.
>
> ^- This is my personal favorite. mutter lines are far more common than
> warning/error lines.
>
> I don't find the absolute date-time to be very useful, when with
> pid+elapsed time+log at startup time you can get it if you need to.
>
> [PID] has some real use cases for sorting out which lines belonged to
> which process. So I'm in favor of adding it.

Same here. The word "warning" has some meaning to the user to say
that it's not been fatal etc, but "mutter" is just a random internal
bit.

Possibly we should only log the full time when it's for say a server
log, and then it should probably go to syslog. For the common cases
of just .bzr.log it should not run long enough to matter.

Thanks
--
Martin

Revision history for this message

Eric Siegerman (eric97) wrote on 2011-01-10:

On Sun, 2011-01-09 at 02:16 +0000, Martin Pool wrote:
> On 8 January 2011 09:26, John A Meinel <email address hidden> wrote:
> > I don't find the absolute date-time to be very useful, when with
> > pid+elapsed time+log at startup time you can get it if you need to.

I've got Python logging to emit the elapsed time. Not nearly as
hard as I'd thought; I just hadn't found the right knob yet :-)

That means that format 5 above is feasible. To repeat it:
[21703] 1.234 MUTTER: Plugin name launchpad already loaded
[21703] 1.236 WARNING: bzr: warning: blah

Or leaving out the "MUTTER:" gives format 6 (but see below):
[21703] 1.234 Plugin name launchpad already loaded
[21703] 1.236 WARNING: bzr: warning: blah

> Possibly we should only log the full time when it's for say a server
> log, and then it should probably go to syslog. For the common cases
> of just .bzr.log it should not run long enough to matter.

I think what you're saying is that:
  - "bzr server" and the like should write to syslog instead of to
    .bzr.log (in which case, IIUC, the format isn't bzr's
    decision, but rather the syslog server's)

- other subcommands should write (only) elapsed times to .bzr.log

Have I got that right?

Does bzr currently log to anywhere other than .bzr.log? If so,
obviously I need to avoid breaking that.

> The word "warning" has some meaning to the user to say
> that it's not been fatal etc, but "mutter" is just a random internal
> bit.

True. What the "MUTTER:" does do, though, is eliminate a special
case from the log-file syntax, and in general I dislike special
cases and try to avoid them. In particular, I find log files
easier to read if the columns line up; and if I want to use a
complicated grep on one, or even slurp it into a spreadsheet,
variant line syntaxes need to be worked around. (Admittedly,
this last point is more important for long-lived servers.)

That said, in this case your collective opinion far outweighs
mine, since you spend a lot more time staring at these logs
than I do. I'm happy to implement whatever consensus y'all
come up with.

- Eric

On Sun, 2011-01-09 at 02:16 +0000, Martin Pool wrote:
> On 8 January 2011 09:26, John A Meinel <john@arbash-meinel.com> wrote:
> > I don't find the absolute date-time to be very useful, when with
> > pid+elapsed time+log at startup time you can get it if you need to.

I've got Python logging to emit the elapsed time.  Not nearly as
hard as I'd thought; I just hadn't found the right knob yet :-)

That means that format 5 above is feasible.  To repeat it:
    [21703] 1.234 MUTTER: Plugin name launchpad already loaded
    [21703] 1.236 WARNING: bzr: warning: blah

Or leaving out the "MUTTER:" gives format 6 (but see below):
    [21703] 1.234 Plugin name launchpad already loaded
    [21703] 1.236 WARNING: bzr: warning: blah

> Possibly we should only log the full time when it's for say a server
> log, and then it should probably go to syslog.  For the common cases
> of just .bzr.log it should not run long enough to matter.

- other subcommands should write (only) elapsed times to .bzr.log

Have I got that right?

Does bzr currently log to anywhere other than .bzr.log?  If so,
obviously I need to avoid breaking that.

> The word "warning" has some meaning to the user to say
> that it's not been fatal etc, but "mutter" is just a random internal
> bit.

True.  What the "MUTTER:" does do, though, is eliminate a special
case from the log-file syntax, and in general I dislike special
cases and try to avoid them.  In particular, I find log files
easier to read if the columns line up; and if I want to use a
complicated grep on one, or even slurp it into a spreadsheet,
variant line syntaxes need to be worked around.  (Admittedly,
this last point is more important for long-lived servers.)

That said, in this case your collective opinion far outweighs
mine, since you spend a lot more time staring at these logs
than I do.  I'm happy to implement whatever consensus y'all
come up with.

- Eric

Revision history for this message

Martin Pool (mbp) wrote on 2011-01-11:

On 10 January 2011 16:51, Eric Siegerman <email address hidden> wrote:
> On Sun, 2011-01-09 at 02:16 +0000, Martin Pool wrote:
>> On 8 January 2011 09:26, John A Meinel <email address hidden> wrote:
>> > I don't find the absolute date-time to be very useful, when with
>> > pid+elapsed time+log at startup time you can get it if you need to.
>
> I've got Python logging to emit the elapsed time. Not nearly as
> hard as I'd thought; I just hadn't found the right knob yet :-)
>
> That means that format 5 above is feasible. To repeat it:
> [21703] 1.234 MUTTER: Plugin name launchpad already loaded
> [21703] 1.236 WARNING: bzr: warning: blah
>
> Or leaving out the "MUTTER:" gives format 6 (but see below):
> [21703] 1.234 Plugin name launchpad already loaded
> [21703] 1.236 WARNING: bzr: warning: blah
>
>
>> Possibly we should only log the full time when it's for say a server
>> log, and then it should probably go to syslog. For the common cases
>> of just .bzr.log it should not run long enough to matter.
>
> I think what you're saying is that:
> - "bzr server" and the like should write to syslog instead of to
> .bzr.log (in which case, IIUC, the format isn't bzr's
> decision, but rather the syslog server's)
>
> - other subcommands should write (only) elapsed times to .bzr.log

Right. Actually sending it to syslog is probably a job for a
different patch. On Windows, syslog is probably not the right choice
- we'd want a file or the MS logging infrastructure.

> Does bzr currently log to anywhere other than .bzr.log? If so,
> obviously I need to avoid breaking that.

I don't think so, except there is some special handling in the test suite.

>> The word "warning" has some meaning to the user to say
>> that it's not been fatal etc, but "mutter" is just a random internal
>> bit.
>
> True. What the "MUTTER:" does do, though, is eliminate a special
> case from the log-file syntax, and in general I dislike special
> cases and try to avoid them. In particular, I find log files
> easier to read if the columns line up; and if I want to use a
> complicated grep on one, or even slurp it into a spreadsheet,
> variant line syntaxes need to be worked around. (Admittedly,
> this last point is more important for long-lived servers.)

I see your point. How about making it 'debug' which is more
meaningful to users, and matches the standard severity scale? Maybe
even lowercase for all of them.

--
Martin

On 10 January 2011 16:51, Eric Siegerman <pub08-lp@davor.org> wrote:
> On Sun, 2011-01-09 at 02:16 +0000, Martin Pool wrote:
>> On 8 January 2011 09:26, John A Meinel <john@arbash-meinel.com> wrote:
>> > I don't find the absolute date-time to be very useful, when with
>> > pid+elapsed time+log at startup time you can get it if you need to.
>
> I've got Python logging to emit the elapsed time.  Not nearly as
> hard as I'd thought; I just hadn't found the right knob yet :-)
>
> That means that format 5 above is feasible.  To repeat it:
>    [21703] 1.234 MUTTER: Plugin name launchpad already loaded
>    [21703] 1.236 WARNING: bzr: warning: blah
>
> Or leaving out the "MUTTER:" gives format 6 (but see below):
>    [21703] 1.234 Plugin name launchpad already loaded
>    [21703] 1.236 WARNING: bzr: warning: blah
>
>
>> Possibly we should only log the full time when it's for say a server
>> log, and then it should probably go to syslog.  For the common cases
>> of just .bzr.log it should not run long enough to matter.
>
> I think what you're saying is that:
>  - "bzr server" and the like should write to syslog instead of to
>    .bzr.log (in which case, IIUC, the format isn't bzr's
>    decision, but rather the syslog server's)
>
>  - other subcommands should write (only) elapsed times to .bzr.log

Right.  Actually sending it to syslog is probably a job for a
different patch.  On Windows, syslog is probably not the right choice
- we'd want a file or the MS logging infrastructure.

> Does bzr currently log to anywhere other than .bzr.log?  If so,
> obviously I need to avoid breaking that.

I don't think so, except there is some special handling in the test suite.

>> The word "warning" has some meaning to the user to say
>> that it's not been fatal etc, but "mutter" is just a random internal
>> bit.
>
> True.  What the "MUTTER:" does do, though, is eliminate a special
> case from the log-file syntax, and in general I dislike special
> cases and try to avoid them.  In particular, I find log files
> easier to read if the columns line up; and if I want to use a
> complicated grep on one, or even slurp it into a spreadsheet,
> variant line syntaxes need to be worked around.  (Admittedly,
> this last point is more important for long-lived servers.)

I see your point.  How about making it 'debug' which is more
meaningful to users, and matches the standard severity scale?  Maybe
even lowercase for all of them.

-- 
Martin

Unmerged revisions

5591. By Eric Siegerman <email address hidden> on 2011-01-08: Doc fix.
5590. By Eric Siegerman <email address hidden> on 2011-01-08: Make test_trace.mutter_prefix global.
Adapt test_selftest.TestRunner.test_unicode_test_output_on_ascii_stream()
to the new mutter() format.
5589. By Eric Siegerman <email address hidden> on 2011-01-08: TestTrace._mutter_prefix now accepts any PID.
We used to require this process's PID, but that would fail should we
ever be asked to match against lines written by a subprocess.
5588. By Eric Siegerman <email address hidden> on 2011-01-08: Reorganize and document mutter()'s field generation.
5587. By Eric Siegerman <email address hidden> on 2011-01-08: Fix formatting of mutter() pid to match what Python logger writes.
5586. By Eric Siegerman <email address hidden> on 2011-01-08: Add absolute date/time and "MUTTER" pseudo-log-level to mutter() output.
5585. By Eric Siegerman <email address hidden> on 2011-01-08: Factor out TestTrace._mutter_prefix.
5584. By Eric Siegerman <email address hidden> on 2011-01-08: Prepend "[pid] " to entries output by mutter().
5583. By Eric Siegerman <email address hidden> on 2011-01-07: Add test_mutter_output_format() and test_mutter_formatting().

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk

Subscribers

People subscribed via source and target branches

to all changes:

Alejandro Cornejo2

Bazaar Codereview Subscribers

Benoit Pierre

Eric Siegerman

Gmood

Karl Bielefeldt

Mahmoud Hassan

Matt Nordhoff

Mohd Fikri Mohd Amin

MrJOHN

Václav Haisman

bzr PQM

vincenzo

to status/vote changes:

Alexander Belchenko

amandla2023

 === modified file 'bzrlib/tests/test_selftest.py'
 --- bzrlib/tests/test_selftest.py	2010-12-26 16:23:16 +0000
 +++ bzrlib/tests/test_selftest.py	2011-01-08 09:18:11 +0000
@@ -72,6 +72,7 @@
      TestUtil,
+     )
  from bzrlib.trace import note, mutter
++from bzrlib.tests.test_trace import mutter_prefix
  from bzrlib.transport import memory
  from bzrlib.version import _get_bzr_source_tree
@@ -1296,7 +1297,7 @@
          self.assertContainsRe(out.getvalue(),
              "Text attachment: log\n"
              "-+\n"
--            "\d+\.\d+  \\\\u2606\n"
++            + mutter_prefix + "\\\\u2606\n"
              "-+\n")
 === modified file 'bzrlib/tests/test_trace.py'
 --- bzrlib/tests/test_trace.py	2010-12-16 13:15:42 +0000
 +++ bzrlib/tests/test_trace.py	2011-01-08 09:18:11 +0000
@@ -41,6 +41,13 @@
+     )
++# Each entry written by mutter() must match this regexp, immediately
++# followed by the message text.
++mutter_prefix = (r'\[ *\d+] '
++    r'\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\.\d\d\d '
++    r'[A-Z]+: \d+\.\d+  '
++    )
++
  def _format_exception():
      """Format an exception as it would normally be displayed to the user"""
      buf = StringIO()
@@ -199,7 +206,7 @@
      def assertLogStartsWith(self, log, string):
          """Like assertStartsWith, but skips the log timestamp."""
          self.assertContainsRe(log,
--            '^\\d+\\.\\d+  ' + re.escape(string))
++            mutter_prefix + re.escape(string))
      def test_mutter_callsite_1(self):
          """mutter_callsite can capture 1 level of stack frame."""
@@ -225,6 +232,23 @@
          # this frame should be the final one
          self.assertEndsWith(log, ' "a string")\n')
++    def test_mutter_output_format(self):
++        """mutter()'s output looks like:
++               [pid] elapsed_time message
++           e.g.
++               [ 123] 4.56 message
++        """
++        mutter("hello world")
++        log = self.get_log()
++        self.assertLogStartsWith(log, "hello world\n")
++
++    def test_mutter_formatting(self):
++        """mutter uses its first arg as a format and the rest as values
++        """
++        mutter("hello %s %d", "world", 42)
++        log = self.get_log()
++        self.assertLogStartsWith(log, "hello world 42\n")
++
      def test_mutter_never_fails(self):
          # Even if the decode/encode stage fails, mutter should not
          # raise an exception
@@ -284,13 +308,14 @@
              # the files were opened in binary mode, so should have exactly
              # these bytes.  and removing the file as the log target should
              # have caused them to be flushed out.  need to match using regexps
--            # as there's a timestamp at the front.
++            # as there are some extra fields at the front.
              tmp1.seek(0)
              self.assertContainsRe(tmp1.read(),
--                r"\d+\.\d+  comment to file1\n\d+\.\d+  again to file1\n")
++                mutter_prefix + r"comment to file1\n" +
++                mutter_prefix + r"again to file1\n")
              tmp2.seek(0)
              self.assertContainsRe(tmp2.read(),
--                r"\d+\.\d+  comment to file2\n")
++                mutter_prefix + r"comment to file2\n")
          finally:
              tmp1.close()
              tmp2.close()
 === modified file 'bzrlib/trace.py'
 --- bzrlib/trace.py	2010-10-05 23:30:18 +0000
 +++ bzrlib/trace.py	2011-01-08 09:18:11 +0000
@@ -55,6 +55,7 @@
  # that.
  import codecs
++import datetime
  import logging
  import os
  import sys
@@ -183,9 +184,20 @@
          out = fmt % tuple(real_args)
      else:
          out = fmt
++
      now = time.time()
--    timestamp = '%0.3f  ' % (now - _bzr_log_start_time,)
--    out = timestamp + out + '\n'
++    elapsed = now - _bzr_log_start_time
++    # Reuse "now" to avoid potential skew between elapsed time and
++    # absolute date/time
++    now_dt = datetime.datetime.fromtimestamp(now)
++    # We want the seconds to three decimal places, but datetime.strftime()
++    # offers no (portable) code for milliseconds, and datetime.isodate()
++    # produces either 0 or 6 places and also might include a timezone offset.
++    # So roll our own.
++    abs_time = now_dt.strftime("%Y-%m-%d %H:%M:%S")     # %S -> *integral* secs
++    abs_millis = now_dt.microsecond / 1000
++    out = "[%5d] %s.%03d MUTTER: %0.3f  %s\n" % (
++        os.getpid(), abs_time, abs_millis, elapsed, out)
      _trace_file.write(out)
      # there's no explicit flushing; the file is typically line buffered.