Attempt to deflake media browsertests and enable more logs.

In the event a ended event occurs before a timeupdate event, the
next timeupdate event would retrigger the seek step. So cleanup
all test advancement listeners during calls to SeekTestStep().

Also, enable console logs on Android by toggling the necessary
base::Feature to help debugging these flakes in the field.

Also, fix "undefined undefined" from showing up in console logs
when the video size information shows up. As a result of this
the way size tests are completed has been reimplemented to avoid
an extraneous title step.

R=jrummell

Change-Id: Ia3799eb4b16583ad3a8751f67e6e33cf0c5d5d20
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2036365
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: John Rummell <jrummell@chromium.org>
Auto-Submit: Dale Curtis <dalecurtis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#738030}

chrome/browser/media/media_browsertest.cc

@@ -31,6 +31,12 @@ void MediaBrowserTest::SetUpCommandLine(base::CommandLine* command_line) {
       switches::kAutoplayPolicy,
       switches::autoplay::kNoUserGestureRequiredPolicy);
 
+  std::vector<base::Feature> enabled_features = {
+#if defined(OS_ANDROID)
+    features::kLogJsConsoleMessages,
+#endif
+  };
+
   std::vector<base::Feature> disabled_features = {
     // Disable fallback after decode error to avoid unexpected test pass on
     // the fallback path.
@@ -43,8 +49,7 @@ void MediaBrowserTest::SetUpCommandLine(base::CommandLine* command_line) {
 #endif
   };
 
-  scoped_feature_list_.InitWithFeatures({/* enabled_features */},
-                                        disabled_features);
+  scoped_feature_list_.InitWithFeatures(enabled_features, disabled_features);
 }
 
 void MediaBrowserTest::RunMediaTestPage(const std::string& html_page,

content/browser/media/media_browsertest.cc

@@ -36,6 +36,12 @@ void MediaBrowserTest::SetUpCommandLine(base::CommandLine* command_line) {
       switches::autoplay::kNoUserGestureRequiredPolicy);
   command_line->AppendSwitch(switches::kExposeInternalsForTesting);
 
+  std::vector<base::Feature> enabled_features = {
+#if defined(OS_ANDROID)
+    features::kLogJsConsoleMessages,
+#endif
+  };
+
   std::vector<base::Feature> disabled_features = {
     // Disable fallback after decode error to avoid unexpected test pass on
     // the fallback path.
@@ -48,8 +54,7 @@ void MediaBrowserTest::SetUpCommandLine(base::CommandLine* command_line) {
 #endif
   };
 
-  scoped_feature_list_.InitWithFeatures({/* enabled_features */},
-                                        disabled_features);
+  scoped_feature_list_.InitWithFeatures(enabled_features, disabled_features);
 }
 
 void MediaBrowserTest::RunMediaTestPage(const std::string& html_page,
@@ -151,13 +156,13 @@ class MediaTest : public testing::WithParamInterface<bool>,
   }
 
   void RunVideoSizeTest(const char* media_file, int width, int height) {
-    std::string expected;
-    expected += base::NumberToString(width);
-    expected += " ";
-    expected += base::NumberToString(height);
+    std::string expected_title = std::string(media::kEnded) + " " +
+                                 base::NumberToString(width) + " " +
+                                 base::NumberToString(height);
     base::StringPairs query_params;
     query_params.emplace_back("video", media_file);
-    RunMediaTestPage("player.html", query_params, expected, false);
+    query_params.emplace_back("sizetest", "true");
+    RunMediaTestPage("player.html", query_params, expected_title, false);
   }
 };
 
@@ -177,15 +182,15 @@ IN_PROC_BROWSER_TEST_P(MediaTest, VideoBearWebm) {
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, AudioBearOpusWebm) {
-  PlayVideo("bear-opus.webm", GetParam());
+  PlayAudio("bear-opus.webm", GetParam());
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, AudioBearOpusMp4) {
-  PlayVideo("bear-opus.mp4", GetParam());
+  PlayAudio("bear-opus.mp4", GetParam());
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, AudioBearOpusOgg) {
-  PlayVideo("bear-opus.ogg", GetParam());
+  PlayAudio("bear-opus.ogg", GetParam());
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, VideoBearSilentWebm) {
@@ -216,11 +221,11 @@ IN_PROC_BROWSER_TEST_P(MediaTest, AudioBearFlac192kHzMp4) {
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, VideoBearMovPcmS16be) {
-  PlayVideo("bear_pcm_s16be.mov", GetParam());
+  PlayAudio("bear_pcm_s16be.mov", GetParam());
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, VideoBearMovPcmS24be) {
-  PlayVideo("bear_pcm_s24be.mov", GetParam());
+  PlayAudio("bear_pcm_s24be.mov", GetParam());
 }
 
 #if BUILDFLAG(USE_PROPRIETARY_CODECS)
@@ -294,7 +299,7 @@ IN_PROC_BROWSER_TEST_P(MediaTest, AudioBearFlac) {
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, AudioBearFlacOgg) {
-  PlayVideo("bear-flac.ogg", GetParam());
+  PlayAudio("bear-flac.ogg", GetParam());
 }
 
 IN_PROC_BROWSER_TEST_P(MediaTest, VideoBearWavAlaw) {

media/test/data/player.html

@@ -7,8 +7,10 @@
 <script type="text/javascript">
 // <audio> or <video> player element.
 var player;
+var tag = '';
 var logs = document.getElementById('logs');
 var heartbeatCount = 0;
+var isSizeTest = false;
 
 function Log(message) {
   logs.innerHTML = message + '<br>' + logs.innerHTML;
@@ -16,7 +18,7 @@ function Log(message) {
 }
 
 function onLogEvent(e) {
-  Log('Event: ' + e.type +' video: ' + getVideoStatus(e.target));
+  Log('Event: ' + e.type + ', State: {' + getMediaStatus(e.target) + '}');
 }
 
 function getTimeRanges(range) {
@@ -27,7 +29,7 @@ function getTimeRanges(range) {
   return '[' + result.join(', ') + ']';
 }
 
-function getVideoStatus(video) {
+function getMediaStatus(video) {
   if (video == null) {
     return 'null';
   }
@@ -40,6 +42,9 @@ function getVideoStatus(video) {
   result.push(`duration: ${video.duration}`);
   result.push(`buffered: ${getTimeRanges(video.buffered)}`);
   result.push(`played: ${getTimeRanges(video.played)}`);
+  if (tag == 'video') {
+    result.push(`size: ${video.videoWidth}x${video.videoHeight}`);
+  }
   if (video.error) {
     result.push(`error: {${video.error.code},${video.error.message}}`);
   }
@@ -54,7 +59,15 @@ function getVideoStatus(video) {
 function InstallTitleEventHandler(element, event) {
   element.addEventListener(event, function(e) {
     onLogEvent(e);
-    document.title = event.toUpperCase();
+
+    if (!isSizeTest) {
+      document.title = event.toUpperCase();
+      return;
+    }
+
+    var video = e.target;
+    document.title =
+        event.toUpperCase() + ` ${video.videoWidth} ${video.videoHeight}`;
   }, false);
 }
 
@@ -89,7 +102,10 @@ function Failed() {
 
 function SeekTestStep(e) {
   if (e) onLogEvent(e);
+
+  // Remove the previous triggers for this step.
   player.removeEventListener('ended', SeekTestStep, false);
+  player.removeEventListener('timeupdate', SeekTestTimeoutSetup, false);
 
   // Test completes on the next ended event.
   InstallTitleEventHandler(player, 'ended');
@@ -99,15 +115,13 @@ function SeekTestStep(e) {
   player.play().catch(function(error) {
     Log(error);
   });
-
 }
 
 function SeekTestTimeoutSetup() {
-  Log('timeupdate @ ' + player.currentTime);
   if (player.currentTime < 2)
     return;
 
-  player.removeEventListener('timeupdate', SeekTestTimeoutSetup, false);
+  Log('Triggering seek due to timeout @ ' + player.currentTime);
   SeekTestStep();
 }
 
@@ -129,7 +143,6 @@ function RunTest() {
   if (url_parts.length != 2)
     return Failed();
 
-  var tag = '';
   var media_url = '';
   var loop = false;
   var error_substr = null;
@@ -156,6 +169,11 @@ function RunTest() {
       error_substr = decodeURIComponent(query_parts[1]);
       continue;
     }
+
+    if (query_parts[0] == 'sizetest') {
+      isSizeTest = true;
+      continue;
+    }
   }
 
   if (tag != 'audio' && tag != 'video') {
@@ -167,15 +185,6 @@ function RunTest() {
   player.controls = true;
   document.getElementById('player_container').appendChild(player);
 
-  // We use loadeddata instead of loadedmetadata to ensure the decoder has
-  // completed initialization, even though we don't need to decode anything to
-  // get the size metadata. This is an unfortunate workaround for an Android
-  // framework bug (http://crbug.com/682387) where we have to avoid killing
-  // the GPU process while the decoder is initializing.
-  player.addEventListener('loadeddata', function(e) {
-    document.title = '' + player.videoWidth + ' ' + player.videoHeight;
-  });
-
   // Transition to the seek test after X seconds of playback or when the ended
   // event occurs, whichever happens first.
   player.addEventListener('ended', SeekTestStep, false);
@@ -193,13 +202,14 @@ function RunTest() {
   player.addEventListener('play', onLogEvent);
   player.addEventListener('playing', onLogEvent);
   player.addEventListener('progress', onLogEvent);
+  player.addEventListener('resize', onLogEvent);
   player.addEventListener('stalled', onLogEvent);
   player.addEventListener('suspend', onLogEvent);
+  player.addEventListener('timeupdate', onLogEvent);
   player.addEventListener('waiting', onLogEvent);
 
   setInterval(function () {
-    Log('heartbeat #' + ++heartbeatCount +
-    ' video: ' + getVideoStatus(player));
+    onLogEvent({'type': 'heartbeat #' + ++heartbeatCount, 'target': player});
   }, 1000);
 
   // Ensure we percolate up any error events, and optionally verify they contain
@@ -210,7 +220,7 @@ function RunTest() {
   player.loop = loop;
   player.preload = 'auto';
   player.src = media_url;
-  Log('Starting by calling play()');
+  Log('Starting test by calling ' + tag + '.play()');
   player.play().catch(function(error) {
     Log(error);
   });