Extends logging for native audio implementations (part II)

Makes some final adjustments in the previous change landed in

https://chromium-review.googlesource.com/c/chromium/src/+/2062428

to ensure that all output streams adds a unique ID and that the logging
style identical for all platforms.

Bug: 1017219
Change-Id: I7d7caa45307e3a7a8270528feea3c3205b5b784c
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2087674Reviewed-by: Guido Urdaneta <guidou@chromium.org>
Commit-Queue: Henrik Andreasson <henrika@chromium.org>
Cr-Commit-Position: refs/heads/master@{#746826}

media/audio/pulse/pulse_input.cc

@@ -15,22 +15,6 @@
 
 namespace media {
 
-namespace {
-
-PRINTF_FORMAT(2, 3)
-void SendLogMessage(const AudioManagerBase::LogCallback& callback,
-                    const char* format,
-                    ...) {
-  if (callback.is_null())
-    return;
-  va_list args;
-  va_start(args, format);
-  callback.Run("PAIS::" + base::StringPrintV(format, args));
-  va_end(args);
-}
-
-}  // namespace
-
 using pulse::AutoPulseLock;
 using pulse::WaitForOperationCompletion;
 
@@ -62,7 +46,7 @@ PulseAudioInputStream::PulseAudioInputStream(
   DCHECK(mainloop);
   DCHECK(context);
   CHECK(params_.IsValid());
-  SendLogMessage(log_callback_, "%s({device_id=%s}, {params=[%s]})", __func__,
+  SendLogMessage("%s({device_id=%s}, {params=[%s]})", __func__,
                  device_name.c_str(), params.AsHumanReadableString().c_str());
 }
 
@@ -74,19 +58,17 @@ PulseAudioInputStream::~PulseAudioInputStream() {
 
 bool PulseAudioInputStream::Open() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  SendLogMessage(log_callback_, "%s()", __func__);
+  SendLogMessage("%s()", __func__);
   if (device_name_ == AudioDeviceDescription::kDefaultDeviceId &&
       audio_manager_->DefaultSourceIsMonitor()) {
-    SendLogMessage(log_callback_, "%s => (ERROR: can't open monitor device)",
-                   __func__);
+    SendLogMessage("%s => (ERROR: can't open monitor device)", __func__);
     return false;
   }
 
   AutoPulseLock auto_lock(pa_mainloop_);
   if (!pulse::CreateInputStream(pa_mainloop_, pa_context_, &handle_, params_,
                                 device_name_, &StreamNotifyCallback, this)) {
-    SendLogMessage(log_callback_, "%s => (ERROR: failed to open PA stream)",
-                   __func__);
+    SendLogMessage("%s => (ERROR: failed to open PA stream)", __func__);
     return false;
   }
 
@@ -99,7 +81,7 @@ void PulseAudioInputStream::Start(AudioInputCallback* callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(callback);
   DCHECK(handle_);
-  SendLogMessage(log_callback_, "%s()", __func__);
+  SendLogMessage("%s()", __func__);
 
   // AGC needs to be started out of the lock.
   StartAgc();
@@ -126,7 +108,7 @@ void PulseAudioInputStream::Start(AudioInputCallback* callback) {
 
 void PulseAudioInputStream::Stop() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  SendLogMessage(log_callback_, "%s()", __func__);
+  SendLogMessage("%s()", __func__);
   AutoPulseLock auto_lock(pa_mainloop_);
   if (!stream_started_)
     return;
@@ -160,7 +142,7 @@ void PulseAudioInputStream::Stop() {
 
 void PulseAudioInputStream::Close() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  SendLogMessage(log_callback_, "%s()", __func__);
+  SendLogMessage("%s()", __func__);
   {
     AutoPulseLock auto_lock(pa_mainloop_);
     if (handle_) {
@@ -192,7 +174,7 @@ void PulseAudioInputStream::SetVolume(double volume) {
   AutoPulseLock auto_lock(pa_mainloop_);
   if (!handle_)
     return;
-  SendLogMessage(log_callback_, "%s({volume=%.2f})", __func__, volume);
+  SendLogMessage("%s({volume=%.2f})", __func__, volume);
 
   size_t index = pa_stream_get_device_index(handle_);
   pa_operation* operation = nullptr;
@@ -204,8 +186,7 @@ void PulseAudioInputStream::SetVolume(double volume) {
     if (!WaitForOperationCompletion(pa_mainloop_, operation, pa_context_,
                                     handle_) ||
         !channels_) {
-      SendLogMessage(log_callback_,
-                     "%s => (WARNING: failed to read number of channels)",
+      SendLogMessage("%s => (WARNING: failed to read number of channels)",
                      __func__);
       return;
     }
@@ -252,6 +233,15 @@ void PulseAudioInputStream::SetOutputDeviceForAec(
   // Not supported. Do nothing.
 }
 
+void PulseAudioInputStream::SendLogMessage(const char* format, ...) {
+  if (log_callback_.is_null())
+    return;
+  va_list args;
+  va_start(args, format);
+  log_callback_.Run("PAIS::" + base::StringPrintV(format, args));
+  va_end(args);
+}
+
 // static, used by pa_stream_set_read_callback.
 void PulseAudioInputStream::ReadCallback(pa_stream* handle,
                                          size_t length,

media/audio/pulse/pulse_input.h

@@ -45,6 +45,9 @@ class PulseAudioInputStream : public AgcAudioStream<AudioInputStream> {
   void SetOutputDeviceForAec(const std::string& output_device_id) override;
 
  private:
+  // Helper method used for sending native logs to the registered client.
+  void SendLogMessage(const char* format, ...) PRINTF_FORMAT(2, 3);
+
   // PulseAudio Callbacks.
   static void ReadCallback(pa_stream* handle, size_t length, void* user_data);
   static void StreamNotifyCallback(pa_stream* stream, void* user_data);

media/audio/pulse/pulse_output.cc

@@ -18,22 +18,6 @@
 
 namespace media {
 
-namespace {
-
-PRINTF_FORMAT(2, 3)
-void SendLogMessage(const AudioManagerBase::LogCallback& callback,
-                    const char* format,
-                    ...) {
-  if (callback.is_null())
-    return;
-  va_list args;
-  va_start(args, format);
-  callback.Run("PAOS::" + base::StringPrintV(format, args));
-  va_end(args);
-}
-
-}  // namespace
-
 using pulse::AutoPulseLock;
 using pulse::WaitForOperationCompletion;
 
@@ -78,10 +62,8 @@ PulseAudioOutputStream::PulseAudioOutputStream(
       source_callback_(nullptr),
       buffer_size_(params_.GetBytesPerBuffer(kSampleFormatF32)) {
   CHECK(params_.IsValid());
-  SendLogMessage(
-      log_callback_,
-      "PulseAudioOutputStream({device_id=%s}, {params=[%s]} [this=%p])",
-      device_id.c_str(), params.AsHumanReadableString().c_str(), this);
+  SendLogMessage("%s({device_id=%s}, {params=[%s]})", __func__,
+                 device_id.c_str(), params.AsHumanReadableString().c_str());
   audio_bus_ = AudioBus::Create(params_);
 }
 
@@ -95,13 +77,13 @@ PulseAudioOutputStream::~PulseAudioOutputStream() {
 
 bool PulseAudioOutputStream::Open() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  SendLogMessage(log_callback_, "Open([this=%p])", this);
+  SendLogMessage("%s()", __func__);
   bool result = pulse::CreateOutputStream(
       &pa_mainloop_, &pa_context_, &pa_stream_, params_, device_id_,
       AudioManager::GetGlobalAppName(), &StreamNotifyCallback,
       &StreamRequestCallback, this);
   if (!result) {
-    SendLogMessage(log_callback_, "Open => (ERROR: failed to open PA stream)");
+    SendLogMessage("%s => (ERROR: failed to open PA stream)", __func__);
   }
   return result;
 }
@@ -147,7 +129,7 @@ void PulseAudioOutputStream::Reset() {
 
 void PulseAudioOutputStream::Close() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  SendLogMessage(log_callback_, "Close([this=%p])", this);
+  SendLogMessage("%s()", __func__);
 
   Reset();
 
@@ -160,6 +142,16 @@ void PulseAudioOutputStream::Close() {
 // sufficient to simply always flush upon Start().
 void PulseAudioOutputStream::Flush() {}
 
+void PulseAudioOutputStream::SendLogMessage(const char* format, ...) {
+  if (log_callback_.is_null())
+    return;
+  va_list args;
+  va_start(args, format);
+  log_callback_.Run("PAOS::" + base::StringPrintV(format, args) +
+                    base::StringPrintf(" [this=%p]", this));
+  va_end(args);
+}
+
 void PulseAudioOutputStream::FulfillWriteRequest(size_t requested_bytes) {
   int bytes_remaining = requested_bytes;
   while (bytes_remaining > 0) {
@@ -231,7 +223,7 @@ void PulseAudioOutputStream::Start(AudioSourceCallback* callback) {
   DCHECK(thread_checker_.CalledOnValidThread());
   CHECK(callback);
   CHECK(pa_stream_);
-  SendLogMessage(log_callback_, "Start([this=%p])", this);
+  SendLogMessage("%s()", __func__);
 
   AutoPulseLock auto_lock(pa_mainloop_);
 
@@ -255,7 +247,7 @@ void PulseAudioOutputStream::Start(AudioSourceCallback* callback) {
 
 void PulseAudioOutputStream::Stop() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  SendLogMessage(log_callback_, "Stop([this=%p])", this);
+  SendLogMessage("%s()", __func__);
 
   // Cork (pause) the stream.  Waiting for the main loop lock will ensure
   // outstanding callbacks have completed.

media/audio/pulse/pulse_output.h

@@ -57,6 +57,9 @@ class PulseAudioOutputStream : public AudioOutputStream {
   void GetVolume(double* volume) override;
 
  private:
+  // Helper method used for sending native logs to the registered client.
+  void SendLogMessage(const char* format, ...) PRINTF_FORMAT(2, 3);
+
   // Called by PulseAudio when |pa_stream_| change state.  If an unexpected
   // failure state change happens and |source_callback_| is set
   // this method will forward the error via OnError().

media/audio/win/audio_low_latency_output_win.cc

@@ -6,6 +6,7 @@
 
 #include <Functiondiscoverykeys_devpkey.h>
 #include <audiopolicy.h>
+#include <inttypes.h>
 #include <objbase.h>
 
 #include <climits>
@@ -455,7 +456,9 @@ void WASAPIAudioOutputStream::SendLogMessage(const char* format, ...) {
     return;
   va_list args;
   va_start(args, format);
-  log_callback_.Run("WAOS::" + base::StringPrintV(format, args));
+  log_callback_.Run("WAOS::" + base::StringPrintV(format, args) +
+                    base::StringPrintf(" [this=0x%" PRIXPTR "]",
+                                       reinterpret_cast<uintptr_t>(this)));
   va_end(args);
 }