1815057 - Intermittent dom/media/test/test_video_low_power_telemetry.html | single tracking bug

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=404585397&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/feWN_UMLSVKSGwy_ickq5A/runs/0/artifacts/public/logs/live_backing.log

---

[task 2023-02-04T11:52:13.326Z] 11:52:13     INFO - TEST-START | dom/media/test/test_video_low_power_telemetry.html
[task 2023-02-04T11:52:16.647Z] 11:52:16     INFO - GECKO(6946) | [Parent 6946, Main Thread] WARNING: NS_ENSURE_TRUE(she && she->mInfo->mSharedState.Get()) failed: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:1164
[task 2023-02-04T11:52:21.044Z] 11:52:21     INFO - GECKO(6946) | [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2023-02-04T11:52:26.070Z] 11:52:26     INFO - GECKO(6946) | JavaScript error: , line 0: uncaught exception: Object
[task 2023-02-04T11:52:26.885Z] 11:52:26     INFO - GECKO(6946) | [RDD 6955, Unnamed thread 10d969380] WARNING: Not registering callback thread due to refcount logging; it may show up as a leak of the TLS-backed nsThread wrapper if the thread outlives xpcom shutdown.: file /builds/worker/checkouts/gecko/dom/media/CallbackThreadRegistry.cpp:57
[task 2023-02-04T11:55:26.192Z] 11:55:26     INFO - TEST-INFO | started process screencapture
[task 2023-02-04T11:55:26.454Z] 11:55:26     INFO - TEST-INFO | screencapture: exit 0
[task 2023-02-04T11:55:26.454Z] 11:55:26     INFO - Buffered messages logged at 11:52:16
[task 2023-02-04T11:55:26.454Z] 11:55:26     INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2023-02-04T11:55:26.455Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | A valid string reason is expected 
[task 2023-02-04T11:55:26.455Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | Reason cannot be empty 
[task 2023-02-04T11:55:26.455Z] 11:55:26     INFO - Running each video for 260 frames.
[task 2023-02-04T11:55:26.456Z] 11:55:26     INFO - Clearing initial telemetry.
[task 2023-02-04T11:55:26.456Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | Should have enough videos to test. 
[task 2023-02-04T11:55:26.457Z] 11:55:26     INFO - Started Sat Feb 04 2023 11:52:16 GMT+0000 (Greenwich Mean Time) (1675511536.655s)
[task 2023-02-04T11:55:26.457Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | [started seek.ogv-0 t=0.145] Length of array should match number of running tests 
[task 2023-02-04T11:55:26.458Z] 11:55:26     INFO - Starting test 1 video seek.ogv.
[task 2023-02-04T11:55:26.458Z] 11:55:26     INFO - Playing test 1.
[task 2023-02-04T11:55:26.458Z] 11:55:26     INFO - Buffered messages logged at 11:52:26
[task 2023-02-04T11:55:26.459Z] 11:55:26     INFO - Test 1 attempting to retrieve telemetry.
[task 2023-02-04T11:55:26.459Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | Test 1 should have telemetry. 
[task 2023-02-04T11:55:26.459Z] 11:55:26     INFO - Test 1 telemetry values are [2] = 0, [3] = 4, [4] = 0, 
[task 2023-02-04T11:55:26.460Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | Test 1 enum 3 should have at least 1 occurrence; found 4. 
[task 2023-02-04T11:55:26.460Z] 11:55:26     INFO - [finished seek.ogv-0] remaining= 
[task 2023-02-04T11:55:26.461Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | [finished seek.ogv-0 t=9.402] Length of array should match number of running tests 
[task 2023-02-04T11:55:26.461Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | [started gizmo.mp4-1 t=9.403] Length of array should match number of running tests 
[task 2023-02-04T11:55:26.461Z] 11:55:26     INFO - Starting test 2 video gizmo.mp4.
[task 2023-02-04T11:55:26.462Z] 11:55:26     INFO - Attempting to enter fullscreen.
[task 2023-02-04T11:55:26.462Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | Document should permit fullscreen-ing of elements. 
[task 2023-02-04T11:55:26.462Z] 11:55:26     INFO - Buffered messages finished
[task 2023-02-04T11:55:26.463Z] 11:55:26     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_video_low_power_telemetry.html | Test timed out! 
[task 2023-02-04T11:55:26.463Z] 11:55:26     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:404:16
[task 2023-02-04T11:55:26.463Z] 11:55:26     INFO -     onTimeout@dom/media/test/manifest.js:2367:9
[task 2023-02-04T11:55:26.463Z] 11:55:26     INFO - gizmo.mp4-1 timed out!
[task 2023-02-04T11:55:26.466Z] 11:55:26     INFO - {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"PAUSED","channels":1,"containerType":"video/mp4","hasAudio":true,"hasVideo":true,"instance":"10213e900","rate":48000,"reader":{"audioChannels":1,"audioDecoderName":"shutdown","audioFramesDecoded":1,"audioRate":48000,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"audio/mp4a-latm","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"shutdown","videoHardwareAccelerated":true,"videoHeight":320,"videoNumSamplesOutputTotal":1,"videoNumSamplesSkippedTotal":0,"videoRate":30.000150680541992,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"video/avc","videoWidth":560},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"idle","clock":-1,"decodedAudioEndTime":0,"decodedVideoEndTime":0,"duration":5589333,"isPlaying":false,"mediaSink":{"audioSinkWrapper":{"audioEnded":true,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":false,"isStarted":false,"lastGoodPosition":0,"outputRate":0,"playbackComplete":false,"startTime":0,"written":0},"isPlaying":false,"isStarted":false},"decodedStream":{"audioQueueFinished":false,"audioQueueSize":0,"data":{"audioFramesWritten":0,"haveSentFinishAudio":false,"haveSentFinishVideo":false,"instance":"","lastVideoEndTime":0,"lastVideoStartTime":0,"nextAudioTime":0,"streamAudioWritten":0,"streamVideoWritten":0},"instance":"","lastAudio":0,"lastOutputTime":0,"playing":0,"startTime":0},"videoSink":{"endPromiseHolderIsEmpty":true,"finished":false,"hasVideo":false,"isPlaying":false,"isStarted":false,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":0,"playState":1,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":"idle"}}}
[task 2023-02-04T11:55:26.467Z] 11:55:26     INFO - [finished gizmo.mp4-1] remaining= 
[task 2023-02-04T11:55:26.467Z] 11:55:26     INFO - TEST-PASS | dom/media/test/test_video_low_power_telemetry.html | [finished gizmo.mp4-1 t=189.612] Length of array should match number of running tests 
[task 2023-02-04T11:55:26.468Z] 11:55:26     INFO - Finished at Sat Feb 04 2023 11:55:26 GMT+0000 (Greenwich Mean Time) (1675511726.419s)
[task 2023-02-04T11:55:26.468Z] 11:55:26     INFO - Running time: 189.766s
[task 2023-02-04T11:55:26.468Z] 11:55:26     INFO - GECKO(6946) | MEMORY STAT | vsize 6722MB | residentFast 161MB | heapAllocated 19MB
[task 2023-02-04T11:55:26.469Z] 11:55:26     INFO - TEST-OK | dom/media/test/test_video_low_power_telemetry.html | took 193116ms
[task 2023-02-04T11:55:29.623Z] 11:55:29     INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2023-02-04T11:55:29.671Z] 11:55:29     INFO - TEST-START | dom/media/test/test_video_to_canvas.html

Comment 1

[Intermittent Failures Robot]

3 failures in 3606 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• try: 1
• mozilla-central: 1

Platform and build breakdown:

• macosx1015-64-qr: 2
  • debug: 2
• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1815057&startday=2023-01-30&endday=2023-02-05&tree=all

Comment 2

[Natalia Csoregi [:nataliaCs]]

First occurrence so far: range of retriggers and backfills

Comment 3

[Intermittent Failures Robot]

3 failures in 3766 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• autoland: 1

Platform and build breakdown:

• macosx1015-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1815057&startday=2023-02-06&endday=2023-02-12&tree=all

Comment 4

[Intermittent Failures Robot]

5 failures in 3856 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 2
• autoland: 3

Platform and build breakdown:

• macosx1015-64-qr: 4
  • debug: 2
  • opt: 2
• macosx1015-64-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1815057&startday=2023-02-13&endday=2023-02-19&tree=all

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.