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

Proposed by Eric Siegerman
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
Reviewer Review Type Date Requested Status
bzr-core 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.)

To post a comment you must log in.
lp:~eric97/bzr/mutter-pid updated
5589. By Eric Siegerman <email address hidden>

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>

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 :

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 :

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

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
5591. By Eric Siegerman <email address hidden>

Doc fix.

Revision history for this message
John A Meinel (jameinel) wrote :
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 &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+cetGt...

Read more...

Revision history for this message
Martin Pool (mbp) wrote :

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

Revision history for this message
Martin Pool (mbp) wrote :

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

Unmerged revisions

5591. By Eric Siegerman <email address hidden>

Doc fix.

5590. By Eric Siegerman <email address hidden>

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>

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>

Reorganize and document mutter()'s field generation.

5587. By Eric Siegerman <email address hidden>

Fix formatting of mutter() pid to match what Python logger writes.

5586. By Eric Siegerman <email address hidden>

Add absolute date/time and "MUTTER" pseudo-log-level to mutter() output.

5585. By Eric Siegerman <email address hidden>

Factor out TestTrace._mutter_prefix.

5584. By Eric Siegerman <email address hidden>

Prepend "[pid] " to entries output by mutter().

5583. By Eric Siegerman <email address hidden>

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
=== 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 @@
72 TestUtil,72 TestUtil,
73 )73 )
74from bzrlib.trace import note, mutter74from bzrlib.trace import note, mutter
75from bzrlib.tests.test_trace import mutter_prefix
75from bzrlib.transport import memory76from bzrlib.transport import memory
76from bzrlib.version import _get_bzr_source_tree77from bzrlib.version import _get_bzr_source_tree
7778
@@ -1296,7 +1297,7 @@
1296 self.assertContainsRe(out.getvalue(),1297 self.assertContainsRe(out.getvalue(),
1297 "Text attachment: log\n"1298 "Text attachment: log\n"
1298 "-+\n"1299 "-+\n"
1299 "\d+\.\d+ \\\\u2606\n"1300 + mutter_prefix + "\\\\u2606\n"
1300 "-+\n")1301 "-+\n")
13011302
13021303
13031304
=== 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 @@
41 )41 )
4242
4343
44# Each entry written by mutter() must match this regexp, immediately
45# followed by the message text.
46mutter_prefix = (r'\[ *\d+] '
47 r'\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\.\d\d\d '
48 r'[A-Z]+: \d+\.\d+ '
49 )
50
44def _format_exception():51def _format_exception():
45 """Format an exception as it would normally be displayed to the user"""52 """Format an exception as it would normally be displayed to the user"""
46 buf = StringIO()53 buf = StringIO()
@@ -199,7 +206,7 @@
199 def assertLogStartsWith(self, log, string):206 def assertLogStartsWith(self, log, string):
200 """Like assertStartsWith, but skips the log timestamp."""207 """Like assertStartsWith, but skips the log timestamp."""
201 self.assertContainsRe(log,208 self.assertContainsRe(log,
202 '^\\d+\\.\\d+ ' + re.escape(string))209 mutter_prefix + re.escape(string))
203210
204 def test_mutter_callsite_1(self):211 def test_mutter_callsite_1(self):
205 """mutter_callsite can capture 1 level of stack frame."""212 """mutter_callsite can capture 1 level of stack frame."""
@@ -225,6 +232,23 @@
225 # this frame should be the final one232 # this frame should be the final one
226 self.assertEndsWith(log, ' "a string")\n')233 self.assertEndsWith(log, ' "a string")\n')
227234
235 def test_mutter_output_format(self):
236 """mutter()'s output looks like:
237 [pid] elapsed_time message
238 e.g.
239 [ 123] 4.56 message
240 """
241 mutter("hello world")
242 log = self.get_log()
243 self.assertLogStartsWith(log, "hello world\n")
244
245 def test_mutter_formatting(self):
246 """mutter uses its first arg as a format and the rest as values
247 """
248 mutter("hello %s %d", "world", 42)
249 log = self.get_log()
250 self.assertLogStartsWith(log, "hello world 42\n")
251
228 def test_mutter_never_fails(self):252 def test_mutter_never_fails(self):
229 # Even if the decode/encode stage fails, mutter should not253 # Even if the decode/encode stage fails, mutter should not
230 # raise an exception254 # raise an exception
@@ -284,13 +308,14 @@
284 # the files were opened in binary mode, so should have exactly308 # the files were opened in binary mode, so should have exactly
285 # these bytes. and removing the file as the log target should309 # these bytes. and removing the file as the log target should
286 # have caused them to be flushed out. need to match using regexps310 # have caused them to be flushed out. need to match using regexps
287 # as there's a timestamp at the front.311 # as there are some extra fields at the front.
288 tmp1.seek(0)312 tmp1.seek(0)
289 self.assertContainsRe(tmp1.read(),313 self.assertContainsRe(tmp1.read(),
290 r"\d+\.\d+ comment to file1\n\d+\.\d+ again to file1\n")314 mutter_prefix + r"comment to file1\n" +
315 mutter_prefix + r"again to file1\n")
291 tmp2.seek(0)316 tmp2.seek(0)
292 self.assertContainsRe(tmp2.read(),317 self.assertContainsRe(tmp2.read(),
293 r"\d+\.\d+ comment to file2\n")318 mutter_prefix + r"comment to file2\n")
294 finally:319 finally:
295 tmp1.close()320 tmp1.close()
296 tmp2.close()321 tmp2.close()
297322
=== 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 @@
55# that.55# that.
5656
57import codecs57import codecs
58import datetime
58import logging59import logging
59import os60import os
60import sys61import sys
@@ -183,9 +184,20 @@
183 out = fmt % tuple(real_args)184 out = fmt % tuple(real_args)
184 else:185 else:
185 out = fmt186 out = fmt
187
186 now = time.time()188 now = time.time()
187 timestamp = '%0.3f ' % (now - _bzr_log_start_time,)189 elapsed = now - _bzr_log_start_time
188 out = timestamp + out + '\n'190 # Reuse "now" to avoid potential skew between elapsed time and
191 # absolute date/time
192 now_dt = datetime.datetime.fromtimestamp(now)
193 # We want the seconds to three decimal places, but datetime.strftime()
194 # offers no (portable) code for milliseconds, and datetime.isodate()
195 # produces either 0 or 6 places and also might include a timezone offset.
196 # So roll our own.
197 abs_time = now_dt.strftime("%Y-%m-%d %H:%M:%S") # %S -> *integral* secs
198 abs_millis = now_dt.microsecond / 1000
199 out = "[%5d] %s.%03d MUTTER: %0.3f %s\n" % (
200 os.getpid(), abs_time, abs_millis, elapsed, out)
189 _trace_file.write(out)201 _trace_file.write(out)
190 # there's no explicit flushing; the file is typically line buffered.202 # there's no explicit flushing; the file is typically line buffered.
191203