CRAS: iodev_list - Retry if init device failed

There are cases that iodev fails to open and that results silent
playback or recording to user.
When this type of error happens, let iodev_list do a retry to open
iodev because user has very few clue on what has happened.

BUG=chromium:666405
TEST=Use hack patch to make USB iodev fail to open, check debug log
to verify open dev retry is working when add new streams and select
different output nodes.

Change-Id: I5163f79c881d88b32f8c02045c1954e20118d44a
Reviewed-on: https://chromium-review.googlesource.com/414854
Commit-Ready: Hsinyu Chao <hychao@chromium.org>
Tested-by: Hsinyu Chao <hychao@chromium.org>
Reviewed-by: Dylan Reid <dgreid@chromium.org>

2 files changed, 164 insertions, 20 deletions

diff --git a/cras/src/server/cras_iodev_list.c b/cras/src/server/cras_iodev_list.c
index 114c6b69..4d87d685 100644
--- a/cras/src/server/cras_iodev_list.c
+++ b/cras/src/server/cras_iodev_list.c
@@ -34,9 +34,11 @@ struct iodev_list {
 
 /* List of enabled input/output devices.
  *    dev - The device.
+ *    init_timer - Timer for a delayed call to init this iodev.
  */
 struct enabled_dev {
 	struct cras_iodev *dev;
+	struct cras_timer *init_timer;
 	struct enabled_dev *prev, *next;
 };
 
@@ -63,6 +65,8 @@ static struct stream_list *stream_list;
 static struct cras_timer *idle_timer;
 /* Flag to indicate that the stream list is disconnected from audio thread. */
 static int stream_list_suspended = 0;
+/* If init device failed, retry after 1 second. */
+static const unsigned int INIT_DEV_DELAY_MS = 1000;
 
 static void idle_dev_check(struct cras_timer *timer, void *data);
 
@@ -484,6 +488,59 @@ static void possibly_enable_fallback(enum CRAS_STREAM_DIRECTION dir)
 		enable_device(fallback_devs[dir]);
 }
 
+static int init_and_attach_streams(struct cras_iodev *dev)
+{
+	int rc;
+	enum CRAS_STREAM_DIRECTION dir = dev->direction;
+	struct cras_rstream *stream;
+
+	/* If called after suspend, for example bluetooth
+	 * profile switching, don't add back the stream list. */
+	if (!stream_list_suspended) {
+		/* If there are active streams to attach to this device,
+		 * open it. */
+		DL_FOREACH(stream_list_get(stream_list), stream) {
+			if (stream->direction != dir || stream->is_pinned)
+				continue;
+			rc = init_device(dev, stream);
+			if (rc) {
+				syslog(LOG_ERR, "Enable %s failed, rc = %d",
+				       dev->info.name, rc);
+				return rc;
+			}
+			audio_thread_add_stream(audio_thread,
+						stream, &dev, 1);
+		}
+	}
+	return 0;
+}
+
+static void init_device_cb(struct cras_timer *timer, void *arg)
+{
+	int rc;
+	struct enabled_dev *edev = (struct enabled_dev *)arg;
+	struct cras_iodev *dev = edev->dev;
+
+	edev->init_timer = NULL;
+	if (cras_iodev_is_open(dev))
+		return;
+
+	rc = init_and_attach_streams(dev);
+	if (rc < 0)
+		syslog(LOG_ERR, "Init device retry failed");
+	else
+		possibly_disable_fallback(dev->direction);
+}
+
+static void schedule_init_device_retry(struct enabled_dev *edev)
+{
+	struct cras_tm *tm = cras_system_state_get_tm();
+
+	if (edev->init_timer == NULL)
+		edev->init_timer = cras_tm_create_timer(
+				tm, INIT_DEV_DELAY_MS, init_device_cb, edev);
+}
+
 static int stream_added_cb(struct cras_rstream *rstream)
 {
 	struct enabled_dev *edev;
@@ -525,6 +582,7 @@ static int stream_added_cb(struct cras_rstream *rstream)
 			 */
 			syslog(LOG_ERR, "Init %s failed, rc = %d",
 			       edev->dev->info.name, rc);
+			schedule_init_device_retry(edev);
 			continue;
 		}
 
@@ -614,7 +672,6 @@ static int enable_device(struct cras_iodev *dev)
 {
 	int rc;
 	struct enabled_dev *edev;
-	struct cras_rstream *stream;
 	enum CRAS_STREAM_DIRECTION dir = dev->direction;
 
 	DL_FOREACH(enabled_devs[dir], edev) {
@@ -624,27 +681,16 @@ static int enable_device(struct cras_iodev *dev)
 
 	edev = calloc(1, sizeof(*edev));
 	edev->dev = dev;
+	edev->init_timer = NULL;
 	DL_APPEND(enabled_devs[dir], edev);
 	dev->is_enabled = 1;
 
-	/* If enable_device is called after suspend, for example bluetooth
-	 * profile switching, don't add back the stream list. */
-	if (!stream_list_suspended) {
-		/* If there are active streams to attach to this device,
-		 * open it. */
-		DL_FOREACH(stream_list_get(stream_list), stream) {
-			if (stream->direction != dir || stream->is_pinned)
-				continue;
-			rc = init_device(dev, stream);
-			if (rc) {
-				syslog(LOG_ERR, "Enable %s failed, rc = %d",
-				       edev->dev->info.name, rc);
-				return rc;
-			}
-			audio_thread_add_stream(audio_thread,
-						stream, &dev, 1);
-		}
+	rc = init_and_attach_streams(dev);
+	if (rc < 0) {
+		schedule_init_device_retry(edev);
+		return rc;
 	}
+
 	if (device_enabled_callback)
 		device_enabled_callback(dev, 1, device_enabled_cb_data);
 
@@ -658,6 +704,11 @@ static int disable_device(struct enabled_dev *edev)
 	struct cras_rstream *stream;
 
 	DL_DELETE(enabled_devs[dir], edev);
+	if (edev->init_timer) {
+		cras_tm_cancel_timer(cras_system_state_get_tm(),
+				     edev->init_timer);
+		edev->init_timer = NULL;
+	}
 	free(edev);
 	dev->is_enabled = 0;
 
@@ -690,6 +741,7 @@ void cras_iodev_list_init()
 	observer_ops.capture_mute_changed = sys_cap_mute_change;
 	observer_ops.suspend_changed = sys_suspend_change;
 	list_observer = cras_observer_add(&observer_ops, NULL);
+	idle_timer = NULL;
 
 	/* Create the audio stream list for the system. */
 	stream_list = stream_list_create(stream_added_cb, stream_removed_cb,
diff --git a/cras/src/tests/iodev_list_unittest.cc b/cras/src/tests/iodev_list_unittest.cc
index 74c0cb9c..94e81c43 100644
--- a/cras/src/tests/iodev_list_unittest.cc
+++ b/cras/src/tests/iodev_list_unittest.cc
@@ -44,7 +44,10 @@ static stream_callback *stream_rm_cb;
 static struct cras_rstream *stream_list_get_ret;
 static int audio_thread_drain_stream_return;
 static int audio_thread_drain_stream_called;
+static int cras_tm_create_timer_called;
+static int cras_tm_cancel_timer_called;
 static void (*cras_tm_timer_cb)(struct cras_timer *t, void *data);
+static void *cras_tm_timer_cb_data;
 static struct timespec clock_gettime_retspec;
 static struct cras_iodev *device_enabled_dev;
 static struct cras_iodev *device_disabled_dev;
@@ -80,6 +83,8 @@ class IoDevTestSuite : public testing::Test {
       stream_list_get_ret = 0;
       audio_thread_drain_stream_return = 0;
       audio_thread_drain_stream_called = 0;
+      cras_tm_create_timer_called = 0;
+      cras_tm_cancel_timer_called = 0;
 
       sample_rates_[0] = 44100;
       sample_rates_[1] = 48000;
@@ -316,7 +321,7 @@ TEST_F(IoDevTestSuite, InitDevFailShouldEnableFallback) {
   EXPECT_EQ(1, audio_thread_add_stream_called);
 }
 
-TEST_F(IoDevTestSuite, SelectNodeOpenFail) {
+TEST_F(IoDevTestSuite, SelectNodeOpenFailShouldScheduleRetry) {
   struct cras_rstream rstream;
   struct cras_rstream *stream_list = NULL;
   int rc;
@@ -345,17 +350,100 @@ TEST_F(IoDevTestSuite, SelectNodeOpenFail) {
       cras_make_node_id(d2_.info.idx, 1));
   EXPECT_EQ(2, cras_iodev_close_called);
   EXPECT_EQ(2, cras_iodev_open_called);
+  EXPECT_EQ(0, cras_tm_create_timer_called);
+  EXPECT_EQ(0, cras_tm_cancel_timer_called);
 
   /* Test that if select to d1 and open d1 fail, fallback doesn't close. */
   cras_iodev_open_called = 0;
   cras_iodev_open_ret[0] = 0;
   cras_iodev_open_ret[1] = -5;
+  cras_iodev_open_ret[2] = 0;
+  cras_tm_timer_cb = NULL;
   cras_iodev_list_select_node(CRAS_STREAM_OUTPUT,
       cras_make_node_id(d1_.info.idx, 1));
   EXPECT_EQ(3, cras_iodev_close_called);
   EXPECT_EQ(&d2_, cras_iodev_close_dev);
+  EXPECT_EQ(2, cras_iodev_open_called);
+  EXPECT_EQ(0, cras_tm_cancel_timer_called);
+
+  /* Assert a timer is scheduled to retry open. */
+  EXPECT_NE((void *)NULL, cras_tm_timer_cb);
+  EXPECT_EQ(1, cras_tm_create_timer_called);
+
+  audio_thread_add_stream_called = 0;
+  cras_tm_timer_cb(NULL, cras_tm_timer_cb_data);
+  EXPECT_EQ(3, cras_iodev_open_called);
+  EXPECT_EQ(1, audio_thread_add_stream_called);
+
+  /* Retry open success will close fallback dev. */
+  EXPECT_EQ(4, cras_iodev_close_called);
+  EXPECT_EQ(0, cras_tm_cancel_timer_called);
+
+  /* Select to d2 and fake an open failure. */
+  cras_iodev_close_called = 0;
+  cras_iodev_open_called = 0;
+  cras_iodev_open_ret[0] = 0;
+  cras_iodev_open_ret[1] = -5;
+  cras_iodev_open_ret[2] = 0;
+  cras_iodev_list_select_node(CRAS_STREAM_OUTPUT,
+      cras_make_node_id(d2_.info.idx, 1));
+  EXPECT_EQ(1, cras_iodev_close_called);
+  EXPECT_EQ(&d1_, cras_iodev_close_dev);
+  EXPECT_EQ(2, cras_tm_create_timer_called);
+  EXPECT_NE((void *)NULL, cras_tm_timer_cb);
+
+  /* Select to another iodev should cancel the timer. */
+  memset(cras_iodev_open_ret, 0, sizeof(cras_iodev_open_ret));
+  cras_iodev_list_select_node(CRAS_STREAM_OUTPUT,
+      cras_make_node_id(d2_.info.idx, 1));
+  EXPECT_EQ(1, cras_tm_cancel_timer_called);
+}
+
+TEST_F(IoDevTestSuite, InitDevFailShouldScheduleRetry) {
+  int rc;
+  struct cras_rstream rstream;
+  struct cras_rstream *stream_list = NULL;
+
+  memset(&rstream, 0, sizeof(rstream));
+  cras_iodev_list_init();
+
+  d1_.direction = CRAS_STREAM_OUTPUT;
+  rc = cras_iodev_list_add_output(&d1_);
+  ASSERT_EQ(0, rc);
+
+  cras_iodev_list_select_node(CRAS_STREAM_OUTPUT,
+      cras_make_node_id(d1_.info.idx, 0));
+
+  cras_iodev_open_ret[0] = -5;
+  cras_iodev_open_ret[1] = 0;
+  cras_tm_timer_cb = NULL;
+  DL_APPEND(stream_list, &rstream);
+  stream_list_get_ret = stream_list;
+  stream_add_cb(&rstream);
+  /* open dev called twice, one for fallback device. */
+  EXPECT_EQ(2, cras_iodev_open_called);
+  EXPECT_EQ(1, audio_thread_add_stream_called);
+
+  EXPECT_NE((void *)NULL, cras_tm_timer_cb);
+  EXPECT_EQ(1, cras_tm_create_timer_called);
+
+  /* If retry still fail, won't schedule more retry. */
+  cras_iodev_open_ret[2] = -5;
+  cras_tm_timer_cb(NULL, cras_tm_timer_cb_data);
+  EXPECT_EQ(1, cras_tm_create_timer_called);
+  EXPECT_EQ(1, audio_thread_add_stream_called);
+
+  cras_tm_timer_cb = NULL;
+  cras_iodev_open_ret[3] = -5;
+  stream_add_cb(&rstream);
+  EXPECT_NE((void *)NULL, cras_tm_timer_cb);
+  EXPECT_EQ(2, cras_tm_create_timer_called);
+
+  cras_iodev_list_rm_output(&d1_);
+  EXPECT_EQ(1, cras_tm_cancel_timer_called);
 }
 
+
 TEST_F(IoDevTestSuite, SelectNode) {
   struct cras_rstream rstream, rstream2, rstream3;
   struct cras_rstream *stream_list = NULL;
@@ -1051,7 +1139,8 @@ void loopback_iodev_destroy(struct cras_iodev *iodev) {
 
 int cras_iodev_open(struct cras_iodev *iodev, unsigned int cb_level)
 {
-  iodev->state = CRAS_IODEV_STATE_OPEN;
+  if (cras_iodev_open_ret[cras_iodev_open_called] == 0)
+    iodev->state = CRAS_IODEV_STATE_OPEN;
   return cras_iodev_open_ret[cras_iodev_open_called++];
 }
 
@@ -1102,10 +1191,13 @@ struct cras_timer *cras_tm_create_timer(
                 void (*cb)(struct cras_timer *t, void *data),
                 void *cb_data) {
   cras_tm_timer_cb = cb;
+  cras_tm_timer_cb_data = cb_data;
+  cras_tm_create_timer_called++;
   return reinterpret_cast<struct cras_timer *>(0x404);
 }
 
 void cras_tm_cancel_timer(struct cras_tm *tm, struct cras_timer *t) {
+  cras_tm_cancel_timer_called++;
 }
 
 void cras_fmt_conv_destroy(struct cras_fmt_conv *conv)