From 645b027dc44f7e1f3a1335155a71e2b4d7375f96 Mon Sep 17 00:00:00 2001 From: Jonas Olsson Date: Thu, 15 Feb 2018 15:16:27 +0100 Subject: [PATCH] Streamline error handling and logging in the audio processing module Bug: webrtc:8529 Change-Id: I40817d578c2c4106892e564df1bc734efcef5503 Reviewed-on: https://webrtc-review.googlesource.com/52540 Commit-Queue: Jonas Olsson Reviewed-by: Alex Loiko Cr-Commit-Position: refs/heads/master@{#22034} --- .../aec3/adaptive_fir_filter.cc | 2 +- modules/audio_processing/agc/agc.cc | 3 +- modules/audio_processing/agc/agc.h | 2 +- .../agc/agc_manager_direct.cc | 50 ++++++++----------- .../agc/agc_manager_direct_unittest.cc | 2 +- modules/audio_processing/agc/mock_agc.h | 4 +- .../audio_processing/audio_processing_impl.cc | 19 +++---- .../echo_control_mobile_impl.cc | 6 +-- .../level_controller/level_controller.cc | 32 ++++++------ .../residual_echo_detector.cc | 26 +++++----- .../transient/transient_suppression_test.cc | 8 ++- 11 files changed, 71 insertions(+), 83 deletions(-) diff --git a/modules/audio_processing/aec3/adaptive_fir_filter.cc b/modules/audio_processing/aec3/adaptive_fir_filter.cc index e080b4b590..b3d8ca56bd 100644 --- a/modules/audio_processing/aec3/adaptive_fir_filter.cc +++ b/modules/audio_processing/aec3/adaptive_fir_filter.cc @@ -466,9 +466,9 @@ void AdaptiveFirFilter::SetSizePartitions(size_t size) { RTC_DCHECK_EQ(GetTimeDomainLength(max_size_partitions_), h_.capacity()); RTC_DCHECK_EQ(H_.size(), H2_.size()); RTC_DCHECK_EQ(h_.size(), GetTimeDomainLength(H_.size())); + RTC_DCHECK_LE(size, max_size_partitions_); if (size > max_size_partitions_) { - RTC_LOG(LS_ERROR) << "Too large adaptive filter size specificed: " << size; size = max_size_partitions_; } diff --git a/modules/audio_processing/agc/agc.cc b/modules/audio_processing/agc/agc.cc index 0c6478e803..e1616765b1 100644 --- a/modules/audio_processing/agc/agc.cc +++ b/modules/audio_processing/agc/agc.cc @@ -48,7 +48,7 @@ float Agc::AnalyzePreproc(const int16_t* audio, size_t length) { return 1.0f * num_clipped / length; } -int Agc::Process(const int16_t* audio, size_t length, int sample_rate_hz) { +void Agc::Process(const int16_t* audio, size_t length, int sample_rate_hz) { vad_.ProcessChunk(audio, length, sample_rate_hz); const std::vector& rms = vad_.chunkwise_rms(); const std::vector& probabilities = @@ -57,7 +57,6 @@ int Agc::Process(const int16_t* audio, size_t length, int sample_rate_hz) { for (size_t i = 0; i < rms.size(); ++i) { histogram_->Update(rms[i], probabilities[i]); } - return 0; } bool Agc::GetRmsErrorDb(int* error) { diff --git a/modules/audio_processing/agc/agc.h b/modules/audio_processing/agc/agc.h index 3a8d5c8122..98bbf1fab3 100644 --- a/modules/audio_processing/agc/agc.h +++ b/modules/audio_processing/agc/agc.h @@ -31,7 +31,7 @@ class Agc { virtual float AnalyzePreproc(const int16_t* audio, size_t length); // |audio| must be mono; in a multi-channel stream, provide the first (usually // left) channel. - virtual int Process(const int16_t* audio, size_t length, int sample_rate_hz); + virtual void Process(const int16_t* audio, size_t length, int sample_rate_hz); // Retrieves the difference between the target RMS level and the current // signal RMS level in dB. Returns true if an update is available and false diff --git a/modules/audio_processing/agc/agc_manager_direct.cc b/modules/audio_processing/agc/agc_manager_direct.cc index 706d4ab037..5ba5f4ff48 100644 --- a/modules/audio_processing/agc/agc_manager_direct.cc +++ b/modules/audio_processing/agc/agc_manager_direct.cc @@ -216,8 +216,8 @@ void AgcManagerDirect::AnalyzePreProcess(int16_t* audio, // gain is increased, through SetMaxLevel(). float clipped_ratio = agc_->AnalyzePreproc(audio, length); if (clipped_ratio > kClippedRatioThreshold) { - RTC_LOG(LS_INFO) << "[agc] Clipping detected. clipped_ratio=" - << clipped_ratio; + RTC_DLOG(LS_INFO) << "[agc] Clipping detected. clipped_ratio=" + << clipped_ratio; // Always decrease the maximum level, even if the current level is below // threshold. SetMaxLevel(std::max(clipped_level_min_, max_level_ - kClippedLevelStep)); @@ -249,10 +249,7 @@ void AgcManagerDirect::Process(const int16_t* audio, CheckVolumeAndReset(); } - if (agc_->Process(audio, length, sample_rate_hz) != 0) { - RTC_LOG(LS_ERROR) << "Agc::Process failed"; - RTC_NOTREACHED(); - } + agc_->Process(audio, length, sample_rate_hz); UpdateGain(); UpdateCompressor(); @@ -262,15 +259,12 @@ void AgcManagerDirect::Process(const int16_t* audio, void AgcManagerDirect::SetLevel(int new_level) { int voe_level = volume_callbacks_->GetMicVolume(); - if (voe_level < 0) { - return; - } if (voe_level == 0) { - RTC_LOG(LS_INFO) + RTC_DLOG(LS_INFO) << "[agc] VolumeCallbacks returned level=0, taking no action."; return; } - if (voe_level > kMaxMicLevel) { + if (voe_level < 0 || voe_level > kMaxMicLevel) { RTC_LOG(LS_ERROR) << "VolumeCallbacks returned an invalid level=" << voe_level; return; @@ -278,8 +272,8 @@ void AgcManagerDirect::SetLevel(int new_level) { if (voe_level > level_ + kLevelQuantizationSlack || voe_level < level_ - kLevelQuantizationSlack) { - RTC_LOG(LS_INFO) << "[agc] Mic volume was manually adjusted. Updating " - << "stored level from " << level_ << " to " << voe_level; + RTC_DLOG(LS_INFO) << "[agc] Mic volume was manually adjusted. Updating " + "stored level from " << level_ << " to " << voe_level; level_ = voe_level; // Always allow the user to increase the volume. if (level_ > max_level_) { @@ -298,9 +292,9 @@ void AgcManagerDirect::SetLevel(int new_level) { } volume_callbacks_->SetMicVolume(new_level); - RTC_LOG(LS_INFO) << "[agc] voe_level=" << voe_level << ", " - << "level_=" << level_ << ", " - << "new_level=" << new_level; + RTC_DLOG(LS_INFO) << "[agc] voe_level=" << voe_level << ", " + << "level_=" << level_ << ", " + << "new_level=" << new_level; level_ = new_level; } @@ -314,8 +308,8 @@ void AgcManagerDirect::SetMaxLevel(int level) { (kMaxMicLevel - clipped_level_min_) * kSurplusCompressionGain + 0.5f); - RTC_LOG(LS_INFO) << "[agc] max_level_=" << max_level_ - << ", max_compression_gain_=" << max_compression_gain_; + RTC_DLOG(LS_INFO) << "[agc] max_level_=" << max_level_ + << ", max_compression_gain_=" << max_compression_gain_; } void AgcManagerDirect::SetCaptureMuted(bool muted) { @@ -336,28 +330,26 @@ float AgcManagerDirect::voice_probability() { int AgcManagerDirect::CheckVolumeAndReset() { int level = volume_callbacks_->GetMicVolume(); - if (level < 0) { - return -1; - } // Reasons for taking action at startup: // 1) A person starting a call is expected to be heard. // 2) Independent of interpretation of |level| == 0 we should raise it so the // AGC can do its job properly. if (level == 0 && !startup_) { - RTC_LOG(LS_INFO) + RTC_DLOG(LS_INFO) << "[agc] VolumeCallbacks returned level=0, taking no action."; return 0; } - if (level > kMaxMicLevel) { - RTC_LOG(LS_ERROR) << "VolumeCallbacks returned an invalid level=" << level; + if (level < 0 || level > kMaxMicLevel) { + RTC_LOG(LS_ERROR) << "[agc] VolumeCallbacks returned an invalid level=" + << level; return -1; } - RTC_LOG(LS_INFO) << "[agc] Initial GetMicVolume()=" << level; + RTC_DLOG(LS_INFO) << "[agc] Initial GetMicVolume()=" << level; int minLevel = startup_ ? startup_min_level_ : kMinMicLevel; if (level < minLevel) { level = minLevel; - RTC_LOG(LS_INFO) << "[agc] Initial volume too low, raising to " << level; + RTC_DLOG(LS_INFO) << "[agc] Initial volume too low, raising to " << level; volume_callbacks_->SetMicVolume(level); } agc_->Reset(); @@ -409,9 +401,9 @@ void AgcManagerDirect::UpdateGain() { const int residual_gain = rtc::SafeClamp(rms_error - raw_compression, -kMaxResidualGainChange, kMaxResidualGainChange); - RTC_LOG(LS_INFO) << "[agc] rms_error=" << rms_error << ", " - << "target_compression=" << target_compression_ << ", " - << "residual_gain=" << residual_gain; + RTC_DLOG(LS_INFO) << "[agc] rms_error=" << rms_error + << ", target_compression=" << target_compression_ + << ", residual_gain=" << residual_gain; if (residual_gain == 0) return; diff --git a/modules/audio_processing/agc/agc_manager_direct_unittest.cc b/modules/audio_processing/agc/agc_manager_direct_unittest.cc index 6a8af6aa71..1a0340203e 100644 --- a/modules/audio_processing/agc/agc_manager_direct_unittest.cc +++ b/modules/audio_processing/agc/agc_manager_direct_unittest.cc @@ -77,7 +77,7 @@ class AgcManagerDirectTest : public ::testing::Test { void CallProcess(int num_calls) { for (int i = 0; i < num_calls; ++i) { - EXPECT_CALL(*agc_, Process(_, _, _)).WillOnce(Return(0)); + EXPECT_CALL(*agc_, Process(_, _, _)).WillOnce(Return()); manager_.Process(nullptr, kSamplesPerChannel, kSampleRateHz); } } diff --git a/modules/audio_processing/agc/mock_agc.h b/modules/audio_processing/agc/mock_agc.h index 36901af50c..b27d28cd89 100644 --- a/modules/audio_processing/agc/mock_agc.h +++ b/modules/audio_processing/agc/mock_agc.h @@ -21,8 +21,8 @@ namespace webrtc { class MockAgc : public Agc { public: MOCK_METHOD2(AnalyzePreproc, float(const int16_t* audio, size_t length)); - MOCK_METHOD3(Process, int(const int16_t* audio, size_t length, - int sample_rate_hz)); + MOCK_METHOD3(Process, void(const int16_t* audio, size_t length, + int sample_rate_hz)); MOCK_METHOD1(GetRmsErrorDb, bool(int* error)); MOCK_METHOD0(Reset, void()); MOCK_METHOD1(set_target_level_dbfs, int(int level)); diff --git a/modules/audio_processing/audio_processing_impl.cc b/modules/audio_processing/audio_processing_impl.cc index 240d663a61..2c292f7a05 100644 --- a/modules/audio_processing/audio_processing_impl.cc +++ b/modules/audio_processing/audio_processing_impl.cc @@ -449,9 +449,8 @@ AudioProcessingImpl::AudioProcessingImpl( private_submodules_->gain_controller2.reset(new GainController2()); RTC_LOG(LS_INFO) << "Capture post processor activated: " - << !!private_submodules_->capture_post_processor; - - RTC_LOG(LS_INFO) << "Render pre processor activated: " + << !!private_submodules_->capture_post_processor + << "\nRender pre processor activated: " << !!private_submodules_->render_pre_processor; } @@ -709,11 +708,10 @@ void AudioProcessingImpl::ApplyConfig(const AudioProcessing::Config& config) { bool config_ok = LevelController::Validate(config_.level_controller); if (!config_ok) { - RTC_LOG(LS_ERROR) << "AudioProcessing module config error" << std::endl - << "level_controller: " + RTC_LOG(LS_ERROR) << "AudioProcessing module config error\n" + "level_controller: " << LevelController::ToString(config_.level_controller) - << std::endl - << "Reverting to default parameter set"; + << "\nReverting to default parameter set"; config_.level_controller = AudioProcessing::Config::LevelController(); } @@ -743,11 +741,10 @@ void AudioProcessingImpl::ApplyConfig(const AudioProcessing::Config& config) { config_ok = GainController2::Validate(config_.gain_controller2); if (!config_ok) { - RTC_LOG(LS_ERROR) << "AudioProcessing module config error" << std::endl - << "Gain Controller 2: " + RTC_LOG(LS_ERROR) << "AudioProcessing module config error\n" + "Gain Controller 2: " << GainController2::ToString(config_.gain_controller2) - << std::endl - << "Reverting to default parameter set"; + << "\nReverting to default parameter set"; config_.gain_controller2 = AudioProcessing::Config::GainController2(); } InitializeGainController2(); diff --git a/modules/audio_processing/echo_control_mobile_impl.cc b/modules/audio_processing/echo_control_mobile_impl.cc index ecb1810666..0ff1bce2c4 100644 --- a/modules/audio_processing/echo_control_mobile_impl.cc +++ b/modules/audio_processing/echo_control_mobile_impl.cc @@ -353,9 +353,9 @@ void EchoControlMobileImpl::Initialize(int sample_rate_hz, return; } - if (stream_properties_->sample_rate_hz > AudioProcessing::kSampleRate16kHz) { - RTC_LOG(LS_ERROR) << "AECM only supports 16 kHz or lower sample rates"; - } + // AECM only supports 16 kHz or lower sample rates. + RTC_DCHECK_LE(stream_properties_->sample_rate_hz, + AudioProcessing::kSampleRate16kHz); cancellers_.resize( NumCancellersRequired(stream_properties_->num_output_channels, diff --git a/modules/audio_processing/level_controller/level_controller.cc b/modules/audio_processing/level_controller/level_controller.cc index 521f82e842..b7854a0c9d 100644 --- a/modules/audio_processing/level_controller/level_controller.cc +++ b/modules/audio_processing/level_controller/level_controller.cc @@ -156,21 +156,23 @@ void LevelController::Metrics::Update(float long_term_peak_level, const int frame_peak_level_dbfs = static_cast( 10 * log10(frame_peak_level * frame_peak_level + 1e-10f) - kdBFSOffset); - RTC_LOG(LS_INFO) << "Level Controller metrics: {" - << "Max noise power: " << max_noise_power_dbfs << " dBFS, " - << "Average noise power: " << average_noise_power_dbfs - << " dBFS, " - << "Max long term peak level: " << max_peak_level_dbfs - << " dBFS, " - << "Average long term peak level: " - << average_peak_level_dbfs << " dBFS, " - << "Max gain: " << max_gain_db << " dB, " - << "Average gain: " << average_gain_db << " dB, " - << "Long term peak level: " << long_term_peak_level_dbfs - << " dBFS, " - << "Last frame peak level: " << frame_peak_level_dbfs - << " dBFS" - << "}"; + RTC_LOG(LS_INFO) << "Level Controller metrics: {Max noise power: " + << max_noise_power_dbfs + << " dBFS, Average noise power: " + << average_noise_power_dbfs + << " dBFS, Max long term peak level: " + << max_peak_level_dbfs + << " dBFS, Average long term peak level: " + << average_peak_level_dbfs + << " dBFS, Max gain: " + << max_gain_db + << " dB, Average gain: " + << average_gain_db + << " dB, Long term peak level: " + << long_term_peak_level_dbfs + << " dBFS, Last frame peak level: " + << frame_peak_level_dbfs + << " dBFS}"; Reset(); } diff --git a/modules/audio_processing/residual_echo_detector.cc b/modules/audio_processing/residual_echo_detector.cc index ef325a032b..cef9b2954a 100644 --- a/modules/audio_processing/residual_echo_detector.cc +++ b/modules/audio_processing/residual_echo_detector.cc @@ -141,19 +141,19 @@ void ResidualEchoDetector::AnalyzeCaptureAudio( read_index -= kLookbackFrames; } RTC_DCHECK_LT(read_index, render_power_.size()); - RTC_LOG_F(LS_ERROR) << "Echo detector internal state: {" - << "Echo likelihood: " << echo_likelihood_ - << ", Best Delay: " << best_delay << ", Covariance: " - << covariances_[best_delay].covariance() - << ", Last capture power: " << capture_power - << ", Capture mean: " << capture_mean - << ", Capture_standard deviation: " - << capture_std_deviation << ", Last render power: " - << render_power_[read_index] - << ", Render mean: " << render_power_mean_[read_index] - << ", Render standard deviation: " - << render_power_std_dev_[read_index] - << ", Reliability: " << reliability_ << "}"; + RTC_LOG_F(LS_ERROR) + << "Echo detector internal state: {" + "Echo likelihood: " << echo_likelihood_ + << ", Best Delay: " << best_delay + << ", Covariance: " << covariances_[best_delay].covariance() + << ", Last capture power: " << capture_power + << ", Capture mean: " << capture_mean + << ", Capture_standard deviation: " << capture_std_deviation + << ", Last render power: " << render_power_[read_index] + << ", Render mean: " << render_power_mean_[read_index] + << ", Render standard deviation: " + << render_power_std_dev_[read_index] + << ", Reliability: " << reliability_ << "}"; log_counter_++; } } diff --git a/modules/audio_processing/transient/transient_suppression_test.cc b/modules/audio_processing/transient/transient_suppression_test.cc index 3442ee0af6..14fe4f8267 100644 --- a/modules/audio_processing/transient/transient_suppression_test.cc +++ b/modules/audio_processing/transient/transient_suppression_test.cc @@ -194,11 +194,9 @@ void void_main() { detection_buffer.get(), reference_file, reference_buffer.get())) { - ASSERT_EQ(0, - agc.Process(audio_buffer_i.get(), - static_cast(audio_buffer_size), - FLAG_sample_rate_hz)) - << "The AGC could not process the frame"; + agc.Process(audio_buffer_i.get(), + static_cast(audio_buffer_size), + FLAG_sample_rate_hz); for (size_t i = 0; i < FLAG_num_channels * audio_buffer_size; ++i) { audio_buffer_f[i] = audio_buffer_i[i];