services/audio/input_controller.cc

// Copyright (c) 2012 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "services/audio/input_controller.h"

#include <inttypes.h>

#include <algorithm>
#include <limits>
#include <memory>
#include <utility>

#include "base/bind.h"
#include "base/logging.h"
#include "base/memory/ptr_util.h"
#include "base/metrics/histogram_macros.h"
#include "base/numerics/ranges.h"
#include "base/single_thread_task_runner.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/stringprintf.h"
#include "base/threading/thread_restrictions.h"
#include "base/threading/thread_task_runner_handle.h"
#include "base/time/time.h"
#include "base/trace_event/trace_event.h"
#include "media/audio/audio_io.h"
#include "media/audio/audio_manager.h"
#include "media/base/audio_bus.h"
#include "media/base/user_input_monitor.h"
#include "services/audio/concurrent_stream_metric_reporter.h"

namespace audio {
namespace {

using OpenOutcome = media::AudioInputStream::OpenOutcome;

const int kMaxInputChannels = 3;
constexpr base::TimeDelta kCheckMutedStateInterval =
    base::TimeDelta::FromSeconds(1);

#if defined(AUDIO_POWER_MONITORING)
// Time in seconds between two successive measurements of audio power levels.
constexpr base::TimeDelta kPowerMonitorLogInterval =
    base::TimeDelta::FromSeconds(15);

// A warning will be logged when the microphone audio volume is below this
// threshold.
const int kLowLevelMicrophoneLevelPercent = 10;

// Logs if the user has enabled the microphone mute or not. This is normally
// done by marking a checkbox in an audio-settings UI which is unique for each
// platform. Elements in this enum should not be added, deleted or rearranged.
enum MicrophoneMuteResult {
  MICROPHONE_IS_MUTED = 0,
  MICROPHONE_IS_NOT_MUTED = 1,
  MICROPHONE_MUTE_MAX = MICROPHONE_IS_NOT_MUTED
};

void LogMicrophoneMuteResult(MicrophoneMuteResult result) {
  UMA_HISTOGRAM_ENUMERATION("Media.MicrophoneMuted", result,
                            MICROPHONE_MUTE_MAX + 1);
}

const char* SilenceStateToString(InputController::SilenceState state) {
  switch (state) {
    case InputController::SILENCE_STATE_NO_MEASUREMENT:
      return "SILENCE_STATE_NO_MEASUREMENT";
    case InputController::SILENCE_STATE_ONLY_AUDIO:
      return "SILENCE_STATE_ONLY_AUDIO";
    case InputController::SILENCE_STATE_ONLY_SILENCE:
      return "SILENCE_STATE_ONLY_SILENCE";
    case InputController::SILENCE_STATE_AUDIO_AND_SILENCE:
      return "SILENCE_STATE_AUDIO_AND_SILENCE";
    default:
      NOTREACHED();
  }
  return "INVALID";
}

// Helper method which calculates the average power of an audio bus. Unit is in
// dBFS, where 0 dBFS corresponds to all channels and samples equal to 1.0.
float AveragePower(const media::AudioBus& buffer) {
  const int frames = buffer.frames();
  const int channels = buffer.channels();
  if (frames <= 0 || channels <= 0)
    return 0.0f;

  // Scan all channels and accumulate the sum of squares for all samples.
  float sum_power = 0.0f;
  for (int ch = 0; ch < channels; ++ch) {
    const float* channel_data = buffer.channel(ch);
    for (int i = 0; i < frames; i++) {
      const float sample = channel_data[i];
      sum_power += sample * sample;
    }
  }

  // Update accumulated average results, with clamping for sanity.
  const float average_power =
      base::ClampToRange(sum_power / (frames * channels), 0.0f, 1.0f);

  // Convert average power level to dBFS units, and pin it down to zero if it
  // is insignificantly small.
  const float kInsignificantPower = 1.0e-10f;  // -100 dBFS
  const float power_dbfs = average_power < kInsignificantPower
                               ? -std::numeric_limits<float>::infinity()
                               : 10.0f * log10f(average_power);

  return power_dbfs;
}
#endif  // AUDIO_POWER_MONITORING

}  // namespace

// Private subclass of AIC that covers the state while capturing audio.
// This class implements the callback interface from the lower level audio
// layer and gets called back on the audio hw thread.
// We implement this in a sub class instead of directly in the AIC so that
// - The AIC itself is not an AudioInputCallback.
// - The lifetime of the AudioCallback is shorter than the AIC
// - How tasks are posted to the AIC from the hw callback thread, is different
//   than how tasks are posted from the AIC to itself from the main thread.
//   So, this difference is isolated to the subclass (see below).
// - The callback class can gather information on what happened during capture
//   and store it in a state that can be fetched after stopping capture
//   (received_callback, error_during_callback).
// The AIC itself must not be AddRef-ed on the hw callback thread so that we
// can be guaranteed to not receive callbacks generated by the hw callback
// thread after Close() has been called on the audio manager thread and
// the callback object deleted. To avoid AddRef-ing the AIC and to cancel
// potentially pending tasks, we use a weak pointer to the AIC instance
// when posting.
class InputController::AudioCallback
    : public media::AudioInputStream::AudioInputCallback {
 public:
  explicit AudioCallback(InputController* controller)
      : task_runner_(base::ThreadTaskRunnerHandle::Get()),
        controller_(controller),
        weak_controller_(controller->weak_ptr_factory_.GetWeakPtr()) {}
  ~AudioCallback() override = default;

  // These should not be called when the stream is live.
  bool received_callback() const { return received_callback_; }
  bool error_during_callback() const { return error_during_callback_; }

 private:
  void OnData(const media::AudioBus* source,
              base::TimeTicks capture_time,
              double volume) override {
    TRACE_EVENT1("audio", "InputController::OnData", "capture time (ms)",
                 (capture_time - base::TimeTicks()).InMillisecondsF());

    if (!received_callback_) {
      // Mark the stream as alive at first audio callback. Currently only used
      // for logging purposes.
      task_runner_->PostTask(
          FROM_HERE,
          base::BindOnce(&InputController::ReportIsAlive, weak_controller_));
    }
    received_callback_ = true;

    DeliverDataToSyncWriter(source, capture_time, volume);
  }

  void OnError() override {
    error_during_callback_ = true;
    task_runner_->PostTask(
        FROM_HERE,
        base::BindOnce(&InputController::DoReportError, weak_controller_));
  }

  void DeliverDataToSyncWriter(const media::AudioBus* source,
                               base::TimeTicks capture_time,
                               double volume) {
    const bool key_pressed = controller_->CheckForKeyboardInput();

    controller_->sync_writer_->Write(source, volume, key_pressed, capture_time);

    // The way the two classes interact here, could be done in a nicer way.
    // As is, we call the AIC here to check the audio power, return and then
    // post a task to the AIC based on what the AIC said.
    // The reason for this is to keep all PostTask calls from the hw callback
    // thread to the AIC, that use a weak pointer, in the same class.
    float average_power_dbfs;
    int mic_volume_percent;
    if (controller_->CheckAudioPower(source, volume, &average_power_dbfs,
                                     &mic_volume_percent)) {
      // Use event handler on the audio thread to relay a message to the ARIH
      // in content which does the actual logging on the IO thread.
      task_runner_->PostTask(
          FROM_HERE,
          base::BindOnce(&InputController::DoLogAudioLevels, weak_controller_,
                         average_power_dbfs, mic_volume_percent));
    }
  }

  const scoped_refptr<base::SingleThreadTaskRunner> task_runner_;
  InputController* const controller_;
  // We do not want any pending posted tasks generated from the callback class
  // to keep the controller object alive longer than it should. So we use
  // a weak ptr whenever we post, we use this weak pointer.
  base::WeakPtr<InputController> weak_controller_;
  bool received_callback_ = false;
  bool error_during_callback_ = false;
};

InputController::InputController(EventHandler* handler,
                                 SyncWriter* sync_writer,
                                 media::UserInputMonitor* user_input_monitor,
                                 InputStreamActivityMonitor* activity_monitor,
                                 const media::AudioParameters& params,
                                 StreamType type)
    : handler_(handler),
      stream_(nullptr),
      sync_writer_(sync_writer),
      type_(type),
      user_input_monitor_(user_input_monitor),
      activity_monitor_(activity_monitor) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  DCHECK(handler_);
  DCHECK(sync_writer_);
  DCHECK(activity_monitor_);
}

InputController::~InputController() {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  DCHECK(!audio_callback_);
  DCHECK(!stream_);
  DCHECK(!check_muted_state_timer_.IsRunning());
}

// static
std::unique_ptr<InputController> InputController::Create(
    media::AudioManager* audio_manager,
    EventHandler* event_handler,
    SyncWriter* sync_writer,
    media::UserInputMonitor* user_input_monitor,
    InputStreamActivityMonitor* activity_monitor,
    const media::AudioParameters& params,
    const std::string& device_id,
    bool enable_agc) {
  DCHECK(audio_manager);
  DCHECK(audio_manager->GetTaskRunner()->BelongsToCurrentThread());
  DCHECK(activity_monitor);
  DCHECK(sync_writer);
  DCHECK(event_handler);
  DCHECK(params.IsValid());

  if (params.channels() > kMaxInputChannels)
    return nullptr;

  // Create the InputController object and ensure that it runs on
  // the audio-manager thread.
  std::unique_ptr<InputController> controller(new InputController(
      event_handler, sync_writer, user_input_monitor, activity_monitor, params,
      ParamsToStreamType(params)));

  controller->DoCreate(audio_manager, params, device_id, enable_agc);
  return controller;
}

void InputController::Record() {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.RecordTime");

  if (!stream_ || audio_callback_)
    return;

  handler_->OnLog("AIC::Record()");

  if (user_input_monitor_) {
    user_input_monitor_->EnableKeyPressMonitoring();
    prev_key_down_count_ = user_input_monitor_->GetKeyPressCount();
  }

  stream_create_time_ = base::TimeTicks::Now();

  audio_callback_ = std::make_unique<AudioCallback>(this);
  stream_->Start(audio_callback_.get());
  activity_monitor_->OnInputStreamActive();
  return;
}

void InputController::Close() {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CloseTime");

  if (!stream_)
    return;

  check_muted_state_timer_.AbandonAndStop();

  std::string log_string;
  static const char kLogStringPrefix[] = "AIC::Close => ";

  // Allow calling unconditionally and bail if we don't have a stream to close.
  if (audio_callback_) {
    stream_->Stop();
    activity_monitor_->OnInputStreamInactive();

    // Sometimes a stream (and accompanying audio track) is created and
    // immediately closed or discarded. In this case they are registered as
    // 'stopped early' rather than 'never got data'.
    const base::TimeDelta duration =
        base::TimeTicks::Now() - stream_create_time_;
    CaptureStartupResult capture_startup_result =
        audio_callback_->received_callback()
            ? CAPTURE_STARTUP_OK
            : (duration.InMilliseconds() < 500
                   ? CAPTURE_STARTUP_STOPPED_EARLY
                   : CAPTURE_STARTUP_NEVER_GOT_DATA);
    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)");

    if (type_ == LOW_LATENCY) {
      if (audio_callback_->received_callback()) {
        UMA_HISTOGRAM_LONG_TIMES("Media.InputStreamDuration", duration);
      } else {
        UMA_HISTOGRAM_LONG_TIMES("Media.InputStreamDurationWithoutCallback",
                                 duration);
      }
    }

    if (user_input_monitor_)
      user_input_monitor_->DisableKeyPressMonitoring();

    audio_callback_.reset();
  } else {
    log_string = base::StringPrintf("%s(WARNING: recording never started)",
                                    kLogStringPrefix);
  }

  handler_->OnLog(log_string);

  stream_->Close();
  stream_ = nullptr;

  sync_writer_->Close();

#if defined(AUDIO_POWER_MONITORING)
  // Send UMA stats if enabled.
  if (power_measurement_is_enabled_) {
    LogSilenceState(silence_state_);
    log_string = base::StringPrintf("%s(silence_state=%s)", kLogStringPrefix,
                                    SilenceStateToString(silence_state_));
    handler_->OnLog(log_string);
  }
#endif

  max_volume_ = 0.0;
  weak_ptr_factory_.InvalidateWeakPtrs();
}

void InputController::SetVolume(double volume) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  DCHECK_GE(volume, 0);
  DCHECK_LE(volume, 1.0);

  if (!stream_)
    return;

  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.
  if (!max_volume_) {
    max_volume_ = stream_->GetMaxVolume();
  }

  if (max_volume_ == 0.0) {
    DLOG(WARNING) << "Failed to access input volume control";
    return;
  }

  // Set the stream volume and scale to a range matched to the platform.
  stream_->SetVolume(max_volume_ * volume);
}

void InputController::SetOutputDeviceForAec(
    const std::string& output_device_id) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  if (stream_)
    stream_->SetOutputDeviceForAec(output_device_id);
}

void InputController::OnStreamActive(Snoopable* output_stream) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
}

void InputController::OnStreamInactive(Snoopable* output_stream) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
}

InputController::ErrorCode MapOpenOutcomeToErrorCode(OpenOutcome outcome) {
  switch (outcome) {
    case OpenOutcome::kFailedSystemPermissions:
      return InputController::STREAM_OPEN_SYSTEM_PERMISSIONS_ERROR;
    case OpenOutcome::kFailedInUse:
      return InputController::STREAM_OPEN_DEVICE_IN_USE_ERROR;
    default:
      return InputController::STREAM_OPEN_ERROR;
  }
}

void InputController::DoCreate(media::AudioManager* audio_manager,
                               const media::AudioParameters& params,
                               const std::string& device_id,
                               bool enable_agc) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  DCHECK(!stream_);
  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CreateTime");
  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
  // only if agc is requested, to avoid adding logs and UMA for non-WebRTC
  // clients.
  power_measurement_is_enabled_ = (type_ == LOW_LATENCY && enable_agc);
  last_audio_level_log_time_ = base::TimeTicks::Now();
#endif

  // Unretained is safe since |this| owns |stream|.
  auto* stream = audio_manager->MakeAudioInputStream(
      params, device_id,
      base::BindRepeating(&InputController::LogMessage,
                          base::Unretained(this)));

  if (!stream) {
    LogCaptureStartupResult(CAPTURE_STARTUP_CREATE_STREAM_FAILED);
    handler_->OnError(STREAM_CREATE_ERROR);
    return;
  }

  auto open_outcome = stream->Open();
  if (open_outcome != OpenOutcome::kSuccess) {
    stream->Close();
    LogCaptureStartupResult(CAPTURE_STARTUP_OPEN_STREAM_FAILED);
    handler_->OnError(MapOpenOutcomeToErrorCode(open_outcome));
    return;
  }

#if defined(AUDIO_POWER_MONITORING)
  bool agc_is_supported = stream->SetAutomaticGainControl(enable_agc);
  // Disable power measurements on platforms that does not support AGC at a
  // lower level. AGC can fail on platforms where we don't support the
  // functionality to modify the input volume slider. One such example is
  // Windows XP.
  power_measurement_is_enabled_ &= agc_is_supported;
  handler_->OnLog(
      base::StringPrintf("AIC::DoCreate => (power_measurement_is_enabled=%d)",
                         power_measurement_is_enabled_));
#else
  stream->SetAutomaticGainControl(enable_agc);
#endif

  // Finally, keep the stream pointer around, update the state and notify.
  stream_ = stream;

  // Send initial muted state along with OnCreated, to avoid races.
  is_muted_ = stream_->IsMuted();
  handler_->OnCreated(is_muted_);
  check_muted_state_timer_.Start(FROM_HERE, kCheckMutedStateInterval, this,
                                 &InputController::CheckMutedState);
  DCHECK(check_muted_state_timer_.IsRunning());
}

void InputController::DoReportError() {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  handler_->OnError(STREAM_ERROR);
}

void InputController::DoLogAudioLevels(float level_dbfs,
                                       int microphone_volume_percent) {
#if defined(AUDIO_POWER_MONITORING)
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  if (!stream_)
    return;

  // Detect if the user has enabled hardware mute by pressing the mute
  // button in audio settings for the selected microphone.
  const bool microphone_is_muted = stream_->IsMuted();
  if (microphone_is_muted) {
    LogMicrophoneMuteResult(MICROPHONE_IS_MUTED);
    handler_->OnLog("AIC::OnData => (microphone is muted)");
  } else {
    LogMicrophoneMuteResult(MICROPHONE_IS_NOT_MUTED);
  }

  std::string log_string = base::StringPrintf(
      "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 + ")");

  if (!microphone_is_muted) {
    UpdateSilenceState(level_dbfs < kSilenceThresholdDBFS);
  }

  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 + ")");
#endif
}

#if defined(AUDIO_POWER_MONITORING)
void InputController::UpdateSilenceState(bool silence) {
  if (silence) {
    if (silence_state_ == SILENCE_STATE_NO_MEASUREMENT) {
      silence_state_ = SILENCE_STATE_ONLY_SILENCE;
    } else if (silence_state_ == SILENCE_STATE_ONLY_AUDIO) {
      silence_state_ = SILENCE_STATE_AUDIO_AND_SILENCE;
    } else {
      DCHECK(silence_state_ == SILENCE_STATE_ONLY_SILENCE ||
             silence_state_ == SILENCE_STATE_AUDIO_AND_SILENCE);
    }
  } else {
    if (silence_state_ == SILENCE_STATE_NO_MEASUREMENT) {
      silence_state_ = SILENCE_STATE_ONLY_AUDIO;
    } else if (silence_state_ == SILENCE_STATE_ONLY_SILENCE) {
      silence_state_ = SILENCE_STATE_AUDIO_AND_SILENCE;
    } else {
      DCHECK(silence_state_ == SILENCE_STATE_ONLY_AUDIO ||
             silence_state_ == SILENCE_STATE_AUDIO_AND_SILENCE);
    }
  }
}

void InputController::LogSilenceState(SilenceState value) {
  UMA_HISTOGRAM_ENUMERATION("Media.AudioInputControllerSessionSilenceReport",
                            value, SILENCE_STATE_MAX + 1);
}
#endif

void InputController::LogCaptureStartupResult(CaptureStartupResult result) {
  switch (type_) {
    case LOW_LATENCY:
      UMA_HISTOGRAM_ENUMERATION("Media.LowLatencyAudioCaptureStartupSuccess",
                                result, CAPTURE_STARTUP_RESULT_MAX + 1);
      break;
    case HIGH_LATENCY:
      UMA_HISTOGRAM_ENUMERATION("Media.HighLatencyAudioCaptureStartupSuccess",
                                result, CAPTURE_STARTUP_RESULT_MAX + 1);
      break;
    case VIRTUAL:
      UMA_HISTOGRAM_ENUMERATION("Media.VirtualAudioCaptureStartupSuccess",
                                result, CAPTURE_STARTUP_RESULT_MAX + 1);
      break;
    default:
      break;
  }
}

void InputController::LogCallbackError() {
  bool error_during_callback = audio_callback_->error_during_callback();
  switch (type_) {
    case LOW_LATENCY:
      UMA_HISTOGRAM_BOOLEAN("Media.Audio.Capture.LowLatencyCallbackError",
                            error_during_callback);
      break;
    case HIGH_LATENCY:
      UMA_HISTOGRAM_BOOLEAN("Media.Audio.Capture.HighLatencyCallbackError",
                            error_during_callback);
      break;
    case VIRTUAL:
      UMA_HISTOGRAM_BOOLEAN("Media.Audio.Capture.VirtualCallbackError",
                            error_during_callback);
      break;
    default:
      break;
  }
}

void InputController::LogMessage(const std::string& message) {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  handler_->OnLog(message);
}

bool InputController::CheckForKeyboardInput() {
  if (!user_input_monitor_)
    return false;

  const size_t current_count = user_input_monitor_->GetKeyPressCount();
  const bool key_pressed = current_count != prev_key_down_count_;
  prev_key_down_count_ = current_count;
  DVLOG_IF(6, key_pressed) << "Detected keypress.";

  return key_pressed;
}

bool InputController::CheckAudioPower(const media::AudioBus* source,
                                      double volume,
                                      float* average_power_dbfs,
                                      int* mic_volume_percent) {
#if defined(AUDIO_POWER_MONITORING)
  // Only do power-level measurements if DoCreate() has been called. It will
  // ensure that logging will mainly be done for WebRTC and WebSpeech
  // clients.
  if (!power_measurement_is_enabled_)
    return false;

  // Perform periodic audio (power) level measurements.
  const auto now = base::TimeTicks::Now();
  if (now - last_audio_level_log_time_ <= kPowerMonitorLogInterval) {
    return false;
  }

  *average_power_dbfs = AveragePower(*source);
  *mic_volume_percent = static_cast<int>(100.0 * volume);

  last_audio_level_log_time_ = now;

  return true;
#else
  return false;
#endif
}

void InputController::CheckMutedState() {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  DCHECK(stream_);
  const bool new_state = stream_->IsMuted();
  if (new_state != is_muted_) {
    is_muted_ = new_state;
    handler_->OnMuted(is_muted_);
    std::string log_string =
        base::StringPrintf("AIC::OnMuted({is_muted=%d})", is_muted_);
    handler_->OnLog(log_string);
  }
}

void InputController::ReportIsAlive() {
  DCHECK_CALLED_ON_VALID_THREAD(owning_thread_);
  DCHECK(stream_);
  // Don't store any state, just log the event for now.
  handler_->OnLog("AIC::OnData => (stream is alive)");
}

// static
InputController::StreamType InputController::ParamsToStreamType(
    const media::AudioParameters& params) {
  switch (params.format()) {
    case media::AudioParameters::Format::AUDIO_PCM_LINEAR:
      return InputController::StreamType::HIGH_LATENCY;
    case media::AudioParameters::Format::AUDIO_PCM_LOW_LATENCY:
      return InputController::StreamType::LOW_LATENCY;
    default:
      // Currently, the remaining supported type is fake. Reconsider if other
      // formats become supported.
      return InputController::StreamType::FAKE;
  }
}

}  // namespace audio