Adjusting expectations https://chromium-review.googlesource.com/c/612281

chrishtr@ could you PTAL as an owner and pass to an appropriate person?

Mac log example:
https://build.chromium.org/p/chromium.webkit/builders/WebKit%20Mac10.9/builds/48909

02:23:43.664 7804   
02:23:43.665 7804   DevTools listening on ws://127.0.0.1:61412/devtools/browser/db066006-1d7a-460e-afdc-338c198fa7be
02:23:43.665 7804 worker/2 virtual/mojo-loading/http/tests/media/media-source/mediasource-config-change-mp4-av-audio-bitrate.html passed
02:23:43.672 7810 worker/6 external/wpt/css/CSS2/linebox/vertical-align-076.xht passed
02:23:43.711 7812 worker/7 http/tests/media/media-source/mediasource-redundant-seek.html output stderr lines:
02:23:43.711 7812   [9599:37123:0811/022343.196263:877351520087:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.712 7812 worker/7 http/tests/media/media-source/mediasource-redundant-seek.html passed
02:23:43.782 7812 worker/7 http/tests/media/media-source/mediasource-addsourcebuffer.html output stderr lines:
02:23:43.782 7812   [9599:771:0811/022343.756226:877911482707:ERROR:render_media_log.cc(30)] MediaEvent: PIPELINE_ERROR DEMUXER_ERROR_COULD_NOT_OPEN
02:23:43.782 7812   [9599:37123:0811/022343.763400:877918656809:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.782 7812 worker/7 http/tests/media/media-source/mediasource-addsourcebuffer.html passed
02:23:43.782 7803 worker/1 external/wpt/css/CSS2/positioning/absolute-replaced-height-002.xht passed
02:23:43.792 7804 worker/2 virtual/mojo-loading/http/tests/media/media-source/mediasource-duration.html output stderr lines:
02:23:43.792 7804   [9603:36867:0811/022343.737591:877892852853:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.792 7804   [9603:36867:0811/022343.738089:877893345046:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.792 7804   [9603:36867:0811/022343.738375:877893629586:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.792 7804   [9603:36867:0811/022343.738656:877893910570:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.792 7804   [9603:36867:0811/022343.738933:877894187776:ERROR:render_media_log.cc(30)] MediaEvent: MEDIA_ERROR_LOG_ENTRY {"error":"Failed to reconcile encoded audio times with decoded output."}
02:23:43.794 7767 [20024/60242] virtual/mojo-loading/http/tests/media/media-source/mediasource-duration.html failed unexpectedly (asserts failed)
02:23:43.793 7804 worker/2 virtual/mojo-loading/http/tests/media/media-source/mediasource-duration.html failed:
02:23:43.793 7804 worker/2  asserts failed

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/bd09f19f5b909ab040b3afa1d8ca5b7fa37c207f

commit bd09f19f5b909ab040b3afa1d8ca5b7fa37c207f
Author: Olga Sharonova <olka@chromium.org>
Date: Fri Aug 11 12:53:05 2017

Adjust expectations for flaky http/tests/media/media-source/mediasource-duration.html

TBR=qyearsley

Bug:  754657 
Change-Id: I31412672252ae0b15fb721920b141ccca2d54c3c
Reviewed-on: https://chromium-review.googlesource.com/612281
Reviewed-by: Olga Sharonova <olka@chromium.org>
Commit-Queue: Olga Sharonova <olka@chromium.org>
Cr-Commit-Position: refs/heads/master@{#493708}
[modify] https://crrev.com/bd09f19f5b909ab040b3afa1d8ca5b7fa37c207f/third_party/WebKit/LayoutTests/TestExpectations

Similar to  bug 754669 

 Issue 754669  has been merged into this issue.

Though I didn't see this when fixing other flakiness and removing the flaky expectation in https://chromium.googlesource.com/chromium/src/+/34e69d173cbdd2deca59604a10ed93282f1773c5, it appears not all the flakiness is fixed yet:

From spot-checks, the underlying problem appears not to be any mediasource-duration.html test case failure. I see only (flaky) text difference related to noise from the element around play()/pause() stuff:

CONSOLE ERROR: Uncaught (in promise) AbortError: The play() request was interrupted by a call to pause(). https://goo.gl/LdLk22
This is a testharness.js-based test.
Harness Error. harness_status.status = 1 , harness_status.message = The play() request was interrupted by a call to pause(). https://goo.gl/LdLk22
PASS Test seek starts on duration reduction below currentTime 
PASS Test appendBuffer completes previous seek to reduced duration 
PASS Test endOfStream completes previous seek to reduced duration 
PASS Test setting same duration multiple times does not fire duplicate durationchange 
PASS Test duration reduction below highest buffered presentation time is disallowed 
Harness: the test ran to completion.

I was able to immediately obtain a local repro. I'm not sure why my attempts to discover any remaining flakiness last week missed this -- perhaps the --repeat-each=100 hides some text-only errors? Or maybe something else changed coincidentally in the tree?

Regardless - I'm looking into a fix now.

Probably the reason I missed catching this before was that I was grepping for "FAIL" and "TIMEOUT" a tee'ed verbose-log output from runs under load (which was necessary to stimulate those other flakiness problems I was fixing). With similar rerun even now, no "FAIL" or "TIMEOUT" occurs, but there is 100% text mismatch locally across 100 runs. It's a timing-thing and is flaky, so CQ didn't catch it.

Ah - while definitely flaky on the bots, there was also an expectation change landed yesterday which matches what the bots usually produce. That's why today I'm hitting local failures when last week I wasn't. Regardless, still flaky on at least bots. I'm working on a fix, though I haven't been able to repro it locally yet.

@#14 (The interim change which makes the expectation match some of the bot's output, and fail locally for me was https://chromium-review.googlesource.com/c/593847)

I have a local fix for much of the flakiness, but now I'm seeing 1-5% timeout flakiness (not apparent testharness.js test case TIMEOUT, but actually the layout test runner indicating "failed unexpectedly (test timed out)"). Still investigating further.
I've ruled out potential WMPI suspension (it's not happening).
It doesn't seem specific to any one of the 5 test cases in mediasource-duration, but that's hard to know for sure with low flakiness.

Suspicions:
* limited concurrent network connections from content_shell?
* something racing in the media element/media pipeline?

Verbose logging seems to reduce the flaky rate unfortunately.
But I have a local log now using only a subset of my normal verbose log settings: (./blink/tools/run_layout_tests.sh --debug --no-retry-failures --repeat-each=15 --iterations=10 --exit-after-n-crashes-or-timeouts=1 --driver-logging --additional-drt-flag="--v=3" --additional-drt-flag="--vmodule=MediaSource*=3,HTMLMediaSource*=3,SourceBuffer*=3,HTMLMediaElement*=3,*=0" --additional-drt-flag="--blink-platform-log-channels=Media" http/tests/media/media-source/mediasource-duration.html 2>&1 | tee tmp.log

(This caught a timeout after 93 runs passed).

After splitting apart the 5 parallel test cases' logs from the failed run captured in #16, it looks like it never successfully reached https://cs.chromium.org/chromium/src/third_party/WebKit/LayoutTests/http/tests/media/media-source/mediasource-duration.html?rcl=13073fa28f8b049204eb1d2b4d53c27919ef5234&l=58, though logs show internal 'finishSeek' + timeChanged, but then a 3 second wall-clock lapse followed by changing readyState from HAVE_ENOUGH_DATA to HAVE_CURRENT_DATA (which would happen if the test expectation manager never received the expected events since after the seek was initiated).

I'll continue digging in the morning, but something seems flaky still around the seeking+timeupdate+seeked event expectations.

+Chris and Dan just for their info.

All the other 4 test cases' logs in #17 match expectation. It indeed looks like the seeking+timeupdate+seeked flakiness still exists though.

Fix is in review @ https://chromium-review.googlesource.com/c/620407

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/20c35b30500d0462381b5115fb90e8ffde2fb968

commit 20c35b30500d0462381b5115fb90e8ffde2fb968
Author: Matt Wolenetz <wolenetz@chromium.org>
Date: Fri Sep 08 01:17:06 2017

MSE: Fix more flakiness in http/tests/media/media-source/mediasource-duration.html

Fixing two sources of remaining flakiness are the focus of this change:

1) Since M50, play() has returned a Promise which could be rejected by
   operations that interrupt playback like pause() or load().

   This is a speculative change (since I could not reproduce the
   flakiness locally) that attempts to avoid one possible route for
   uncaught play() Promise rejection exceptions by avoiding ever calling
   play() in the top-suspected test case. (Actually playing is not
   important in that case, so this change should be benign in that
   respect.)

   Also, optimistically removes the associated flakiness expectation
   along with platform expectations which included the
   hopefully-now-prevented uncaught exception.

2) While testing (1) locally, I hit infrequent timeout. After including
   some durationchange count test cleanup, the timeout still occurred
   about 1-5% locally. See  https://crbug.com/754657#c17  for detail.
   Further relaxation of a timeupdate event expectation is now included
   and I no longer see those timeouts locally.

3) durationchange event counting test code is improved.

BUG= 754657 

Change-Id: I958675d12cbfabe2962a66ed7aa5b1fcf7f7d768
Reviewed-on: https://chromium-review.googlesource.com/620407
Reviewed-by: Chrome Cunningham <chcunningham@chromium.org>
Commit-Queue: Matthew Wolenetz <wolenetz@chromium.org>
Cr-Commit-Position: refs/heads/master@{#500464}
[modify] https://crrev.com/20c35b30500d0462381b5115fb90e8ffde2fb968/third_party/WebKit/LayoutTests/TestExpectations
[modify] https://crrev.com/20c35b30500d0462381b5115fb90e8ffde2fb968/third_party/WebKit/LayoutTests/http/tests/media/media-source/mediasource-duration.html
[delete] https://crrev.com/8fd1b3cda0a769d3d2273bd246995c70f90535b0/third_party/WebKit/LayoutTests/platform/linux/http/tests/media/media-source/mediasource-duration-expected.txt
[delete] https://crrev.com/8fd1b3cda0a769d3d2273bd246995c70f90535b0/third_party/WebKit/LayoutTests/platform/linux/virtual/mojo-loading/http/tests/media/media-source/mediasource-duration-expected.txt

#21 should fix this.

Quite clear transition from flakiness->green appears to confirm this is fixed:
https://test-results.appspot.com/dashboards/flakiness_dashboard.html#testType=webkit_layout_tests&tests=http%2Ftests%2Fmedia%2Fmedia-source%2Fmediasource-duration.html%0A