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

RESOLVED FIXED in Firefox 59

Status

()

defect
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: asuth, Assigned: asuth)

Tracking

(Blocks 1 bug)

unspecified
mozilla59
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox59 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

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
Attachment #8940955 - Flags: review?(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.
Attachment #8940955 - Flags: review?(erahm) → review+
This casts to a long as proposed.  Try run of just builds coming up plus post to dev-platform.
Assignee: nobody → bugmail
Attachment #8940955 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #8941477 - Flags: review+
Does it make any sense to add MOZ_LOG options to turn off bits that increase the line length (nopid, notid, etc.)?
(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.)
(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).
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
https://hg.mozilla.org/mozilla-central/rev/e8663f41a424
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
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).
You need to log in before you can comment on or make changes to this bug.