Improves native logs in InputStream and InputController

Fine tunes current native logs to match latest changes in the AudioInputDeviceManager (AIDM).

Now makes it easier to track a stream identified with a unique ID (many logs contain multiple
streams).

audio::IS::Ctor({id=4E660FF11A9BBFEFB85C97DF686A4E77}, {device_id=default}, {params=[format: 1, channel_layout: 3, channels: 2, sample_rate: 44100, frames_per_buffer: 441, effects: 0, mic_positions: ]}, {enable_agc=1})
AIC::DoCreate({device_id=default}) [id=4E660FF11A9BBFEFB85C97DF686A4E77]
audio::IS::OnCreated({id=4E660FF11A9BBFEFB85C97DF686A4E77}, {muted=0})
audio::IS::Record({id=4E660FF11A9BBFEFB85C97DF686A4E77})
AIC::Record() [id=4E660FF11A9BBFEFB85C97DF686A4E77]
audio::IS::SetOutputDeviceForAec({id=4E660FF11A9BBFEFB85C97DF686A4E77}, {output_device_id=})
audio::IS::SetOutputDeviceForAec({id=4E660FF11A9BBFEFB85C97DF686A4E77}, {output_device_id=})
AIC::OnData => (average audio level=-80.88 dBFS <=> low audio input level) [id=4E660FF11A9BBFEFB85C97DF686A4E77]
AIC::OnData => (microphone volume=65%) [id=4E660FF11A9BBFEFB85C97DF686A4E77]
AIC::OnMuted({is_muted=1}) [id=4E660FF11A9BBFEFB85C97DF686A4E77]
AIC::OnMuted({is_muted=0}) [id=4E660FF11A9BBFEFB85C97DF686A4E77]
audio::IS::Dtor({id=4E660FF11A9BBFEFB85C97DF686A4E77})
AIC::Close => (stream duration=1 seconds) [id=4E660FF11A9BBFEFB85C97DF686A4E77]

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

services/audio/input_controller.cc

@@ -464,7 +464,7 @@ void InputController::Record() {
   if (!stream_ || audio_callback_)
     return;
 
-  handler_->OnLog("AIC::Record");
+  handler_->OnLog("AIC::Record()");
 
   if (user_input_monitor_) {
     user_input_monitor_->EnableKeyPressMonitoring();
@@ -511,7 +511,7 @@ void InputController::Close() {
 #endif
 
   std::string log_string;
-  static const char kLogStringPrefix[] = "AIC::DoClose:";
+  static const char kLogStringPrefix[] = "AIC::Close => ";
 
   // Allow calling unconditionally and bail if we don't have a stream to close.
   if (audio_callback_) {
@@ -531,10 +531,11 @@ void InputController::Close() {
     LogCaptureStartupResult(capture_startup_result);
     LogCallbackError();
 
-    log_string = base::StringPrintf(
-        "%s stream duration=%" PRId64 " seconds%s", kLogStringPrefix,
-        duration.InSeconds(),
-        audio_callback_->received_callback() ? "" : " (no callbacks received)");
+    log_string = base::StringPrintf("%s(stream duration=%" PRId64 " seconds%s",
+                                    kLogStringPrefix, duration.InSeconds(),
+                                    audio_callback_->received_callback()
+                                        ? ")"
+                                        : " - no callbacks received)");
 
     if (type_ == LOW_LATENCY) {
       if (audio_callback_->received_callback()) {
@@ -550,8 +551,8 @@ void InputController::Close() {
 
     audio_callback_.reset();
   } else {
-    log_string =
-        base::StringPrintf("%s recording never started", kLogStringPrefix);
+    log_string = base::StringPrintf("%s(WARNING: recording never started)",
+                                    kLogStringPrefix);
   }
 
   handler_->OnLog(log_string);
@@ -579,8 +580,7 @@ void InputController::SetVolume(double volume) {
   if (!stream_)
     return;
 
-  std::string log_string = base::StringPrintf("AIC::SetVolume: %.2f", volume);
-  handler_->OnLog(log_string);
+  handler_->OnLog(base::StringPrintf("AIC::SetVolume({volume=%.2f})", volume));
 
   // Only ask for the maximum volume at first call and use cached value
   // for remaining function calls.
@@ -649,10 +649,7 @@ void InputController::DoCreate(media::AudioManager* audio_manager,
   DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
   DCHECK(!stream_);
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CreateTime");
-  std::string log_string = base::StringPrintf(
-      "AIC::DoCreate: device_id=%s, enable_agc=%d, params=%s",
-      device_id.c_str(), enable_agc, params.AsHumanReadableString().c_str());
-  handler_->OnLog(log_string);
+  handler_->OnLog("AIC::DoCreate({device_id=" + device_id + "})");
 
 #if defined(AUDIO_POWER_MONITORING)
   // We only do power measurements for UMA stats for low latency streams, and
@@ -698,9 +695,6 @@ void InputController::DoCreate(media::AudioManager* audio_manager,
   // Send initial muted state along with OnCreated, to avoid races.
   is_muted_ = stream_->IsMuted();
   handler_->OnCreated(is_muted_);
-  log_string = base::StringPrintf("AIC::OnCreated: is_muted=%d", is_muted_);
-  handler_->OnLog(log_string);
-
   check_muted_state_timer_.Start(FROM_HERE, kCheckMutedStateInterval, this,
                                  &InputController::CheckMutedState);
   DCHECK(check_muted_state_timer_.IsRunning());
@@ -723,7 +717,7 @@ void InputController::DoLogAudioLevels(float level_dbfs,
   const bool microphone_is_muted = stream_->IsMuted();
   if (microphone_is_muted) {
     LogMicrophoneMuteResult(MICROPHONE_IS_MUTED);
-    handler_->OnLog("AIC::OnData: microphone is muted!");
+    handler_->OnLog("AIC::OnData => (microphone is muted)");
     // Return early if microphone is muted. No need to adding logs and UMA stats
     // of audio levels if we know that the microphone is muted.
     return;
@@ -732,19 +726,19 @@ void InputController::DoLogAudioLevels(float level_dbfs,
   LogMicrophoneMuteResult(MICROPHONE_IS_NOT_MUTED);
 
   std::string log_string = base::StringPrintf(
-      "AIC::OnData: average audio level=%.2f dBFS", level_dbfs);
+      "AIC::OnData => (average audio level=%.2f dBFS", level_dbfs);
   static const float kSilenceThresholdDBFS = -72.24719896f;
   if (level_dbfs < kSilenceThresholdDBFS)
-    log_string += " <=> low audio input level!";
-  handler_->OnLog(log_string);
+    log_string += " <=> low audio input level";
+  handler_->OnLog(log_string + ")");
 
   UpdateSilenceState(level_dbfs < kSilenceThresholdDBFS);
 
-  log_string = base::StringPrintf("AIC::OnData: microphone volume=%d%%",
+  log_string = base::StringPrintf("AIC::OnData => (microphone volume=%d%%",
                                   microphone_volume_percent);
   if (microphone_volume_percent < kLowLevelMicrophoneLevelPercent)
-    log_string += " <=> low microphone level!";
-  handler_->OnLog(log_string);
+    log_string += " <=> low microphone level";
+  handler_->OnLog(log_string + ")");
 #endif
 }
 
@@ -869,7 +863,7 @@ void InputController::CheckMutedState() {
     is_muted_ = new_state;
     handler_->OnMuted(is_muted_);
     std::string log_string =
-        base::StringPrintf("AIC::OnMuted: is_muted=%d", is_muted_);
+        base::StringPrintf("AIC::OnMuted({is_muted=%d})", is_muted_);
     handler_->OnLog(log_string);
   }
 }

services/audio/input_stream.cc

@@ -25,8 +25,35 @@ namespace audio {
 
 namespace {
 const int kMaxInputChannels = 3;
+
+const char* ErrorCodeToString(InputController::ErrorCode error) {
+  switch (error) {
+    case (InputController::STREAM_CREATE_ERROR):
+      return "STREAM_CREATE_ERROR";
+    case (InputController::STREAM_OPEN_ERROR):
+      return "STREAM_OPEN_ERROR";
+    case (InputController::STREAM_ERROR):
+      return "STREAM_ERROR";
+    default:
+      NOTREACHED();
+  }
+  return "UNKNOWN_ERROR";
+}
+
+std::string GetCtorLogString(const base::UnguessableToken& id,
+                             const std::string& device_id,
+                             const media::AudioParameters& params,
+                             bool enable_agc) {
+  std::string str = base::StringPrintf("Ctor({id=%s}, ", id.ToString().c_str());
+  base::StringAppendF(&str, "{device_id=%s}, ", device_id.c_str());
+  base::StringAppendF(&str, "{params=[%s]}, ",
+                      params.AsHumanReadableString().c_str());
+  base::StringAppendF(&str, "{enable_agc=%d})", enable_agc);
+  return str;
 }
 
+}  // namespace
+
 InputStream::InputStream(
     CreatedCallback created_callback,
     DeleteCallback delete_callback,
@@ -68,6 +95,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));
 
   // |this| owns these objects, so unretained is safe.
   base::RepeatingClosure error_handler = base::BindRepeating(
@@ -104,6 +132,7 @@ InputStream::InputStream(
 
 InputStream::~InputStream() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  SendLogMessage("Dtor({id=" + id_.ToString() + "})");
 
   if (log_)
     log_->OnClosed();
@@ -142,12 +171,15 @@ void InputStream::SetOutputDeviceForAec(const std::string& output_device_id) {
     log_->OnLogMessage(
         base::StrCat({"SetOutputDeviceForAec: ", output_device_id}));
   }
+  SendLogMessage("SetOutputDeviceForAec({id=" + id_.ToString() + "}, " +
+                 "{output_device_id=" + output_device_id + "})");
 }
 
 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() + "})");
 
   controller_->Record();
   if (observer_)
@@ -177,6 +209,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));
 
   base::ReadOnlySharedMemoryRegion shared_memory_region =
       writer_->TakeSharedMemoryRegion();
@@ -202,8 +236,9 @@ void InputStream::OnError(InputController::ErrorCode error_code) {
   client_->OnError();
   if (log_) {
     log_->OnError();
-    log_->OnLogMessage(
-        base::StringPrintf("AIC::OnError: %d", error_code).c_str());
+    SendLogMessage(base::StringPrintf("OnError({id=%s}, {error_code=%s})",
+                                      id_.ToString().c_str(),
+                                      ErrorCodeToString(error_code)));
   }
   OnStreamError(true);
 }
@@ -211,7 +246,7 @@ void InputStream::OnError(InputController::ErrorCode error_code) {
 void InputStream::OnLog(base::StringPiece message) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   if (log_)
-    log_->OnLogMessage(message.as_string());
+    log_->OnLogMessage(message.as_string() + " [id=" + id_.ToString() + "]");
 }
 
 void InputStream::OnMuted(bool is_muted) {
@@ -230,8 +265,8 @@ void InputStream::OnStreamError(bool signalPlatformError) {
         std::string());
   }
 
-  if (signalPlatformError && log_) {
-    log_->OnLogMessage(base::StringPrintf("IC::OnStreamError").c_str());
+  if (signalPlatformError) {
+    SendLogMessage("OnStreamError({id=" + id_.ToString() + "})");
   }
 
   // Defer callback so we're not destructed while in the constructor.
@@ -247,4 +282,11 @@ void InputStream::CallDeleter() {
   std::move(delete_callback_).Run(this);
 }
 
+void InputStream::SendLogMessage(const std::string& message) {
+  DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  if (log_) {
+    log_->OnLogMessage("audio::IS::" + message);
+  }
+}
+
 }  // namespace audio

services/audio/input_stream.h

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