1248565 - NSPR logging and XPCOM Logging write to the same file

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Honza Bambas (:mayhemer)]

Just discovered that NSPR logging first opens (fopen/PR_Open [1]) a file specified in NSPR_LOG_FILE and later xpcom/base/Logging opens the same file path again (fopen [2]).  Seems like only mozilla::Logging writes to it now.

When we link with mozilla::Logging NSPR logging init should be bypassed (at compile time) and any use of that framework should assert(false).

[1]:
>	nss3.dll!_PR_InitLog() Line 241	C
 	nss3.dll!_PR_InitStuff() Line 206	C
 	nss3.dll!_PR_ImplicitInitialization() Line 226	C
 	nss3.dll!PR_GetCurrentThread(...) Line 143	C
 	xul.dll!nsAutoOwningThread::nsAutoOwningThread() Line 109	C++
 	xul.dll!ComponentsSH::ComponentsSH(0) Line 3522	C++
 	xul.dll!`dynamic initializer for 'ComponentsSH::singleton''() Line 3539	C++
 	msvcr120.dll!_initterm(0x00000465, 0x1657e9bc) Line 954	C
 	xul.dll!_CRT_INIT(0x0fba0000, 1, 0x00000000) Line 295	C
 	xul.dll!__DllMainCRTStartup(0x0fba0000, 1, 0x00000000) Line 502	C
 	xul.dll!_DllMainCRTStartup(0x0fba0000, 1, 0x00000000) Line 472	C
 	ntdll.dll!_LdrxCallInitRoutine@16()	Unknown
 	ntdll.dll!LdrpCallInitRoutine()	Unknown
 	ntdll.dll!LdrpInitializeNode()	Unknown
 	ntdll.dll!LdrpInitializeGraphRecurse()	Unknown
 	ntdll.dll!LdrpPrepareModuleForExecution()	Unknown
 	ntdll.dll!LdrpLoadDllInternal()	Unknown
 	ntdll.dll!LdrpLoadDll()	Unknown
 	ntdll.dll!_LdrLoadDll@16()	Unknown
 	mozglue.dll!`anonymous namespace'::patched_LdrLoadDll(0x00000009, 0x0018f600, 0x0018f610, 0x0018f604) Line 714	C++
 	KernelBase.dll!_LoadLibraryExW@12()	Unknown
 	firefox.exe!GetLibHandle(0x0018f65c) Line 53	C++
 	firefox.exe!ReadDependentCB(0x0018f65c, true) Line 214	C++
 	firefox.exe!ReadDependentCB(0x0018f9b8, true) Line 228	C++
 	firefox.exe!XPCOMGlueLoad(0x0018fafc) Line 383	C++
 	firefox.exe!XPCOMGlueStartup(0x0018fafc) Line 485	C++
 	firefox.exe!InitXPCOMGlue(0x005716f8, 0x0018fc38) Line 262	C++
 	firefox.exe!NS_internal_main(4, 0x005716c8, 0x00574d20) Line 327	C++
 	firefox.exe!wmain(4, 0x005758a8) Line 135	C++


[2]:
>	xul.dll!mozilla::LogModuleManager::Init() Line 145	C++
 	xul.dll!mozilla::LogModule::Init() Line 284	C++
 	xul.dll!NS_InitXPCOM2(0x00c050c8, 0x00c1c220, 0x0018f93c) Line 493	C++
 	xul.dll!ScopedXPCOMStartup::Initialize() Line 1497	C++
 	xul.dll!XREMain::XRE_main(4, 0x005716c8, 0x0018fa38) Line 4376	C++
 	xul.dll!XRE_main(4, 0x005716c8, 0x0018fa38, 0) Line 4482	C++
 	firefox.exe!do_main(4, 0x005716c8, 0x00574d20, 0x00c1c100) Line 220	C++
 	firefox.exe!NS_internal_main(4, 0x005716c8, 0x00574d20) Line 360	C++
 	firefox.exe!wmain(4, 0x005758a8) Line 135	C++

Comment 1

[Nicholas Nethercote [inactive]]

erahm, care to take a look?

Comment 2

[Eric Rahm [:erahm]]

Honza, I agree this is an issue, I'm not sure what you're suggesting as a solution. Do you want me to add some sort of |#ifdef MOZILLA don't init| to NSPR/NSS? That's probably not going to be feasible given:
  1) I haven't had much luck getting logging changes landed into NSPR
  2) They do need to init their loggers (NSPR and NSS use NSPR logging)
  3) They aren't going to switch to mozilla logging

Some thoughts:
  1) We could just log to a different file (add -moz to the name?)
  2) We could open the file in a non-exclusive mode

Comment 3

[Honza Bambas (:mayhemer)]

(In reply to Eric Rahm [:erahm] from comment #2)
> Honza, I agree this is an issue, I'm not sure what you're suggesting as a
> solution. 

Actually, I'm also not sure what the solution should be here...

> Do you want me to add some sort of |#ifdef MOZILLA don't init| to
> NSPR/NSS? That's probably not going to be feasible given:
>   1) I haven't had much luck getting logging changes landed into NSPR

Me neither! :D

>   2) They do need to init their loggers (NSPR and NSS use NSPR logging)
>   3) They aren't going to switch to mozilla logging
> 
> Some thoughts:
>   1) We could just log to a different file (add -moz to the name?)
>   2) We could open the file in a non-exclusive mode

Other possible solution could be to use a different env vars for mozlog (actually I don't think it would be a bad idea regardless this bug!)  


Add new MOZ_LOG_MODULES and MOZ_LOG_FILE.  But when those are not set, fallback to NSPR_LOG_* env vars!  This preserves compatibility, as well as we can start use MOZ_LOG* for test harness, daily development.

An NS_WARNING that NSPR file and MOZ file are identical can be issued.


If you are against, let's try to go with your 2) first.  If there are problems (like overrides from NSS) we should add a suffix to the mozlogging file..

Comment 4

[Honza Bambas (:mayhemer)]

what do you think about comment 3 and MOZ_LOG_* variables?

Comment 5

[Eric Rahm [:erahm]]

(In reply to Honza Bambas (:mayhemer) from comment #4)
> what do you think about comment 3 and MOZ_LOG_* variables?

I think its a reasonable solution, the one downside is that if we switch to MOZ_LOG_* in the test harness is we won't get NSPR/NSS's logs, but I suppose we could set NSPR_LOG_* as well.

Comment 6

[Honza Bambas (:mayhemer)]

Attachment: part1 - core, v1

As suggested.  A pretty simple patch.

Comment 7

[Eric Rahm [:erahm]]

Comment on attachment 8729037 [details] [diff] [review]
part1 - core, v1

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

r=me Thank you for taking care of this. We might also want file follow ups to update the few references in our test harnesses.

Comment 8

[Nathan Froyd [:froydnj]]

A dev-platform post would be helpful, too, I think.

Comment 9

[Honza Bambas (:mayhemer)]

(In reply to Eric Rahm [:erahm] (Out until 3/10) from comment #7)
> Comment on attachment 8729037 [details] [diff] [review]
> v1 (part1 - core)
> 
> Review of attachment 8729037 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> r=me Thank you for taking care of this. We might also want file follow ups
> to update the few references in our test harnesses.

I already have the patches, I'll rather put them here if there are some problems coming out of them, we can stop this effort soon.  We should land these as a whole IMO.

(In reply to Nathan Froyd [:froydnj] from comment #8)
> A dev-platform post would be helpful, too, I think.

Having a draft already written, yes ;)

Comment 10

[Nathan Froyd [:froydnj]]

(In reply to Honza Bambas (:mayhemer) from comment #9)
> (In reply to Nathan Froyd [:froydnj] from comment #8)
> > A dev-platform post would be helpful, too, I think.
> 
> Having a draft already written, yes ;)

Excellent, thank you!

Comment 11

[Honza Bambas (:mayhemer)]

Attachment: part2 - child process log name altering, v1

- works with both, NSPR and MOZ logging.

Comment 12

[Honza Bambas (:mayhemer)]

Attachment: part3 - test infra update, v1

runtests.py now only works with the new MOZ_LOG* vars.  NSPR_LOG_* is no longer supported.  I personally don't remember when I last used logging of something that only NSPR code or NSS code was producing.  So I think it's fine for now.

When needed, can be added the support.

Comment 13

[Honza Bambas (:mayhemer)]

And here is a try run if this all works
https://treeherder.mozilla.org/#/jobs?repo=try&revision=09e2d8b999b6

Comment 14

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8729585 [details] [diff] [review]
part3 - test infra update, v1

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

just one question- everything else seems great.

::: testing/mochitest/runtests.py
@@ -1194,5 @@
>          # this script).
> -        self.nsprLogs = NSPR_LOG_MODULES and "MOZ_UPLOAD_DIR" in os.environ
> -        if self.nsprLogs:
> -            browserEnv["NSPR_LOG_MODULES"] = NSPR_LOG_MODULES
> -            browserEnv["GECKO_SEPARATE_NSPR_LOGS"] = "1"

what about GECKO_SEPARATE_NSPR_LOGS?

Comment 15

[Honza Bambas (:mayhemer)]

(In reply to Joel Maher (:jmaher) from comment #14)
> 
> what about GECKO_SEPARATE_NSPR_LOGS?

Ah, sorry, forget to mention it.  That env var is no longer used and we always separate the child logs.  Hence removed when I'm here.

Comment 16

[Joel Maher ( :jmaher ) (UTC -8)]

great!

Comment 17

[Honza Bambas (:mayhemer)]

(In reply to Honza Bambas (:mayhemer) from comment #13)
> And here is a try run if this all works
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=09e2d8b999b6

Seems to be working!

Comment 18

[Honza Bambas (:mayhemer)]

Also it seems like many places are not migrated to the new logging API (LazyLogModule):

https://mxr.mozilla.org/mozilla-central/search?string=PR_NewLogModule(%22

All of these will not be put to a log when only the MOZ_LOG_* vars will be defined.  Is there a bug filed to do the remaining migration?

Comment 19

[Eric Rahm [:erahm]]

(In reply to Honza Bambas (:mayhemer) from comment #18)
> Also it seems like many places are not migrated to the new logging API
> (LazyLogModule):
> 
> https://mxr.mozilla.org/mozilla-central/search?string=PR_NewLogModule(%22
> 
> All of these will not be put to a log when only the MOZ_LOG_* vars will be
> defined.  Is there a bug filed to do the remaining migration?

We can (and must) ignore the |nsprpub| and |security/nss| items. See bug 1219461 and its dependencies for bugs on replacing the rest. It looks like the contributor who picked most of them up has stalled out.

Comment 20

[Honza Bambas (:mayhemer)]

(In reply to Honza Bambas (:mayhemer) from comment #11)
> Created attachment 8729583 [details] [diff] [review]
> part2 - child process log name altering, v1
> 
> - works with both, NSPR and MOZ logging.

Jason, the review is simple.  Please don't let this rot.

Comment 21

[Honza Bambas (:mayhemer)]

Thanks!

Comment 22

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b01c58d030d0
https://hg.mozilla.org/integration/mozilla-inbound/rev/fc3daa3b3aef
https://hg.mozilla.org/integration/mozilla-inbound/rev/deba80c525f0

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b01c58d030d0
https://hg.mozilla.org/mozilla-central/rev/fc3daa3b3aef
https://hg.mozilla.org/mozilla-central/rev/deba80c525f0

Comment 24

[Honza Bambas (:mayhemer)]

The documentation for the new XPCOM logging engine should be updated with this reference to these new env vars.

Eric, can you either do it or give me the link to that document and I may update it?

Comment 25

[Eric Rahm [:erahm]]

(In reply to Honza Bambas (:mayhemer) from comment #24)
> The documentation for the new XPCOM logging engine should be updated with
> this reference to these new env vars.
> 
> Eric, can you either do it or give me the link to that document and I may
> update it?

I'll take care of this, we don't even have MOZ_LOG documentation up yet. Thanks for getting this in Honza!

Comment 26

[Ralph Giles (:rillian)]

Attachment: MozReview Request: Bug 1248565 - Switch debugging to MOZ_LOG. r?erahm

This is shorter than MOZ_LOG_MODULES and equally clear.

Also add a deprecation warning to encourge folks to migrate.

Review commit: https://reviewboard.mozilla.org/r/54982/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54982/

Comment 27

[Ralph Giles (:rillian)]

Comment on attachment 8756144 [details]
MozReview Request: Bug 1248565 - Switch debugging to MOZ_LOG. r?erahm

Sorry, wrong bug number.

Comment 28

[Ralph Giles (:rillian)]

Follow-up is bug 1275439. Looks like you found it.

Comment 29

[Honza Bambas (:mayhemer)]

Can you please tell me the correct bug#?  I'd like to overlook the bug.

Comment 30

[Ralph Giles (:rillian)]

Comment on attachment 8756144 [details]
MozReview Request: Bug 1248565 - Switch debugging to MOZ_LOG. r?erahm

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54982/diff/1-2/

Comment 31

[Ralph Giles (:rillian)]

Comment on attachment 8756144 [details]
MozReview Request: Bug 1248565 - Switch debugging to MOZ_LOG. r?erahm

Oops, I did it again.

Comment 32

[Boris Zbarsky [:bzbarsky]]

We have tons of documentation that will need to be updated for this, right?  And some of it will probably need to talk about both ways of doing it for a bit.... I'm thinking of https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging for example.

Comment 33

[Honza Bambas (:mayhemer)]

So far, we are fully backwards compatible, so no rush.  But this is definitely one place to update soon, we give it to people quite often.