Minor log changes in OutputStream and InputStream.

Ensures that style is consistent. Goal is to fix these details before
M82 cut.

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

services/audio/input_stream.cc

@@ -40,11 +40,10 @@ const char* ErrorCodeToString(InputController::ErrorCode error) {
   return "UNKNOWN_ERROR";
 }
 
-std::string GetCtorLogString(const base::UnguessableToken& id,
-                             const std::string& device_id,
+std::string GetCtorLogString(const std::string& device_id,
                              const media::AudioParameters& params,
                              bool enable_agc) {
-  std::string str = base::StringPrintf("Ctor({id=%s}, ", id.ToString().c_str());
+  std::string str = base::StringPrintf("Ctor(");
   base::StringAppendF(&str, "{device_id=%s}, ", device_id.c_str());
   base::StringAppendF(&str, "{params=[%s]}, ",
                       params.AsHumanReadableString().c_str());
@@ -95,7 +94,7 @@ InputStream::InputStream(
   TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("audio", "InputStream", this, "device id",
                                     device_id, "params",
                                     params.AsHumanReadableString());
-  SendLogMessage(GetCtorLogString(id_, device_id, params, enable_agc));
+  SendLogMessage("%s", GetCtorLogString(device_id, params, enable_agc).c_str());
 
   // |this| owns these objects, so unretained is safe.
   base::RepeatingClosure error_handler = base::BindRepeating(
@@ -132,7 +131,7 @@ InputStream::InputStream(
 
 InputStream::~InputStream() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
-  SendLogMessage("Dtor({id=" + id_.ToString() + "})");
+  SendLogMessage("Dtor()");
 
   if (log_)
     log_->OnClosed();
@@ -167,20 +166,15 @@ void InputStream::SetOutputDeviceForAec(const std::string& output_device_id) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(controller_);
   controller_->SetOutputDeviceForAec(output_device_id);
-  if (log_) {
-    log_->OnLogMessage(
-        base::StrCat({"SetOutputDeviceForAec: ", output_device_id}));
-  }
-  SendLogMessage("SetOutputDeviceForAec({id=" + id_.ToString() + "}, " +
-                 "{output_device_id=" + output_device_id + "})");
+  SendLogMessage("%s({output_device_id=%s})", __func__,
+                 output_device_id.c_str());
 }
 
 void InputStream::Record() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(controller_);
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "Record", this);
-  SendLogMessage("Record({id=" + id_.ToString() + "})");
-
+  SendLogMessage("%s()", __func__);
   controller_->Record();
   if (observer_)
     observer_->DidStartRecording();
@@ -209,8 +203,8 @@ void InputStream::OnCreated(bool initially_muted) {
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("audio", "Created", this,
                                       "initially muted", initially_muted);
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
-  SendLogMessage(base::StringPrintf("OnCreated({id=%s}, {muted=%d})",
-                                    id_.ToString().c_str(), initially_muted));
+  SendLogMessage("%s({muted=%s})", __func__,
+                 initially_muted ? "true" : "false");
 
   base::ReadOnlySharedMemoryRegion shared_memory_region =
       writer_->TakeSharedMemoryRegion();
@@ -233,12 +227,10 @@ void InputStream::OnError(InputController::ErrorCode error_code) {
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "Error", this);
 
   client_->OnError();
-  if (log_) {
+  if (log_)
     log_->OnError();
-    SendLogMessage(base::StringPrintf("OnError({id=%s}, {error_code=%s})",
-                                      id_.ToString().c_str(),
-                                      ErrorCodeToString(error_code)));
-  }
+  SendLogMessage("%s({error_code=%s})", __func__,
+                 ErrorCodeToString(error_code));
   OnStreamError(true);
 }
 
@@ -265,7 +257,7 @@ void InputStream::OnStreamError(bool signalPlatformError) {
   }
 
   if (signalPlatformError) {
-    SendLogMessage("OnStreamError({id=" + id_.ToString() + "})");
+    SendLogMessage("%s()", __func__);
   }
 
   // Defer callback so we're not destructed while in the constructor.
@@ -281,11 +273,15 @@ void InputStream::CallDeleter() {
   std::move(delete_callback_).Run(this);
 }
 
-void InputStream::SendLogMessage(const std::string& message) {
+void InputStream::SendLogMessage(const char* format, ...) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
-  if (log_) {
-    log_->OnLogMessage("audio::IS::" + message);
-  }
+  if (!log_)
+    return;
+  va_list args;
+  va_start(args, format);
+  log_->OnLogMessage("audio::IS::" + base::StringPrintV(format, args) +
+                     base::StringPrintf(" [id=%s]", id_.ToString().c_str()));
+  va_end(args);
 }
 
 }  // namespace audio

services/audio/input_stream.h

@@ -77,7 +77,7 @@ class InputStream final : public media::mojom::AudioInputStream,
  private:
   void OnStreamError(bool signalPlatformError);
   void CallDeleter();
-  void SendLogMessage(const std::string& message);
+  void SendLogMessage(const char* format, ...) PRINTF_FORMAT(2, 3);
 
   const base::UnguessableToken id_;
 

services/audio/output_stream.cc

@@ -20,13 +20,12 @@ const float kSilenceThresholdDBFS = -72.24719896f;
 // "blip" sounds won't be detected.  http://crbug.com/339133#c4
 const int kPowerMeasurementsPerSecond = 15;
 
-std::string GetCtorLogString(const base::UnguessableToken& id,
-                             media::AudioManager* audio_manager,
+std::string GetCtorLogString(media::AudioManager* audio_manager,
                              const std::string& device_id,
                              const media::AudioParameters& params) {
   return base::StringPrintf(
-      "Ctor({id=%s}, {audio_manager_name=%s}, {device_id=%s}, {params=[%s]})",
-      id.ToString().c_str(), audio_manager->GetName(), device_id.c_str(),
+      "Ctor({audio_manager_name=%s}, {device_id=%s}, {params=[%s]})",
+      audio_manager->GetName(), device_id.c_str(),
       params.AsHumanReadableString().c_str());
 }
 
@@ -72,9 +71,8 @@ OutputStream::OutputStream(
   TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("audio", "OutputStream", this, "device id",
                                     output_device_id, "params",
                                     params.AsHumanReadableString());
-  SendLogMessage("%s", GetCtorLogString(processing_id, audio_manager,
-                                        output_device_id, params)
-                           .c_str());
+  SendLogMessage(
+      "%s", GetCtorLogString(audio_manager, output_device_id, params).c_str());
 
   // |this| owns these objects, so unretained is safe.
   base::RepeatingClosure error_handler =
@@ -128,6 +126,7 @@ OutputStream::~OutputStream() {
 
 void OutputStream::Play() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  SendLogMessage("%s()", __func__);
 
   controller_.Play();
   if (log_)
@@ -136,6 +135,7 @@ void OutputStream::Play() {
 
 void OutputStream::Pause() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  SendLogMessage("%s()", __func__);
 
   controller_.Pause();
   if (log_)
@@ -144,6 +144,7 @@ void OutputStream::Pause() {
 
 void OutputStream::Flush() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  SendLogMessage("%s()", __func__);
 
   controller_.Flush();
 }
@@ -168,8 +169,7 @@ void OutputStream::CreateAudioPipe(CreatedCallback created_callback) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(reader_.IsValid());
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "CreateAudioPipe", this);
-  SendLogMessage("CreateAudioPipe({id=%s})",
-                 processing_id().ToString().c_str());
+  SendLogMessage("%s()", __func__);
 
   base::UnsafeSharedMemoryRegion shared_memory_region =
       reader_.TakeSharedMemoryRegion();
@@ -231,8 +231,7 @@ void OutputStream::OnControllerPaused() {
 void OutputStream::OnControllerError() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "OnControllerError", this);
-  SendLogMessage("OnControllerError({id=%s})",
-                 processing_id().ToString().c_str());
+  SendLogMessage("%s()", __func__);
 
   // Stop checking the audio level to avoid using this object while it's being
   // torn down.
@@ -310,7 +309,9 @@ void OutputStream::SendLogMessage(const char* format, ...) {
     return;
   va_list args;
   va_start(args, format);
-  log_->OnLogMessage("audio::OS::" + base::StringPrintV(format, args));
+  log_->OnLogMessage(
+      "audio::OS::" + base::StringPrintV(format, args) +
+      base::StringPrintf(" [id=%s]", processing_id().ToString().c_str()));
   va_end(args);
 }
 

services/audio/stream_factory.cc

@@ -65,7 +65,11 @@ void StreamFactory::CreateInputStream(
     // If the buffer size is incorrect, the data can't be fed into the APM.
     // This should never happen unless a renderer misbehaves.
     mojo::Remote<media::mojom::AudioLog> log(std::move(pending_log));
-    log->OnLogMessage("Invalid APM config.");
+
+    log->OnLogMessage(
+        "audio::SF::" +
+        base::StringPrintf("%s => (ERROR: Invalid APM configuration)",
+                           __func__));
     log->OnError();
     // The callback must still be invoked or mojo complains.
     std::move(created_callback).Run(nullptr, false, base::nullopt);