[media][audio_core][e2e] Tweaks to support virtual audio

This CL makes the following surgical changes to prepare AudioCore
for the usage of VirtualAudio technology, in support of the e2e push:

* Includes error codes with ShutdownSelf calls (previously 6 of 21
  call sites didn't),
* Handle AUDIO STREAM_PLUG_DETECT_NOTIFY as other messages are (as
  opposed to hard-coding the assumption that it is identical to an
  AUDIO_STREAM_CMD_PLUG_DETECT response),
* Accept (but ignore) AUDIO_RB_POSITION_NOTIFY messages, rather than
  shutting down the stream when these are received,
* Don't log the initially-configured format, as each new device is
  detected and initialized. The debug log chatter as these devices
  come and go was reducing the usefulness of the logs overall. A
  TODO suggests that we store this info in the hub, if it something
  worth knowing later.

AudioCore does NOT request ring-buffer position notifications from
drivers during streaming; this is unchanged. Instead, it relies upon
CLOCK_MONOTONIC as the source of chronological truth.

Test: build, CQ

Change-Id: I6b8b4b0186999bb22e9e855ec2e69efab48bdcac
diff --git a/garnet/bin/media/audio_core/audio_driver.cc b/garnet/bin/media/audio_core/audio_driver.cc
index cd58272..3982242 100644
--- a/garnet/bin/media/audio_core/audio_driver.cc
+++ b/garnet/bin/media/audio_core/audio_driver.cc
@@ -57,7 +57,7 @@
       [this](const ::dispatcher::Channel* channel) {
         OBTAIN_EXECUTION_DOMAIN_TOKEN(token, owner_->mix_domain_);
         FXL_DCHECK(stream_channel_.get() == channel);
-        ShutdownSelf("Stream channel closed unexpectedly");
+        ShutdownSelf("Stream channel closed unexpectedly", ZX_ERR_PEER_CLOSED);
       });
 
   res = stream_channel_->Activate(
@@ -74,7 +74,7 @@
       [this](::dispatcher::Timer* timer) -> zx_status_t {
         OBTAIN_EXECUTION_DOMAIN_TOKEN(token, owner_->mix_domain_);
         FXL_DCHECK(cmd_timeout_.get() == timer);
-        ShutdownSelf("Unexpected command timeout");
+        ShutdownSelf("Unexpected command timeout", ZX_ERR_TIMED_OUT);
         return ZX_OK;
       });
 
@@ -455,7 +455,7 @@
     FXL_LOG(ERROR) << "Channel response is too small to hold even a "
                    << "message header (" << *bytes_read_out << " < "
                    << sizeof(audio_cmd_hdr_t) << ").";
-    ShutdownSelf();
+    ShutdownSelf("Channel response too small", ZX_ERR_INVALID_ARGS);
     return ZX_ERR_INVALID_ARGS;
   }
 
@@ -559,9 +559,9 @@
       break;
 
     case AUDIO_STREAM_PLUG_DETECT_NOTIFY:
-      CHECK_RESP(AUDIO_STREAM_CMD_PLUG_DETECT, pd_resp, false, true);
-      plug_state = ((msg.pd_resp.flags & AUDIO_PDNF_PLUGGED) != 0);
-      ReportPlugStateChange(plug_state, msg.pd_resp.plug_state_time);
+      CHECK_RESP(AUDIO_STREAM_CMD_PLUG_DETECT_NOTIFY, pd_notify, false, true);
+      plug_state = ((msg.pd_notify.flags & AUDIO_PDNF_PLUGGED) != 0);
+      ReportPlugStateChange(plug_state, msg.pd_notify.plug_state_time);
       break;
 
     default:
@@ -587,6 +587,7 @@
     audio_rb_cmd_get_buffer_resp_t get_buffer;
     audio_rb_cmd_start_resp_t start;
     audio_rb_cmd_stop_resp_t stop;
+    audio_rb_position_notify_t pos_notify;
   } msg;
   static_assert(sizeof(msg) <= 256,
                 "Message buffer is becoming too large to hold on the stack!");
@@ -618,6 +619,15 @@
       res = ProcessStopResponse(msg.stop);
       break;
 
+    // Currently we ignore driver-reported position, instead using the system-
+    // internal clock. This message is benign and can be safely ignored, but
+    // because we did not request it, this may indicate some other problem in
+    // the driver state machine. We issue a warning, eat the msg and continue.
+    case AUDIO_RB_POSITION_NOTIFY:
+      CHECK_RESP(AUDIO_RB_POSITION_NOTIFY, pos_notify, false, true);
+      res = ProcessPositionNotify(msg.pos_notify);
+      break;
+
     default:
       FXL_LOG(ERROR) << "Unrecognized ring buffer channel response 0x"
                      << std::hex << msg.hdr.cmd;
@@ -708,17 +718,22 @@
   }
 
   // Sanity checks
+  if (resp.format_range_count == 0) {
+    FXL_LOG(ERROR) << "Driver reported that it supports no format ranges!";
+    return ZX_ERR_INVALID_ARGS;
+  }
+
   if (resp.first_format_range_ndx >= resp.format_range_count) {
-    FXL_LOG(ERROR) << "Bad format range index in get formats response! ("
-                   << resp.first_format_range_ndx
-                   << " >= " << resp.format_range_count;
+    FXL_LOG(ERROR) << "Bad format range index in get formats response! (index "
+                   << resp.first_format_range_ndx << " should be < total "
+                   << resp.format_range_count << ")";
     return ZX_ERR_INVALID_ARGS;
   }
 
   if (resp.first_format_range_ndx != format_ranges_.size()) {
-    FXL_LOG(ERROR) << "Out of order message in get formats response! ("
-                   << resp.first_format_range_ndx
-                   << " != " << format_ranges_.size();
+    FXL_LOG(ERROR) << "Out of order message in get formats response! (index "
+                   << resp.first_format_range_ndx << " != the expected "
+                   << format_ranges_.size() << ")";
     return ZX_ERR_INVALID_ARGS;
   }
 
@@ -768,7 +783,7 @@
       [this](const ::dispatcher::Channel* channel) {
         OBTAIN_EXECUTION_DOMAIN_TOKEN(token, owner_->mix_domain_);
         FXL_DCHECK(rb_channel_.get() == channel);
-        ShutdownSelf("Ring buffer channel closed unexpectedly");
+        ShutdownSelf("Ring buffer channel closed");
       });
 
   zx_status_t res;
@@ -886,8 +901,9 @@
                                             resp.num_ring_buffer_frames,
                                             owner_->is_input());
     if (ring_buffer_ == nullptr) {
-      ShutdownSelf("Failed to allocate and map driver ring buffer");
-      return ZX_ERR_INTERNAL;
+      ShutdownSelf("Failed to allocate and map driver ring buffer",
+                   ZX_ERR_NO_MEMORY);
+      return ZX_ERR_NO_MEMORY;
     }
     FXL_DCHECK(!clock_mono_to_ring_pos_bytes_.invertable());
 
@@ -957,17 +973,25 @@
   return ZX_OK;
 }
 
-void AudioDriver::ShutdownSelf(const char* debug_reason,
-                               zx_status_t debug_status) {
+zx_status_t AudioDriver::ProcessPositionNotify(
+    const audio_rb_position_notify_t& notify) {
+  FXL_DLOG(INFO) << "Unsolicited ring buffer position notification!  Time:"
+                 << zx_clock_get(ZX_CLOCK_MONOTONIC)
+                 << " Pos:" << notify.ring_buffer_pos;
+
+  // Although this notification was unsolicited and unexpected, we only complain
+  // (and only on debug builds), rather than abort-closing the channel.
+  return ZX_OK;
+}
+
+void AudioDriver::ShutdownSelf(const char* reason, zx_status_t status) {
   if (state_ == State::Shutdown) {
     return;
   }
 
-  if (debug_reason != nullptr) {
-    FXL_LOG(INFO) << "AudioDriver ("
-                  << (owner_->is_input() ? "input" : "output")
-                  << ") shutting down: reason = \"" << debug_reason
-                  << "\" (status = " << debug_status << ")";
+  if (reason != nullptr) {
+    FXL_LOG(INFO) << (owner_->is_input() ? " Input" : "Output")
+                  << " shutting down '" << reason << "', status:" << status;
   }
 
   // Our owner will call our Cleanup function within this call.
@@ -1007,7 +1031,7 @@
 zx_status_t AudioDriver::OnDriverInfoFetched(uint32_t info) {
   // We should never fetch the same info twice.
   if (fetched_driver_info_ & info) {
-    ShutdownSelf("Duplicate driver info fetch\n");
+    ShutdownSelf("Duplicate driver info fetch\n", ZX_ERR_BAD_STATE);
     return ZX_ERR_BAD_STATE;
   }
 
diff --git a/garnet/bin/media/audio_core/audio_driver.h b/garnet/bin/media/audio_core/audio_driver.h
index 6058601..42f7664 100644
--- a/garnet/bin/media/audio_core/audio_driver.h
+++ b/garnet/bin/media/audio_core/audio_driver.h
@@ -170,6 +170,8 @@
       FXL_EXCLUSIVE_LOCKS_REQUIRED(owner_->mix_domain_->token());
   zx_status_t ProcessStopResponse(const audio_rb_cmd_stop_resp_t& resp)
       FXL_EXCLUSIVE_LOCKS_REQUIRED(owner_->mix_domain_->token());
+  zx_status_t ProcessPositionNotify(const audio_rb_position_notify_t& notify)
+      FXL_EXCLUSIVE_LOCKS_REQUIRED(owner_->mix_domain_->token());
 
   // Transition to the Shutdown state and begin the process of shutting down.
   void ShutdownSelf(const char* debug_reason = nullptr,
diff --git a/garnet/bin/media/audio_core/audio_input.cc b/garnet/bin/media/audio_core/audio_input.cc
index 7aaf96a..69c2258 100644
--- a/garnet/bin/media/audio_core/audio_input.cc
+++ b/garnet/bin/media/audio_core/audio_input.cc
@@ -76,9 +76,7 @@
     return;
   }
 
-  FXL_LOG(INFO) << "AudioInput Configuring for " << pref_fps << " Hz "
-                << pref_chan << " channel(s) sample format(0x" << std::hex
-                << static_cast<uint32_t>(pref_fmt) << ")";
+  // TODO(mpuryear): Save to the hub the configured format for this input.
 
   // Send config request; recompute distance between start|end sampling fences.
   driver_->Configure(pref_fps, pref_chan, pref_fmt, kMaxFenceDistance);
diff --git a/garnet/bin/media/audio_core/driver_output.cc b/garnet/bin/media/audio_core/driver_output.cc
index d805907..8d73129 100644
--- a/garnet/bin/media/audio_core/driver_output.cc
+++ b/garnet/bin/media/audio_core/driver_output.cc
@@ -315,10 +315,7 @@
     return;
   }
 
-  FXL_LOG(INFO) << "Output: configuring the following best-fit format: "
-                << pref_fps << " Hz, " << pref_chan
-                << "-channel, sample format 0x" << std::hex
-                << static_cast<uint32_t>(pref_fmt);
+  // TODO(mpuryear): Save to the hub the configured format for this output.
 
   TimelineRate ns_to_frames(pref_fps, ZX_SEC(1));
   int64_t retention_frames = ns_to_frames.Scale(kDefaultMaxRetentionNsec);