Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=403493799&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/anKQfuKYTqO7QqNQvG-BUg/runs/0/artifacts/public/logs/live_backing.log
[task 2023-01-25T12:30:20.015Z] 12:30:20 INFO - TEST-PASS | dom/media/test/test_eme_canvas_blocked.html | [started video-only with 2 keys-1 t=0.008] Length of array should match number of running tests
[task 2023-01-25T12:30:20.015Z] 12:30:20 INFO - [12:30:19.342] vp9 in mp4-0 sourceopen
[task 2023-01-25T12:30:20.015Z] 12:30:20 INFO - [12:30:19.343] vp9 in mp4-0 video: addSourceBuffer(video/mp4; codecs="vp9.0")
[task 2023-01-25T12:30:20.015Z] 12:30:20 INFO - [12:30:19.346] vp9 in mp4-0 video: addNextFragment() fetching next fragment short-vp9-encrypted-video.mp4
[task 2023-01-25T12:30:20.016Z] 12:30:20 INFO - [12:30:19.347] vp9 in mp4-0 audio: addSourceBuffer(audio/mp4; codecs="mp4a.40.2")
[task 2023-01-25T12:30:20.016Z] 12:30:20 INFO - [12:30:19.347] vp9 in mp4-0 audio: addNextFragment() fetching next fragment short-aac-encrypted-audio.mp4
[task 2023-01-25T12:30:20.017Z] 12:30:20 INFO - [12:30:19.367] video-only with 2 keys-1 sourceopen
[task 2023-01-25T12:30:20.017Z] 12:30:20 INFO - [12:30:19.369] video-only with 2 keys-1 video: addSourceBuffer(video/mp4; codecs="avc1.4d4015")
[task 2023-01-25T12:30:20.018Z] 12:30:20 INFO - [12:30:19.385] video-only with 2 keys-1 video: addNextFragment() fetching next fragment bipbop-cenc-videoinit.mp4
[task 2023-01-25T12:30:20.018Z] 12:30:20 INFO - [12:30:19.405] vp9 in mp4-0 video: fetch of short-vp9-encrypted-video.mp4 complete, appending
[task 2023-01-25T12:30:20.019Z] 12:30:20 INFO - [12:30:19.407] vp9 in mp4-0 video: updateend for short-vp9-encrypted-video.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=0-0.416666, audioTracks=-, videoTracks=-}
[task 2023-01-25T12:30:20.019Z] 12:30:20 INFO - [12:30:19.407] vp9 in mp4-0 video: end of track
[task 2023-01-25T12:30:20.019Z] 12:30:20 INFO - [12:30:19.417] video-only with 2 keys-1 video: fetch of bipbop-cenc-videoinit.mp4 complete, appending
[task 2023-01-25T12:30:20.020Z] 12:30:20 INFO - [12:30:19.418] vp9 in mp4-0 audio: fetch of short-aac-encrypted-audio.mp4 complete, appending
[task 2023-01-25T12:30:20.021Z] 12:30:20 INFO - [12:30:19.421] video-only with 2 keys-1 got encrypted(cenc, 0000004470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000027e571d037e571d037e571d037e571d037e571d047e571d047e571d047e571d0400000000) event.
[task 2023-01-25T12:30:20.022Z] 12:30:20 INFO - [12:30:19.423] vp9 in mp4-0 got encrypted(cenc, 0000003470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000012cdb0ed6119853e7850671c3e9906c3c00000000) event.
[task 2023-01-25T12:30:20.023Z] 12:30:20 INFO - [12:30:19.423] vp9 in mp4-0 got encrypted(cenc, 0000003470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000012cdb0ed6119853e7850671c3e9906c3c00000000) event.
[task 2023-01-25T12:30:20.023Z] 12:30:20 INFO - [12:30:19.424] video-only with 2 keys-1 video: updateend for bipbop-cenc-videoinit.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=-, audioTracks=-, videoTracks=-}
[task 2023-01-25T12:30:20.023Z] 12:30:20 INFO - [12:30:19.425] video-only with 2 keys-1 video: addNextFragment() fetching next fragment bipbop-cenc-video1.m4s
[task 2023-01-25T12:30:20.024Z] 12:30:20 INFO - [12:30:19.426] vp9 in mp4-0 audio: updateend for short-aac-encrypted-audio.mp4, SourceBuffer{AppendMode=-, updating=false, buffered=0-0.487619, audioTracks=-, videoTracks=-}
[task 2023-01-25T12:30:20.025Z] 12:30:20 INFO - [12:30:19.427] vp9 in mp4-0 audio: end of track
[task 2023-01-25T12:30:20.025Z] 12:30:20 INFO - [12:30:19.437] vp9 in mp4-0 Tracks loaded, calling MediaSource.endOfStream()
[task 2023-01-25T12:30:20.026Z] 12:30:20 INFO - [12:30:19.461] video-only with 2 keys-1 video: fetch of bipbop-cenc-video1.m4s complete, appending
[task 2023-01-25T12:30:20.027Z] 12:30:20 INFO - [12:30:19.462] video-only with 2 keys-1 video: updateend for bipbop-cenc-video1.m4s, SourceBuffer{AppendMode=-, updating=false, buffered=0-0.801666, audioTracks=-, videoTracks=-}
[task 2023-01-25T12:30:20.028Z] 12:30:20 INFO - [12:30:19.463] video-only with 2 keys-1 video: addNextFragment() fetching next fragment bipbop-cenc-video2.m4s
[task 2023-01-25T12:30:20.029Z] 12:30:20 INFO - [12:30:19.507] video-only with 2 keys-1 video: fetch of bipbop-cenc-video2.m4s complete, appending
[task 2023-01-25T12:30:20.030Z] 12:30:20 INFO - [12:30:19.507] video-only with 2 keys-1 video: updateend for bipbop-cenc-video2.m4s, SourceBuffer{AppendMode=-, updating=false, buffered=0-1.601666, audioTracks=-, videoTracks=-}
[task 2023-01-25T12:30:20.030Z] 12:30:20 INFO - [12:30:19.507] video-only with 2 keys-1 video: end of track
[task 2023-01-25T12:30:20.031Z] 12:30:20 INFO - [12:30:19.508] video-only with 2 keys-1 Tracks loaded, calling MediaSource.endOfStream()
[task 2023-01-25T12:30:20.031Z] 12:30:20 INFO - [12:30:19.511] video-only with 2 keys-1 session[].generateRequest(cenc, 0000004470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000027e571d037e571d037e571d037e571d037e571d047e571d047e571d047e571d0400000000)
[task 2023-01-25T12:30:20.032Z] 12:30:20 INFO - [12:30:19.512] vp9 in mp4-0 session[].generateRequest(cenc, 0000003470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000012cdb0ed6119853e7850671c3e9906c3c00000000)
[task 2023-01-25T12:30:20.033Z] 12:30:20 INFO - [12:30:19.512] vp9 in mp4-0 session[].generateRequest(cenc, 0000003470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000012cdb0ed6119853e7850671c3e9906c3c00000000)
[task 2023-01-25T12:30:20.034Z] 12:30:20 INFO - [12:30:19.515] video-only with 2 keys-1 sending update message to CDM: {"keys":[{"kty":"oct","kid":"flcdA35XHQN-Vx0DflcdAw","k":"flczM35XMzN-VzMzflczMw"},{"kty":"oct","kid":"flcdBH5XHQR-Vx0EflcdBA","k":"fldERH5XRER-V0REfldERA"}],"type":"temporary"}
[task 2023-01-25T12:30:20.034Z] 12:30:20 INFO - [12:30:19.517] vp9 in mp4-0 sending update message to CDM: {"keys":[{"kty":"oct","kid":"LNsO1hGYU-eFBnHD6ZBsPA","k":"gIua2sOE3h5PVhQPStdhlA"}],"type":"temporary"}
[task 2023-01-25T12:30:20.035Z] 12:30:20 INFO - [12:30:19.518] vp9 in mp4-0 sending update message to CDM: {"keys":[{"kty":"oct","kid":"LNsO1hGYU-eFBnHD6ZBsPA","k":"gIua2sOE3h5PVhQPStdhlA"}],"type":"temporary"}
[task 2023-01-25T12:30:20.036Z] 12:30:20 INFO - [12:30:19.519] video-only with 2 keys-1 MediaKeySession update ok!
[task 2023-01-25T12:30:20.037Z] 12:30:20 INFO - [12:30:19.520] vp9 in mp4-0 MediaKeySession update ok!
[task 2023-01-25T12:30:20.038Z] 12:30:20 INFO - [12:30:19.520] vp9 in mp4-0 MediaKeySession update ok!
[task 2023-01-25T12:30:20.039Z] 12:30:20 INFO - Buffered messages finished
[task 2023-01-25T12:30:20.040Z] 12:30:20 ERROR - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | application terminated with exit code 245
[task 2023-01-25T12:30:20.040Z] 12:30:20 INFO - runtests.py | Application ran for: 0:00:06.617938
[task 2023-01-25T12:30:20.041Z] 12:30:20 INFO - zombiecheck | Reading PID log: /tmp/tmpv3lgsuiqpidlog
[task 2023-01-25T12:30:20.042Z] 12:30:20 INFO - ==> process 7438 launched child process 7460
[task 2023-01-25T12:30:20.043Z] 12:30:20 INFO - ==> process 7438 launched child process 7507
[task 2023-01-25T12:30:20.044Z] 12:30:20 INFO - ==> process 7438 launched child process 7536
[task 2023-01-25T12:30:20.044Z] 12:30:20 INFO - ==> process 7438 launched child process 7558
[task 2023-01-25T12:30:20.045Z] 12:30:20 INFO - ==> process 7438 launched child process 7609
[task 2023-01-25T12:30:20.046Z] 12:30:20 INFO - ==> process 7438 launched child process 7655
[task 2023-01-25T12:30:20.046Z] 12:30:20 INFO - ==> process 7438 launched child process 7667
[task 2023-01-25T12:30:20.047Z] 12:30:20 INFO - ==> process 7438 launched child process 7679
[task 2023-01-25T12:30:20.048Z] 12:30:20 INFO - ==> process 7438 launched child process 7683
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7683
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7460
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7558
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7655
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7536
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7507
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7667
[task 2023-01-25T12:30:20.054Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7609
[task 2023-01-25T12:30:20.055Z] 12:30:20 INFO - zombiecheck | Checking for orphan process with PID: 7679
[task 2023-01-25T12:30:20.055Z] 12:30:20 INFO - Stopping web server
[task 2023-01-25T12:30:20.055Z] 12:30:20 INFO - Server shut down.
[task 2023-01-25T12:30:20.068Z] 12:30:20 INFO - Web server killed.
Description
•