Bug 1336945 - Modernize MSG/GraphDriver logging. r?jesup draft
authorPaul Adenot <paul@paul.cx>
Mon, 06 Feb 2017 16:22:36 +0100
changeset 479358 d81f216e7c037bc8a5ca0c7f6f37ecb44271881b
parent 479345 68cbf38fb671f48ddcb649dc1327dd164059b9c8
child 479840 41dc4e72ce41b632e727bb9ebcc118750181bb63
push id44232
push userpaul@paul.cx
push dateMon, 06 Feb 2017 15:24:07 +0000
reviewersjesup
bugs1336945
milestone54.0a1
Bug 1336945 - Modernize MSG/GraphDriver logging. r?jesup MozReview-Commit-ID: 5Redgg5uaQG
dom/media/GraphDriver.cpp
dom/media/MediaStreamGraph.cpp
--- a/dom/media/GraphDriver.cpp
+++ b/dom/media/GraphDriver.cpp
@@ -14,31 +14,20 @@
 #include "webrtc/MediaEngineWebRTC.h"
 #endif
 
 #ifdef XP_MACOSX
 #include <sys/sysctl.h>
 #endif
 
 extern mozilla::LazyLogModule gMediaStreamGraphLog;
-#define STREAM_LOG(type, msg) MOZ_LOG(gMediaStreamGraphLog, type, msg)
-
-// We don't use NSPR log here because we want this interleaved with adb logcat
-// on Android/B2G
-// #define ENABLE_LIFECYCLE_LOG
-#ifdef ENABLE_LIFECYCLE_LOG
-#ifdef ANDROID
-#include "android/log.h"
-#define LIFECYCLE_LOG(...)  __android_log_print(ANDROID_LOG_INFO, "Gecko - MSG" , __VA_ARGS__);
-#else
-#define LIFECYCLE_LOG(...) printf(__VA_ARGS__);printf("\n");
-#endif
-#else
-#define LIFECYCLE_LOG(...)
-#endif
+#ifdef LOG
+#undef LOG
+#endif // LOG
+#define LOG(type, msg) MOZ_LOG(gMediaStreamGraphLog, type, msg)
 
 namespace mozilla {
 
 StaticRefPtr<nsIThreadPool> AsyncCubebTask::sThreadPool;
 
 GraphDriver::GraphDriver(MediaStreamGraphImpl* aGraphImpl)
   : mIterationStart(0),
     mIterationEnd(0),
@@ -59,35 +48,39 @@ void GraphDriver::SetGraphTime(GraphDriv
   // mIterationStart of the next iteration by setting the end of the previous
   // iteration.
   mIterationStart = aLastSwitchNextIterationStart;
   mIterationEnd = aLastSwitchNextIterationEnd;
 
   MOZ_ASSERT(!PreviousDriver());
   MOZ_ASSERT(aPreviousDriver);
 
-  STREAM_LOG(LogLevel::Debug, ("Setting previous driver: %p (%s)",
-                               aPreviousDriver,
-                               aPreviousDriver->AsAudioCallbackDriver()
-                                 ? "AudioCallbackDriver"
-                                 : "SystemClockDriver"));
+  LOG(LogLevel::Debug,
+      ("Setting previous driver: %p (%s)",
+       aPreviousDriver,
+       aPreviousDriver->AsAudioCallbackDriver() ? "AudioCallbackDriver"
+                                                : "SystemClockDriver"));
   SetPreviousDriver(aPreviousDriver);
 }
 
 void GraphDriver::SwitchAtNextIteration(GraphDriver* aNextDriver)
 {
   GraphImpl()->GetMonitor().AssertCurrentThreadOwns();
-  LIFECYCLE_LOG("Switching to new driver: %p (%s)",
-      aNextDriver, aNextDriver->AsAudioCallbackDriver() ?
-      "AudioCallbackDriver" : "SystemClockDriver");
+  LOG(LogLevel::Debug,
+      ("Switching to new driver: %p (%s)",
+       aNextDriver,
+       aNextDriver->AsAudioCallbackDriver() ? "AudioCallbackDriver"
+                                            : "SystemClockDriver"));
   if (mNextDriver &&
       mNextDriver != GraphImpl()->CurrentDriver()) {
-    LIFECYCLE_LOG("Discarding previous next driver: %p (%s)",
-                  mNextDriver.get(), mNextDriver->AsAudioCallbackDriver() ?
-                  "AudioCallbackDriver" : "SystemClockDriver");
+    LOG(LogLevel::Debug,
+        ("Discarding previous next driver: %p (%s)",
+         mNextDriver.get(),
+         mNextDriver->AsAudioCallbackDriver() ? "AudioCallbackDriver"
+                                              : "SystemClockDriver"));
   }
   SetNextDriver(aNextDriver);
 }
 
 GraphTime
 GraphDriver::StateComputedTime() const
 {
   return mGraphImpl->mStateComputedTime;
@@ -96,17 +89,18 @@ GraphDriver::StateComputedTime() const
 void GraphDriver::EnsureNextIteration()
 {
   mGraphImpl->EnsureNextIteration();
 }
 
 void GraphDriver::Shutdown()
 {
   if (AsAudioCallbackDriver()) {
-    LIFECYCLE_LOG("Releasing audio driver off main thread (GraphDriver::Shutdown).\n");
+    LOG(LogLevel::Debug,
+        ("Releasing audio driver off main thread (GraphDriver::Shutdown)."));
     RefPtr<AsyncCubebTask> releaseEvent =
       new AsyncCubebTask(AsAudioCallbackDriver(), AsyncCubebOperation::SHUTDOWN);
     releaseEvent->Dispatch(NS_DISPATCH_SYNC);
   } else {
     Stop();
   }
 }
 
@@ -178,30 +172,30 @@ ThreadedDriver::~ThreadedDriver()
 class MediaStreamGraphInitThreadRunnable : public Runnable {
 public:
   explicit MediaStreamGraphInitThreadRunnable(ThreadedDriver* aDriver)
     : mDriver(aDriver)
   {
   }
   NS_IMETHOD Run() override
   {
-    STREAM_LOG(LogLevel::Debug, ("Starting system thread"));
-    LIFECYCLE_LOG("Starting a new system driver for graph %p\n",
-                  mDriver->mGraphImpl);
+    LOG(LogLevel::Debug,
+        ("Starting a new system driver for graph %p", mDriver->mGraphImpl));
 
     GraphDriver* previousDriver = nullptr;
     {
       MonitorAutoLock mon(mDriver->mGraphImpl->GetMonitor());
       previousDriver = mDriver->PreviousDriver();
     }
     if (previousDriver) {
-      LIFECYCLE_LOG("%p releasing an AudioCallbackDriver(%p), for graph %p\n",
-                    mDriver.get(),
-                    previousDriver,
-                    mDriver->GraphImpl());
+      LOG(LogLevel::Debug,
+          ("%p releasing an AudioCallbackDriver(%p), for graph %p",
+           mDriver.get(),
+           previousDriver,
+           mDriver->GraphImpl()));
       MOZ_ASSERT(!mDriver->AsAudioCallbackDriver());
       RefPtr<AsyncCubebTask> releaseEvent =
         new AsyncCubebTask(previousDriver->AsAudioCallbackDriver(), AsyncCubebOperation::SHUTDOWN);
       releaseEvent->Dispatch();
 
       MonitorAutoLock mon(mDriver->mGraphImpl->GetMonitor());
       mDriver->SetPreviousDriver(nullptr);
     } else {
@@ -216,17 +210,18 @@ public:
   }
 private:
   RefPtr<ThreadedDriver> mDriver;
 };
 
 void
 ThreadedDriver::Start()
 {
-  LIFECYCLE_LOG("Starting thread for a SystemClockDriver  %p\n", mGraphImpl);
+  LOG(LogLevel::Debug,
+      ("Starting thread for a SystemClockDriver  %p", mGraphImpl));
   Unused << NS_WARN_IF(mThread);
   if (!mThread) { // Ensure we haven't already started it
     nsCOMPtr<nsIRunnable> event = new MediaStreamGraphInitThreadRunnable(this);
     // Note: mThread may be null during event->Run() if we pass to NewNamedThread!  See AudioInitTask
     nsresult rv = NS_NewNamedThread("MediaStreamGrph", getter_AddRefs(mThread));
     if (NS_SUCCEEDED(rv)) {
       mThread->Dispatch(event, NS_DISPATCH_NORMAL);
     }
@@ -239,17 +234,17 @@ ThreadedDriver::Resume()
   Start();
 }
 
 void
 ThreadedDriver::Revive()
 {
   // Note: only called on MainThread, without monitor
   // We know were weren't in a running state
-  STREAM_LOG(LogLevel::Debug, ("AudioCallbackDriver reviving."));
+  LOG(LogLevel::Debug, ("AudioCallbackDriver reviving."));
   // If we were switching, switch now. Otherwise, tell thread to run the main
   // loop again.
   MonitorAutoLock mon(mGraphImpl->GetMonitor());
   if (NextDriver()) {
     NextDriver()->SetGraphTime(this, mIterationStart, mIterationEnd);
     mGraphImpl->SetCurrentDriver(NextDriver());
     NextDriver()->Start();
   } else {
@@ -263,17 +258,17 @@ ThreadedDriver::RemoveCallback()
 {
 }
 
 void
 ThreadedDriver::Stop()
 {
   NS_ASSERTION(NS_IsMainThread(), "Must be called on main thread");
   // mGraph's thread is not running so it's OK to do whatever here
-  STREAM_LOG(LogLevel::Debug, ("Stopping threads for MediaStreamGraph %p", this));
+  LOG(LogLevel::Debug, ("Stopping threads for MediaStreamGraph %p", this));
 
   if (mThread) {
     mThread->Shutdown();
     mThread = nullptr;
   }
 }
 
 SystemClockDriver::SystemClockDriver(MediaStreamGraphImpl* aGraphImpl)
@@ -303,49 +298,54 @@ ThreadedDriver::RunThread()
 {
   bool stillProcessing = true;
   while (stillProcessing) {
     mIterationStart = IterationEnd();
     mIterationEnd += GetIntervalForIteration();
 
     GraphTime stateComputedTime = StateComputedTime();
     if (stateComputedTime < mIterationEnd) {
-      STREAM_LOG(LogLevel::Warning, ("Media graph global underrun detected"));
+      LOG(LogLevel::Warning, ("Media graph global underrun detected"));
       mIterationEnd = stateComputedTime;
     }
 
     if (mIterationStart >= mIterationEnd) {
       NS_ASSERTION(mIterationStart == mIterationEnd ,
                    "Time can't go backwards!");
       // This could happen due to low clock resolution, maybe?
-      STREAM_LOG(LogLevel::Debug, ("Time did not advance"));
+      LOG(LogLevel::Debug, ("Time did not advance"));
     }
 
     GraphTime nextStateComputedTime =
       mGraphImpl->RoundUpToNextAudioBlock(
         mIterationEnd + mGraphImpl->MillisecondsToMediaTime(AUDIO_TARGET_MS));
     if (nextStateComputedTime < stateComputedTime) {
       // A previous driver may have been processing further ahead of
       // iterationEnd.
-      STREAM_LOG(LogLevel::Warning,
-                 ("Prevent state from going backwards. interval[%ld; %ld] state[%ld; %ld]",
-                  (long)mIterationStart, (long)mIterationEnd,
-                  (long)stateComputedTime, (long)nextStateComputedTime));
+      LOG(LogLevel::Warning,
+          ("Prevent state from going backwards. interval[%ld; %ld] state[%ld; "
+           "%ld]",
+           (long)mIterationStart,
+           (long)mIterationEnd,
+           (long)stateComputedTime,
+           (long)nextStateComputedTime));
       nextStateComputedTime = stateComputedTime;
     }
-    STREAM_LOG(LogLevel::Verbose,
-               ("interval[%ld; %ld] state[%ld; %ld]",
-               (long)mIterationStart, (long)mIterationEnd,
-               (long)stateComputedTime, (long)nextStateComputedTime));
+    LOG(LogLevel::Verbose,
+        ("interval[%ld; %ld] state[%ld; %ld]",
+         (long)mIterationStart,
+         (long)mIterationEnd,
+         (long)stateComputedTime,
+         (long)nextStateComputedTime));
 
     stillProcessing = mGraphImpl->OneIteration(nextStateComputedTime);
 
     MonitorAutoLock lock(GraphImpl()->GetMonitor());
     if (NextDriver() && stillProcessing) {
-      STREAM_LOG(LogLevel::Debug, ("Switching to AudioCallbackDriver"));
+      LOG(LogLevel::Debug, ("Switching to AudioCallbackDriver"));
       RemoveCallback();
       NextDriver()->SetGraphTime(this, mIterationStart, mIterationEnd);
       mGraphImpl->SetCurrentDriver(NextDriver());
       NextDriver()->Start();
       return;
     }
   }
 }
@@ -394,29 +394,31 @@ SystemClockDriver::WaitForNextIteration(
   // mGraphDriverAsleep
   if (another || mGraphImpl->mNeedAnotherIteration) { // atomic
     int64_t timeoutMS = MEDIA_GRAPH_TARGET_PERIOD_MS -
       int64_t((now - mCurrentTimeStamp).ToMilliseconds());
     // Make sure timeoutMS doesn't overflow 32 bits by waking up at
     // least once a minute, if we need to wake up at all
     timeoutMS = std::max<int64_t>(0, std::min<int64_t>(timeoutMS, 60*1000));
     timeout = PR_MillisecondsToInterval(uint32_t(timeoutMS));
-    STREAM_LOG(LogLevel::Verbose,
-               ("Waiting for next iteration; at %f, timeout=%f",
-                (now - mInitialTimeStamp).ToSeconds(), timeoutMS/1000.0));
+    LOG(LogLevel::Verbose,
+        ("Waiting for next iteration; at %f, timeout=%f",
+         (now - mInitialTimeStamp).ToSeconds(),
+         timeoutMS / 1000.0));
     if (mWaitState == WAITSTATE_WAITING_INDEFINITELY) {
       mGraphImpl->mGraphDriverAsleep = false; // atomic
     }
     mWaitState = WAITSTATE_WAITING_FOR_NEXT_ITERATION;
   }
   if (timeout > 0) {
     mGraphImpl->GetMonitor().Wait(timeout);
-    STREAM_LOG(LogLevel::Verbose, ("Resuming after timeout; at %f, elapsed=%f",
-          (TimeStamp::Now() - mInitialTimeStamp).ToSeconds(),
-          (TimeStamp::Now() - now).ToSeconds()));
+    LOG(LogLevel::Verbose,
+        ("Resuming after timeout; at %f, elapsed=%f",
+         (TimeStamp::Now() - mInitialTimeStamp).ToSeconds(),
+         (TimeStamp::Now() - now).ToSeconds()));
   }
 
   if (mWaitState == WAITSTATE_WAITING_INDEFINITELY) {
     mGraphImpl->mGraphDriverAsleep = false; // atomic
   }
   // Note: this can race against the EnsureNextIteration setting
   // WAITSTATE_RUNNING and setting mGraphDriverAsleep to false, so you can
   // have an iteration with WAITSTATE_WAKING_UP instead of RUNNING.
@@ -509,25 +511,27 @@ AsyncCubebTask::EnsureThread()
 
 NS_IMETHODIMP
 AsyncCubebTask::Run()
 {
   MOZ_ASSERT(mDriver);
 
   switch(mOperation) {
     case AsyncCubebOperation::INIT: {
-      LIFECYCLE_LOG("AsyncCubebOperation::INIT driver=%p\n", mDriver.get());
+      LOG(LogLevel::Debug,
+          ("AsyncCubebOperation::INIT driver=%p", mDriver.get()));
       if (!mDriver->Init()) {
         return NS_ERROR_FAILURE;
       }
       mDriver->CompleteAudioContextOperations(mOperation);
       break;
     }
     case AsyncCubebOperation::SHUTDOWN: {
-      LIFECYCLE_LOG("AsyncCubebOperation::SHUTDOWN driver=%p\n", mDriver.get());
+      LOG(LogLevel::Debug,
+          ("AsyncCubebOperation::SHUTDOWN driver=%p", mDriver.get()));
       mDriver->Stop();
 
       mDriver->CompleteAudioContextOperations(mOperation);
 
       mDriver = nullptr;
       mShutdownGrip = nullptr;
       break;
     }
@@ -557,17 +561,17 @@ AudioCallbackDriver::AudioCallbackDriver
   , mStarted(false)
   , mAudioInput(nullptr)
   , mAudioChannel(aGraphImpl->AudioChannel())
   , mAddedMixer(false)
   , mInCallback(false)
   , mMicrophoneActive(false)
   , mFromFallback(false)
 {
-  STREAM_LOG(LogLevel::Debug, ("AudioCallbackDriver ctor for graph %p", aGraphImpl));
+  LOG(LogLevel::Debug, ("AudioCallbackDriver ctor for graph %p", aGraphImpl));
 }
 
 AudioCallbackDriver::~AudioCallbackDriver()
 {
   MOZ_ASSERT(mPromisesForOperation.IsEmpty());
 }
 
 bool IsMacbookOrMacbookAir()
@@ -724,63 +728,66 @@ AudioCallbackDriver::Init()
   bool aec;
   Unused << mGraphImpl->AudioTrackPresent(aec);
   SetMicrophoneActive(aec);
 
   cubeb_stream_register_device_changed_callback(mAudioStream,
                                                 AudioCallbackDriver::DeviceChangedCallback_s);
 
   if (!StartStream()) {
-    STREAM_LOG(LogLevel::Warning, ("AudioCallbackDriver couldn't start stream."));
+    LOG(LogLevel::Warning, ("AudioCallbackDriver couldn't start stream."));
     return false;
   }
 
-  STREAM_LOG(LogLevel::Debug, ("AudioCallbackDriver started."));
+  LOG(LogLevel::Debug, ("AudioCallbackDriver started."));
   return true;
 }
 
 
 void
 AudioCallbackDriver::Destroy()
 {
-  STREAM_LOG(LogLevel::Debug, ("AudioCallbackDriver destroyed."));
+  LOG(LogLevel::Debug, ("AudioCallbackDriver destroyed."));
   mAudioInput = nullptr;
   mAudioStream.reset();
 }
 
 void
 AudioCallbackDriver::Resume()
 {
-  STREAM_LOG(LogLevel::Debug, ("Resuming audio threads for MediaStreamGraph %p", mGraphImpl));
+  LOG(LogLevel::Debug,
+      ("Resuming audio threads for MediaStreamGraph %p", mGraphImpl));
   if (cubeb_stream_start(mAudioStream) != CUBEB_OK) {
     NS_WARNING("Could not start cubeb stream for MSG.");
   }
 }
 
 void
 AudioCallbackDriver::Start()
 {
   if (mPreviousDriver) {
     if (mPreviousDriver->AsAudioCallbackDriver()) {
-      LIFECYCLE_LOG("Releasing audio driver off main thread.");
+      LOG(LogLevel::Debug, ("Releasing audio driver off main thread."));
       RefPtr<AsyncCubebTask> releaseEvent =
         new AsyncCubebTask(mPreviousDriver->AsAudioCallbackDriver(),
                            AsyncCubebOperation::SHUTDOWN);
       releaseEvent->Dispatch();
       mPreviousDriver = nullptr;
     } else {
-      LIFECYCLE_LOG("Dropping driver reference for SystemClockDriver.");
+      LOG(LogLevel::Debug,
+          ("Dropping driver reference for SystemClockDriver."));
       MOZ_ASSERT(mPreviousDriver->AsSystemClockDriver());
       mFromFallback = mPreviousDriver->AsSystemClockDriver()->IsFallback();
       mPreviousDriver = nullptr;
     }
   }
 
-  LIFECYCLE_LOG("Starting new audio driver off main thread, "
-                "to ensure it runs after previous shutdown.");
+  LOG(LogLevel::Debug,
+      ("Starting new audio driver off main thread, "
+       "to ensure it runs after previous shutdown."));
   RefPtr<AsyncCubebTask> initEvent =
     new AsyncCubebTask(AsAudioCallbackDriver(), AsyncCubebOperation::INIT);
   initEvent->Dispatch();
 }
 
 bool
 AudioCallbackDriver::StartStream()
 {
@@ -805,26 +812,28 @@ AudioCallbackDriver::Stop()
   }
 }
 
 void
 AudioCallbackDriver::Revive()
 {
   // Note: only called on MainThread, without monitor
   // We know were weren't in a running state
-  STREAM_LOG(LogLevel::Debug, ("AudioCallbackDriver reviving."));
+  LOG(LogLevel::Debug, ("AudioCallbackDriver reviving."));
   // If we were switching, switch now. Otherwise, start the audio thread again.
   MonitorAutoLock mon(mGraphImpl->GetMonitor());
   if (NextDriver()) {
     RemoveCallback();
     NextDriver()->SetGraphTime(this, mIterationStart, mIterationEnd);
     mGraphImpl->SetCurrentDriver(NextDriver());
     NextDriver()->Start();
   } else {
-    STREAM_LOG(LogLevel::Debug, ("Starting audio threads for MediaStreamGraph %p from a new thread.", mGraphImpl));
+    LOG(LogLevel::Debug,
+        ("Starting audio threads for MediaStreamGraph %p from a new thread.",
+         mGraphImpl));
     RefPtr<AsyncCubebTask> initEvent =
       new AsyncCubebTask(this, AsyncCubebOperation::INIT);
     initEvent->Dispatch();
   }
 }
 
 void
 AudioCallbackDriver::RemoveCallback()
@@ -963,32 +972,39 @@ AudioCallbackDriver::DataCallback(const 
     // We want the interval [mIterationStart; mIterationEnd] to be before the
     // interval [stateComputedTime; nextStateComputedTime]. We also want
     // the distance between these intervals to be roughly equivalent each time, to
     // ensure there is no clock drift between current time and state time. Since
     // we can't act on the state time because we have to fill the audio buffer, we
     // reclock the current time against the state time, here.
     mIterationEnd = mIterationStart + 0.8 * inGraph;
 
-    STREAM_LOG(LogLevel::Verbose, ("interval[%ld; %ld] state[%ld; %ld] (frames: %ld) (durationMS: %u) (duration ticks: %ld)\n",
-                                   (long)mIterationStart, (long)mIterationEnd,
-                                   (long)stateComputedTime, (long)nextStateComputedTime,
-                                   (long)aFrames, (uint32_t)durationMS,
-                                   (long)(nextStateComputedTime - stateComputedTime)));
+    LOG(LogLevel::Verbose,
+        ("interval[%ld; %ld] state[%ld; %ld] (frames: %ld) (durationMS: %u) "
+         "(duration ticks: %ld)",
+         (long)mIterationStart,
+         (long)mIterationEnd,
+         (long)stateComputedTime,
+         (long)nextStateComputedTime,
+         (long)aFrames,
+         (uint32_t)durationMS,
+         (long)(nextStateComputedTime - stateComputedTime)));
 
     mCurrentTimeStamp = TimeStamp::Now();
 
     if (stateComputedTime < mIterationEnd) {
-      STREAM_LOG(LogLevel::Warning, ("Media graph global underrun detected"));
+      LOG(LogLevel::Warning, ("Media graph global underrun detected"));
       mIterationEnd = stateComputedTime;
     }
 
     stillProcessing = mGraphImpl->OneIteration(nextStateComputedTime);
   } else {
-    STREAM_LOG(LogLevel::Verbose, ("DataCallback buffer filled entirely from scratch buffer, skipping iteration."));
+    LOG(LogLevel::Verbose,
+        ("DataCallback buffer filled entirely from scratch "
+         "buffer, skipping iteration."));
     stillProcessing = true;
   }
 
   mBuffer.BufferFilled();
 
   // Callback any observers for the AEC speaker data.  Note that one
   // (maybe) of these will be full-duplex, the others will get their input
   // data off separate cubeb callbacks.  Take care with how stuff is
@@ -1005,37 +1021,38 @@ AudioCallbackDriver::DataCallback(const 
 
   if (switching && stillProcessing) {
     // If the audio stream has not been started by the previous driver or
     // the graph itself, keep it alive.
     MonitorAutoLock mon(mGraphImpl->GetMonitor());
     if (!IsStarted()) {
       return aFrames;
     }
-    STREAM_LOG(LogLevel::Debug, ("Switching to system driver."));
+    LOG(LogLevel::Debug, ("Switching to system driver."));
     RemoveCallback();
     NextDriver()->SetGraphTime(this, mIterationStart, mIterationEnd);
     mGraphImpl->SetCurrentDriver(NextDriver());
     NextDriver()->Start();
     // Returning less than aFrames starts the draining and eventually stops the
     // audio thread. This function will never get called again.
     return aFrames - 1;
   }
 
   if (!stillProcessing) {
-    LIFECYCLE_LOG("Stopping audio thread for MediaStreamGraph %p", this);
+    LOG(LogLevel::Debug,
+        ("Stopping audio thread for MediaStreamGraph %p", this));
     return aFrames - 1;
   }
   return aFrames;
 }
 
 void
 AudioCallbackDriver::StateCallback(cubeb_state aState)
 {
-  STREAM_LOG(LogLevel::Debug, ("AudioCallbackDriver State: %d", aState));
+  LOG(LogLevel::Debug, ("AudioCallbackDriver State: %d", aState));
 }
 
 void
 AudioCallbackDriver::MixerCallback(AudioDataValue* aMixedBuffer,
                                    AudioSampleFormat aFormat,
                                    uint32_t aChannels,
                                    uint32_t aFrames,
                                    uint32_t aSampleRate)
--- a/dom/media/MediaStreamGraph.cpp
+++ b/dom/media/MediaStreamGraph.cpp
@@ -42,65 +42,54 @@
 using namespace mozilla::layers;
 using namespace mozilla::dom;
 using namespace mozilla::gfx;
 using namespace mozilla::media;
 
 namespace mozilla {
 
 LazyLogModule gMediaStreamGraphLog("MediaStreamGraph");
-#define STREAM_LOG(type, msg) MOZ_LOG(gMediaStreamGraphLog, type, msg)
-
-// #define ENABLE_LIFECYCLE_LOG
-
-// We don't use NSPR log here because we want this interleaved with adb logcat
-// on Android/B2G
-#ifdef ENABLE_LIFECYCLE_LOG
-#  ifdef ANDROID
-#    include "android/log.h"
-#    define LIFECYCLE_LOG(...)  __android_log_print(ANDROID_LOG_INFO, "Gecko - MSG", ## __VA_ARGS__);
-#  else
-#    define LIFECYCLE_LOG(...) printf(__VA_ARGS__);printf("\n");
-#  endif
-#else
-#  define LIFECYCLE_LOG(...)
-#endif
+#ifdef LOG
+#undef LOG
+#endif // LOG
+#define LOG(type, msg) MOZ_LOG(gMediaStreamGraphLog, type, msg)
 
 enum SourceMediaStream::TrackCommands : uint32_t {
   TRACK_CREATE = TrackEventCommand::TRACK_EVENT_CREATED,
   TRACK_END = TrackEventCommand::TRACK_EVENT_ENDED,
   TRACK_UNUSED = TrackEventCommand::TRACK_EVENT_UNUSED,
 };
 
 /**
  * A hash table containing the graph instances, one per AudioChannel.
  */
 static nsDataHashtable<nsUint32HashKey, MediaStreamGraphImpl*> gGraphs;
 
 MediaStreamGraphImpl::~MediaStreamGraphImpl()
 {
   NS_ASSERTION(IsEmpty(),
                "All streams should have been destroyed by messages from the main thread");
-  STREAM_LOG(LogLevel::Debug, ("MediaStreamGraph %p destroyed", this));
-  LIFECYCLE_LOG("MediaStreamGraphImpl::~MediaStreamGraphImpl\n");
+  LOG(LogLevel::Debug, ("MediaStreamGraph %p destroyed", this));
+  LOG(LogLevel::Debug, ("MediaStreamGraphImpl::~MediaStreamGraphImpl"));
 }
 
 void
 MediaStreamGraphImpl::FinishStream(MediaStream* aStream)
 {
   if (aStream->mFinished)
     return;
-  STREAM_LOG(LogLevel::Debug, ("MediaStream %p will finish", aStream));
+  LOG(LogLevel::Debug, ("MediaStream %p will finish", aStream));
 #ifdef DEBUG
   for (StreamTracks::TrackIter track(aStream->mTracks);
          !track.IsEnded(); track.Next()) {
     if (!track->IsEnded()) {
-      STREAM_LOG(LogLevel::Error,
-                 ("MediaStream %p will finish, but track %d has not ended.",
-                  aStream, track->GetID()));
+      LOG(LogLevel::Error,
+          ("MediaStream %p will finish, but track %d has not ended.",
+           aStream,
+           track->GetID()));
       NS_ASSERTION(false, "Finished stream cannot contain live track");
     }
   }
 #endif
   aStream->mFinished = true;
   aStream->mTracks.AdvanceKnownTracksTime(STREAM_TIME_MAX);
 
   SetStreamOrderDirty();
@@ -116,21 +105,31 @@ MediaStreamGraphImpl::AddStreamGraphThre
     TimeStamp currentTimeStamp = CurrentDriver()->GetCurrentTimeStamp();
     TimeStamp processedTimeStamp = currentTimeStamp +
       TimeDuration::FromSeconds(MediaTimeToSeconds(mProcessedTime - IterationEnd()));
     source->SetStreamTracksStartTimeStamp(processedTimeStamp);
   }
 
   if (aStream->IsSuspended()) {
     mSuspendedStreams.AppendElement(aStream);
-    STREAM_LOG(LogLevel::Debug, ("Adding media stream %p to the graph, in the suspended stream array", aStream));
+    LOG(LogLevel::Debug,
+        ("Adding media stream %p to the graph, in the suspended stream array",
+         aStream));
   } else {
     mStreams.AppendElement(aStream);
-    STREAM_LOG(LogLevel::Debug, ("Adding media stream %p to graph %p, count %lu", aStream, this, mStreams.Length()));
-    LIFECYCLE_LOG("Adding media stream %p to graph %p, count %lu", aStream, this, (long)mStreams.Length());
+    LOG(LogLevel::Debug,
+        ("Adding media stream %p to graph %p, count %lu",
+         aStream,
+         this,
+         mStreams.Length()));
+    LOG(LogLevel::Debug,
+        ("Adding media stream %p to graph %p, count %lu",
+         aStream,
+         this,
+         (long)mStreams.Length()));
   }
 
   SetStreamOrderDirty();
 }
 
 void
 MediaStreamGraphImpl::RemoveStreamGraphThread(MediaStream* aStream)
 {
@@ -150,20 +149,26 @@ MediaStreamGraphImpl::RemoveStreamGraphT
   SetStreamOrderDirty();
 
   if (aStream->IsSuspended()) {
     mSuspendedStreams.RemoveElement(aStream);
   } else {
     mStreams.RemoveElement(aStream);
   }
 
-  STREAM_LOG(LogLevel::Debug, ("Removed media stream %p from graph %p, count %lu",
-                               aStream, this, mStreams.Length()));
-  LIFECYCLE_LOG("Removed media stream %p from graph %p, count %lu",
-                aStream, this, (long)mStreams.Length());
+  LOG(LogLevel::Debug,
+      ("Removed media stream %p from graph %p, count %lu",
+       aStream,
+       this,
+       mStreams.Length()));
+  LOG(LogLevel::Debug,
+      ("Removed media stream %p from graph %p, count %lu",
+       aStream,
+       this,
+       (long)mStreams.Length()));
 
   NS_RELEASE(aStream); // probably destroying it
 }
 
 void
 MediaStreamGraphImpl::ExtractPendingInput(SourceMediaStream* aStream,
                                           GraphTime aDesiredUpToTime,
                                           bool* aEnsureNextIteration)
@@ -171,26 +176,31 @@ MediaStreamGraphImpl::ExtractPendingInpu
   bool finished;
   {
     MutexAutoLock lock(aStream->mMutex);
     if (aStream->mPullEnabled && !aStream->mFinished &&
         !aStream->mListeners.IsEmpty()) {
       // Compute how much stream time we'll need assuming we don't block
       // the stream at all.
       StreamTime t = aStream->GraphTimeToStreamTime(aDesiredUpToTime);
-      STREAM_LOG(LogLevel::Verbose, ("Calling NotifyPull aStream=%p t=%f current end=%f", aStream,
-                                  MediaTimeToSeconds(t),
-                                  MediaTimeToSeconds(aStream->mTracks.GetEnd())));
+      LOG(LogLevel::Verbose,
+          ("Calling NotifyPull aStream=%p t=%f current end=%f",
+           aStream,
+           MediaTimeToSeconds(t),
+           MediaTimeToSeconds(aStream->mTracks.GetEnd())));
       if (t > aStream->mTracks.GetEnd()) {
         *aEnsureNextIteration = true;
 #ifdef DEBUG
         if (aStream->mListeners.Length() == 0) {
-          STREAM_LOG(LogLevel::Error, ("No listeners in NotifyPull aStream=%p desired=%f current end=%f",
-                                    aStream, MediaTimeToSeconds(t),
-                                    MediaTimeToSeconds(aStream->mTracks.GetEnd())));
+          LOG(
+            LogLevel::Error,
+            ("No listeners in NotifyPull aStream=%p desired=%f current end=%f",
+             aStream,
+             MediaTimeToSeconds(t),
+             MediaTimeToSeconds(aStream->mTracks.GetEnd())));
           aStream->DumpTrackInfo();
         }
 #endif
         for (uint32_t j = 0; j < aStream->mListeners.Length(); ++j) {
           MediaStreamListener* l = aStream->mListeners[j];
           {
             MutexAutoUnlock unlock(aStream->mMutex);
             l->NotifyPull(this, t);
@@ -251,33 +261,39 @@ MediaStreamGraphImpl::ExtractPendingInpu
         }
         b.mListener->NotifyQueuedChanges(this, offset, *data->mData);
         if (data->mCommands & SourceMediaStream::TRACK_END) {
           b.mListener->NotifyEnded();
         }
       }
       if (data->mCommands & SourceMediaStream::TRACK_CREATE) {
         MediaSegment* segment = data->mData.forget();
-        STREAM_LOG(LogLevel::Debug, ("SourceMediaStream %p creating track %d, start %lld, initial end %lld",
-                                  aStream, data->mID, int64_t(data->mStart),
-                                  int64_t(segment->GetDuration())));
+        LOG(LogLevel::Debug,
+            ("SourceMediaStream %p creating track %d, start %lld, initial end "
+             "%lld",
+             aStream,
+             data->mID,
+             int64_t(data->mStart),
+             int64_t(segment->GetDuration())));
 
         data->mEndOfFlushedData += segment->GetDuration();
         aStream->mTracks.AddTrack(data->mID, data->mStart, segment);
         // The track has taken ownership of data->mData, so let's replace
         // data->mData with an empty clone.
         data->mData = segment->CreateEmptyClone();
         data->mCommands &= ~SourceMediaStream::TRACK_CREATE;
         shouldNotifyTrackCreated = true;
       } else if (data->mData->GetDuration() > 0) {
         MediaSegment* dest = aStream->mTracks.FindTrack(data->mID)->GetSegment();
-        STREAM_LOG(LogLevel::Verbose, ("SourceMediaStream %p track %d, advancing end from %lld to %lld",
-                                    aStream, data->mID,
-                                    int64_t(dest->GetDuration()),
-                                    int64_t(dest->GetDuration() + data->mData->GetDuration())));
+        LOG(LogLevel::Verbose,
+            ("SourceMediaStream %p track %d, advancing end from %lld to %lld",
+             aStream,
+             data->mID,
+             int64_t(dest->GetDuration()),
+             int64_t(dest->GetDuration() + data->mData->GetDuration())));
         data->mEndOfFlushedData += data->mData->GetDuration();
         dest->AppendFrom(data->mData);
       }
       if (data->mCommands & SourceMediaStream::TRACK_END) {
         aStream->mTracks.FindTrack(data->mID)->SetEnded();
         aStream->mUpdateTracks.RemoveElementAt(i);
       }
     }
@@ -321,20 +337,21 @@ MediaStreamGraphImpl::UpdateCurrentTimeF
     bool isAnyBlocked = stream->mStartBlocking < mStateComputedTime;
     bool isAnyUnblocked = stream->mStartBlocking > aPrevCurrentTime;
 
     // Calculate blocked time and fire Blocked/Unblocked events
     GraphTime blockedTime = mStateComputedTime - stream->mStartBlocking;
     NS_ASSERTION(blockedTime >= 0, "Error in blocking time");
     stream->AdvanceTimeVaryingValuesToCurrentTime(mStateComputedTime,
                                                   blockedTime);
-    STREAM_LOG(LogLevel::Verbose,
-               ("MediaStream %p bufferStartTime=%f blockedTime=%f", stream,
-                MediaTimeToSeconds(stream->mTracksStartTime),
-                MediaTimeToSeconds(blockedTime)));
+    LOG(LogLevel::Verbose,
+        ("MediaStream %p bufferStartTime=%f blockedTime=%f",
+         stream,
+         MediaTimeToSeconds(stream->mTracksStartTime),
+         MediaTimeToSeconds(blockedTime)));
     stream->mStartBlocking = mStateComputedTime;
 
     if (isAnyUnblocked && stream->mNotifiedBlocked) {
       for (uint32_t j = 0; j < stream->mListeners.Length(); ++j) {
         MediaStreamListener* l = stream->mListeners[j];
         l->NotifyBlockingChanged(this, MediaStreamListener::UNBLOCKED);
       }
       stream->mNotifiedBlocked = false;
@@ -390,22 +407,23 @@ MediaStreamGraphImpl::ProcessChunkMetada
     }
     offset += chunk->GetDuration();
     if (chunk->IsNull() || offset < aStart) {
       continue;
     }
     PrincipalHandle principalHandle = chunk->GetPrincipalHandle();
     if (principalHandle != aSegment.GetLastPrincipalHandle()) {
       aSegment.SetLastPrincipalHandle(principalHandle);
-      STREAM_LOG(LogLevel::Debug, ("MediaStream %p track %d, principalHandle "
-                                   "changed in %sChunk with duration %lld",
-                                   aStream, aTrackID,
-                                   aSegment.GetType() == MediaSegment::AUDIO
-                                       ? "Audio" : "Video",
-                                   (long long) chunk->GetDuration()));
+      LOG(LogLevel::Debug,
+          ("MediaStream %p track %d, principalHandle "
+           "changed in %sChunk with duration %lld",
+           aStream,
+           aTrackID,
+           aSegment.GetType() == MediaSegment::AUDIO ? "Audio" : "Video",
+           (long long)chunk->GetDuration()));
       for (const TrackBound<MediaStreamTrackListener>& listener : aStream->mTrackListeners) {
         if (listener.mTrackID == aTrackID) {
           listener.mListener->NotifyPrincipalHandleChanged(this, principalHandle);
         }
       }
     }
   }
 }
@@ -448,20 +466,25 @@ MediaStreamGraphImpl::WillUnderrun(Media
     return aEndBlockingDecisions;
   }
   // This stream isn't finished or suspended. We don't need to call
   // StreamTimeToGraphTime since an underrun is the only thing that can block
   // it.
   GraphTime bufferEnd = aStream->GetTracksEnd() + aStream->mTracksStartTime;
 #ifdef DEBUG
   if (bufferEnd < mProcessedTime) {
-    STREAM_LOG(LogLevel::Error, ("MediaStream %p underrun, "
-                              "bufferEnd %f < mProcessedTime %f (%lld < %lld), Streamtime %lld",
-                              aStream, MediaTimeToSeconds(bufferEnd), MediaTimeToSeconds(mProcessedTime),
-                              bufferEnd, mProcessedTime, aStream->GetTracksEnd()));
+    LOG(LogLevel::Error,
+        ("MediaStream %p underrun, "
+         "bufferEnd %f < mProcessedTime %f (%lld < %lld), Streamtime %lld",
+         aStream,
+         MediaTimeToSeconds(bufferEnd),
+         MediaTimeToSeconds(mProcessedTime),
+         bufferEnd,
+         mProcessedTime,
+         aStream->GetTracksEnd()));
     aStream->DumpTrackInfo();
     NS_ASSERTION(bufferEnd >= mProcessedTime, "Buffer underran");
   }
 #endif
   return std::min(bufferEnd, aEndBlockingDecisions);
 }
 
 namespace {
@@ -778,17 +801,18 @@ MediaStreamGraphImpl::CreateOrDestroyAud
     return;
   }
 
   if (!aStream->GetStreamTracks().GetAndResetTracksDirty() &&
       !aStream->mAudioOutputStreams.IsEmpty()) {
     return;
   }
 
-  STREAM_LOG(LogLevel::Debug, ("Updating AudioOutputStreams for MediaStream %p", aStream));
+  LOG(LogLevel::Debug,
+      ("Updating AudioOutputStreams for MediaStream %p", aStream));
 
   AutoTArray<bool,2> audioOutputStreamsFound;
   for (uint32_t i = 0; i < aStream->mAudioOutputStreams.Length(); ++i) {
     audioOutputStreamsFound.AppendElement(false);
   }
 
   for (StreamTracks::TrackIter tracks(aStream->GetStreamTracks(), MediaSegment::AUDIO);
        !tracks.IsEnded(); tracks.Next()) {
@@ -868,55 +892,73 @@ MediaStreamGraphImpl::PlayAudio(MediaStr
 
       // Check how many ticks of sound we can provide if we are blocked some
       // time in the middle of this cycle.
       StreamTime toWrite = end - t;
 
       if (blocked) {
         output.InsertNullDataAtStart(toWrite);
         ticksWritten += toWrite;
-        STREAM_LOG(LogLevel::Verbose, ("MediaStream %p writing %ld blocking-silence samples for %f to %f (%ld to %ld)\n",
-                                    aStream, toWrite, MediaTimeToSeconds(t), MediaTimeToSeconds(end),
-                                    offset, offset + toWrite));
+        LOG(LogLevel::Verbose,
+            ("MediaStream %p writing %ld blocking-silence samples for "
+             "%f to %f (%ld to %ld)",
+             aStream,
+             toWrite,
+             MediaTimeToSeconds(t),
+             MediaTimeToSeconds(end),
+             offset,
+             offset + toWrite));
       } else {
         StreamTime endTicksNeeded = offset + toWrite;
         StreamTime endTicksAvailable = audio->GetDuration();
 
         if (endTicksNeeded <= endTicksAvailable) {
-          STREAM_LOG(LogLevel::Verbose,
-                     ("MediaStream %p writing %ld samples for %f to %f "
-                      "(samples %ld to %ld)\n",
-                      aStream, toWrite, MediaTimeToSeconds(t),
-                      MediaTimeToSeconds(end), offset, endTicksNeeded));
+          LOG(LogLevel::Verbose,
+              ("MediaStream %p writing %ld samples for %f to %f "
+               "(samples %ld to %ld)",
+               aStream,
+               toWrite,
+               MediaTimeToSeconds(t),
+               MediaTimeToSeconds(end),
+               offset,
+               endTicksNeeded));
           output.AppendSlice(*audio, offset, endTicksNeeded);
           ticksWritten += toWrite;
           offset = endTicksNeeded;
         } else {
           // MOZ_ASSERT(track->IsEnded(), "Not enough data, and track not ended.");
           // If we are at the end of the track, maybe write the remaining
           // samples, and pad with/output silence.
           if (endTicksNeeded > endTicksAvailable &&
               offset < endTicksAvailable) {
             output.AppendSlice(*audio, offset, endTicksAvailable);
-            STREAM_LOG(LogLevel::Verbose,
-                       ("MediaStream %p writing %ld samples for %f to %f "
-                        "(samples %ld to %ld)\n",
-                        aStream, toWrite, MediaTimeToSeconds(t),
-                        MediaTimeToSeconds(end), offset, endTicksNeeded));
+            LOG(LogLevel::Verbose,
+                ("MediaStream %p writing %ld samples for %f to %f "
+                 "(samples %ld to %ld)",
+                 aStream,
+                 toWrite,
+                 MediaTimeToSeconds(t),
+                 MediaTimeToSeconds(end),
+                 offset,
+                 endTicksNeeded));
             uint32_t available = endTicksAvailable - offset;
             ticksWritten += available;
             toWrite -= available;
             offset = endTicksAvailable;
           }
           output.AppendNullData(toWrite);
-          STREAM_LOG(LogLevel::Verbose,
-                     ("MediaStream %p writing %ld padding slsamples for %f to "
-                      "%f (samples %ld to %ld)\n",
-                      aStream, toWrite, MediaTimeToSeconds(t),
-                      MediaTimeToSeconds(end), offset, endTicksNeeded));
+          LOG(LogLevel::Verbose,
+              ("MediaStream %p writing %ld padding slsamples for %f to "
+               "%f (samples %ld to %ld)",
+               aStream,
+               toWrite,
+               MediaTimeToSeconds(t),
+               MediaTimeToSeconds(end),
+               offset,
+               endTicksNeeded));
           ticksWritten += toWrite;
         }
         output.ApplyVolume(volume);
       }
       t = end;
     }
     audioOutput.mLastTickWritten = offset;
 
@@ -956,24 +998,28 @@ MediaStreamGraphImpl::OpenAudioInputImpl
     // we close cubeb.
     mInputDeviceID = aID;
     mAudioInputs.AppendElement(aListener); // always monitor speaker data
 
     // Switch Drivers since we're adding input (to input-only or full-duplex)
     MonitorAutoLock mon(mMonitor);
     if (mLifecycleState == LIFECYCLE_RUNNING) {
       AudioCallbackDriver* driver = new AudioCallbackDriver(this);
-      STREAM_LOG(LogLevel::Debug, ("OpenAudioInput: starting new AudioCallbackDriver(input) %p", driver));
-      LIFECYCLE_LOG("OpenAudioInput: starting new AudioCallbackDriver(input) %p", driver);
+      LOG(
+        LogLevel::Debug,
+        ("OpenAudioInput: starting new AudioCallbackDriver(input) %p", driver));
+      LOG(
+        LogLevel::Debug,
+        ("OpenAudioInput: starting new AudioCallbackDriver(input) %p", driver));
       driver->SetInputListener(aListener);
       CurrentDriver()->SwitchAtNextIteration(driver);
    } else {
-      STREAM_LOG(LogLevel::Error, ("OpenAudioInput in shutdown!"));
-      LIFECYCLE_LOG("OpenAudioInput in shutdown!");
-      NS_ASSERTION(false, "Can't open cubeb inputs in shutdown");
+     LOG(LogLevel::Error, ("OpenAudioInput in shutdown!"));
+     LOG(LogLevel::Debug, ("OpenAudioInput in shutdown!"));
+     NS_ASSERTION(false, "Can't open cubeb inputs in shutdown");
     }
   }
 }
 
 nsresult
 MediaStreamGraphImpl::OpenAudioInput(int aID,
                                      AudioDataListener *aListener)
 {
@@ -1025,22 +1071,23 @@ MediaStreamGraphImpl::CloseAudioInputImp
   bool shouldAEC = false;
   bool audioTrackPresent = AudioTrackPresent(shouldAEC);
 
   MonitorAutoLock mon(mMonitor);
   if (mLifecycleState == LIFECYCLE_RUNNING) {
     GraphDriver* driver;
     if (audioTrackPresent) {
       // We still have audio output
-      STREAM_LOG(LogLevel::Debug, ("CloseInput: output present (AudioCallback)"));
+      LOG(LogLevel::Debug, ("CloseInput: output present (AudioCallback)"));
 
       driver = new AudioCallbackDriver(this);
       CurrentDriver()->SwitchAtNextIteration(driver);
     } else if (CurrentDriver()->AsAudioCallbackDriver()) {
-      STREAM_LOG(LogLevel::Debug, ("CloseInput: no output present (SystemClockCallback)"));
+      LOG(LogLevel::Debug,
+          ("CloseInput: no output present (SystemClockCallback)"));
 
       driver = new SystemClockDriver(this);
       CurrentDriver()->SwitchAtNextIteration(driver);
     } // else SystemClockDriver->SystemClockDriver, no switch
   }
 }
 
 void
@@ -1268,22 +1315,26 @@ MediaStreamGraphImpl::UpdateGraph(GraphT
 
     if (stream->mFinished) {
       // The stream's not suspended, and since it's finished, underruns won't
       // stop it playing out. So there's no blocking other than what we impose
       // here.
       GraphTime endTime = stream->GetStreamTracks().GetAllTracksEnd() +
           stream->mTracksStartTime;
       if (endTime <= mStateComputedTime) {
-        STREAM_LOG(LogLevel::Verbose, ("MediaStream %p is blocked due to being finished", stream));
+        LOG(LogLevel::Verbose,
+            ("MediaStream %p is blocked due to being finished", stream));
         stream->mStartBlocking = mStateComputedTime;
       } else {
-        STREAM_LOG(LogLevel::Verbose, ("MediaStream %p is finished, but not blocked yet (end at %f, with blocking at %f)",
-            stream, MediaTimeToSeconds(stream->GetTracksEnd()),
-            MediaTimeToSeconds(endTime)));
+        LOG(LogLevel::Verbose,
+            ("MediaStream %p is finished, but not blocked yet (end at %f, with "
+             "blocking at %f)",
+             stream,
+             MediaTimeToSeconds(stream->GetTracksEnd()),
+             MediaTimeToSeconds(endTime)));
         // Data can't be added to a finished stream, so underruns are irrelevant.
         stream->mStartBlocking = std::min(endTime, aEndBlockingDecisions);
       }
     } else {
       stream->mStartBlocking = WillUnderrun(stream, aEndBlockingDecisions);
     }
   }
 
@@ -1381,17 +1432,18 @@ MediaStreamGraphImpl::UpdateMainThreadSt
   MonitorAutoLock lock(mMonitor);
   bool finalUpdate = mForceShutDown ||
     (mProcessedTime >= mEndTime && AllFinishedStreamsNotified()) ||
     (IsEmpty() && mBackMessageQueue.IsEmpty());
   PrepareUpdatesToMainThreadState(finalUpdate);
   if (finalUpdate) {
     // Enter shutdown mode. The stable-state handler will detect this
     // and complete shutdown. Destroy any streams immediately.
-    STREAM_LOG(LogLevel::Debug, ("MediaStreamGraph %p waiting for main thread cleanup", this));
+    LOG(LogLevel::Debug,
+        ("MediaStreamGraph %p waiting for main thread cleanup", this));
     // We'll shut down this graph object if it does not get restarted.
     mLifecycleState = LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP;
     // No need to Destroy streams here. The main-thread owner of each
     // stream is responsible for calling Destroy on them.
     return false;
   }
 
   CurrentDriver()->WaitForNextIteration();
@@ -1444,17 +1496,17 @@ MediaStreamGraphImpl::ApplyStreamUpdate(
     stream->NotifyMainThreadListeners();
   }
 }
 
 void
 MediaStreamGraphImpl::ForceShutDown(ShutdownTicket* aShutdownTicket)
 {
   NS_ASSERTION(NS_IsMainThread(), "Must be called on main thread");
-  STREAM_LOG(LogLevel::Debug, ("MediaStreamGraph %p ForceShutdown", this));
+  LOG(LogLevel::Debug, ("MediaStreamGraph %p ForceShutdown", this));
 
   MonitorAutoLock lock(mMonitor);
   if (aShutdownTicket) {
     MOZ_ASSERT(!mForceShutdownTicket);
     // Avoid waiting forever for a graph to shut down
     // synchronously.  Reports are that some 3rd-party audio drivers
     // occasionally hang in shutdown (both for us and Chrome).
     mShutdownTimer = do_CreateInstance(NS_TIMER_CONTRACTID);
@@ -1499,17 +1551,17 @@ public:
   explicit MediaStreamGraphShutDownRunnable(MediaStreamGraphImpl* aGraph)
     : mGraph(aGraph)
   {}
   NS_IMETHOD Run()
   {
     NS_ASSERTION(mGraph->mDetectedNotRunning,
                  "We should know the graph thread control loop isn't running!");
 
-    LIFECYCLE_LOG("Shutting down graph %p", mGraph.get());
+    LOG(LogLevel::Debug, ("Shutting down graph %p", mGraph.get()));
 
     // We've asserted the graph isn't running.  Use mDriver instead of CurrentDriver
     // to avoid thread-safety checks
 #if 0 // AudioCallbackDrivers are released asynchronously anyways
     // XXX a better test would be have setting mDetectedNotRunning make sure
     // any current callback has finished and block future ones -- or just
     // handle it all in Shutdown()!
     if (mGraph->mDriver->AsAudioCallbackDriver()) {
@@ -1621,32 +1673,32 @@ MediaStreamGraphImpl::RunInStableState(b
 
   {
     MonitorAutoLock lock(mMonitor);
     if (aSourceIsMSG) {
       MOZ_ASSERT(mPostedRunInStableStateEvent);
       mPostedRunInStableStateEvent = false;
     }
 
-#ifdef ENABLE_LIFECYCLE_LOG
-  // This should be kept in sync with the LifecycleState enum in
-  // MediaStreamGraphImpl.h
-  const char * LifecycleState_str[] = {
-    "LIFECYCLE_THREAD_NOT_STARTED",
-    "LIFECYCLE_RUNNING",
-    "LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP",
-    "LIFECYCLE_WAITING_FOR_THREAD_SHUTDOWN",
-    "LIFECYCLE_WAITING_FOR_STREAM_DESTRUCTION"
-  };
-
-  if (mLifecycleState != LIFECYCLE_RUNNING) {
-    LIFECYCLE_LOG("Running %p in stable state. Current state: %s\n",
-        this, LifecycleState_str[mLifecycleState]);
-  }
-#endif
+    // This should be kept in sync with the LifecycleState enum in
+    // MediaStreamGraphImpl.h
+    const char* LifecycleState_str[] = {
+      "LIFECYCLE_THREAD_NOT_STARTED",
+      "LIFECYCLE_RUNNING",
+      "LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP",
+      "LIFECYCLE_WAITING_FOR_THREAD_SHUTDOWN",
+      "LIFECYCLE_WAITING_FOR_STREAM_DESTRUCTION"
+    };
+
+    if (mLifecycleState != LIFECYCLE_RUNNING) {
+      LOG(LogLevel::Debug,
+          ("Running %p in stable state. Current state: %s",
+           this,
+           LifecycleState_str[mLifecycleState]));
+    }
 
     runnables.SwapElements(mUpdateRunnables);
     for (uint32_t i = 0; i < mStreamUpdates.Length(); ++i) {
       StreamUpdate* update = &mStreamUpdates[i];
       if (update->mStream) {
         ApplyStreamUpdate(update);
       }
     }
@@ -1655,21 +1707,22 @@ MediaStreamGraphImpl::RunInStableState(b
     if (mCurrentTaskMessageQueue.IsEmpty()) {
       if (mLifecycleState == LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP && IsEmpty()) {
         // Complete shutdown. First, ensure that this graph is no longer used.
         // A new graph graph will be created if one is needed.
         // Asynchronously clean up old graph. We don't want to do this
         // synchronously because it spins the event loop waiting for threads
         // to shut down, and we don't want to do that in a stable state handler.
         mLifecycleState = LIFECYCLE_WAITING_FOR_THREAD_SHUTDOWN;
-        LIFECYCLE_LOG("Sending MediaStreamGraphShutDownRunnable %p", this);
+        LOG(LogLevel::Debug,
+            ("Sending MediaStreamGraphShutDownRunnable %p", this));
         nsCOMPtr<nsIRunnable> event = new MediaStreamGraphShutDownRunnable(this );
         NS_DispatchToMainThread(event.forget());
 
-        LIFECYCLE_LOG("Disconnecting MediaStreamGraph %p", this);
+        LOG(LogLevel::Debug, ("Disconnecting MediaStreamGraph %p", this));
         MediaStreamGraphImpl* graph;
         if (gGraphs.Get(uint32_t(mAudioChannel), &graph) && graph == this) {
           // null out gGraph if that's the graph being shut down
           gGraphs.Remove(uint32_t(mAudioChannel));
         }
       }
     } else {
       if (mLifecycleState <= LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP) {
@@ -1684,19 +1737,21 @@ MediaStreamGraphImpl::RunInStableState(b
       // processing.
       if (mLifecycleState == LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP &&
           mRealtime && !mForceShutDown) {
         mLifecycleState = LIFECYCLE_RUNNING;
         // Revive the MediaStreamGraph since we have more messages going to it.
         // Note that we need to put messages into its queue before reviving it,
         // or it might exit immediately.
         {
-          LIFECYCLE_LOG("Reviving a graph (%p) ! %s\n",
-              this, CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver" :
-                                                               "SystemDriver");
+          LOG(LogLevel::Debug,
+              ("Reviving a graph (%p) ! %s",
+               this,
+               CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver"
+                                                        : "SystemDriver"));
           RefPtr<GraphDriver> driver = CurrentDriver();
           MonitorAutoUnlock unlock(mMonitor);
           driver->Revive();
         }
       }
     }
 
     // Don't start the thread for a non-realtime graph until it has been
@@ -1705,20 +1760,21 @@ MediaStreamGraphImpl::RunInStableState(b
         (mRealtime || mNonRealtimeProcessing)) {
       mLifecycleState = LIFECYCLE_RUNNING;
       // Start the thread now. We couldn't start it earlier because
       // the graph might exit immediately on finding it has no streams. The
       // first message for a new graph must create a stream.
       {
         // We should exit the monitor for now, because starting a stream might
         // take locks, and we don't want to deadlock.
-        LIFECYCLE_LOG("Starting a graph (%p) ! %s\n",
-                      this,
-                      CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver" :
-                                                                 "SystemDriver");
+        LOG(LogLevel::Debug,
+            ("Starting a graph (%p) ! %s",
+             this,
+             CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver"
+                                                      : "SystemDriver"));
         RefPtr<GraphDriver> driver = CurrentDriver();
         MonitorAutoUnlock unlock(mMonitor);
         driver->Start();
         // It's not safe to Shutdown() a thread from StableState, and
         // releasing this may shutdown a SystemClockDriver thread.
         // Proxy the release to outside of StableState.
         NS_ReleaseOnMainThread(driver.forget(), true); // always proxy
       }
@@ -2106,26 +2162,26 @@ MediaStream::SetAudioOutputVolume(void* 
     float mVolume;
   };
   GraphImpl()->AppendMessage(MakeUnique<Message>(this, aKey, aVolume));
 }
 
 void
 MediaStream::AddAudioOutputImpl(void* aKey)
 {
-  STREAM_LOG(LogLevel::Info, ("MediaStream %p Adding AudioOutput for key %p",
-                              this, aKey));
+  LOG(LogLevel::Info,
+      ("MediaStream %p Adding AudioOutput for key %p", this, aKey));
   mAudioOutputs.AppendElement(AudioOutput(aKey));
 }
 
 void
 MediaStream::RemoveAudioOutputImpl(void* aKey)
 {
-  STREAM_LOG(LogLevel::Info, ("MediaStream %p Removing AudioOutput for key %p",
-                              this, aKey));
+  LOG(LogLevel::Info,
+      ("MediaStream %p Removing AudioOutput for key %p", this, aKey));
   for (uint32_t i = 0; i < mAudioOutputs.Length(); ++i) {
     if (mAudioOutputs[i].mKey == aKey) {
       mAudioOutputs.RemoveElementAt(i);
       return;
     }
   }
   NS_ERROR("Audio output key not found");
 }
@@ -2146,18 +2202,20 @@ MediaStream::RemoveAudioOutput(void* aKe
   GraphImpl()->AppendMessage(MakeUnique<Message>(this, aKey));
 }
 
 void
 MediaStream::AddVideoOutputImpl(already_AddRefed<MediaStreamVideoSink> aSink,
                                 TrackID aID)
 {
   RefPtr<MediaStreamVideoSink> sink = aSink;
-  STREAM_LOG(LogLevel::Info, ("MediaStream %p Adding MediaStreamVideoSink %p as output",
-                              this, sink.get()));
+  LOG(LogLevel::Info,
+      ("MediaStream %p Adding MediaStreamVideoSink %p as output",
+       this,
+       sink.get()));
   MOZ_ASSERT(aID != TRACK_NONE);
    for (auto entry : mVideoOutputs) {
      if (entry.mListener == sink &&
          (entry.mTrackID == TRACK_ANY || entry.mTrackID == aID)) {
        return;
      }
    }
    TrackBound<MediaStreamVideoSink>* l = mVideoOutputs.AppendElement();
@@ -2166,18 +2224,19 @@ MediaStream::AddVideoOutputImpl(already_
 
    AddDirectTrackListenerImpl(sink.forget(), aID);
 }
 
 void
 MediaStream::RemoveVideoOutputImpl(MediaStreamVideoSink* aSink,
                                    TrackID aID)
 {
-  STREAM_LOG(LogLevel::Info, ("MediaStream %p Removing MediaStreamVideoSink %p as output",
-                              this, aSink));
+  LOG(
+    LogLevel::Info,
+    ("MediaStream %p Removing MediaStreamVideoSink %p as output", this, aSink));
   MOZ_ASSERT(aID != TRACK_NONE);
 
   // Ensure that any frames currently queued for playback by the compositor
   // are removed.
   aSink->ClearFrames();
   for (size_t i = 0; i < mVideoOutputs.Length(); ++i) {
     if (mVideoOutputs[i].mListener == aSink &&
         (mVideoOutputs[i].mTrackID == TRACK_ANY ||
@@ -2692,17 +2751,20 @@ SourceMediaStream::SetPullEnabled(bool a
 void
 SourceMediaStream::AddTrackInternal(TrackID aID, TrackRate aRate, StreamTime aStart,
                                     MediaSegment* aSegment, uint32_t aFlags)
 {
   MutexAutoLock lock(mMutex);
   nsTArray<TrackData> *track_data = (aFlags & ADDTRACK_QUEUED) ?
                                     &mPendingTracks : &mUpdateTracks;
   TrackData* data = track_data->AppendElement();
-  LIFECYCLE_LOG("AddTrackInternal: %lu/%lu", (long)mPendingTracks.Length(), (long)mUpdateTracks.Length());
+  LOG(LogLevel::Debug,
+      ("AddTrackInternal: %lu/%lu",
+       (long)mPendingTracks.Length(),
+       (long)mUpdateTracks.Length()));
   data->mID = aID;
   data->mInputRate = aRate;
   data->mResamplerChannelCount = 0;
   data->mStart = aStart;
   data->mEndOfFlushedData = aStart;
   data->mCommands = TRACK_CREATE;
   data->mData = aSegment;
   ResampleAudioToGraphSampleRate(data, aSegment);
@@ -2718,17 +2780,20 @@ SourceMediaStream::AddAudioTrack(TrackID
   AddTrackInternal(aID, aRate, aStart, aSegment, aFlags);
 }
 
 void
 SourceMediaStream::FinishAddTracks()
 {
   MutexAutoLock lock(mMutex);
   mUpdateTracks.AppendElements(Move(mPendingTracks));
-  LIFECYCLE_LOG("FinishAddTracks: %lu/%lu", (long)mPendingTracks.Length(), (long)mUpdateTracks.Length());
+  LOG(LogLevel::Debug,
+      ("FinishAddTracks: %lu/%lu",
+       (long)mPendingTracks.Length(),
+       (long)mUpdateTracks.Length()));
   if (GraphImpl()) {
     GraphImpl()->EnsureNextIteration();
   }
 }
 
 void
 SourceMediaStream::ResampleAudioToGraphSampleRate(TrackData* aTrackData, MediaSegment* aSegment)
 {
@@ -2887,18 +2952,21 @@ SourceMediaStream::AddDirectTrackListene
                                               TrackID aTrackID)
 {
   MOZ_ASSERT(IsTrackIDExplicit(aTrackID));
   TrackData* updateData = nullptr;
   StreamTracks::Track* track = nullptr;
   bool isAudio = false;
   bool isVideo = false;
   RefPtr<DirectMediaStreamTrackListener> listener = aListener;
-  STREAM_LOG(LogLevel::Debug, ("Adding direct track listener %p bound to track %d to source stream %p",
-             listener.get(), aTrackID, this));
+  LOG(LogLevel::Debug,
+      ("Adding direct track listener %p bound to track %d to source stream %p",
+       listener.get(),
+       aTrackID,
+       this));
 
   {
     MutexAutoLock lock(mMutex);
     updateData = FindDataForTrack(aTrackID);
     track = FindTrack(aTrackID);
     if (track) {
       isAudio = track->GetType() == MediaSegment::AUDIO;
       isVideo = track->GetType() == MediaSegment::VIDEO;
@@ -2931,31 +2999,34 @@ SourceMediaStream::AddDirectTrackListene
 
       TrackBound<DirectMediaStreamTrackListener>* sourceListener =
         mDirectTrackListeners.AppendElement();
       sourceListener->mListener = listener;
       sourceListener->mTrackID = aTrackID;
     }
   }
   if (!track) {
-    STREAM_LOG(LogLevel::Warning, ("Couldn't find source track for direct track listener %p",
-                                   listener.get()));
+    LOG(LogLevel::Warning,
+        ("Couldn't find source track for direct track listener %p",
+         listener.get()));
     listener->NotifyDirectListenerInstalled(
       DirectMediaStreamTrackListener::InstallationResult::TRACK_NOT_FOUND_AT_SOURCE);
     return;
   }
   if (!isAudio && !isVideo) {
-    STREAM_LOG(LogLevel::Warning, ("Source track for direct track listener %p is unknown",
-                                   listener.get()));
+    LOG(
+      LogLevel::Warning,
+      ("Source track for direct track listener %p is unknown", listener.get()));
     // It is not a video or audio track.
     MOZ_ASSERT(true);
     return;
   }
-  STREAM_LOG(LogLevel::Debug, ("Added direct track listener %p. ended=%d",
-                               listener.get(), !updateData));
+  LOG(
+    LogLevel::Debug,
+    ("Added direct track listener %p. ended=%d", listener.get(), !updateData));
   listener->NotifyDirectListenerInstalled(
     DirectMediaStreamTrackListener::InstallationResult::SUCCESS);
   if (!updateData) {
     // The track exists but the mUpdateTracks entry was removed.
     // This means that the track has ended.
     listener->NotifyEnded();
   }
 }
@@ -3028,24 +3099,28 @@ SourceMediaStream::SetTrackEnabledImpl(T
     MutexAutoLock lock(mMutex);
     for (TrackBound<DirectMediaStreamTrackListener>& l: mDirectTrackListeners) {
       if (l.mTrackID != aTrackID) {
         continue;
       }
       DisabledTrackMode oldMode = GetDisabledTrackMode(aTrackID);
       bool oldEnabled = oldMode == DisabledTrackMode::ENABLED;
       if (!oldEnabled && aMode == DisabledTrackMode::ENABLED) {
-        STREAM_LOG(LogLevel::Debug, ("SourceMediaStream %p track %d setting "
-                                     "direct listener enabled",
-                                     this, aTrackID));
+        LOG(LogLevel::Debug,
+            ("SourceMediaStream %p track %d setting "
+             "direct listener enabled",
+             this,
+             aTrackID));
         l.mListener->DecreaseDisabled(oldMode);
       } else if (oldEnabled && aMode != DisabledTrackMode::ENABLED) {
-        STREAM_LOG(LogLevel::Debug, ("SourceMediaStream %p track %d setting "
-                                     "direct listener disabled",
-                                     this, aTrackID));
+        LOG(LogLevel::Debug,
+            ("SourceMediaStream %p track %d setting "
+             "direct listener disabled",
+             this,
+             aTrackID));
         l.mListener->IncreaseDisabled(aMode);
       }
     }
   }
   MediaStream::SetTrackEnabledImpl(aTrackID, aMode);
 }
 
 void
@@ -3093,18 +3168,21 @@ SourceMediaStream::HasPendingAudioTrack(
   }
 
   return audioTrackPresent;
 }
 
 void
 MediaInputPort::Init()
 {
-  STREAM_LOG(LogLevel::Debug, ("Adding MediaInputPort %p (from %p to %p) to the graph",
-             this, mSource, mDest));
+  LOG(LogLevel::Debug,
+      ("Adding MediaInputPort %p (from %p to %p) to the graph",
+       this,
+       mSource,
+       mDest));
   mSource->AddConsumer(this);
   mDest->AddInput(this);
   // mPortCount decremented via MediaInputPort::Destroy's message
   ++mDest->GraphImpl()->mPortCount;
 }
 
 void
 MediaInputPort::Disconnect()
@@ -3446,35 +3524,36 @@ MediaStreamGraph::GetInstance(MediaStrea
     }
 
     graph = new MediaStreamGraphImpl(aGraphDriverRequested,
                                      CubebUtils::PreferredSampleRate(),
                                      aChannel);
 
     gGraphs.Put(channel, graph);
 
-    STREAM_LOG(LogLevel::Debug,
+    LOG(LogLevel::Debug,
         ("Starting up MediaStreamGraph %p for channel %s",
-         graph, AudioChannelValues::strings[channel].value));
+         graph,
+         AudioChannelValues::strings[channel].value));
   }
 
   return graph;
 }
 
 MediaStreamGraph*
 MediaStreamGraph::CreateNonRealtimeInstance(TrackRate aSampleRate)
 {
   NS_ASSERTION(NS_IsMainThread(), "Main thread only");
 
   MediaStreamGraphImpl* graph =
     new MediaStreamGraphImpl(OFFLINE_THREAD_DRIVER,
                              aSampleRate,
                              AudioChannel::Normal);
 
-  STREAM_LOG(LogLevel::Debug, ("Starting up Offline MediaStreamGraph %p", graph));
+  LOG(LogLevel::Debug, ("Starting up Offline MediaStreamGraph %p", graph));
 
   return graph;
 }
 
 void
 MediaStreamGraph::DestroyNonRealtimeInstance(MediaStreamGraph* aGraph)
 {
   NS_ASSERTION(NS_IsMainThread(), "Main thread only");
@@ -3764,19 +3843,21 @@ MediaStreamGraphImpl::SuspendOrResumeStr
   // streams from the set of streams that are going to be processed.
   for (MediaStream* stream : aStreamSet) {
     if (aAudioContextOperation == AudioContextOperation::Resume) {
       DecrementSuspendCount(stream);
     } else {
       IncrementSuspendCount(stream);
     }
   }
-  STREAM_LOG(LogLevel::Debug, ("Moving streams between suspended and running"
-      "state: mStreams: %d, mSuspendedStreams: %d\n", mStreams.Length(),
-      mSuspendedStreams.Length()));
+  LOG(LogLevel::Debug,
+      ("Moving streams between suspended and running"
+       "state: mStreams: %d, mSuspendedStreams: %d",
+       mStreams.Length(),
+       mSuspendedStreams.Length()));
 #ifdef DEBUG
   // The intersection of the two arrays should be null.
   for (uint32_t i = 0; i < mStreams.Length(); i++) {
     for (uint32_t j = 0; j < mSuspendedStreams.Length(); j++) {
       MOZ_ASSERT(
         mStreams[i] != mSuspendedStreams[j],
         "The suspended stream set and running stream set are not disjoint.");
     }