Stop source and fire MediaStreamTrack ended event if missing audio input callbacks are detected.

media/audio/audio_input_device.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 "media/audio/audio_input_device.h"
 
 #include <stdint.h>
 #include <utility>
 
 #include "base/bind.h"
+#include "base/callback_forward.h"
 #include "base/macros.h"
 #include "base/strings/stringprintf.h"
 #include "base/threading/thread_restrictions.h"
-#include "base/time/time.h"
 #include "build/build_config.h"
 #include "media/audio/audio_manager_base.h"
 #include "media/base/audio_bus.h"
 
 namespace media {
 
+namespace {
+
 // The number of shared memory buffer segments indicated to browser process
 // in order to avoid data overwriting. This number can be any positive number,
 // dependent how fast the renderer process can pick up captured data from
 // shared memory.
-static const int kRequestedSharedMemoryCount = 10;
+const int kRequestedSharedMemoryCount = 10;
+
+// The number of seconds with missing callbacks before we report an error.
+// The value is based on that the Mac audio implementations (see
+// media/audio/mac/audio_low_latency_input_mac.h/cc) has a restart mechanism
+// that triggers after 10 seconds of missing callbacks, and after that an 8
+// seconds delay before detecting still missing callbacks. We don't want to stop
+// the source before that to allow logging and stats reporting to take place.
+// TODO(grunell): The delay in the Mac implementation could probably be shorter.
+const int kMissingCallbacksTimeBeforeErrorSeconds = 20;

[tommi (sloooow) - chröme, 2017/05/19 11:00:37]

20 seems pretty long.  In the comment, can you point out what stats we rely on
for deciding on this value?
Also, what about taking care of the TODO in this CL?

[Henrik Grunell, 2017/05/20 08:40:51]

Hmm, first of all the 10 seconds is really 10-15 seconds since we check every 5
seconds and 10 seconds is the minimum time. So total time is 18-23 seconds...

Secondly, the startup success stats we report after 18-23 seconds isn't really
what we want to report. That stat should be for the startup only, not a restart
when we already have missing callbacks. we should have a separate stat for if
the restart helped or not; we don't have that today. So in that light we could
disregard that stats reporting.

Also, I saw that there is no WebRTC logging at the startup success check, so we
won't be missing out on that. Plus we log in the capturers called from this
class so that should be enough.

We anyway need 15 seconds to allow a restart and some more time if callbacks are
back (pun intended).

I've started a mail thread with henrika@ who introduced the restart and picked
the values. Maybe they can be reduced, maybe restart removed altogether.

Updated the text, removed todo since it will be sorted out during this review.

+
+// The interval for checking missing callbacks.
+const int kCheckMissingCallbacksIntervalSeconds = 5;
+
+}  // namespace
 
 // Takes care of invoking the capture callback on the audio thread.
 // An instance of this class is created for each capture stream in
 // OnLowLatencyCreated().
 class AudioInputDevice::AudioThreadCallback
     : public AudioDeviceThread::Callback {
  public:
-  AudioThreadCallback(const AudioParameters& audio_parameters,
-                      base::SharedMemoryHandle memory,
-                      int memory_length,
-                      int total_segments,
-                      CaptureCallback* capture_callback);
+  using DataCallbackNotificationCallback =
+      base::RepeatingCallback<void(base::TimeTicks last_callback_time)>;
+
+  AudioThreadCallback(
+      const AudioParameters& audio_parameters,
+      base::SharedMemoryHandle memory,
+      int memory_length,
+      int total_segments,
+      CaptureCallback* capture_callback,
+      DataCallbackNotificationCallback data_callback_notification_callback);

[tommi (sloooow) - chröme, 2017/05/19 11:00:37]

yo dawg, I heard you like callbacks, so...

[ossu-chromium, 2017/05/19 11:26:48]

Yeah, this name... could it be made a bit clearer? Or shorter? :)
Also, why is setting the last callback time done by calling callbacks and
posting tasks? Since this (hopefully) happens many times per second, why not
just set it atomically directly from the callback?

[Henrik Grunell, 2017/05/20 08:40:51]

Haha, yep it's a callback to notify about a callback. Can't be clearer. :)

Set it atomically would lead to hacky ways. TimeTicks internal value can be
retrieved and set, but it's discouraged to use it for calculations, for good
reasons. TimeTicks can't be re-created from it either.

Changed the name to GotDataCallback.

[ossu-chromium, 2017/05/22 11:27:35]

Alright, but this seems very wasteful. IIUC, with a 128 sample buffer and a
sample rate of 48000 you'd queue 375 tasks per second, per input stream, each
potentially leading to two task switches to get the I/O thread to execute. Also
locks.

Making this atomic could improve things, but that still has performance
implications. I think your best bet would be to not update this "inter-thread"
state every callback. Perhaps first accumulating, say, a second's worth of
callbacks on the callback thread before pushing a new TimeTicks (or similar)
across to the AudioInputDevice object. I bet that could be done by counting
samples, and you wouldn't have to access the timer each callback, though that's
much less of a problem than the locks and task switches.

I'll give you a bonus point if you do that update atomically. :)
Perhaps by utilizing TimeTicks::operator- to get a TimeDelta relative to the
start of the stream and using TimeDelta::InMicroseconds (or some other
precision) to get a raw integer to work with.

[Max Morin, 2017/05/22 11:44:59]

Another idea is to not use TimeTicks and have an atomic sample count and a timer
checking it ~every second. In this case, we could also detect anomalies like
"got 60 samples last second but expected 100".

[Henrik Grunell, 2017/05/22 15:04:54]

That's a nice idea. However, it seems dangerous since we can't assume that we
get an exact amount of data during a period of time.

[Henrik Grunell, 2017/05/22 15:04:54]

Agree.
That's a reasonable approach. Changed to report once a second. Counting samples
should work fine, doing that.
Done too. I'm using a reference start time, but I saw that I was wrong about
TimeTicks not being possible to create from its internal value. It is possible,
so the internal value could be stored atomically and TimeTicks recreated from it
without doing calculations on it. I kept the original code in a patch set anyway
for reference.

   ~AudioThreadCallback() override;
 
   void MapSharedMemory() override;
 
   // Called whenever we receive notifications about pending data.
   void Process(uint32_t pending_data) override;
 
  private:
   const double bytes_per_ms_;
   int current_segment_id_;
   uint32_t last_buffer_id_;
   std::vector<std::unique_ptr<media::AudioBus>> audio_buses_;
   CaptureCallback* capture_callback_;
+  DataCallbackNotificationCallback data_callback_notification_callback_;
 
   DISALLOW_COPY_AND_ASSIGN(AudioThreadCallback);
 };
 
 AudioInputDevice::AudioInputDevice(
     std::unique_ptr<AudioInputIPC> ipc,
     const scoped_refptr<base::SingleThreadTaskRunner>& io_task_runner)
     : ScopedTaskRunnerObserver(io_task_runner),
       callback_(NULL),
       ipc_(std::move(ipc)),
@@ skipping 78 matching lines @@
   base::AutoLock auto_lock(audio_thread_lock_);
   // TODO(miu): See TODO in OnStreamCreated method for AudioOutputDevice.
   // Interface changes need to be made; likely, after AudioInputDevice is merged
   // into AudioOutputDevice (http://crbug.com/179597).
   if (stopping_hack_)
     return;
 
   DCHECK(!audio_callback_);
   DCHECK(!audio_thread_);
   audio_callback_.reset(new AudioInputDevice::AudioThreadCallback(
-      audio_parameters_, handle, length, total_segments, callback_));
+      audio_parameters_, handle, length, total_segments, callback_,
+      base::BindRepeating(&AudioInputDevice::SetLastCallbackTime, this)));
   audio_thread_.reset(new AudioDeviceThread(audio_callback_.get(),
                                             socket_handle, "AudioInputDevice"));
 
   state_ = RECORDING;
   ipc_->RecordStream();
+
+  // Start detecting missing callbacks.
+  last_callback_time_ = base::TimeTicks::Now();
+  check_alive_timer_.Start(
+      FROM_HERE,
+      base::TimeDelta::FromSeconds(kCheckMissingCallbacksIntervalSeconds), this,
+      &AudioInputDevice::CheckIfInputStreamIsAlive);
+  DCHECK(check_alive_timer_.IsRunning());
 }
 
 void AudioInputDevice::OnError() {
   DCHECK(task_runner()->BelongsToCurrentThread());
 
   // Do nothing if the stream has been closed.
   if (state_ < CREATING_STREAM)
     return;
 
   DLOG(WARNING) << "AudioInputDevice::OnStateChanged(ERROR)";
@@ skipping 50 matching lines @@
   }
 
   state_ = CREATING_STREAM;
   ipc_->CreateStream(this, session_id_, audio_parameters_,
                      agc_is_enabled_, kRequestedSharedMemoryCount);
 }
 
 void AudioInputDevice::ShutDownOnIOThread() {
   DCHECK(task_runner()->BelongsToCurrentThread());
 
+  check_alive_timer_.Stop();
+  DCHECK(!check_alive_timer_.IsRunning());
+
   // Close the stream, if we haven't already.
   if (state_ >= CREATING_STREAM) {
     ipc_->CloseStream();
     state_ = IDLE;
     agc_is_enabled_ = false;
   }
 
   // We can run into an issue where ShutDownOnIOThread is called right after
   // OnStreamCreated is called in cases where Start/Stop are called before we
   // get the OnStreamCreated callback.  To handle that corner case, we call
@@ skipping 26 matching lines @@
   // We simply store the new AGC setting here. This value will be used when
   // a new stream is initialized and by GetAutomaticGainControl().
   agc_is_enabled_ = enabled;
 }
 
 void AudioInputDevice::WillDestroyCurrentMessageLoop() {
   LOG(ERROR) << "IO loop going away before the input device has been stopped";
   ShutDownOnIOThread();
 }
 
+void AudioInputDevice::CheckIfInputStreamIsAlive() {
+  DCHECK(task_runner()->BelongsToCurrentThread());
+  base::TimeDelta time_since_last_callback =
+      base::TimeTicks::Now() - last_callback_time_;
+  if (time_since_last_callback >
+      base::TimeDelta::FromSeconds(kMissingCallbacksTimeBeforeErrorSeconds)) {
+    callback_->OnCaptureError("No audio received from audio capture device.");

[ossu-chromium, 2017/05/19 11:26:48]

Should we also tie this to a UMA stat, like we do for the audio inputs on Mac?
Seems like a stat here would encompass all our inputs and allow us to track them
all with a single stat.

[Henrik Grunell, 2017/05/20 08:40:51]

Thanks for reminding. Yes, we should have that. We need to compare against when
no error occurred. I added a flag for if missing callbacks have been detected
and report a boolean when stopping. In the future we could add stats for other
capture errors, but this serves the purpose of this detection.

+  }
+}
+
+void AudioInputDevice::SetLastCallbackTime(base::TimeTicks last_callback_time) {
+  task_runner()->PostTask(
+      FROM_HERE, base::Bind(&AudioInputDevice::SetLastCallbackTimeOnIOThread,
+                            this, last_callback_time));
+}
+
+void AudioInputDevice::SetLastCallbackTimeOnIOThread(
+    base::TimeTicks last_callback_time) {
+  DCHECK(task_runner()->BelongsToCurrentThread());
+  last_callback_time_ = last_callback_time;
+}
+
 // AudioInputDevice::AudioThreadCallback
 AudioInputDevice::AudioThreadCallback::AudioThreadCallback(
     const AudioParameters& audio_parameters,
     base::SharedMemoryHandle memory,
     int memory_length,
     int total_segments,
-    CaptureCallback* capture_callback)
+    CaptureCallback* capture_callback,
+    DataCallbackNotificationCallback data_callback_notification_callback)
     : AudioDeviceThread::Callback(audio_parameters,
                                   memory,
                                   memory_length,
                                   total_segments),
       bytes_per_ms_(static_cast<double>(audio_parameters.GetBytesPerSecond()) /
                     base::Time::kMillisecondsPerSecond),
       current_segment_id_(0),
       last_buffer_id_(UINT32_MAX),
-      capture_callback_(capture_callback) {}
+      capture_callback_(capture_callback),
+      data_callback_notification_callback_(
+          std::move(data_callback_notification_callback)) {}
 
 AudioInputDevice::AudioThreadCallback::~AudioThreadCallback() {
 }
 
 void AudioInputDevice::AudioThreadCallback::MapSharedMemory() {
   shared_memory_.Map(memory_length_);
 
   // Create vector of audio buses by wrapping existing blocks of memory.
   uint8_t* ptr = static_cast<uint8_t*>(shared_memory_.memory());
   for (int i = 0; i < total_segments_; ++i) {
@@ skipping 37 matching lines @@
         "Segment id not matching. Remote = %u. Local = %d.",
         pending_data, current_segment_id_);
     LOG(ERROR) << message;
     capture_callback_->OnCaptureError(message);
   }
   last_buffer_id_ = buffer->params.id;
 
   // Use pre-allocated audio bus wrapping existing block of shared memory.
   media::AudioBus* audio_bus = audio_buses_[current_segment_id_].get();
 
+  // Inform that we have gotten a callback.
+  data_callback_notification_callback_.Run(base::TimeTicks::Now());
+
   // Deliver captured data to the client in floating point format and update
   // the audio delay measurement.
   capture_callback_->Capture(
       audio_bus,
       buffer->params.hardware_delay_bytes / bytes_per_ms_,  // Delay in ms
       buffer->params.volume, buffer->params.key_pressed);
 
   if (++current_segment_id_ >= total_segments_)
     current_segment_id_ = 0;
 }
 
 }  // namespace media