Closed Bug 783630 Opened 7 years ago Closed 7 years ago

console.info output shows up twice in logcat when done from OOP apps

Categories

(Firefox OS Graveyard :: General, defect, major)

x86_64
Gonk (Firefox OS)
defect
Not set
major

Tracking

(blocking-kilimanjaro:?, blocking-basecamp:-, firefox19 fixed, b2g18 fixed)

RESOLVED FIXED
DeveloperPhone
blocking-kilimanjaro ?
blocking-basecamp -
Tracking Status
firefox19 --- fixed
b2g18 --- fixed

People

(Reporter: dhylands, Assigned: dhylands)

Details

Attachments

(1 file, 1 obsolete file)

If you call console.info("some text"); from JS running in an OOP app, then you will see 2 logcats:

11:36:01.229 1175/1175              GeckoConsole  E   Content JS INFO at app://gallery.b2g.hylands.org/shared/js/mediadb.js:268 in initDeviceStorage: initDeviceStorage called
11:36:01.269 1150/1150              GeckoConsole  E   Content JS INFO at app://gallery.b2g.hylands.org/shared/js/mediadb.js:268 in initDeviceStorage: initDeviceStorage called

The first one (PID 1175/1175) comes from the plugin-container, and the second one (PID 1150) comes from the b2g main app.
The console implementation is proxied.  Looks like the impl is unconditionally dumping to logcat but then also proxying.  We should just always proxy.
I'd prefer that the logcat be done by the process that the console.info command originated from. Then the PID is correct.
Current jsconsole won't work if we do that, AFAIK.  It's easy to log the pid (etc.) from the centralized location.

In the long run though, I agree with you --- devtools need to be multiprocess aware.
The duplication of messages is very unfortunate and misleads developers both Gaia developers and future B2G developers, thus I'm requesting to change this bug blocking-basecamp+ to ensure that the developer phone is fixed at that respect.
Severity: normal → major
blocking-basecamp: --- → ?
OS: Linux → Gonk
Target Milestone: --- → DeveloperPhone
blocking-kilimanjaro: --- → ?
While we need to fix this, we can't block on it.
blocking-basecamp: ? → -
Attachment #677683 - Flags: review?(philipp)
Comment on attachment 677683 [details] [diff] [review]
Make OOP console logs show up exactly once in logcat

Why not just make the android-specific code only execute in the parent process?
Sometimes it's really useful to know which process/thread the output is coming from.

By leaving the __android_log call in the child, that is accomplished
(logcat -v threadtime shows timestamps and the PID/TID of the caller).
Comment on attachment 677683 [details] [diff] [review]
Make OOP console logs show up exactly once in logcat

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

Flinging this one over to bz as well.

::: xpcom/base/nsIConsoleService.idl
@@ +13,5 @@
> +%{ C++
> +    enum {
> +        SuppressLog = 0,
> +        OutputToLog = 1
> +    };

I think the way we typically do this is to put consts on the interface. XPIDL automatically converts them to enums IIRC.
Attachment #677683 - Flags: review?(philipp) → review?(bzbarsky)
Comment on attachment 677683 [details] [diff] [review]
Make OOP console logs show up exactly once in logcat

Indeed.  Just define constants on the interface.

That said, there needs to be some documentation for the new method.  And if you're planning to land this on aurora you need to mark this as an addon compat problem, since you're changing the vtable...

r=me with that, but I'd like to see the API comments.
Attachment #677683 - Flags: review?(bzbarsky) → review+
I reworked the patch so that it no longer needs to make any IDL changes.
Attachment #677683 - Attachment is obsolete: true
Attachment #677926 - Flags: review?(bzbarsky)
Comment on attachment 677926 [details] [diff] [review]
Reworked patch to not modify IDL

I assume there are no ContentParents that live through shutdown, which is why you don't have to drop your ref?

The getter should just return a raw non-addrefed pointer, since you're just storing it in a member anyway.

s/NS_IMETHOD/virtual nsresult/ and s/NS_IMETHODIMP/nsresult/.

r=me with those nits
Attachment #677926 - Flags: review?(bzbarsky) → review+
(In reply to Boris Zbarsky (:bz) from comment #12)
> Comment on attachment 677926 [details] [diff] [review]
> Reworked patch to not modify IDL
> 
> I assume there are no ContentParents that live through shutdown, which is
> why you don't have to drop your ref?

I drop the ref (set mConsoleService to nullptr) in the ContentParent::ActorDestroy which is where ContentParent seems to be doing all of its shutdown stuff (removing xpcom-shutdown observer plus others, etc)

> The getter should just return a raw non-addrefed pointer, since you're just
> storing it in a member anyway.

That makes things a bit simpler too.

> s/NS_IMETHOD/virtual nsresult/ and s/NS_IMETHODIMP/nsresult/.
> 
> r=me with those nits

Thanks
> I drop the ref (set mConsoleService to nullptr) in the ContentParent::ActorDestroy

So you do.  Reading comprehension fail on my part, sorry.  :(
Assignee: nobody → dhylands
Comment on attachment 677926 [details] [diff] [review]
Reworked patch to not modify IDL

[Triage Comment]
This has been working on m-c for a while now, and we're having lots of problems with wifi, so anything that can help with debugging that is a big help.
Attachment #677926 - Flags: approval-mozilla-beta+
Attachment #677926 - Flags: approval-mozilla-aurora+
Attachment #677926 - Flags: approval-mozilla-beta+ → approval-mozilla-b2g18+
This landed when m-c was still Mozilla19, so it's already on Aurora.

https://hg.mozilla.org/releases/mozilla-b2g18/rev/e3cf3f457660
https://hg.mozilla.org/releases/mozilla-b2g18/rev/4ddf7580bfea
Whiteboard: [status-b2g18:fixed]
Whiteboard: [status-b2g18:fixed]
You need to log in before you can comment on or make changes to this bug.