Closed Bug 1593308 Opened 5 years ago Closed 5 years ago

Debian 10 - dom/media/test/test_eme_pssh_in_moof.html | Test timed out!

Categories

(Core :: Audio/Video: Playback, defect, P5)

Product:
Core
Component:
Audio/Video: Playback
Type:
defect

Tracking

()

Status:
RESOLVED INVALID

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=273372850&repo=try
Full log: https://queue.taskcluster.net/v1/task/BRpm6_00Q0SbHXPb6H3gjQ/runs/0/artifacts/public/logs/live_backing.log

suite: mochitest-media-1

context

from bug 1387679:
Edwin and I discussed this a bit elsewhere:

It looks like the test is timing out, specifically the first of the two media files (the bear one).
It's not yet clear why. There are ffmpeg warnings in the logs, but I would expect other tests to fail if ffmpeg is not decoding audio properly.
On the images Edwin is testing the failure repros 100% of the time.
    My understanding is that because of this another bug to track the permafail may be created, while this bug is left to track the intermittent issue.

My understanding is that we're going to try testing with different ffmpeg versions to see if that makes a difference -- this may be tracked on the other bug. Please NI me on this or the other bug if you would like me to look further at anything.

[task 2019-10-29T00:09:47.084Z] 00:09:47 INFO - TEST-START | dom/media/test/test_eme_pssh_in_moof.html
[task 2019-10-29T00:09:47.422Z] 00:09:47 INFO - GECKO(5352) | [Child 5406, MediaDecoderStateMachine #1] WARNING: Decoder=7fc568f2f400 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<58>::DoDecode(mozilla::MediaRawData *, uint8_t , int, bool , mozilla::MediaDataDecoder::DecodedData &): FFmpeg audio error:-1094995529: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3308
[task 2019-10-29T00:12:47.150Z] 00:12:47 INFO - TEST-INFO | started process screentopng
[task 2019-10-29T00:12:47.338Z] 00:12:47 INFO - TEST-INFO | screentopng: exit 0
[task 2019-10-29T00:12:47.338Z] 00:12:47 INFO - Buffered messages logged at 00:09:47
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | A valid string reason is expected
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | Reason cannot be empty
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - Started Tue Oct 29 2019 00:09:47 GMT+0000 (Coordinated Universal Time) (1572307787.139s)
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | [started bear-640x360-cenc-key-rotation-0 t=0.004] Length of array should match number of running tests
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | [started bipbop-clearkey-keyrotation-clear-lead-1 t=0.007] Length of array should match number of running tests
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - [00:09:47.200] bear-640x360-cenc-key-rotation-0 sourceopen
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - [00:09:47.201] bear-640x360-cenc-key-rotation-0 video: addSourceBuffer(video/mp4; codecs="avc1.64000d")
[task 2019-10-29T00:12:47.339Z] 00:12:47 INFO - [00:09:47.202] bear-640x360-cenc-key-rotation-0 video: addNextFragment() fetching next fragment bear-640x360-v_frag-cenc-key_rotation.mp4
[task 2019-10-29T00:12:47.342Z] 00:12:47 INFO - [00:09:47.202] bear-640x360-cenc-key-rotation-0 audio: addSourceBuffer(audio/mp4; codecs="mp4a.40.2")
[task 2019-10-29T00:12:47.342Z] 00:12:47 INFO - [00:09:47.202] bear-640x360-cenc-key-rotation-0 audio: addNextFragment() fetching next fragment bear-640x360-a_frag-cenc-key_rotation.mp4
[task 2019-10-29T00:12:47.343Z] 00:12:47 INFO - [00:09:47.203] bipbop-clearkey-keyrotation-clear-lead-1 sourceopen
[task 2019-10-29T00:12:47.343Z] 00:12:47 INFO - [00:09:47.204] bipbop-clearkey-keyrotation-clear-lead-1 video: addSourceBuffer(video/mp4; codecs="avc1.4d4015")
[task 2019-10-29T00:12:47.343Z] 00:12:47 INFO - [00:09:47.204] bipbop-clearkey-keyrotation-clear-lead-1 video: addNextFragment() fetching next fragment bipbop-clearkey-keyrotation-clear-lead-video.mp4
[task 2019-10-29T00:12:47.343Z] 00:12:47 INFO - [00:09:47.206] bipbop-clearkey-keyrotation-clear-lead-1 audio: addSourceBuffer(audio/mp4; codecs="mp4a.40.2")
[task 2019-10-29T00:12:47.344Z] 00:12:47 INFO - [00:09:47.212] bipbop-clearkey-keyrotation-clear-lead-1 audio: addNextFragment() fetching next fragment bipbop-clearkey-keyrotation-clear-lead-audio.mp4
[task 2019-10-29T00:12:47.345Z] 00:12:47 INFO - [00:09:47.318] bipbop-clearkey-keyrotation-clear-lead-1 audio: fetch of bipbop-clearkey-keyrotation-clear-lead-audio.mp4 complete, appending
[task 2019-10-29T00:12:47.348Z] 00:12:47 INFO - [00:09:47.321] bipbop-clearkey-keyrotation-clear-lead-1 audio: updateend for bipbop-clearkey-keyrotation-clear-lead-audio.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=0-10.03102, audioTracks=-, videoTracks=-}
[task 2019-10-29T00:12:47.348Z] 00:12:47 INFO - [00:09:47.322] bipbop-clearkey-keyrotation-clear-lead-1 audio: end of track
[task 2019-10-29T00:12:47.348Z] 00:12:47 INFO - [00:09:47.340] bear-640x360-cenc-key-rotation-0 audio: fetch of bear-640x360-a_frag-cenc-key_rotation.mp4 complete, appending
[task 2019-10-29T00:12:47.349Z] 00:12:47 INFO - [00:09:47.343] bear-640x360-cenc-key-rotation-0 audio: updateend for bear-640x360-a_frag-cenc-key_rotation.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=0-2.80399, audioTracks=-, videoTracks=-}
[task 2019-10-29T00:12:47.349Z] 00:12:47 INFO - [00:09:47.343] bear-640x360-cenc-key-rotation-0 audio: end of track
[task 2019-10-29T00:12:47.349Z] 00:12:47 INFO - [00:09:47.401] bear-640x360-cenc-key-rotation-0 video: fetch of bear-640x360-v_frag-cenc-key_rotation.mp4 complete, appending
[task 2019-10-29T00:12:47.350Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | 'encrypted' event should have 'cenc' initDataType
[task 2019-10-29T00:12:47.357Z] 00:12:47 INFO - [00:09:47.405] bear-640x360-cenc-key-rotation-0 encrypted event => len=850 000000347073736800000000fde979fd4aa3fd27fdfd1d21fd000000140801121030313233343536373839303132333435000002fd7073736800000000fd04fd79fd4042fdfdfdfd5bfdfd5ffd000002fdfd02000001000100fd023c00570052004d00480045004100440045005200200078006d006c006e0073003d00220068007400740070003a002f002f0073006300680065006d00610073002e006d006900630072006f0073006f00660074002e0063006f006d002f00440052004d002f0032003000300037002f00300033002f0050006c00610079005200650061006400790048006500610064006500720022002000760065007200730069006f006e003d00220034002e0030002e0030002e00300022003e003c0044004100540041003e003c00500052004f00540045004300540049004e0046004f003e003c004b00450059004c0045004e003e00310036003c002f004b00450059004c0045004e003e003c0041004c004700490044003e004100450053004300540052003c002f0041004c004700490044003e003c002f00500052004f00540045004300540049004e0046004f003e003c004b00490044003e004d007a00490078004d004400550030004e007a00590034004f005400410078004d006a004d0030004e0051003d003d003c002f004b00490044003e003c0043004800450043004b00530055004d003e0044004d0039004c00590079006d003000470049006f003d003c002f0043004800450043004b00530055004d003e003c004c0041005f00550052004c003e00680074007400700073003a002f002f007700770077002e0079006f00750074007500620065002e0063006f006d002f006100700069002f00640072006d002f0070006c0061007900720065006100640079003f0073006f0075007200630065003d0059004f0055005400550042004500260061006d0070003b0076006900640065006f005f00690064003d00540065007300740056006900640065006f00490064003c002f004c0041005f00550052004c003e003c002f0044004100540041003e003c002f00570052004d004800450041004400450052003e000000003470737368010000001077fdfdfdfd4d02fdfd3c1e52fdfd4b000000013031323334353637383930313233343500000000
[task 2019-10-29T00:12:47.358Z] 00:12:47 INFO - [00:09:47.411] bear-640x360-cenc-key-rotation-0 video: updateend for bear-640x360-v_frag-cenc-key_rotation.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=0.033-2.769066, audioTracks=-, videoTracks=-}
[task 2019-10-29T00:12:47.358Z] 00:12:47 INFO - [00:09:47.411] bear-640x360-cenc-key-rotation-0 video: end of track
[task 2019-10-29T00:12:47.358Z] 00:12:47 INFO - [00:09:47.411] bear-640x360-cenc-key-rotation-0 Tracks loaded, calling MediaSource.endOfStream()
[task 2019-10-29T00:12:47.359Z] 00:12:47 INFO - [00:09:47.416] bipbop-clearkey-keyrotation-clear-lead-1 video: fetch of bipbop-clearkey-keyrotation-clear-lead-video.mp4 complete, appending
[task 2019-10-29T00:12:47.359Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | 'encrypted' event should have 'cenc' initDataType
[task 2019-10-29T00:12:47.359Z] 00:12:47 INFO - [00:09:47.428] bipbop-clearkey-keyrotation-clear-lead-1 encrypted event => len=52 0000003470737368010000001077fdfdfdfd4d02fdfd3c1e52fdfd4b000000010011223344556677fdfdfdfdfdfdfdfd00000000
[task 2019-10-29T00:12:47.359Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | 'encrypted' event should have 'cenc' initDataType
[task 2019-10-29T00:12:47.360Z] 00:12:47 INFO - [00:09:47.429] bipbop-clearkey-keyrotation-clear-lead-1 encrypted event => len=52 0000003470737368010000001077fdfdfdfd4d02fdfd3c1e52fdfd4b0000000111223344556677fdfdfdfdfdfdfdfd0000000000
[task 2019-10-29T00:12:47.360Z] 00:12:47 INFO - [00:09:47.429] bipbop-clearkey-keyrotation-clear-lead-1 video: updateend for bipbop-clearkey-keyrotation-clear-lead-video.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=0.095-9.971677, audioTracks=-, videoTracks=-}
[task 2019-10-29T00:12:47.360Z] 00:12:47 INFO - [00:09:47.430] bipbop-clearkey-keyrotation-clear-lead-1 video: end of track
[task 2019-10-29T00:12:47.361Z] 00:12:47 INFO - [00:09:47.430] bipbop-clearkey-keyrotation-clear-lead-1 Tracks loaded, calling MediaSource.endOfStream()
[task 2019-10-29T00:12:47.361Z] 00:12:47 INFO - Buffered messages logged at 00:09:58
[task 2019-10-29T00:12:47.361Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | Should get one 'encrypted' event per run of contiguous PSSH boxes in media.
[task 2019-10-29T00:12:47.362Z] 00:12:47 INFO - [finished bipbop-clearkey-keyrotation-clear-lead-1] remaining= bear-640x360-cenc-key-rotation-0
[task 2019-10-29T00:12:47.362Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | [finished bipbop-clearkey-keyrotation-clear-lead-1 t=11.143] Length of array should match number of running tests
[task 2019-10-29T00:12:47.362Z] 00:12:47 INFO - Buffered messages finished
[task 2019-10-29T00:12:47.364Z] 00:12:47 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_pssh_in_moof.html | Test timed out!
[task 2019-10-29T00:12:47.364Z] 00:12:47 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:277:18
[task 2019-10-29T00:12:47.364Z] 00:12:47 INFO - onTimeout@https://example.com/tests/dom/media/test/manifest.js:2086:9
[task 2019-10-29T00:12:47.364Z] 00:12:47 INFO - setTimeout handlerMediaTestManager/this.started@https://example.com/tests/dom/media/test/manifest.js:2093:57
[task 2019-10-29T00:12:47.364Z] 00:12:47 INFO - startTest@https://example.com/tests/dom/media/test/test_eme_pssh_in_moof.html:84:15
[task 2019-10-29T00:12:47.365Z] 00:12:47 INFO - MediaTestManager/this.nextTest@https://example.com/tests/dom/media/test/manifest.js:2167:12
[task 2019-10-29T00:12:47.365Z] 00:12:47 INFO - MediaTestManager/this.runTests/<@https://example.com/tests/dom/media/test/manifest.js:2062:12
[task 2019-10-29T00:12:47.365Z] 00:12:47 INFO - AsyncMediaTestManager/this.runTests@https://example.com/tests/dom/media/test/manifest.js:2061:19
[task 2019-10-29T00:12:47.365Z] 00:12:47 INFO - @https://example.com/tests/dom/media/test/test_eme_pssh_in_moof.html:137:13
[task 2019-10-29T00:12:47.365Z] 00:12:47 INFO - bear-640x360-cenc-key-rotation-0 timed out!
[task 2019-10-29T00:12:47.366Z] 00:12:47 INFO - [finished bear-640x360-cenc-key-rotation-0] remaining=
[task 2019-10-29T00:12:47.367Z] 00:12:47 INFO - TEST-PASS | dom/media/test/test_eme_pssh_in_moof.html | [finished bear-640x360-cenc-key-rotation-0 t=180.006] Length of array should match number of running tests
[task 2019-10-29T00:12:47.367Z] 00:12:47 INFO - Finished at Tue Oct 29 2019 00:12:47 GMT+0000 (Coordinated Universal Time) (1572307967.217s)
[task 2019-10-29T00:12:47.368Z] 00:12:47 INFO - Running time: 180.079s
[task 2019-10-29T00:12:47.368Z] 00:12:47 INFO - GECKO(5352) | MEMORY STAT | vsize 2536MB | residentFast 177MB | heapAllocated 20MB
[task 2019-10-29T00:12:47.368Z] 00:12:47 INFO - TEST-OK | dom/media/test/test_eme_pssh_in_moof.html | took 180143ms

It was agreed in bug 1387679 that I will try different versions of ffmpeg to investigate this issue.

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=b61f4ba8b3f6a618cb2099ebe033ce1f4101c3ad

In the above try push I installed two new packages:

+apt_packages+=('libavcodec58')
+apt_packages+=('ffmpeg')

But this does not appear to have resolved the issue.

The last try push I did on this issue so far made the following changes:

  • install libavcodec58
  • install ffmpeg
  • install gstreamer1.0 in place of gstreamer0.10

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=a0e38970705b48296fda9ca82e885e5470b2e583

This test continues to fail despite those attempts.

I attempted to install all of the ffmpeg packages when setting up the docker image, but this approach also failed:

Push:
https://hg.mozilla.org/try/rev/3fb73a37b99ad504ab098b48da7b0ace436aa623

[task 2019-11-01T21:05:16.456Z] 
[task 2019-11-01T21:05:16.456Z] apt-get install -y -f -q        \
[task 2019-11-01T21:05:16.456Z]     libav*
[task 2019-11-01T21:05:18.059Z] Reading package lists...
[task 2019-11-01T21:05:18.460Z] Building dependency tree...
[task 2019-11-01T21:05:18.461Z] Reading state information...
[task 2019-11-01T21:05:18.648Z] libavahi-client3 is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-client3 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavahi-common-data is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-common-data set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavahi-common3 is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-common3 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavahi-core7 is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-core7 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavahi-glib1 is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-glib1 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavahi-gobject0 is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-gobject0 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavahi-ui-gtk3-0 is already the newest version (0.7-4+b1).
[task 2019-11-01T21:05:18.648Z] libavahi-ui-gtk3-0 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavcodec58 is already the newest version (7:4.1.4-1~deb10u1).
[task 2019-11-01T21:05:18.648Z] libavdevice58 is already the newest version (7:4.1.4-1~deb10u1).
[task 2019-11-01T21:05:18.648Z] libavdevice58 set to manually installed.
[task 2019-11-01T21:05:18.648Z] libavfilter7 is already the newest version (7:4.1.4-1~deb10u1).
[task 2019-11-01T21:05:18.648Z] libavfilter7 set to manually installed.
[task 2019-11-01T21:05:18.649Z] libavformat58 is already the newest version (7:4.1.4-1~deb10u1).
[task 2019-11-01T21:05:18.649Z] libavformat58 set to manually installed.
[task 2019-11-01T21:05:18.649Z] libavresample4 is already the newest version (7:4.1.4-1~deb10u1).
[task 2019-11-01T21:05:18.649Z] libavresample4 set to manually installed.
[task 2019-11-01T21:05:18.649Z] libavutil56 is already the newest version (7:4.1.4-1~deb10u1).
[task 2019-11-01T21:05:18.649Z] libavutil56 set to manually installed.
[task 2019-11-01T21:05:18.649Z] libavc1394-0 is already the newest version (0.5.4-5).
[task 2019-11-01T21:05:18.649Z] libavc1394-0 set to manually installed.
[task 2019-11-01T21:05:18.649Z] Some packages could not be installed. This may mean that you have
[task 2019-11-01T21:05:18.649Z] requested an impossible situation or if you are using the unstable
[task 2019-11-01T21:05:18.649Z] distribution that some required packages have not yet been created
[task 2019-11-01T21:05:18.649Z] or been moved out of Incoming.
[task 2019-11-01T21:05:18.649Z] The following information may help to resolve the situation:
[task 2019-11-01T21:05:18.649Z] 
[task 2019-11-01T21:05:18.649Z] The following packages have unmet dependencies:
[task 2019-11-01T21:05:18.720Z]  libavahi-ui-gtk3-dev : Conflicts: libavahi-ui-dev but 0.6.31-5 is to be installed
[task 2019-11-01T21:05:18.721Z]  libavahi-ui0.0-cil : Depends: libmono-corlib4.0-cil (>= 2.10.1) but it is not going to be installed
[task 2019-11-01T21:05:18.721Z]  libavahi1.0-cil : Depends: libmono-corlib4.0-cil (>= 2.10.1) but it is not going to be installed
[task 2019-11-01T21:05:18.721Z]  libavcodec-extra-56 : Conflicts: libavcodec56 but 6:11.12-1~deb8u1 is to be installed
[task 2019-11-01T21:05:18.721Z]  libavcodec-extra58 : Conflicts: libavcodec58
[task 2019-11-01T21:05:18.721Z]  libavcodec56 : Conflicts: libavcodec-extra-56 but 6:11.12-1~deb8u1 is to be installed
[task 2019-11-01T21:05:18.721Z]  libavfilter-extra7 : Conflicts: libavfilter7
[task 2019-11-01T21:05:18.749Z] E: Unable to correct problems, you have held broken packages.
[task 2019-11-01T21:05:19.633Z] The command [/bin/sh -c bash /setup/system-setup.sh] returned a non-zero code: 100
kill 9
+ kill 9
[taskcluster 2019-11-01 21:05:20.138Z] === Task Finished ===
[taskcluster 2019-11-01 21:05:20.252Z] Artifact "public/image.tar.zst" not found at "/builds/worker/workspace/artifacts/image.tar.zst"
[taskcluster 2019-11-01 21:05:20.572Z] Unsuccessful task run with exit code: 100 completed in 450.51 seconds

I suppose I can try falling back to libavcodec-56 since that is the version I believe is being used by Ubuntu 16.04 test image, but that seems like a temporary kludge to avoid the inevitable.

I am closing this issue since I have decided to place my efforts to upgrade the linux in CI to use ubunt1804, which has much better continuity for our test suites than debian10.

With ubuntu1804, this is no longer an issue.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.