1428979 - MOZ_LOG should make it possible/easy to know the pid of the logging process under e10s using mach

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Andrew Sutherland [:asuth] (he/him)]

Attachment: Include the pid with the thread name.

MOZ_LOG's default format output identifies the thread name, but not the process id of the logging process.  This is confusing under e10s.

My most immediate use-case is running tests under mach.  mach and its logging helpers attempt to identify the process that logged something, but since the content processes just inherit the stderr of the parent process, all output is identified as originating from the parent process.  (In order for mach to understand what's happening, e10s process spawning would need to mint a new stderr fd for each content process and use magic sendmsg to send the fd out to mach or whatever the fd-aware wrapper magic is.)

My naive solution is to just prepend the thread name with the pid in all cases.  Log parsers that rely on the wrapping []'s for parsing like :mayhemer's logan tool[1] should be fine with the change if they treat the thread names as opaque strings.  Other options include adding a "pid" flag like "timestamp", but having pid be anything but the default seems un-helpful for a browser that ships with e10s on by default.

1: https://github.com/mayhemer/logan/blob/master/logan-rules.js#L5

Comment 1

[Eric Rahm [:erahm]]

Comment on attachment 8940955 [details] [diff] [review]
Include the pid with the thread name.

Review of attachment 8940955 [details] [diff] [review]:
-----------------------------------------------------------------

This seems reasonable. My only concern is that we're increasing the line length yet again, but I agree that having the PID in there is more useful than not. As you noted this might break some log parsers (such as my log-spam-alyzer) but that's easy enough to fix. Can you send a quick note to dev-platform before landing as a heads up?

::: xpcom/base/Logging.cpp
@@ +363,5 @@
>    void Print(const char* aName, LogLevel aLevel, const char* aFmt, va_list aArgs)
>      MOZ_FORMAT_PRINTF(4, 0)
>    {
> +    // We don't do nuwa-style forking anymore, so our pid can't change.
> +    static base::ProcessId pid = base::GetCurrentProcId();

Super minor nit:

Maybe we should cast this to a known printf-friendly-type? On Win it's DWORD otherwise pid_t, I don't really know the rules for pid_t. So maybe just explicitly `static_cast<int>` and keep the '%d' below or `static_cast<long>` and switch to '%ld' below.

Comment 2

[Andrew Sutherland [:asuth] (he/him)]

Attachment: Include the pid with the thread name v2.

This casts to a long as proposed.  Try run of just builds coming up plus post to dev-platform.

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c6b6c513a6c655a6a34580ff95533a8a5ac68a41

Comment 4

[Nathan Froyd [:froydnj]]

Does it make any sense to add MOZ_LOG options to turn off bits that increase the line length (nopid, notid, etc.)?

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e136381fa9018b61b384a7fde24eb09b1aa2d836

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Nathan Froyd [:froydnj] from comment #4)
> Does it make any sense to add MOZ_LOG options to turn off bits that increase
> the line length (nopid, notid, etc.)?

Is this something you or another non-hypothetical person would desire?  At some point it seems like enabling a limited width display might be better accomplished via a script that the log output can be piped through to re-format to the terminal width as a columnar display with wrapping and truncation.  (Not entirely hypothetical.  I'm hacking on a derived version of :mayhemer's logan tool, and I've been thinking about hacking up a very limited non-curses colorizing command-line filter using part of the pipeline.)

Comment 7

[Eric Rahm [:erahm]]

(In reply to Andrew Sutherland [:asuth] from comment #6)
> (In reply to Nathan Froyd [:froydnj] from comment #4)
> > Does it make any sense to add MOZ_LOG options to turn off bits that increase
> > the line length (nopid, notid, etc.)?
> 
> Is this something you or another non-hypothetical person would desire?  At
> some point it seems like enabling a limited width display might be better
> accomplished via a script that the log output can be piped through to
> re-format to the terminal width as a columnar display with wrapping and
> truncation.  (Not entirely hypothetical.  I'm hacking on a derived version
> of :mayhemer's logan tool, and I've been thinking about hacking up a very
> limited non-curses colorizing command-line filter using part of the
> pipeline.)

I think it's overkill. Of course, Nathan, feel free to file a follow up to add those options if you feel strongly. I think in the end a better solution would be to add some sort of structured logging and consumers can output as they see fit. jimb is, in theory, working on something that could be the basis of that (think OnePipeline for all the outputs).

Comment 8

[Andrew Sutherland [:asuth] (he/him)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/e8663f41a424979b28d588bb850ffbb3fe4247cc
Bug 1428979 - MOZ_LOG should include the pid with the thread name by default. r=erahm

Comment 9

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/e8663f41a424

Comment 10

[Nathan Froyd [:froydnj]]

I don't feel particularly strongly about the options, was just throwing them out for discussion, since we've had the "oh, but longer log lines" review comments come up several times.  Post-processing the logs in some way seems like a reasonable thing to do, especially if we had some common framework (e.g. mach commands).