1219480 - Replace PRLogModuleInfo usage with LazyLogModule in dom/media

Status: RESOLVED FIXED

(Core :: WebRTC, defect, P2)

Description

[Eric Rahm [:erahm]]

This covers replacing PRLogModuleInfo w/ LazyLogModule in everything in the 'dom/media/' directory

Current usage:
> ./dom/media/CubebUtils.cpp:129:  gAudioStreamLog = PR_NewLogModule("AudioStream");
> ./dom/media/directshow/DirectShowReader.cpp:26:    log = PR_NewLogModule("DirectShowDecoder");
> ./dom/media/DOMMediaStream.cpp:322:    gMediaStreamLog = PR_NewLogModule("MediaStream");
> ./dom/media/eme/EMEUtils.cpp:14:    log = PR_NewLogModule("EME");
> ./dom/media/eme/EMEUtils.cpp:22:    log = PR_NewLogModule("EMEV");
> ./dom/media/encoder/MediaEncoder.cpp:83:    gMediaEncoderLog = PR_NewLogModule("MediaEncoder");
> ./dom/media/encoder/TrackEncoder.cpp:41:    gTrackEncoderLog = PR_NewLogModule("TrackEncoder");
> ./dom/media/encoder/VorbisTrackEncoder.cpp:29:    gVorbisTrackEncoderLog = PR_NewLogModule("VorbisTrackEncoder");
> ./dom/media/encoder/VP8TrackEncoder.cpp:41:    gVP8TrackEncoderLog = PR_NewLogModule("VP8TrackEncoder");
> ./dom/media/fmp4/MP4Demuxer.cpp:26:    log = PR_NewLogModule("MP4Demuxer");
> ./dom/media/gmp/GMPService.cpp:54:    sLog = PR_NewLogModule("GMP");
> ./dom/media/imagecapture/ImageCapture.cpp:25:    log = PR_NewLogModule("ImageCapture");
> ./dom/media/Latency.cpp:45:    sLog = PR_NewLogModule("MediaLatency");
> ./dom/media/MediaCache.cpp:584:    gMediaCacheLog = PR_NewLogModule("MediaCache");
> ./dom/media/MediaDecoder.cpp:127:  gMediaDecoderLog = PR_NewLogModule("MediaDecoder");
> ./dom/media/MediaDecoder.cpp:128:  gMediaTimerLog = PR_NewLogModule("MediaTimer");
> ./dom/media/MediaDecoder.cpp:129:  gMediaSampleLog = PR_NewLogModule("MediaSample");
> ./dom/media/MediaFormatReader.cpp:34:    log = PR_NewLogModule("MediaFormatReader");
> ./dom/media/MediaManager.cpp:112:    sLog = PR_NewLogModule("MediaManager");
> ./dom/media/MediaRecorder.cpp:774:    gMediaRecorderLog = PR_NewLogModule("MediaRecorder");
> ./dom/media/MediaRecorder.cpp:807:    gMediaRecorderLog = PR_NewLogModule("MediaRecorder");
> ./dom/media/MediaResource.cpp:83:    gMediaResourceLog = PR_NewLogModule("MediaResource");
> ./dom/media/mediasource/MediaSource.cpp:42:    sLogModule = PR_NewLogModule("MediaSource");
> ./dom/media/mediasource/MediaSource.cpp:51:    sLogModule = PR_NewLogModule("MediaSource");
> ./dom/media/mediasource/SourceBufferResource.cpp:20:    sLogModule = PR_NewLogModule("SourceBufferResource");
> ./dom/media/mediasource/TrackBuffersManager.cpp:35:    sLogModule = PR_NewLogModule("MediaSourceSamples");
> ./dom/media/MediaStreamGraph.cpp:2573:    gMediaStreamGraphLog = PR_NewLogModule("MediaStreamGraph");
> ./dom/media/MP3Demuxer.cpp:118:    gMP3DemuxerLog = PR_NewLogModule("MP3Demuxer");
> ./dom/media/omx/AudioOffloadPlayer.cpp:67:    gAudioOffloadPlayerLog = PR_NewLogModule("AudioOffloadPlayer");
> ./dom/media/omx/AudioOutput.cpp:41:    gAudioOffloadPlayerLog = PR_NewLogModule("AudioOffloadPlayer");
> ./dom/media/omx/I420ColorConverterHelper.cpp:23:    gI420ColorConverterHelperLog = PR_NewLogModule("I420ColorConverterHelper");
> ./dom/media/omx/OmxDecoder.cpp:112:    gOmxDecoderLog = PR_NewLogModule("OmxDecoder");
> ./dom/media/platforms/PlatformDecoderModule.cpp:12:    log = PR_NewLogModule("PlatformDecoderModule");
> ./dom/media/platforms/wrappers/FuzzingWrapper.cpp:12:    log = PR_NewLogModule("MediaFuzzingWrapper");
> ./dom/media/RtspMediaResource.cpp:509:    gRtspMediaResourceLog = PR_NewLogModule("RtspMediaResource");
> ./dom/media/systemservices/CamerasChild.cpp:60:      gCamerasChildLog = PR_NewLogModule("CamerasChild");
> ./dom/media/systemservices/CamerasChild.cpp:148:      gCamerasChildLog = PR_NewLogModule("CamerasChild");
> ./dom/media/systemservices/CamerasChild.cpp:710:    gCamerasChildLog = PR_NewLogModule("CamerasChild");
> ./dom/media/systemservices/CamerasParent.cpp:825:    gCamerasParentLog = PR_NewLogModule("CamerasParent");
> ./dom/media/systemservices/LoadManager.cpp:50:    gLoadManagerLog = PR_NewLogModule("LoadManager");
> ./dom/media/systemservices/MediaChild.cpp:72:    gMediaChildLog = PR_NewLogModule("MediaChild");
> ./dom/media/systemservices/MediaParent.cpp:515:    gMediaParentLog = PR_NewLogModule("MediaParent");
> ./dom/media/systemservices/OpenSLESProvider.cpp:31:    gOpenSLESProviderLog = PR_NewLogModule("OpenSLESProvider");
> ./dom/media/TrackUnionStream.cpp:52:    gTrackUnionStreamLog = PR_NewLogModule("TrackUnionStream");
> ./dom/media/webm/WebMDemuxer.cpp:149:    gNesteggLog = PR_NewLogModule("Nestegg");
> ./dom/media/webm/WebMDemuxer.cpp:152:    gWebMDemuxerLog = PR_NewLogModule("WebMDemuxer");
> ./dom/media/webm/WebMReader.cpp:141:    gNesteggLog = PR_NewLogModule("Nestegg");
> ./dom/media/webrtc/MediaEngineWebRTC.cpp:21:    sLog = PR_NewLogModule("GetUserMedia");
> ./dom/media/webspeech/recognition/SpeechRecognition.cpp:61:    sLog = PR_NewLogModule("SpeechRecognition");
> ./dom/media/webspeech/synth/SpeechSynthesis.cpp:25:    sLog = PR_NewLogModule("SpeechSynthesis");
> ./dom/media/WebVTTListener.cpp:39:    gTextTrackLog = PR_NewLogModule("TextTrack");

Comment 1

[Ralph Giles (:rillian)]

LazyLogModule is, in fact better. Can you do a patch for us?

Comment 2

[Eric Rahm [:erahm]]

(In reply to Ralph Giles (:rillian) from comment #1)
> LazyLogModule is, in fact better. Can you do a patch for us?

We're hoping that module owners / peers can take lead on this (or perhaps offer to mentor others).

Comment 3

[sajitk]

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

Comment 4

[sajitk]

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

Comment 5

[sajitk]

Attachment: Replace PRLogModuleInfo with LazyLogModule in the media directory

Comment 6

[Nathan Froyd [:froydnj]]

Comment on attachment 8684639 [details] [diff] [review]
Replace PRLogModuleInfo with LazyLogModule in the media directory

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

I'm not sure I'm the right person to review this code.  Ralph already expressed positive feelings about doing this; Ralph, do you want to review?

Comment 7

[Ralph Giles (:rillian)]

Comment on attachment 8684639 [details] [diff] [review]
Replace PRLogModuleInfo with LazyLogModule in the media directory

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

Thanks for taking this on. It would have been nice if you'd split out at least the more popular loggers into separate patches, though. This is a lot to review at once.

Please don't use the mozilla:: prefix for variables and functions already declared inside namespace mozilla { ... }. I don't expect any conflict. I marked the first few, but this applies to most of them.

r=me with comments addressed.

::: dom/media/Latency.cpp
@@ +44,2 @@
>    return sLog;
> +} 

No trailing whitespace, please.

@@ -110,5 @@
>  /* static */
>  void AsyncLatencyLogger::InitializeStatics()
>  {
>    NS_ASSERTION(NS_IsMainThread(), "Main thread only");
> -  GetLatencyLog();

It's worth leaving this, I think. Given we're logging latency, making sure the initial allocation happens here is better than it happening on the first AsyncLatencyLogger call. Comment with '// Make sure the underlying logger is allocated.' if you like.

Logging is always expensive of course, so the additional hashtable lookup on use isn't a big deal.

::: dom/media/MediaCache.cpp
@@ +23,5 @@
>  #include <algorithm>
>  
>  namespace mozilla {
>  
> +mozilla::LazyLogModule gMediaCacheLog("MediaCache");

You don't need the mozilla:: prefix inside namespace mozilla.

::: dom/media/MediaDecoder.cpp
@@ +45,5 @@
>  
>  // avoid redefined macro in unified build
>  #undef DECODER_LOG
>  
> +mozilla::LazyLogModule gMediaDecoderLog("MediaDecoder");

You don't need the mozilla:: namespace prefix here.

@@ +113,5 @@
>  StaticRefPtr<MediaMemoryTracker> MediaMemoryTracker::sUniqueInstance;
>  
>  #if defined(PR_LOGGING)
> +mozilla::LazyLogModule gMediaTimerLog("MediaTimer");
> +mozilla::LazyLogModule gMediaSampleLog("MediaSample");

or here.

::: dom/media/MediaDecoderStateMachine.h
@@ +107,5 @@
>  class DecodedStream;
>  class TaskQueue;
>  
> +extern mozilla::LazyLogModule gMediaDecoderLog;
> +extern mozilla::LazyLogModule gMediaSampleLog;

You don't need the mozilla:: namespace prefix here.

::: dom/media/MediaTimer.h
@@ +17,5 @@
>  #include "mozilla/RefPtr.h"
>  
>  namespace mozilla {
>  
> +extern mozilla::LazyLogModule gMediaTimerLog;

You don't need the mozilla:: namespace prefix here.

::: dom/media/directshow/AudioSinkFilter.cpp
@@ +22,5 @@
>  using namespace mozilla::media;
>  
>  namespace mozilla {
>  
> +mozilla::LogModule* GetDirectShowLog();

Doesn't this need to be `extern` here and elsewhere? Disable the unified build to verify.

::: dom/media/eme/EMEUtils.cpp
@@ +9,5 @@
>  namespace mozilla {
>  
> +mozilla::LogModule*  GetEMELog() {
> +  static mozilla::LazyLogModule log("EME");
> +  return (mozilla::LogModule*)log;

Extra space in the declaration.

Why does this return value need a cast when the others don't?

Comment 8

[sajitk]

Attachment: 1219480.patch

Review comments incorporated.

Comment 9

[Carsten Book [:Tomcat]]

Hi, this failed to apply:

patching file dom/media/omx/OmxDecoder.cpp
Hunk #2 FAILED at 102
1 out of 2 hunks FAILED -- saving rejects to file dom/media/omx/OmxDecoder.cpp.rej
patching file dom/media/platforms/gonk/GonkMediaDataDecoder.cpp
Hunk #1 FAILED at 10
1 out of 1 hunks FAILED -- saving rejects to file dom/media/platforms/gonk/GonkMediaDataDecoder.cpp.rej

Comment 10

[sajitk]

Attachment: 1219480.patch

Fixed "failed to apply" rejections

Comment 11

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1e5f3d1151d6

Comment 12

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Backed out for cpp unittest bustage: https://treeherder.mozilla.org/logviewer.html#?job_id=17143498&repo=mozilla-inbound
https://hg.mozilla.org/integration/mozilla-inbound/rev/66a799321ef8

Comment 13

[sajitk]

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

Comment 14

[sajitk]

Hi, my checkin for this bug failed because of a segmentation fault in the Android emulator, when running a CppUnit test.

The test calls the opensl_init method from media/libcubeb/src/cubeb_opensl.c. This in turn invokes the (C++) static method mozilla::OpenSLESProvider::Get which eventually instantiates a static LazyLogModule variable. The seg fault seems to occur when a MOZ_LOG call is made on the LazyLogModule, in the constructor of OffTheBooksMutex.

Can you please let me know if the LazyLogModule (and associated classes such as LogModule, LogModuleManager, OffTheBooksMutex etc) can be used in this fashion (from C code)? Could you point me to any examples?

Thanks,

Comment 15

[sajitk]

backtrace from the fault: 
>   #00  pc 0036df90  /data/local/tests/cppunittests/b/libxul.so (mozilla::OffTheBooksMutex::OffTheBooksMutex(char const*)+47)
>   #01  pc 0036ea23  /data/local/tests/cppunittests/b/libxul.so (mozilla::LogModule::Get(char const*)+18)
>   #02  pc 0037cca3  /data/local/tests/cppunittests/b/libxul.so (mozilla::LazyLogModule::operator mozilla::LogModule*()+14)
>   #03  pc 00d4b4e1  /data/local/tests/cppunittests/b/libxul.so (mozilla::OpenSLESProvider::OpenSLESProvider()+28)
>   #04  pc 00d4b51f  /data/local/tests/cppunittests/b/libxul.so (mozilla::OpenSLESProvider::getInstance()+26)
>   #05  pc 00d4bb99  /data/local/tests/cppunittests/b/libxul.so (mozilla::OpenSLESProvider::Get(SLObjectItf_ const* const**, unsigned long, SLEngineOption_ const*)+8)
>   #06  pc 0000280b  /data/local/tests/cppunittests/b/test_tone
>   #07  pc 00001773  /data/local/tests/cppunittests/b/test_tone
>   #08  pc 0000161b  /data/local/tests/cppunittests/b/test_tone
>   #09  pc 0000db4f  /system/lib/libc.so (__libc_init+50)
>   #10  pc 0000146c  /data/local/tests/cppunittests/b/test_tone

Comment 16

[Nathan Froyd [:froydnj]]

I wouldn't expect any problems calling into the logging code from C code.  What does look like a problem is that test_tone.cpp doesn't initialize XPCOM, which means that LogModule::Init never gets called.

The "easy" way forward here is to add a |ScopedXPCOM xpcom("test_tone");| to the very start of test_tone.cpp's main function (and likely the other cppunit tests in that directory...and maybe some others, I'd imagine).  You should probably just indiscriminately add a ScopedXPCOM to every cpp unit test that doesn't already have one, actually.  I *think* that should solve the problem.

Comment 17

[Nathan Froyd [:froydnj]]

(To be explicit: that ScopedXPCOM should eventually wind up calling LogModule::Init(), which would fix the null deref.  If it doesn't, then we probably have some other work to do.)

Comment 18

[sajitk]

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

Comment 19

[sajitk]

Attachment: 1219480.patch

Added ScopedXPCOM to the unit tests in the media/libcubeb directory

Comment 20

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/5d977c74e574

Comment 21

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/5d977c74e574

Comment 22

[Matthew Gregan [:kinetik]]

(In reply to sajitk from comment #19)
> Created attachment 8687554 [details] [diff] [review]
> 1219480.patch
> 
> Added ScopedXPCOM to the unit tests in the media/libcubeb directory

Adding Gecko-specific code to third-party tests imported from upstream code is not okay.