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

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[Dave Hylands [:dhylands]]

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.

Comment 1

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

The console implementation is proxied.  Looks like the impl is unconditionally dumping to logcat but then also proxying.  We should just always proxy.

Comment 2

[Dave Hylands [:dhylands]]

I'd prefer that the logcat be done by the process that the console.info command originated from. Then the PID is correct.

Comment 3

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

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.

Comment 4

[Jose Manuel Cantera]

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.

Comment 5

[Andrew Overholt [:overholt]]

While we need to fix this, we can't block on it.

Comment 6

[Dave Hylands [:dhylands]]

Attachment: Make OOP console logs show up exactly once in logcat

Comment 7

[Josh Matthews [:jdm]]

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?

Comment 8

[Dave Hylands [:dhylands]]

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 9

[Philipp von Weitershausen [:philikon]]

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.

Comment 10

[Boris Zbarsky [: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.

Comment 11

[Dave Hylands [:dhylands]]

Attachment: Reworked patch to not modify IDL

I reworked the patch so that it no longer needs to make any IDL changes.

Comment 12

[Boris Zbarsky [: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

Comment 13

[Dave Hylands [:dhylands]]

(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

Comment 14

[Boris Zbarsky [:bzbarsky]]

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

So you do.  Reading comprehension fail on my part, sorry.  :(

Comment 15

[Dave Hylands [:dhylands]]

Pushed to inbound
https://hg.mozilla.org/integration/mozilla-inbound/rev/e80cebf5468b

Comment 16

[Dave Hylands [:dhylands]]

Fixed bustage on inbound:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fc4edef8bbed

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e80cebf5468b
https://hg.mozilla.org/mozilla-central/rev/fc4edef8bbed

Comment 18

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

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.

Comment 19

[Ryan VanderMeulen [:RyanVM]]

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