Closed
Bug 1503756
Opened 6 years ago
Closed 6 years ago
Perma Linux mda webrtc failures with "NotFoundError: The object can not be found here." after Ubuntu 16.04 docker image upgrade
Categories
(Firefox Build System :: Task Configuration, task, P1)
Firefox Build System
Task Configuration
Tracking
(firefox-esr60 fixed, firefox65 fixed)
RESOLVED
FIXED
mozilla65
People
(Reporter: stefan_hindli, Assigned: gps)
References
Details
Attachments
(2 files, 1 obsolete file)
https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=6fc2aad03a346ba27b63dff77e59e139a58889fc&selectedJob=209013255 https://treeherder.mozilla.org/logviewer.html#?job_id=209013255&repo=autoland&lineNumber=2430 [task 2018-10-31T22:58:31.167Z] 22:58:31 INFO - TEST-START | dom/media/test/test_mediarecorder_avoid_recursion.html [task 2018-10-31T22:58:31.406Z] 22:58:31 INFO - TEST-INFO | started process screentopng [task 2018-10-31T22:58:31.958Z] 22:58:31 INFO - TEST-INFO | screentopng: exit 0 [task 2018-10-31T22:58:31.961Z] 22:58:31 INFO - Buffered messages logged at 22:58:31 [task 2018-10-31T22:58:31.963Z] 22:58:31 INFO - TEST-PASS | dom/media/test/test_mediarecorder_avoid_recursion.html | A valid string reason is expected [task 2018-10-31T22:58:31.966Z] 22:58:31 INFO - TEST-PASS | dom/media/test/test_mediarecorder_avoid_recursion.html | Reason cannot be empty [task 2018-10-31T22:58:31.968Z] 22:58:31 INFO - Buffered messages finished [task 2018-10-31T22:58:31.970Z] 22:58:31 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_avoid_recursion.html | Unexpected error fired with: NotFoundError: The object can not be found here. [task 2018-10-31T22:58:31.972Z] 22:58:31 INFO - startTest@dom/media/test/test_mediarecorder_avoid_recursion.html:49:5 [task 2018-10-31T22:58:31.973Z] 22:58:31 INFO - async*@dom/media/test/test_mediarecorder_avoid_recursion.html:55:1 [task 2018-10-31T22:58:31.975Z] 22:58:31 INFO - GECKO(1457) | MEMORY STAT | vsize 20973659MB | residentFast 910MB [task 2018-10-31T22:58:31.977Z] 22:58:31 INFO - TEST-OK | dom/media/test/test_mediarecorder_avoid_recursion.html | took 281ms [task 2018-10-31T22:58:31.979Z] 22:58:31 INFO - TEST-START | dom/media/test/test_mediarecorder_bitrate.html [task 2018-10-31T22:58:32.463Z] 22:58:32 INFO - GECKO(1457) | MEMORY STAT | vsize 20973709MB | residentFast 919MB [task 2018-10-31T22:58:32.480Z] 22:58:32 INFO - TEST-OK | dom/media/test/test_mediarecorder_bitrate.html | took 953ms [task 2018-10-31T22:58:32.562Z] 22:58:32 INFO - TEST-START | dom/media/test/test_mediarecorder_creation.html [task 2018-10-31T22:58:32.976Z] 22:58:32 INFO - GECKO(1457) | MEMORY STAT | vsize 20973687MB | residentFast 923MB [task 2018-10-31T22:58:33.017Z] 22:58:33 INFO - TEST-OK | dom/media/test/test_mediarecorder_creation.html | took 458ms [task 2018-10-31T22:58:33.086Z] 22:58:33 INFO - TEST-START | dom/media/test/test_mediarecorder_creation_fail.html [task 2018-10-31T22:58:33.331Z] 22:58:33 INFO - GECKO(1457) | MEMORY STAT | vsize 20973708MB | residentFast 927MB [task 2018-10-31T22:58:33.353Z] 22:58:33 INFO - TEST-OK | dom/media/test/test_mediarecorder_creation_fail.html | took 270ms [task 2018-10-31T22:58:33.414Z] 22:58:33 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:33.435Z] 22:58:33 INFO - TEST-START | dom/media/test/test_mediarecorder_fires_start_event_once_when_erroring.html [task 2018-10-31T22:58:35.526Z] 22:58:35 INFO - GECKO(1457) | MEMORY STAT | vsize 20973719MB | residentFast 929MB [task 2018-10-31T22:58:35.547Z] 22:58:35 INFO - TEST-OK | dom/media/test/test_mediarecorder_fires_start_event_once_when_erroring.html | took 2111ms [task 2018-10-31T22:58:35.606Z] 22:58:35 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:35.622Z] 22:58:35 INFO - TEST-START | dom/media/test/test_mediarecorder_getencodeddata.html [task 2018-10-31T22:58:35.943Z] 22:58:35 INFO - GECKO(1457) | MEMORY STAT | vsize 20973722MB | residentFast 932MB [task 2018-10-31T22:58:35.964Z] 22:58:35 INFO - TEST-OK | dom/media/test/test_mediarecorder_getencodeddata.html | took 344ms [task 2018-10-31T22:58:36.027Z] 22:58:36 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:36.049Z] 22:58:36 INFO - TEST-START | dom/media/test/test_mediarecorder_pause_resume_video.html [task 2018-10-31T22:58:40.428Z] 22:58:40 INFO - GECKO(1457) | MEMORY STAT | vsize 20973715MB | residentFast 917MB [task 2018-10-31T22:58:40.449Z] 22:58:40 INFO - TEST-OK | dom/media/test/test_mediarecorder_pause_resume_video.html | took 4398ms [task 2018-10-31T22:58:40.518Z] 22:58:40 INFO - TEST-START | dom/media/test/test_mediarecorder_playback_can_repeat.html [task 2018-10-31T22:58:42.766Z] 22:58:42 INFO - GECKO(1457) | MEMORY STAT | vsize 20973717MB | residentFast 920MB [task 2018-10-31T22:58:42.787Z] 22:58:42 INFO - TEST-OK | dom/media/test/test_mediarecorder_playback_can_repeat.html | took 2266ms [task 2018-10-31T22:58:42.850Z] 22:58:42 INFO - TEST-START | dom/media/test/test_mediarecorder_principals.html [task 2018-10-31T22:58:44.022Z] 22:58:44 INFO - GECKO(1457) | MEMORY STAT | vsize 20973736MB | residentFast 926MB [task 2018-10-31T22:58:44.060Z] 22:58:44 INFO - TEST-OK | dom/media/test/test_mediarecorder_principals.html | took 1206ms [task 2018-10-31T22:58:44.126Z] 22:58:44 INFO - TEST-START | dom/media/test/test_mediarecorder_record_4ch_audiocontext.html [task 2018-10-31T22:58:46.655Z] 22:58:46 INFO - GECKO(1457) | MEMORY STAT | vsize 20973740MB | residentFast 931MB [task 2018-10-31T22:58:46.673Z] 22:58:46 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_4ch_audiocontext.html | took 2536ms [task 2018-10-31T22:58:46.721Z] 22:58:46 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:46.742Z] 22:58:46 INFO - TEST-START | dom/media/test/test_mediarecorder_record_addtracked_stream.html [task 2018-10-31T22:58:47.027Z] 22:58:47 INFO - GECKO(1457) | TEST DEVICES: Got loopback audio: Monitor of Null Output [task 2018-10-31T22:58:47.029Z] 22:58:47 INFO - GECKO(1457) | TEST DEVICES: Got loopback video: Dummy video device (0x0000) [task 2018-10-31T22:58:52.694Z] 22:58:52 INFO - GECKO(1457) | MEMORY STAT | vsize 20973702MB | residentFast 906MB [task 2018-10-31T22:58:52.751Z] 22:58:52 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_addtracked_stream.html | took 5996ms [task 2018-10-31T22:58:52.789Z] 22:58:52 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:52.817Z] 22:58:52 INFO - TEST-START | dom/media/test/test_mediarecorder_record_audiocontext.html [task 2018-10-31T22:58:54.062Z] 22:58:54 INFO - GECKO(1457) | MEMORY STAT | vsize 20973698MB | residentFast 907MB [task 2018-10-31T22:58:54.080Z] 22:58:54 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_audiocontext.html | took 1257ms [task 2018-10-31T22:58:54.137Z] 22:58:54 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:54.159Z] 22:58:54 INFO - TEST-START | dom/media/test/test_mediarecorder_record_audiocontext_mlk.html [task 2018-10-31T22:58:54.318Z] 22:58:54 INFO - GECKO(1457) | MEMORY STAT | vsize 20973701MB | residentFast 909MB [task 2018-10-31T22:58:54.340Z] 22:58:54 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_audiocontext_mlk.html | took 181ms [task 2018-10-31T22:58:54.417Z] 22:58:54 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:54.436Z] 22:58:54 INFO - TEST-START | dom/media/test/test_mediarecorder_record_audionode.html [task 2018-10-31T22:58:55.895Z] 22:58:55 INFO - GECKO(1457) | MEMORY STAT | vsize 20973709MB | residentFast 910MB [task 2018-10-31T22:58:55.916Z] 22:58:55 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_audionode.html | took 1490ms [task 2018-10-31T22:58:55.978Z] 22:58:55 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:55.980Z] 22:58:55 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:55.981Z] 22:58:55 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:58:56.003Z] 22:58:56 INFO - TEST-START | dom/media/test/test_mediarecorder_record_canvas_captureStream.html [task 2018-10-31T22:58:57.269Z] 22:58:57 INFO - GECKO(1457) | MEMORY STAT | vsize 20973727MB | residentFast 913MB [task 2018-10-31T22:58:57.286Z] 22:58:57 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_canvas_captureStream.html | took 1279ms [task 2018-10-31T22:58:57.368Z] 22:58:57 INFO - TEST-START | dom/media/test/test_mediarecorder_record_changing_video_resolution.html [task 2018-10-31T22:58:58.081Z] 22:58:58 INFO - GECKO(1457) | MEMORY STAT | vsize 20973746MB | residentFast 921MB [task 2018-10-31T22:58:58.102Z] 22:58:58 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_changing_video_resolution.html | took 735ms [task 2018-10-31T22:58:58.179Z] 22:58:58 INFO - TEST-START | dom/media/test/test_mediarecorder_record_downsize_resolution.html [task 2018-10-31T22:58:58.755Z] 22:58:58 INFO - GECKO(1457) | MEMORY STAT | vsize 20973743MB | residentFast 920MB [task 2018-10-31T22:58:58.772Z] 22:58:58 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_downsize_resolution.html | took 601ms [task 2018-10-31T22:58:58.855Z] 22:58:58 INFO - TEST-START | dom/media/test/test_mediarecorder_record_getdata_afterstart.html [task 2018-10-31T22:58:59.200Z] 22:58:59 INFO - GECKO(1457) | MEMORY STAT | vsize 20973764MB | residentFast 924MB [task 2018-10-31T22:58:59.221Z] 22:58:59 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | took 362ms [task 2018-10-31T22:58:59.319Z] 22:58:59 INFO - TEST-START | dom/media/test/test_mediarecorder_record_gum_video_timeslice.html [task 2018-10-31T22:58:59.509Z] 22:58:59 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-10-31T22:58:59.510Z] 22:58:59 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_record_gum_video_timeslice.html | Unexpected error fired with: NotFoundError: The object can not be found here. [task 2018-10-31T22:58:59.510Z] 22:58:59 INFO - startTest@dom/media/test/test_mediarecorder_record_gum_video_timeslice.html:80:5 [task 2018-10-31T22:58:59.511Z] 22:58:59 INFO - async*@dom/media/test/test_mediarecorder_record_gum_video_timeslice.html:86:1 [task 2018-10-31T22:58:59.527Z] 22:58:59 INFO - GECKO(1457) | MEMORY STAT | vsize 20973765MB | residentFast 928MB [task 2018-10-31T22:58:59.546Z] 22:58:59 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_gum_video_timeslice.html | took 221ms [task 2018-10-31T22:58:59.604Z] 22:58:59 INFO - TEST-START | dom/media/test/test_mediarecorder_record_immediate_stop.html [task 2018-10-31T22:59:00.121Z] 22:59:00 INFO - GECKO(1457) | MEMORY STAT | vsize 20973782MB | residentFast 931MB [task 2018-10-31T22:59:00.157Z] 22:59:00 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_immediate_stop.html | took 555ms [task 2018-10-31T22:59:00.308Z] 22:59:00 INFO - TEST-START | dom/media/test/test_mediarecorder_record_no_timeslice.html [task 2018-10-31T22:59:01.287Z] 22:59:01 INFO - GECKO(1457) | MEMORY STAT | vsize 20973754MB | residentFast 937MB [task 2018-10-31T22:59:01.308Z] 22:59:01 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_no_timeslice.html | took 997ms [task 2018-10-31T22:59:01.472Z] 22:59:01 INFO - TEST-START | dom/media/test/test_mediarecorder_record_session.html [task 2018-10-31T22:59:01.834Z] 22:59:01 INFO - GECKO(1457) | MEMORY STAT | vsize 20973713MB | residentFast 928MB [task 2018-10-31T22:59:01.851Z] 22:59:01 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_session.html | took 385ms [task 2018-10-31T22:59:01.914Z] 22:59:01 INFO - TEST-START | dom/media/test/test_mediarecorder_record_startstopstart.html [task 2018-10-31T22:59:03.654Z] 22:59:03 INFO - GECKO(1457) | MEMORY STAT | vsize 20973716MB | residentFast 930MB [task 2018-10-31T22:59:03.674Z] 22:59:03 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_startstopstart.html | took 1752ms [task 2018-10-31T22:59:03.732Z] 22:59:03 INFO - GECKO(1457) | JavaScript error: , line 0: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable [task 2018-10-31T22:59:03.749Z] 22:59:03 INFO - TEST-START | dom/media/test/test_mediarecorder_record_timeslice.html [task 2018-10-31T22:59:04.220Z] 22:59:04 INFO - GECKO(1457) | MEMORY STAT | vsize 20973720MB | residentFast 908MB [task 2018-10-31T22:59:04.297Z] 22:59:04 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_timeslice.html | took 549ms [task 2018-10-31T22:59:04.367Z] 22:59:04 INFO - TEST-START | dom/media/test/test_mediarecorder_record_upsize_resolution.html [task 2018-10-31T22:59:04.961Z] 22:59:04 INFO - GECKO(1457) | MEMORY STAT | vsize 20973692MB | residentFast 912MB [task 2018-10-31T22:59:04.977Z] 22:59:04 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_upsize_resolution.html | took 612ms [task 2018-10-31T22:59:05.041Z] 22:59:05 INFO - TEST-START | dom/media/test/test_mediarecorder_reload_crash.html [task 2018-10-31T22:59:05.634Z] 22:59:05 INFO - GECKO(1457) | MEMORY STAT | vsize 20973723MB | residentFast 908MB [task 2018-10-31T22:59:05.651Z] 22:59:05 INFO - TEST-OK | dom/media/test/test_mediarecorder_reload_crash.html | took 606ms [task 2018-10-31T22:59:05.719Z] 22:59:05 INFO - TEST-START | dom/media/test/test_mediarecorder_unsupported_src.html [task 2018-10-31T22:59:06.007Z] 22:59:06 INFO - GECKO(1457) | MEMORY STAT | vsize 20973726MB | residentFast 912MB [task 2018-10-31T22:59:06.172Z] 22:59:06 INFO - TEST-OK | dom/media/test/test_mediarecorder_unsupported_src.html | took 452ms [task 2018-10-31T22:59:06.261Z] 22:59:06 INFO - TEST-START | dom/media/test/test_mediarecorder_webm_support.html [task 2018-10-31T22:59:06.424Z] 22:59:06 INFO - GECKO(1457) | MEMORY STAT | vsize 20973727MB | residentFast 913MB [task 2018-10-31T22:59:06.441Z] 22:59:06 INFO - TEST-OK | dom/media/test/test_mediarecorder_webm_support.html | took 176ms [task 2018-10-31T22:59:06.503Z] 22:59:06 INFO - TEST-START | dom/media/test/test_mediatrack_consuming_mediaresource.html [task 2018-10-31T22:59:16.417Z] 22:59:16 INFO - GECKO(1457) | MEMORY STAT | vsize 20973729MB | residentFast 921MB [task 2018-10-31T22:59:16.466Z] 22:59:16 INFO - TEST-OK | dom/media/test/test_mediatrack_consuming_mediaresource.html | took 9957ms [task 2018-10-31T22:59:16.556Z] 22:59:16 INFO - TEST-START | dom/media/test/test_mediatrack_consuming_mediastream.html [task 2018-10-31T22:59:16.815Z] 22:59:16 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-10-31T22:59:16.818Z] 22:59:16 INFO - Buffered messages logged at 22:59:16 [task 2018-10-31T22:59:16.819Z] 22:59:16 INFO - TEST-PASS | dom/media/test/test_mediatrack_consuming_mediastream.html | A valid string reason is expected [task 2018-10-31T22:59:16.820Z] 22:59:16 INFO - TEST-PASS | dom/media/test/test_mediatrack_consuming_mediastream.html | Reason cannot be empty [task 2018-10-31T22:59:16.820Z] 22:59:16 INFO - Buffered messages finished [task 2018-10-31T22:59:16.821Z] 22:59:16 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediatrack_consuming_mediastream.html | Unexpected error fired with: NotFoundError: The object can not be found here. [task 2018-10-31T22:59:16.821Z] 22:59:16 INFO - startTest@dom/media/test/test_mediatrack_consuming_mediastream.html:28:5 [task 2018-10-31T22:59:16.821Z] 22:59:16 INFO - GECKO(1457) | MEMORY STAT | vsize 20973691MB | residentFast 907MB [task 2018-10-31T22:59:16.855Z] 22:59:16 INFO - TEST-OK | dom/media/test/test_mediatrack_consuming_mediastream.html | took 291ms [task 2018-10-31T22:59:16.922Z] 22:59:16 INFO - TEST-START | dom/media/test/test_mediatrack_events.html [task 2018-10-31T22:59:17.161Z] 22:59:17 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-10-31T22:59:17.163Z] 22:59:17 INFO - Buffered messages logged at 22:59:17 [task 2018-10-31T22:59:17.164Z] 22:59:17 INFO - TEST-PASS | dom/media/test/test_mediatrack_events.html | A valid string reason is expected [task 2018-10-31T22:59:17.165Z] 22:59:17 INFO - TEST-PASS | dom/media/test/test_mediatrack_events.html | Reason cannot be empty [task 2018-10-31T22:59:17.166Z] 22:59:17 INFO - Buffered messages finished [task 2018-10-31T22:59:17.168Z] 22:59:17 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediatrack_events.html | Unexpected error fired with: NotFoundError: The object can not be found here. [task 2018-10-31T22:59:17.169Z] 22:59:17 INFO - startTest@dom/media/test/test_mediatrack_events.html:21:5 [task 2018-10-31T22:59:17.170Z] 22:59:17 INFO - GECKO(1457) | MEMORY STAT | vsize 20973693MB | residentFast 910MB [task 2018-10-31T22:59:17.192Z] 22:59:17 INFO - TEST-OK | dom/media/test/test_mediatrack_events.html | took 272ms [task 2018-10-31T22:59:17.255Z] 22:59:17 INFO - TEST-START | dom/media/test/test_mediatrack_parsing_ogg.html [task 2018-10-31T22:59:18.220Z] 22:59:18 INFO - GECKO(1457) | MEMORY STAT | vsize 20973695MB | residentFast 916MB [task 2018-10-31T22:59:18.245Z] 22:59:18 INFO - TEST-OK | dom/media/test/test_mediatrack_parsing_ogg.html | took 989ms [task 2018-10-31T22:59:18.328Z] 22:59:18 INFO - TEST-START | dom/media/test/test_mediatrack_replay_from_end.html [task 2018-10-31T22:59:28.489Z] 22:59:28 INFO - GECKO(1457) | MEMORY STAT | vsize 20973717MB | residentFast 932MB [task 2018-10-31T22:59:28.546Z] 22:59:28 INFO - TEST-OK | dom/media/test/test_mediatrack_replay_from_end.html | took 10213ms [task 2018-10-31T22:59:28.611Z] 22:59:28 INFO - TEST-START | dom/media/test/test_metadata.html [task 2018-10-31T22:59:31.236Z] 22:59:31 INFO - GECKO(1457) | MEMORY STAT | vsize 20973698MB | residentFast 919MB [task 2018-10-31T22:59:31.265Z] 22:59:31 INFO - TEST-OK | dom/media/test/test_metadata.html | took 2653ms [task 2018-10-31T22:59:31.350Z] 22:59:31 INFO - TEST-START | dom/media/test/test_midflight_redirect_blocked.html [task 2018-10-31T22:59:33.974Z] 22:59:33 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=616000193e80 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T22:59:33.974Z] 22:59:33 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=616000193e80 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T22:59:35.734Z] 22:59:35 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=61600040a180 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T22:59:35.737Z] 22:59:35 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=61600040a180 Decode error: NS_ERROR_DOM_MEDIA_DEMUXER_ERR (0x806e000c): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T22:59:38.198Z] 22:59:38 INFO - GECKO(1457) | MEMORY STAT | vsize 20973688MB | residentFast 921MB [task 2018-10-31T22:59:38.241Z] 22:59:38 INFO - TEST-OK | dom/media/test/test_midflight_redirect_blocked.html | took 6892ms [task 2018-10-31T22:59:38.365Z] 22:59:38 INFO - TEST-START | dom/media/test/test_mixed_principals.html [task 2018-10-31T22:59:39.686Z] 22:59:39 INFO - GECKO(1457) | MEMORY STAT | vsize 20973711MB | residentFast 931MB [task 2018-10-31T22:59:39.723Z] 22:59:39 INFO - TEST-OK | dom/media/test/test_mixed_principals.html | took 1357ms [task 2018-10-31T22:59:39.821Z] 22:59:39 INFO - TEST-START | dom/media/test/test_mozHasAudio.html [task 2018-10-31T22:59:41.184Z] 22:59:41 INFO - GECKO(1457) | MEMORY STAT | vsize 20973712MB | residentFast 938MB [task 2018-10-31T22:59:41.221Z] 22:59:41 INFO - TEST-OK | dom/media/test/test_mozHasAudio.html | took 1400ms [task 2018-10-31T22:59:41.324Z] 22:59:41 INFO - TEST-START | dom/media/test/test_multiple_mediastreamtracks.html [task 2018-10-31T22:59:41.565Z] 22:59:41 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-10-31T22:59:41.565Z] 22:59:41 INFO - Buffered messages logged at 22:59:41 [task 2018-10-31T22:59:41.565Z] 22:59:41 INFO - TEST-PASS | dom/media/test/test_multiple_mediastreamtracks.html | A valid string reason is expected [task 2018-10-31T22:59:41.565Z] 22:59:41 INFO - TEST-PASS | dom/media/test/test_multiple_mediastreamtracks.html | Reason cannot be empty [task 2018-10-31T22:59:41.567Z] 22:59:41 INFO - Buffered messages finished [task 2018-10-31T22:59:41.568Z] 22:59:41 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_multiple_mediastreamtracks.html | Unexpected error fired with: NotFoundError: The object can not be found here. [task 2018-10-31T22:59:41.569Z] 22:59:41 INFO - startTest@dom/media/test/test_multiple_mediastreamtracks.html:31:5 [task 2018-10-31T22:59:41.570Z] 22:59:41 INFO - GECKO(1457) | MEMORY STAT | vsize 20973713MB | residentFast 939MB [task 2018-10-31T22:59:41.591Z] 22:59:41 INFO - TEST-OK | dom/media/test/test_multiple_mediastreamtracks.html | took 268ms [task 2018-10-31T22:59:41.669Z] 22:59:41 INFO - TEST-START | dom/media/test/test_networkState.html [task 2018-10-31T22:59:41.883Z] 22:59:41 INFO - GECKO(1457) | MEMORY STAT | vsize 20973710MB | residentFast 935MB [task 2018-10-31T22:59:41.904Z] 22:59:41 INFO - TEST-OK | dom/media/test/test_networkState.html | took 230ms [task 2018-10-31T22:59:42.090Z] 22:59:42 INFO - TEST-START | dom/media/test/test_new_audio.html [task 2018-10-31T22:59:49.401Z] 22:59:49 INFO - GECKO(1457) | MEMORY STAT | vsize 20973717MB | residentFast 943MB [task 2018-10-31T22:59:49.458Z] 22:59:49 INFO - TEST-OK | dom/media/test/test_new_audio.html | took 7361ms [task 2018-10-31T22:59:49.519Z] 22:59:49 INFO - TEST-START | dom/media/test/test_no_load_event.html [task 2018-10-31T22:59:50.052Z] 22:59:50 INFO - GECKO(1457) | MEMORY STAT | vsize 20973693MB | residentFast 924MB [task 2018-10-31T22:59:50.069Z] 22:59:50 INFO - TEST-OK | dom/media/test/test_no_load_event.html | took 552ms [task 2018-10-31T22:59:50.140Z] 22:59:50 INFO - TEST-START | dom/media/test/test_paused.html [task 2018-10-31T22:59:50.382Z] 22:59:50 INFO - GECKO(1457) | MEMORY STAT | vsize 20973697MB | residentFast 930MB [task 2018-10-31T22:59:50.425Z] 22:59:50 INFO - TEST-OK | dom/media/test/test_paused.html | took 287ms [task 2018-10-31T22:59:50.494Z] 22:59:50 INFO - TEST-START | dom/media/test/test_paused_after_ended.html [task 2018-10-31T23:00:01.728Z] 23:00:01 INFO - GECKO(1457) | MEMORY STAT | vsize 20973698MB | residentFast 928MB [task 2018-10-31T23:00:01.750Z] 23:00:01 INFO - TEST-OK | dom/media/test/test_paused_after_ended.html | took 11258ms [task 2018-10-31T23:00:01.827Z] 23:00:01 INFO - TEST-START | dom/media/test/test_play_events.html [task 2018-10-31T23:00:16.211Z] 23:00:16 INFO - GECKO(1457) | MEMORY STAT | vsize 20973695MB | residentFast 923MB [task 2018-10-31T23:00:16.232Z] 23:00:16 INFO - TEST-OK | dom/media/test/test_play_events.html | took 14405ms [task 2018-10-31T23:00:16.294Z] 23:00:16 INFO - TEST-START | dom/media/test/test_play_events_2.html [task 2018-10-31T23:00:28.705Z] 23:00:28 INFO - GECKO(1457) | MEMORY STAT | vsize 20973693MB | residentFast 926MB [task 2018-10-31T23:00:28.723Z] 23:00:28 INFO - TEST-OK | dom/media/test/test_play_events_2.html | took 12431ms [task 2018-10-31T23:00:28.801Z] 23:00:28 INFO - TEST-START | dom/media/test/test_play_promise_1.html [task 2018-10-31T23:00:30.792Z] 23:00:30 INFO - GECKO(1457) | MEMORY STAT | vsize 20973714MB | residentFast 930MB [task 2018-10-31T23:00:30.829Z] 23:00:30 INFO - TEST-OK | dom/media/test/test_play_promise_1.html | took 2030ms [task 2018-10-31T23:00:30.866Z] 23:00:30 INFO - GECKO(1457) | [Child 1571, MediaPlayback #4] WARNING: Decoder=6160000c9080 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:30.969Z] 23:00:30 INFO - TEST-START | dom/media/test/test_play_promise_10.html [task 2018-10-31T23:00:31.341Z] 23:00:31 INFO - GECKO(1457) | MEMORY STAT | vsize 20973706MB | residentFast 935MB [task 2018-10-31T23:00:31.370Z] 23:00:31 INFO - TEST-OK | dom/media/test/test_play_promise_10.html | took 404ms [task 2018-10-31T23:00:31.439Z] 23:00:31 INFO - TEST-START | dom/media/test/test_play_promise_11.html [task 2018-10-31T23:00:31.862Z] 23:00:31 INFO - GECKO(1457) | MEMORY STAT | vsize 20973682MB | residentFast 931MB [task 2018-10-31T23:00:31.971Z] 23:00:31 INFO - TEST-OK | dom/media/test/test_play_promise_11.html | took 535ms [task 2018-10-31T23:00:32.288Z] 23:00:32 INFO - TEST-START | dom/media/test/test_play_promise_12.html [task 2018-10-31T23:00:32.803Z] 23:00:32 INFO - JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2894: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray] [task 2018-10-31T23:00:34.527Z] 23:00:34 INFO - GECKO(1457) | MEMORY STAT | vsize 20973702MB | residentFast 934MB [task 2018-10-31T23:00:34.588Z] 23:00:34 INFO - TEST-OK | dom/media/test/test_play_promise_12.html | took 2307ms [task 2018-10-31T23:00:34.629Z] 23:00:34 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=6160000edc80 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:34.740Z] 23:00:34 INFO - TEST-START | dom/media/test/test_play_promise_13.html [task 2018-10-31T23:00:36.368Z] 23:00:36 INFO - GECKO(1457) | MEMORY STAT | vsize 20973704MB | residentFast 944MB [task 2018-10-31T23:00:36.410Z] 23:00:36 INFO - TEST-OK | dom/media/test/test_play_promise_13.html | took 1672ms [task 2018-10-31T23:00:36.559Z] 23:00:36 INFO - TEST-START | dom/media/test/test_play_promise_14.html [task 2018-10-31T23:00:36.769Z] 23:00:36 INFO - JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2894: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray] [task 2018-10-31T23:00:37.034Z] 23:00:37 INFO - JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2894: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray] [task 2018-10-31T23:00:38.947Z] 23:00:38 INFO - GECKO(1457) | MEMORY STAT | vsize 20973707MB | residentFast 952MB [task 2018-10-31T23:00:38.997Z] 23:00:38 INFO - TEST-OK | dom/media/test/test_play_promise_14.html | took 2436ms [task 2018-10-31T23:00:39.034Z] 23:00:39 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=616000021680 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:39.141Z] 23:00:39 INFO - TEST-START | dom/media/test/test_play_promise_15.html [task 2018-10-31T23:00:39.548Z] 23:00:39 INFO - GECKO(1457) | MEMORY STAT | vsize 20973708MB | residentFast 954MB [task 2018-10-31T23:00:39.625Z] 23:00:39 INFO - TEST-OK | dom/media/test/test_play_promise_15.html | took 483ms [task 2018-10-31T23:00:39.727Z] 23:00:39 INFO - TEST-START | dom/media/test/test_play_promise_16.html [task 2018-10-31T23:00:42.204Z] 23:00:42 INFO - GECKO(1457) | MEMORY STAT | vsize 20973714MB | residentFast 959MB [task 2018-10-31T23:00:42.260Z] 23:00:42 INFO - TEST-OK | dom/media/test/test_play_promise_16.html | took 2525ms [task 2018-10-31T23:00:42.362Z] 23:00:42 INFO - TEST-START | dom/media/test/test_play_promise_17.html [task 2018-10-31T23:00:42.731Z] 23:00:42 INFO - JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2894: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray] [task 2018-10-31T23:00:43.107Z] 23:00:43 INFO - GECKO(1457) | MEMORY STAT | vsize 20973717MB | residentFast 964MB [task 2018-10-31T23:00:43.251Z] 23:00:43 INFO - TEST-OK | dom/media/test/test_play_promise_17.html | took 886ms [task 2018-10-31T23:00:43.383Z] 23:00:43 INFO - TEST-START | dom/media/test/test_play_promise_18.html [task 2018-10-31T23:00:44.011Z] 23:00:44 INFO - JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2894: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray] [task 2018-10-31T23:00:45.664Z] 23:00:45 INFO - GECKO(1457) | MEMORY STAT | vsize 20973736MB | residentFast 969MB [task 2018-10-31T23:00:45.733Z] 23:00:45 INFO - TEST-OK | dom/media/test/test_play_promise_18.html | took 2347ms [task 2018-10-31T23:00:45.776Z] 23:00:45 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=61600005d980 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:45.883Z] 23:00:45 INFO - TEST-START | dom/media/test/test_play_promise_2.html [task 2018-10-31T23:00:47.132Z] 23:00:47 INFO - GECKO(1457) | MEMORY STAT | vsize 20973734MB | residentFast 959MB [task 2018-10-31T23:00:47.201Z] 23:00:47 INFO - TEST-OK | dom/media/test/test_play_promise_2.html | took 1318ms [task 2018-10-31T23:00:47.239Z] 23:00:47 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=61600049fb80 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:47.320Z] 23:00:47 INFO - TEST-START | dom/media/test/test_play_promise_3.html [task 2018-10-31T23:00:47.481Z] 23:00:47 INFO - JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2894: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray] [task 2018-10-31T23:00:49.210Z] 23:00:49 INFO - GECKO(1457) | MEMORY STAT | vsize 20973735MB | residentFast 961MB [task 2018-10-31T23:00:49.251Z] 23:00:49 INFO - TEST-OK | dom/media/test/test_play_promise_3.html | took 1931ms [task 2018-10-31T23:00:49.302Z] 23:00:49 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=616000206780 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:49.380Z] 23:00:49 INFO - TEST-START | dom/media/test/test_play_promise_4.html [task 2018-10-31T23:00:50.312Z] 23:00:50 INFO - GECKO(1457) | MEMORY STAT | vsize 20973719MB | residentFast 957MB [task 2018-10-31T23:00:50.334Z] 23:00:50 INFO - TEST-OK | dom/media/test/test_play_promise_4.html | took 958ms [task 2018-10-31T23:00:50.477Z] 23:00:50 INFO - TEST-START | dom/media/test/test_play_promise_5.html [task 2018-10-31T23:00:51.291Z] 23:00:51 INFO - GECKO(1457) | MEMORY STAT | vsize 20973701MB | residentFast 962MB [task 2018-10-31T23:00:51.314Z] 23:00:51 INFO - TEST-OK | dom/media/test/test_play_promise_5.html | took 837ms [task 2018-10-31T23:00:51.383Z] 23:00:51 INFO - TEST-START | dom/media/test/test_play_promise_6.html [task 2018-10-31T23:00:53.767Z] 23:00:53 INFO - GECKO(1457) | MEMORY STAT | vsize 20973727MB | residentFast 955MB [task 2018-10-31T23:00:53.808Z] 23:00:53 INFO - TEST-OK | dom/media/test/test_play_promise_6.html | took 2430ms [task 2018-10-31T23:00:53.849Z] 23:00:53 INFO - GECKO(1457) | [Child 1571, MediaPlayback #3] WARNING: Decoder=6160001eab80 Decode error: NS_ERROR_DOM_MEDIA_DECODE_ERR (0x806e0004) - virtual mozilla::MediaResult mozilla::FFmpegAudioDecoder<46465650>::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 3434 [task 2018-10-31T23:00:53.951Z] 23:00:53 INFO - TEST-START | dom/media/test/test_play_promise_7.html [task 2018-10-31T23:00:55.518Z] 23:00:55 INFO - GECKO(1457) | MEMORY STAT | vsize 20973724MB | residentFast 952MB [task 2018-10-31T23:00:55.538Z] 23:00:55 INFO - TEST-OK | dom/media/test/test_play_promise_7.html | took 1596ms [task 2018-10-31T23:00:55.607Z] 23:00:55 INFO - TEST-START | dom/media/test/test_play_promise_8.html [task 2018-10-31T23:00:57.296Z] 23:00:57 INFO - GECKO(1457) | MEMORY STAT | vsize 20973720MB | residentFast 953MB [task 2018-10-31T23:00:57.345Z] 23:00:57 INFO - TEST-OK | dom/media/test/test_play_promise_8.html | took 1739ms [task 2018-10-31T23:00:57.467Z] 23:00:57 INFO - TEST-START | dom/media/test/test_play_promise_9.html [task 2018-10-31T23:00:57.819Z] 23:00:57 INFO - GECKO(1457) | MEMORY STAT | vsize 20973723MB | residentFast 958MB [task 2018-10-31T23:00:57.847Z] 23:00:57 INFO - TEST-OK | dom/media/test/test_play_promise_9.html | took 386ms [task 2018-10-31T23:00:57.910Z] 23:00:57 INFO - TEST-START | dom/media/test/test_play_twice.html [task 2018-10-31T23:01:15.923Z] 23:01:15 INFO - GECKO(1457) | MEMORY STAT | vsize 20973715MB | residentFast 947MB [task 2018-10-31T23:01:15.941Z] 23:01:15 INFO - TEST-OK | dom/media/test/test_play_twice.html | took 18029ms [task 2018-10-31T23:01:16.004Z] 23:01:16 INFO - TEST-START | dom/media/test/test_playback.html [task 2018-10-31T23:03:24.632Z] 23:03:24 INFO - GECKO(1457) | MEMORY STAT | vsize 20973709MB | residentFast 1008MB [task 2018-10-31T23:03:24.652Z] 23:03:24 INFO - TEST-OK | dom/media/test/test_playback.html | took 128650ms [task 2018-10-31T23:03:24.729Z] 23:03:24 INFO - TEST-START | dom/media/test/test_playback_errors.html [task 2018-10-31T23:03:25.072Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=61600079f880 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T23:03:25.074Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=61600079f880 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:25.115Z] 23:03:25 INFO - GECKO(1457) | JavaScript error: , line 0: NotSupportedError: The media resource indicated by the src attribute or assigned media provider object was not suitable. [task 2018-10-31T23:03:25.134Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #2] WARNING: Decoder=6160007aa980 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T23:03:25.134Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #2] WARNING: Decoder=6160007aa980 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:25.170Z] 23:03:25 INFO - GECKO(1457) | JavaScript error: , line 0: NotSupportedError: The media resource indicated by the src attribute or assigned media provider object was not suitable. [task 2018-10-31T23:03:25.270Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=6160003b7680 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T23:03:25.272Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=6160003b7680 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:25.301Z] 23:03:25 INFO - GECKO(1457) | JavaScript error: , line 0: NotSupportedError: The media resource indicated by the src attribute or assigned media provider object was not suitable. [task 2018-10-31T23:03:25.371Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=616000371d80 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T23:03:25.373Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=616000371d80 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:25.391Z] 23:03:25 INFO - GECKO(1457) | JavaScript error: , line 0: NotSupportedError: The media resource indicated by the src attribute or assigned media provider object was not suitable. [task 2018-10-31T23:03:25.467Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=616000083480 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 372 [task 2018-10-31T23:03:25.469Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #1] WARNING: Decoder=616000083480 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:25.489Z] 23:03:25 INFO - GECKO(1457) | JavaScript error: , line 0: NotSupportedError: The media resource indicated by the src attribute or assigned media provider object was not suitable. [task 2018-10-31T23:03:25.913Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #2] WARNING: Decoder=61600011b880 Decode error: NS_ERROR_DOM_MEDIA_FATAL_ERR (0x806e0005) - virtual RefPtr<MediaDataDecoder::InitPromise> mozilla::VorbisDataDecoder::Init(): Could not decode vorbis header.: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:25.914Z] 23:03:25 INFO - GECKO(1457) | [Child 1571, MediaPlayback #2] WARNING: Decoder=6160000cde80 Decode error: NS_ERROR_DOM_MEDIA_FATAL_ERR (0x806e0005) - virtual RefPtr<MediaDataDecoder::InitPromise> mozilla::VorbisDataDecoder::Init(): Systhesis init fail.: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 3434 [task 2018-10-31T23:03:26.079Z] 23:03:26 INFO - GECKO(1457) | MEMORY STAT | vsize 20973704MB | residentFast 1016MB [task 2018-10-31T23:03:26.080Z] 23:03:26 INFO - GECKO(1457) | JavaScript error: , line 0: AbortError: The fetching process for the media resource was aborted by the user agent at the user's request. [task 2018-10-31T23:03:26.082Z] 23:03:26 INFO - GECKO(1457) | JavaScript error: , line 0: AbortError: The fetching process for the media resource was aborted by the user agent at the user's request. [task 2018-10-31T23:03:26.105Z] 23:03:26 INFO - TEST-OK | dom/media/test/test_playback_errors.html | took 1381ms
|
||
Comment 1•6 years ago
|
||
These are the package versions difference from the upgrade that happens when rebuilding the docker images: 32,33c32,33 < ii apt 1.2.27 amd64 commandline package manager < ii apt-utils 1.2.27 amd64 package management related utility programs --- > ii apt 1.2.29 amd64 commandline package manager > ii apt-utils 1.2.29 amd64 package management related utility programs 73c73 < ii chromium-codecs-ffmpeg-extra 69.0.3497.81-0ubuntu0.16.04.1 amd64 Extra ffmpeg codecs for the Chromium Browser --- > ii chromium-codecs-ffmpeg-extra 70.0.3538.77-0ubuntu0.16.04.1 amd64 Extra ffmpeg codecs for the Chromium Browser 103c103 < ii curl 7.47.0-1ubuntu2.9 amd64 command line tool for transferring data with URL syntax --- > ii curl 7.47.0-1ubuntu2.11 amd64 command line tool for transferring data with URL syntax 122c122 < ii distro-info-data 0.28ubuntu0.8 all information about the distributions' releases (data files) --- > ii distro-info-data 0.28ubuntu0.9 all information about the distributions' releases (data files) 130c130 < ii dpkg-dev 1.18.4ubuntu1.4 all Debian package development tools --- > ii dpkg-dev 1.18.4ubuntu1.5 all Debian package development tools 150c150 < ii firefox 62.0.3+build1-0ubuntu0.16.04.2 amd64 Safe and easy web browser from Mozilla --- > ii firefox 63.0+build2-0ubuntu0.16.04.2 amd64 Safe and easy web browser from Mozilla 240,241c240,241 < ii ghostscript 9.25~dfsg+1-0ubuntu0.16.04.1 amd64 interpreter for the PostScript language and for PDF < ii ghostscript-x 9.25~dfsg+1-0ubuntu0.16.04.1 amd64 interpreter for the PostScript language and for PDF - X11 support --- > ii ghostscript 9.25~dfsg+1-0ubuntu0.16.04.2 amd64 interpreter for the PostScript language and for PDF > ii ghostscript-x 9.25~dfsg+1-0ubuntu0.16.04.2 amd64 interpreter for the PostScript language and for PDF - X11 support 268c268 < ii gir1.2-packagekitglib-1.0 0.8.17-4ubuntu6~gcc5.4ubuntu1.3 amd64 GObject introspection data for the PackageKit GLib library --- > ii gir1.2-packagekitglib-1.0 0.8.17-4ubuntu6~gcc5.4ubuntu1.4 amd64 GObject introspection data for the PackageKit GLib library 462c462 < ii libapt-inst2.0:amd64 1.2.27 amd64 deb package format runtime library --- > ii libapt-inst2.0:amd64 1.2.29 amd64 deb package format runtime library 464c464 < ii libapt-pkg5.0:amd64 1.2.27 amd64 package management runtime library --- > ii libapt-pkg5.0:amd64 1.2.29 amd64 package management runtime library 618,620c618,620 < ii libcurl3:amd64 7.47.0-1ubuntu2.9 amd64 easy-to-use client-side URL transfer library (OpenSSL flavour) < ii libcurl3-gnutls:amd64 7.47.0-1ubuntu2.9 amd64 easy-to-use client-side URL transfer library (GnuTLS flavour) < ii libcurl4-openssl-dev:amd64 7.47.0-1ubuntu2.9 amd64 development files and documentation for libcurl (OpenSSL flavour) --- > ii libcurl3:amd64 7.47.0-1ubuntu2.11 amd64 easy-to-use client-side URL transfer library (OpenSSL flavour) > ii libcurl3-gnutls:amd64 7.47.0-1ubuntu2.11 amd64 easy-to-use client-side URL transfer library (GnuTLS flavour) > ii libcurl4-openssl-dev:amd64 7.47.0-1ubuntu2.11 amd64 development files and documentation for libcurl (OpenSSL flavour) 653c653 < ii libdpkg-perl 1.18.4ubuntu1.4 all Dpkg perl modules --- > ii libdpkg-perl 1.18.4ubuntu1.5 all Dpkg perl modules 844,845c844,845 < ii libgs9:amd64 9.25~dfsg+1-0ubuntu0.16.04.1 amd64 interpreter for the PostScript language and for PDF - Library < ii libgs9-common 9.25~dfsg+1-0ubuntu0.16.04.1 all interpreter for the PostScript language and for PDF - common files --- > ii libgs9:amd64 9.25~dfsg+1-0ubuntu0.16.04.2 amd64 interpreter for the PostScript language and for PDF - Library > ii libgs9-common 9.25~dfsg+1-0ubuntu0.16.04.2 all interpreter for the PostScript language and for PDF - common files 1008c1008 < ii libmad0:amd64 0.15.1b-8ubuntu1 amd64 MPEG audio decoder library --- > ii libmad0:amd64 0.15.1b-9ubuntu16.04.1 amd64 MPEG audio decoder library 1056c1056 < ii libmysqlclient20:amd64 5.7.23-0ubuntu0.16.04.1 amd64 MySQL database client library --- > ii libmysqlclient20:amd64 5.7.24-0ubuntu0.16.04.1 amd64 MySQL database client library 1141c1141 < ii libpackagekit-glib2-16:amd64 0.8.17-4ubuntu6~gcc5.4ubuntu1.3 amd64 Library for accessing PackageKit using GLib --- > ii libpackagekit-glib2-16:amd64 0.8.17-4ubuntu6~gcc5.4ubuntu1.4 amd64 Library for accessing PackageKit using GLib 1147c1147 < ii libpam-systemd:amd64 229-4ubuntu21.4 amd64 system and service manager - PAM module --- > ii libpam-systemd:amd64 229-4ubuntu21.5 amd64 system and service manager - PAM module 1382,1383c1382,1383 < ii libsystemd0:amd64 229-4ubuntu21.4 amd64 systemd utility library < ii libsystemd0:i386 229-4ubuntu21.4 i386 systemd utility library --- > ii libsystemd0:amd64 229-4ubuntu21.5 amd64 systemd utility library > ii libsystemd0:i386 229-4ubuntu21.5 i386 systemd utility library 1423,1424c1423,1424 < ii libudev1:amd64 229-4ubuntu21.4 amd64 libudev shared library < ii libudev1:i386 229-4ubuntu21.4 i386 libudev shared library --- > ii libudev1:amd64 229-4ubuntu21.5 amd64 libudev shared library > ii libudev1:i386 229-4ubuntu21.5 i386 libudev shared library 1715c1715 < ii mysql-common 5.7.23-0ubuntu0.16.04.1 all MySQL database common files, e.g. /etc/mysql/my.cnf --- > ii mysql-common 5.7.24-0ubuntu0.16.04.1 all MySQL database common files, e.g. /etc/mysql/my.cnf 1737,1741c1737,1741 < ii openjdk-8-jdk:i386 8u181-b13-0ubuntu0.16.04.1 i386 OpenJDK Development Kit (JDK) < ii openjdk-8-jdk-headless:i386 8u181-b13-0ubuntu0.16.04.1 i386 OpenJDK Development Kit (JDK) (headless) < ii openjdk-8-jre:i386 8u181-b13-0ubuntu0.16.04.1 i386 OpenJDK Java runtime, using Hotspot JIT < ii openjdk-8-jre-headless:amd64 8u181-b13-0ubuntu0.16.04.1 amd64 OpenJDK Java runtime, using Hotspot JIT (headless) < ii openjdk-8-jre-headless:i386 8u181-b13-0ubuntu0.16.04.1 i386 OpenJDK Java runtime, using Hotspot JIT (headless) --- > ii openjdk-8-jdk:i386 8u181-b13-1ubuntu0.16.04.1 i386 OpenJDK Development Kit (JDK) > ii openjdk-8-jdk-headless:i386 8u181-b13-1ubuntu0.16.04.1 i386 OpenJDK Development Kit (JDK) (headless) > ii openjdk-8-jre:i386 8u181-b13-1ubuntu0.16.04.1 i386 OpenJDK Java runtime, using Hotspot JIT > ii openjdk-8-jre-headless:amd64 8u181-b13-1ubuntu0.16.04.1 amd64 OpenJDK Java runtime, using Hotspot JIT (headless) > ii openjdk-8-jre-headless:i386 8u181-b13-1ubuntu0.16.04.1 i386 OpenJDK Java runtime, using Hotspot JIT (headless) 1934c1934 < ii secureboot-db 1.1 amd64 Secure Boot updates for DB and DBX --- > ii secureboot-db 1.4~ubuntu0.16.04.1 amd64 Secure Boot updates for DB and DBX 1971c1971 < ii systemd 229-4ubuntu21.4 amd64 system and service manager --- > ii systemd 229-4ubuntu21.5 amd64 system and service manager 1996c1996 < ii tzdata 2018e-0ubuntu0.16.04 all time zone and daylight-saving time data --- > ii tzdata 2018g-0ubuntu0.16.04 all time zone and daylight-saving time data 2018c2018 < ii udev 229-4ubuntu21.4 amd64 /dev/ and hotplug management daemon --- > ii udev 229-4ubuntu21.5 amd64 /dev/ and hotplug management daemon One of those presumably breaks some expectation from the test.
Summary: Perma Linux mda webrtc failures with "NotFoundError: The object can not be found here." after hg server certificate updated and docker images rebuilt → Perma Linux mda webrtc failures with "NotFoundError: The object can not be found here." after Ubuntu 16.04 docker image upgrade
|
Reporter | |
Updated•6 years ago
|
Flags: needinfo?(gps)
|
||
Comment 2•6 years ago
|
||
The common nominator for the test failures from the description and the link which got posted into #media https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&fromchange=c70dbc64d293cbaa0497206da31c0c4627d6bff4&searchStr=mda&selectedJob=209011970 Are two things: - test which are calling getUserMedia() appear to be affected - I only see test failures on Linux This suggests to me that something in the docker image upgrade/update is missing or broken in terms of what the tests are expecting. The thing which most recently got change specifically on Linux regarding gUM() was to add audio loopback support. Alex can you help investigating what could be missing from the new docker images in terms of Linux audio loopback?
Flags: needinfo?(achronop)
|
||
Comment 3•6 years ago
|
||
I suspect problems with v4l2loopback: > [task 2018-10-31T22:49:33.845Z] 22:49:33 INFO - Setting pipeline to PAUSED ... > [task 2018-10-31T22:49:33.847Z] 22:49:33 INFO - libv4l2: error getting pixformat: Invalid argument > [task 2018-10-31T22:49:33.847Z] 22:49:33 INFO - Pipeline is PREROLLING ... > [task 2018-10-31T22:49:33.848Z] 22:49:33 INFO - Pipeline is PREROLLED ... > [task 2018-10-31T22:49:33.849Z] 22:49:33 INFO - Setting pipeline to PLAYING ... > [task 2018-10-31T22:49:33.850Z] 22:49:33 INFO - New clock: GstSystemClock > [task 2018-10-31T22:49:33.886Z] 22:49:33 INFO - Got EOS from element "pipeline0". > [task 2018-10-31T22:49:33.888Z] 22:49:33 INFO - Execution ended after 0:00:00.033482868 > [task 2018-10-31T22:49:33.890Z] 22:49:33 INFO - Setting pipeline to PAUSED ... > [task 2018-10-31T22:49:33.891Z] 22:49:33 INFO - Setting pipeline to READY ... > [task 2018-10-31T22:49:33.893Z] 22:49:33 INFO - (gst-launch-1.0:703): GStreamer-CRITICAL **: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed > [task 2018-10-31T22:49:33.894Z] 22:49:33 INFO - Setting pipeline to NULL ... > [task 2018-10-31T22:49:33.895Z] 22:49:33 INFO - Freeing pipeline ... In particular I don't recognize this: > [task 2018-10-31T22:49:33.847Z] 22:49:33 INFO - libv4l2: error getting pixformat: Invalid argument Running `v4l2-ctl --list-devices` on one of these machines should be a good smoke test. It should report something like: > Dummy video device (0x0000) (platform:v4l2loopback-000): > /dev/video0
|
|
||
Comment 4•6 years ago
|
||
This is the output on both the old and the new image:
# v4l2-ctl --list-devices
Dummy video device (0x0000) (platform:v4l2loopback-000):
/dev/video0
High priority as we're blocking another high priority.
Priority: -- → P1
|
||
Comment 6•6 years ago
|
||
All failed tests request for audio. Similar test, which request video only, like test_imagecapture.html does not fail. Can you check if PulseAudio is installed and running? I am running locally: [achronop@fedora ~]$ ps aux|grep pulseaudio gdm 2293 0.0 0.0 1587808 11472 ? S<l 10:35 0:00 /usr/bin/pulseaudio --start --log-target=syslog achronop 3047 0.0 0.0 2686744 14036 ? S<l 10:35 0:00 /usr/bin/pulseaudio --start achronop 5481 0.0 0.0 118456 1012 pts/0 S+ 11:06 0:00 grep --color=auto pulseaudio [achronop@fedora ~]$ pacmd load-module module-null-source [achronop@fedora ~]$ pacmd list-modules |grep module-null-source name: <module-null-source> [achronop@fedora ~]$ pacmd unload-module module-null-source [achronop@fedora ~]$ pacmd list-modules |grep module-null-source [achronop@fedora ~]$ pacmd load-module module-null-sink [achronop@fedora ~]$ pacmd list-modules |grep module-null-sink name: <module-null-sink> [achronop@fedora ~]$ pacmd unload-module module-null-sink [achronop@fedora ~]$ pacmd list-modules |grep module-null-sink [achronop@fedora ~]$ pactl load-module module-null-sink <------This is what we do in [1] and without it we do not have devices 32 [achronop@fedora ~]$ pactl unload-module module-null-sink [achronop@fedora ~]$ pactl load-module module-null-sink 33 [1] https://searchfox.org/mozilla-central/rev/eac6295c397133b7346822ad31867197e30d7e94/testing/mochitest/runtests.py#771
Flags: needinfo?(achronop)
|
|
||
Comment 7•6 years ago
|
||
For the record pulse looks good in the logs: [task 2018-10-31T22:46:13.623Z] + maybe_start_pulse [task 2018-10-31T22:46:13.623Z] + true [task 2018-10-31T22:46:13.624Z] + pulseaudio --fail --daemonize --start [task 2018-10-31T22:46:13.625Z] + compiz [task 2018-10-31T22:46:13.638Z] compiz (core) - Info: Loading plugin: core [task 2018-10-31T22:46:13.639Z] compiz (core) - Info: Starting plugin: core [task 2018-10-31T22:46:13.658Z] compiz (core) - Info: Loading plugin: ccp [task 2018-10-31T22:46:13.664Z] compiz (core) - Info: Starting plugin: ccp [task 2018-10-31T22:46:13.742Z] + pactl load-module module-null-sink [task 2018-10-31T22:46:13.755Z] 17
|
||
Comment 8•6 years ago
|
||
Possibly related, at the very end of the log: [task 2018-10-31T23:11:01.085Z] XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":0" [task 2018-10-31T23:11:01.085Z] after 7240 requests (7240 known processed) with 0 events remaining.
|
|
||
Updated•6 years ago
|
|
|
||
Comment 9•6 years ago
|
||
This sounds like Bug 1503329. I saw it yesterday but I was clueless about what is going on there.
|
Assignee | |
Comment 10•6 years ago
|
||
Auditing the package version diff in comment 1, two packages seemed related to media. I have try pushes in progress to test pinning the existing package version: chromium-codecs-ffmpeg-extra and libmad0 https://treeherder.mozilla.org/#/jobs?repo=try&revision=238d3187284d5c5243b91cbff25f30d289b4411a just chromium-codecs-ffmpeg-extra https://treeherder.mozilla.org/#/jobs?repo=try&revision=1a42268350fcd129c2358f7dbe7167ce8955925b just libmad0 https://treeherder.mozilla.org/#/jobs?repo=try&revision=daacf2927f6f59a9f3189ccc8fde07870a0afeb7 If these come back green, IMO we should land the commit to pin the package against a known working version. This will unblock landing other changes that require rebuilding Docker images (I'm aware of at least 4 things currently blocked on this). Then someone else can figure out why the tests are failing with the latest version, fix things, and remove the package version pin. My immediate priority is to unblock other Firefox CI work.
Flags: needinfo?(gps)
|
|
Assignee | |
Comment 11•6 years ago
|
||
Oops. My initial Try pushes pinned the wrong version of chromium-codecs-ffmpeg-extra. Both packages pinned: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8abe5cc7ebc0c9505cc041200de15ce17d0d72a6 Just chromium-codecs-ffmpeg-extra: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a0970330341bb38df7d22f5c5d4b0b0e08d96b5c
|
|
Assignee | |
Comment 12•6 years ago
|
||
I also tried to pin gir1.2-packagekitglib-1.0 and libpackagekit-glib2-16:amd64 for good measure. However, of the 4 packages I attempted to pin, only the old package for libmad0 could be installed. The upstream package mirrors typically delete packages with known security vulnerabilities, making them uninstallable. This is a measure to protect end-users. Unfortunately, it prevents people like us from pinning packages and expecting deterministic operation over time. Unfortunately, tests are still failing with the pinned libmad0. We could find an old package binary and download and install it manually. But it might just be quicker to fix the underlying bug causing these tests to fail. We should do that anyway...
|
|
||
Comment 13•6 years ago
|
||
Alex I don't see how this here is related to https://bugzilla.mozilla.org/show_bug.cgi?id=1503329#c7 as that is crashing when processing H264 RTP packets. This here appears to an audio gUM Linux only problem. Alex, do we still have an option to turn off the loopback support on Linux? If yes could you please kick off a try without loopback to see if makes this green again? I would not want that as a permanent option, but then we would know that something in the Docker image upgrade broke the loopback support.
Flags: needinfo?(achronop)
|
|
||
Comment 14•6 years ago
|
||
(In reply to Nils Ohlmeier [:drno] from comment #13) > Alex I don't see how this here is related to > https://bugzilla.mozilla.org/show_bug.cgi?id=1503329#c7 as that is crashing > when processing H264 RTP packets. This here appears to an audio gUM Linux > only problem. Hmm I do not see it either. I must have been confused and posted on the wrong bug. > Alex, do we still have an option to turn off the loopback support on Linux? > If yes could you please kick off a try without loopback to see if makes this > green again? I would not want that as a permanent option, but then we would > know that something in the Docker image upgrade broke the loopback support. Sure, I guess it's not a normal try push, I have to do something special to trigger a push on a new Docker.
Flags: needinfo?(achronop)
|
|
||
Comment 15•6 years ago
|
||
Can you please give me instruction how to push on try using the updated docker image?
Flags: needinfo?(shindli)
|
||
Comment 16•6 years ago
|
||
If your change contains modifications to docker configurations similar to https://hg.mozilla.org/try/rev/58ba62355cee1be83375d0f308ce715fea4f1237 , the images will get rebuilt and builds and tests run after it has been completed.
Flags: needinfo?(shindli)
|
|
||
Comment 17•6 years ago
|
||
(In reply to Nils Ohlmeier [:drno] from comment #13) > Alex I don't see how this here is related to > https://bugzilla.mozilla.org/show_bug.cgi?id=1503329#c7 as that is crashing > when processing H264 RTP packets. This here appears to an audio gUM Linux > only problem. Remember now, at the time I wrote this comment Karl had not updated the bug with his findings. The old description of Bug 1503329 contained the error mentioned in comment 8 of this bug. The summary was: fatal IO error 11 (Resource temporarily unavailable) on X server ":0". My comment was an answer to that. But indeed, after Karl's update the bugs seem unrelated.
|
|
Assignee | |
Comment 18•6 years ago
|
||
Make a change to the `taskcluster/scripts/run-task` file (add a comment below the shebang for example) to force nearly all Docker images to rebuild. Alternatively, run `mach try fuzzy --full` and select the tasks with "docker" in their name to force specific Docker images to rebuild. Any Docker images explicitly rebuilt this way should be used by tasks in that Try push. This approach should be faster, as you can only select the "build-docker-image-desktop1604-test" task (the Docker image that is busted) and your try push won't have to wait for other Docker images and their downstream dependencies to rebuild. This includes ~1 hr of tasks to rebuild toolchains.
|
|
||
Comment 19•6 years ago
|
||
A simpler (and faster) way is to do a try push based on https://hg.mozilla.org/integration/autoland/rev/6fc2aad03a34 That will pull the docker image that was built then, instead of rebuilding one.
|
|
||
Comment 20•6 years ago
|
||
Thanks for the responses! In try run [1] I have disabled the loopback devices and the fake devices are used. The failures in mda2 (test_getUserMedia_audioConstraints.html) and mda3 (test_setSinkId.html) are expected when when loopback devices are off, on a Linux execution. However, I do not see the other errors that we get with loopback devices on, so the problem is not reproducible with fake streams. This was expected though because the fake streams are implemented inside Gecko and they do not depend on external libraries. I have pushed a couple of more try runs in order to narrow down the case but without luck. In [2] I only reproduced the problem and in [3] I tried disabling the cubeb remote (and using the c-backend instead of the rust one). I'll continue enabling some logs in case we see something in there. [1] https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=211693134&revision=c88dd18a4015c5f8361470ac3a6f466c5832b818 [2] https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=211693134&revision=eae1429511c944f2eb67eab2c552ef6c9cf06c53 [3] https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=211693134&revision=9ee5b297dfc442cf037f866c8dba930f3ad23229
|
|
||
Comment 21•6 years ago
|
||
One more question is how to connect on the machine. I try the "create interactive task" option from try but the task get resolved before being ready. Please let me know if there is a workaround for that.
|
|
||
Comment 22•6 years ago
|
||
Try run with log activated: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e3a3cb636fa9825f0a93f04280a62bf777c1c65a
|
||
Comment 23•6 years ago
|
||
I wonder if we ought to replace our Ubuntu tester images with ones based on Debian so we can make them reproducible like our builder images? I realize that they'd be less consistent with what people actually use in the wild, but until Ubuntu gets something like Debian's snapshot server we're going to continue to waste huge amounts of engineering time every time we rebuild a tester image and pick up unexpected package updates. We've been through this same problem with the build image (see bug 1338651 comment 168) which got fixed in bug 1399679. bug 1289812 has some more information.
|
|
Assignee | |
Comment 24•6 years ago
|
||
Apparently every time we switch the major distro version of the main test image, it causes a ton of test fallout. Apparently it can be several weeks of people time to sort through. I believe jmaher can share horror stories. It is probably easier to coerce the existing images into being deterministic. I've explored running a snapshotted Apt mirror previously so we can remove the 3rd party dependency completely. However, this requires running new infrastructure indefinitely. There was also talk of potentially using a caching HTTP proxy to capture the files requested by Apt and reusing that cache/snapshot on subsequent image builds. I think solutions are moderate effort (1+ week) and are out of scope for this bug. But we shouldn't let them fall off our radar because this kind of stop-the-world-for-several-weeks issue stemming from non-deterministic and non-hermetic Docker builds causes significant disruption and happens a few times per year.
|
|
||
Comment 25•6 years ago
|
||
Gah, I don't believe it ... The problem was that in that system the "null device" is called "dummy device". We hardcode the device name and it is the one expected to be found and be used by getUserMedia request. In [1] is a green try with that change. I need to find a smarter solution for that, though. [1] https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=211709478&revision=5dc96597847b2b4f2e4039f6d456fec067692e3b
|
|
Assignee | |
Comment 26•6 years ago
|
||
Excellent news on finding the problem! Since this issue is blocking the landing of a handful of other patches, I think a hacky solution to unblock others is justified. I would gladly r+ a patch that makes the device name change along with a change forcing the desktop1604-test image to be rebuilt so others are unblocked. Such a change would be to change any file under docker/desktop1604-test. It could be as simple as adding a comment to the Dockerfile file. Or if you'll have a proper patch without much effort, we can wait a bit. But I'd prefer to not wait more than a few hours.
|
|
||
Comment 27•6 years ago
|
||
In that case you can just use the patch from the try and go on. Fell free to use r=me on that. However, it's necessary to tight the change to the new image otherwise tests on the old image will break. A proper solution would be to experiment with PulseAudio commands in order to set the name of the device and see how this affects the name of monitor device. I found something relevant in [1]. However, I need to experiment a little with that and test it on try which will be more than a few hours. [1] https://unix.stackexchange.com/questions/128371/pulseaudio-naming-a-device
|
|
Assignee | |
Comment 28•6 years ago
|
||
Regenerating the ubuntu1604-test Docker image pulls in a new package version that changes the name of a media device. This media device name is currently hard coded in the mochitest test harness. This commit makes a change to force regeneration of the Docker image and updates the hardcoded device name to reflect the new version.
|
|
Assignee | |
Comment 29•6 years ago
|
||
Patch is queued. Autoland is closed. Presumably others can queue patches that would regenerate desktop1604-test now, since Lando should process landings in FIFO order. Although it is safer to wait to avoid excessive backout risk.
|
|
||
Comment 30•6 years ago
|
||
Note that freezing the testing images can be seen as both good *and* bad. Good because it would avoid problems like this one popping up randomly, but bad because when those things happen it *does* mean Ubuntu 16.04 *has* changed in ways that break tests, which may or may not also mean that there are problems in the wild with Ubuntu 16.04. OTOH, we don't test other versions of Ubuntu, so...
|
||
Comment 31•6 years ago
|
||
Pushed by gszorc@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/daffe63f1a1f Change name of media device; r=achronop
|
||
Comment 32•6 years ago
|
||
Backed out for failing multiple android tests Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=daffe63f1a1f313446c7f4c29e24de04f4ed1062 Failure log: clipboard: https://treeherder.mozilla.org/logviewer.html#?job_id=211818923&repo=autoland&lineNumber=1180 crashtest: https://treeherder.mozilla.org/logviewer.html#?job_id=211848287&repo=autoland&lineNumber=1188 gpu: https://treeherder.mozilla.org/logviewer.html#?job_id=211848293&repo=autoland&lineNumber=1188 Backout: https://hg.mozilla.org/integration/autoland/rev/2a9517f92a0d29bd8280e7f6fd897f19c4cf68c3
Flags: needinfo?(gps)
|
|
||
Comment 33•6 years ago
|
||
(In reply to Mike Hommey [:glandium] from comment #30) > Note that freezing the testing images can be seen as both good *and* bad. > Good because it would avoid problems like this one popping up randomly, but > bad because when those things happen it *does* mean Ubuntu 16.04 *has* > changed in ways that break tests, which may or may not also mean that there > are problems in the wild with Ubuntu 16.04. OTOH, we don't test other > versions of Ubuntu, so... Ideally we'd be able to deal with this pain in measured doses, though, by explicitly updating our testing images to a newer version. Not by picking up a bunch of unintentional updates when the image gets rebuilt for any reason.
|
|
Assignee | |
Comment 34•6 years ago
|
||
There was a 2nd instance of "Null Output" being used for the media.cubeb.output_device pref. https://treeherder.mozilla.org/#/jobs?repo=try&revision=ae8401009d4bd34f3f74ba27cc4bd93a591edbb2 is a Try push changing that as well and triggering the new failures that caused the backout. If that comes back green, I'll get that reviewed and landed.
Flags: needinfo?(gps)
|
|
Assignee | |
Comment 35•6 years ago
|
||
My Try push is yielding failures on Android x86 :( https://treeherder.mozilla.org/#/jobs?repo=try&author=gszorc%40mozilla.com&selectedJob=212009567
|
|
Assignee | |
Comment 36•6 years ago
|
||
bc: I'm a bit out of my league dealing with ADB issues. Is there any chance you can help us diagnose the Android 7.0 x86 opt failures in the Try push in comment 34? It obviously has something to do with regenerating the desktop1604-test Docker image. But unlike the other diagnosed failure in this bug, it looks like we can't connect to ADB at all with the new Docker image. It's possible we may have a 2nd failure as a result of rebuilding the Docker image :/
Flags: needinfo?(bob)
|
||
Comment 37•6 years ago
|
||
Sure. I'll take a look. gbrown might be able to help as well.
Flags: needinfo?(gbrown)
|
|
||
Comment 38•6 years ago
|
||
We could presumably switch the android tests to a Debian-based docker image.
|
|
||
Comment 39•6 years ago
|
||
It appears the emulator isn't starting completely. I think there were issues with the docker image used for x86/packet.net initially. Maybe gbrown knows more.
|
|
||
Comment 40•6 years ago
|
||
(In reply to Gregory Szorc [:gps] from comment #35) > My Try push is yielding failures on Android x86 :( > > https://treeherder.mozilla.org/#/jobs?repo=try&author=gszorc%40mozilla. > com&selectedJob=212009567 The emulator logs are incomplete: Emulator startup has not completed, but I don't see any errors or other indication of why it didn't start. The most common problem I've seen with emulator startup failing like this is kvm not working, but that seems okay in this case: https://taskcluster-artifacts.net/XMu6GC5PSzClYoZKuZdeEA/0/public/test_info//emulator-8_Mv0M.log emulator: CPU Acceleration: working emulator: CPU Acceleration status: KVM (version 12) is installed and usable. emulator: checking cpu acceleration from main qemu params ... emulator: trying to find: /builds/worker/workspace/build/android-sdk-linux/emulator/bios.bin emulator: trying to find: /builds/worker/workspace/build/android-sdk-linux/emulator/lib/pc-bios/bios.bin emulator: trying to find: /builds/worker/workspace/build/android-sdk-linux/emulator/vgabios-cirrus.bin emulator: trying to find: /builds/worker/workspace/build/android-sdk-linux/emulator/lib/pc-bios/vgabios-cirrus.bin <eof>
|
|
||
Comment 41•6 years ago
|
||
Normally we'd see: ... emulator: trying to find: /builds/worker/workspace/build/android-sdk-linux/emulator/lib/pc-bios/vgabios-cirrus.bin emulator: control console listening on port 5554, ADB on port 5555 Not using any http proxy emulator: Adding boot property: 'qemu.timezone' = 'Etc/UTC' emulator: android_hw_fingerprint_init: fingerprint qemud listen service initialized ...
|
|
||
Comment 42•6 years ago
|
||
(In reply to Bob Clary [:bc:] from comment #39) > I think there were issues > with the docker image used for x86/packet.net initially. As I recall, the only change to the docker image was https://hg.mozilla.org/mozilla-central/rev/8a820882e927
|
|
||
Comment 43•6 years ago
|
||
Looking at the tasks which created the docker image for the currently running tests on mozilla-central and the version created for this try run, it appears to me that the qemu-kvm is the same in both. I'll try to do a more complete comparison of the logs.
|
|
||
Comment 44•6 years ago
|
||
I avoided the python crash and tried to get screenshots of the Ubuntu desktop at https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&selectedJob=212086725&revision=9caa8031c1b665828b33345aa1446a8afe8a63c1 but they all came back blank (all black). Curious. Also, the log there shows, after killing the emulator, defunct pulseaudio and other processes: [task 2018-11-16T00:53:15.535Z] 00:53:15 INFO - Killing every process called emulator64-x86 [task 2018-11-16T00:53:15.541Z] 00:53:15 INFO - Killing pid 204. [task 2018-11-16T00:53:15.546Z] UID PID PPID C STIME TTY TIME CMD [task 2018-11-16T00:53:15.546Z] worker 1 0 0 00:40 pts/0 00:00:00 /usr/bin/python3 -u /builds/worker/bin/run-task -- /builds/worker/bin/test-linux.sh --installer-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/geckoview-androidTest.apk --test-packages-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/target.test_packages.json --test-suite=mochitest-plain-gpu --download-symbols=ondemand [task 2018-11-16T00:53:15.547Z] worker 7 1 0 00:40 pts/0 00:00:00 /bin/bash -xe /builds/worker/bin/test-linux.sh --installer-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/geckoview-androidTest.apk --test-packages-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/target.test_packages.json --test-suite=mochitest-plain-gpu --download-symbols=ondemand [task 2018-11-16T00:53:15.547Z] worker 22 1 0 00:40 ? 00:00:00 SCREEN -dmS xvfb Xvfb :0 -nolisten tcp -screen 0 1600x1200x24 [task 2018-11-16T00:53:15.547Z] worker 24 22 0 00:40 pts/1 00:00:00 Xvfb :0 -nolisten tcp -screen 0 1600x1200x24 [task 2018-11-16T00:53:15.547Z] worker 63 1 0 00:41 pts/0 00:00:00 dbus-launch --autolaunch=56caa9d9ae584fd1b186eeed9e0880f5 --binary-syntax --close-stderr [task 2018-11-16T00:53:15.547Z] worker 69 1 0 00:41 ? 00:00:00 /usr/bin/dbus-daemon --fork --print-pid 5 --print-address 7 --session [task 2018-11-16T00:53:15.547Z] worker 73 1 0 00:41 ? 00:00:00 /usr/lib/dconf/dconf-service [task 2018-11-16T00:53:15.547Z] worker 99 1 0 00:41 ? 00:00:00 [ssh-agent] <defunct> [task 2018-11-16T00:53:15.547Z] worker 102 1 0 00:41 pts/0 00:00:00 /usr/bin/dbus-launch --exit-with-session /usr/bin/im-launch x-session-manager [task 2018-11-16T00:53:15.547Z] worker 103 1 0 00:41 ? 00:00:00 /usr/bin/dbus-daemon --fork --print-pid 5 --print-address 7 --session [task 2018-11-16T00:53:15.547Z] worker 116 1 0 00:41 ? 00:00:00 /usr/lib/gvfs/gvfsd [task 2018-11-16T00:53:15.547Z] worker 121 1 0 00:41 ? 00:00:00 [gvfsd-fuse] <defunct> [task 2018-11-16T00:53:15.547Z] worker 129 7 0 00:41 pts/0 00:00:00 compiz [task 2018-11-16T00:53:15.547Z] worker 135 1 0 00:41 ? 00:00:00 [pulseaudio] <defunct> [task 2018-11-16T00:53:15.547Z] worker 136 1 0 00:41 ? 00:00:00 [pulseaudio] <defunct> [task 2018-11-16T00:53:15.547Z] worker 141 1 0 00:41 ? 00:00:00 /usr/lib/x86_64-linux-gnu/gconf/gconfd-2 [task 2018-11-16T00:53:15.547Z] worker 157 7 2 00:41 pts/0 00:00:15 python2.7 /builds/worker/workspace/mozharness/scripts/android_emulator_unittest.py --config-file /builds/worker/workspace/mozharness/configs/android/android_common.py --config-file /builds/worker/workspace/mozharness/configs/android/androidx86_7_0.py --installer-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/geckoview-androidTest.apk --test-packages-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/target.test_packages.json --test-suite=mochitest-plain-gpu --download-symbols=ondemand [task 2018-11-16T00:53:15.547Z] worker 159 1 0 00:41 ? 00:00:00 /usr/lib/at-spi2-core/at-spi-bus-launcher [task 2018-11-16T00:53:15.547Z] worker 164 159 0 00:41 ? 00:00:00 /usr/bin/dbus-daemon --config-file=/etc/at-spi2/accessibility.conf --nofork --print-address 3 [task 2018-11-16T00:53:15.547Z] worker 166 1 0 00:41 ? 00:00:00 /usr/lib/at-spi2-core/at-spi2-registryd --use-gnome-session [task 2018-11-16T00:53:15.547Z] worker 204 157 99 00:41 pts/0 00:11:31 [emulator64-x86] <defunct> [task 2018-11-16T00:53:15.547Z] worker 206 204 0 00:41 pts/0 00:00:00 /builds/worker/workspace/build/android-sdk-linux/emulator/emulator64-crash-service -pipe 10 -ppid 204 -data-dir /tmp/android-worker/d8fae19a-0906-43e9-9bdc-fcf32e5d168c [task 2018-11-16T00:53:15.547Z] worker 693 157 0 00:53 pts/0 00:00:00 ps -ef [task 2018-11-16T00:53:15.547Z] worker 9983 157 0 00:42 pts/0 00:00:00 python2.7 /builds/worker/workspace/mozharness/scripts/android_emulator_unittest.py --config-file /builds/worker/workspace/mozharness/configs/android/android_common.py --config-file /builds/worker/workspace/mozharness/configs/android/androidx86_7_0.py --installer-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/geckoview-androidTest.apk --test-packages-url=https://queue.taskcluster.net/v1/task/c-RyV1PqRH20e0bYc5CMcQ/artifacts/public/build/target.test_packages.json --test-suite=mochitest-plain-gpu --download-symbols=ondemand [task 2018-11-16T00:53:15.547Z] worker 15626 1 0 00:43 ? 00:00:00 adb -L tcp:5037 fork-server server --reply-fd 10 I'm not sure what to make of that.
|
|
||
Comment 45•6 years ago
|
||
We can just download this image and try to run things locally with Docker, right? The version of Docker from the Fedora 29 repos it is pretty old and Docker-CE doesn't support Fedora 29 yet, but I could probably try to run one on an autophone spare server.
|
|
||
Comment 46•6 years ago
|
||
You can just go to https://tools.taskcluster.net/groups/ABRE6GdnSUeBx1hhX3CKkw/tasks/UiV8OwUGRnGGdtBaztA08A/details click actions -> Edit as interactive task
|
|
||
Comment 47•6 years ago
|
||
Sorry, I don't understand how that would help me run an image interactively. I downloaded the image to an ubuntu vm and attempted to run it but all I can get are no such file or directory when attempting to run commands. I'm at a loss on how to debug this.
Flags: needinfo?(bob)
|
|
||
Comment 48•6 years ago
|
||
With an interactive task, you can get shell access. (once it's running, you can go to artifacts and open the shell.html file)
|
|
||
Comment 49•6 years ago
|
||
fwiw, I've been pending for 3 hours. Hopefully I'll catch it when it starts to run.
|
|
||
Comment 50•6 years ago
|
||
I've had a similar experience to bc: Can't get an interactive task, possibly because of a backlog. I tried downloading image.tar.zst / zstd -d image.tar.zst / docker import image.tar / docker run -ti <image> /bin/bash (and variants) but the docker run always fails: 'docker: Error response from daemon: OCI runtime create failed: container_linux.go:348: starting container process caused "exec: \"/bin/bash\": stat /bin/bash: no such file or directory": unknown.'
|
|
Assignee | |
Comment 51•6 years ago
|
||
Try using `mach taskcluster-load-image <taskid>` to import the Docker image.
|
|
||
Comment 52•6 years ago
|
||
Thanks. 'mach taskcluster-load-image --task-id UqXjBDhuRw2Q50IFq3OmfQ' worked -- I can docker run now.
|
|
||
Comment 53•6 years ago
|
||
With the new image, Xsession is crashing, even in Linux and Android 4.3 tasks; I suspect the x86 emulator is more sensitive to its graphical environment, while Linux and Android 4.3 tests can muddle through. Xsession is started at https://dxr.mozilla.org/mozilla-central/rev/b0b856065d5b7ad2996f707e6e797d0d72afd803/taskcluster/scripts/tester/test-linux.sh#141 If you look at any of the Linux or Android tests from gps' original push, you see: https://taskcluster-artifacts.net/Z7cTKkyMS6-4EwZqsJ4T-A/0/public/logs/live_backing.log [task 2018-11-15T17:58:55.477Z] /builds/worker/bin/test-linux.sh: line 191: 36 Trace/breakpoint trap /etc/X11/Xsession 2>&1 Running the docker image locally, I see: root@83a42b9d7153:~# /etc/X11/Xsession Trace/breakpoint trap (core dumped) Tasks have a xsession-errors.log artifact such as https://taskcluster-artifacts.net/Z7cTKkyMS6-4EwZqsJ4T-A/0/public/test/public/xsession-errors.log Xsession: X session started for worker at Thu Nov 15 17:39:48 UTC 2018 localuser:worker being added to access control list openConnection: connect: No such file or directory cannot connect to brltty at :0 /builds/worker/Desktop was removed, reassigning DESKTOP to homedir /builds/worker/Downloads was removed, reassigning DOWNLOAD to homedir /builds/worker/Templates was removed, reassigning TEMPLATES to homedir /builds/worker/Public was removed, reassigning PUBLICSHARE to homedir gnome-session-is-accelerated: llvmpipe detected. gnome-session-binary[36]: ERROR: Failed to connect to system bus: Could not connect: No such file or directory aborting... Also, screenshots show an all black desktop with the new image, and 'ps -ef' is missing many of the gvfs/evolution/etc processes associated with the window manager. None of this points to an obvious solution, but hopefully I've narrowed down the scope of the problem?
Flags: needinfo?(gbrown)
|
|
||
Comment 54•6 years ago
|
||
I guess part of the problem is that we're running tests in an environment that doesn't run any of the daemons that normally run on an Ubuntu system (here, probably the dbus system daemon)
|
|
||
Comment 55•6 years ago
|
||
Comparing process lists from system-info.log artifacts from a normal Linux test: https://taskcluster-artifacts.net/Se57jPcNSduPOHHVwTHCDw/0/public/test_info//system-info.log to one from gps' try push: https://taskcluster-artifacts.net/Z7cTKkyMS6-4EwZqsJ4T-A/0/public/test_info//system-info.log They both have dbus-daemon and dbus-launch processes, but gps' is missing PID 100 ssh-agent ['/usr/bin/ssh-agent', '/usr/bin/dbus-launch', '--exit-with-session', '/usr/bin/im-launch', 'x-session-manager']
|
|
||
Comment 56•6 years ago
|
||
ssh-agent is there, just with different arguments. There's another ton missing, though: PID 159 gnome-screensaver ['/usr/bin/gnome-screensaver', '--no-daemon'] created at 2018-11-16 22:43:18.690000 PID 175 dconf-service ['/usr/lib/dconf/dconf-service'] created at 2018-11-16 22:43:18.940000 PID 241 nautilus ['nautilus', '-n'] created at 2018-11-16 22:43:21.690000 PID 246 indicator-session-service ['/usr/lib/x86_64-linux-gnu/indicator-session/indicator-session-service'] created at 2018-11-16 22:43:21.700000 PID 248 indicator-power-service ['/usr/lib/x86_64-linux-gnu/indicator-power/indicator-power-service'] created at 2018-11-16 22:43:21.710000 PID 257 indicator-datetime-service ['/usr/lib/x86_64-linux-gnu/indicator-datetime/indicator-datetime-service'] created at 2018-11-16 22:43:21.760000 PID 268 indicator-application-service ['/usr/lib/x86_64-linux-gnu/indicator-application/indicator-application-service'] created at 2018-11-16 22:43:21.770000 PID 272 indicator-keyboard-service ['/usr/lib/x86_64-linux-gnu/indicator-keyboard/indicator-keyboard-service'] created at 2018-11-16 22:43:21.790000 PID 273 indicator-bluetooth-service ['/usr/lib/x86_64-linux-gnu/indicator-bluetooth/indicator-bluetooth-service'] created at 2018-11-16 22:43:21.790000 PID 292 gvfs-udisks2-volume-monitor ['/usr/lib/gvfs/gvfs-udisks2-volume-monitor'] created at 2018-11-16 22:43:21.870000 PID 301 gvfs-mtp-volume-monitor ['/usr/lib/gvfs/gvfs-mtp-volume-monitor'] created at 2018-11-16 22:43:21.900000 PID 307 evolution-source-registry ['/usr/lib/evolution/evolution-source-registry'] created at 2018-11-16 22:43:21.910000 PID 309 initctl [] created at 2018-11-16 22:43:21.910000 PID 318 gvfs-afc-volume-monitor ['/usr/lib/gvfs/gvfs-afc-volume-monitor'] created at 2018-11-16 22:43:21.930000 PID 325 gvfs-gphoto2-volume-monitor ['/usr/lib/gvfs/gvfs-gphoto2-volume-monitor'] created at 2018-11-16 22:43:21.960000 PID 330 gvfs-goa-volume-monitor ['/usr/lib/gvfs/gvfs-goa-volume-monitor'] created at 2018-11-16 22:43:21.970000 PID 338 evolution-calendar-factory ['/usr/lib/evolution/evolution-calendar-factory'] created at 2018-11-16 22:43:22.140000 PID 354 gvfsd-trash ['/usr/lib/gvfs/gvfsd-trash', '--spawner', ':1.1', '/org/gtk/gvfs/exec_spaw/0'] created at 2018-11-16 22:43:22.440000 PID 360 evolution-calendar-factory-subprocess ['/usr/lib/evolution/evolution-calendar-factory-subprocess', '--factory', 'contacts', '--bus-name', 'org.gnome.evolution.dataserver.Subprocess.Backend.Calendarx338x2', '--own-path', '/org/gnome/evolution/dataserver/Subprocess/Backend/Calendar/338/2'] created at 2018-11-16 22:43:22.470000 PID 373 evolution-addressbook-factory ['/usr/lib/evolution/evolution-addressbook-factory'] created at 2018-11-16 22:43:22.650000 PID 375 evolution-calendar-factory-subprocess ['/usr/lib/evolution/evolution-calendar-factory-subprocess', '--factory', 'local', '--bus-name', 'org.gnome.evolution.dataserver.Subprocess.Backend.Calendarx338x3', '--own-path', '/org/gnome/evolution/dataserver/Subprocess/Backend/Calendar/338/3'] created at 2018-11-16 22:43:22.650000 PID 384 evolution-addressbook-factory-subprocess ['/usr/lib/evolution/evolution-addressbook-factory-subprocess', '--factory', 'local', '--bus-name', 'org.gnome.evolution.dataserver.Subprocess.Backend.AddressBookx373x2', '--own-path', '/org/gnome/evolution/dataserver/Subprocess/Backend/AddressBook/373/2'] created at 2018-11-16 22:43:22.800000 PID 399 gvfsd-metadata ['/usr/lib/gvfs/gvfsd-metadata'] created at 2018-11-16 22:43:22.860000 PID 439 zeitgeist-datahub ['zeitgeist-datahub'] created at 2018-11-16 22:43:41.810000 PID 446 sh ['/bin/sh', '-c', '/usr/lib/x86_64-linux-gnu/zeitgeist/zeitgeist-maybe-vacuum; /usr/bin/zeitgeist-daemon'] created at 2018-11-16 22:43:41.820000 PID 450 zeitgeist-daemon ['/usr/bin/zeitgeist-daemon'] created at 2018-11-16 22:43:41.830000 PID 456 zeitgeist-datah [] created at 2018-11-16 22:43:41.850000 PID 467 update-notifier ['update-notifier'] created at 2018-11-16 22:44:21.810000
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 58•6 years ago
|
||
what are the next steps to move forward here? This seems like a linux docker image issue in general- do we have an owner for that?
Flags: needinfo?(klibby)
Flags: needinfo?(dustin)
|
|
||
Comment 59•6 years ago
|
||
That would be the build team -- the people commenting on this bug.
Flags: needinfo?(klibby)
Flags: needinfo?(dustin)
|
|
||
Comment 60•6 years ago
|
||
Can one of you three recommend the next steps here? I see this bug and while it appears to cause android failures, :gbrown pointed out there are many other issues with the image in general.
Flags: needinfo?(ted)
Flags: needinfo?(mh+mozilla)
Flags: needinfo?(gps)
|
|
Assignee | |
Comment 61•6 years ago
|
||
I don't think there's an obvious owner to this problem :/ Per the modules system, the code falls in the Taskgraph module, which is a sub-module of the build system. The respective module owners are Dustin and me. However, the Docker images - like the task definitions - are typically maintained by the people who need them. e.g. the build team manages the Docker images used to build Firefox. The Docker files just happen to be located in source control in an area governed by the Taskgraph module. So, the owner of the desktop1604-test image would be the people who need that module - namely the owners of test automation. That being said, I think the current way we manage Docker images is sub-optimal because it can lead to non-deterministic surprises like this. This bug is the latest in a line of similar, productivity-sucking issues. I'd prefer if we had a more robust and more deterministic way of building Docker images so all Docker images weren't susceptible to issues like this. A good first step is to convert all Docker images to Debian so we can support Debian's snapshotted package archives. But my understanding is that changing the image backing the unified test image is a large endeavor. I recall the upgrade to Ubuntu 16.04 taking months because of test fallout. But converting all images to Debian isn't sufficient: we would still incur a dependency on a 3rd party service - a 3rd party service that has historically been unreliable. (Bug 1461802 tracks this.) There has been talk of standing up our own package mirror or proxy to alleviate the 3rd party service instability. I seriously barked up this tree last year. I even have some formal proposals somewhere. However, at the time, Amy Rich was (justifiably) reluctant to stand up yet another new piece of server infrastructure while her team was bogged down with other important work. And the Taskcluster team (which is the other team that traditionally operates server infrastructure for CI) seems to always be backlogged and my recollection is they weren't too keen on yet another new piece of server infrastructure. I was willing to lend my time to the effort earlier this year. But that was disrupted / fell through the cracks by a reorg :/ Regardless of what we do in the medium or long term, we need to fix the Docker image as-is because we'll likely be unable to reproduce the previous state of the image, since various package versions have disappeared from Apt package repos. I'd like to think the owner should be the image owner, which are the people responsible for the test infrastructure. It isn't fair to them that others have created this mess and they don't exactly have the ability to easily transition to a deterministic and reliable image building process :/ FWIW this bug blocks a multi-month project I've been working on and once I finish my work and am hard blocked on this bug, I will likely do whatever it takes to unblock my work. i.e. I'll investigate and try to fix this bug. That could potentially happen this week. But I'm not a domain expert in this Docker image and all its nuances. (I've broken this image before by making changes I thought were OK.) I suspect someone else could debug things more efficiently than me and I would (selfishly) prefer that be the outcome. But if this bug is still blocking me in a few days, I'll likely jump in.
Flags: needinfo?(ted)
Flags: needinfo?(gps)
|
|
||
Comment 62•6 years ago
|
||
One way around this bug is to avoid any change to the desktop1604-test image, and do all the changes in an image derived from it. One way to do that would be to copy all the files that participate in the image to some other location, where they'll stay untouched, then create another image that copies the original files on top of that. That will keep some changes from happening still, though, like adding new packages. Note that switching from Ubuntu to Debian might end up hitting the same underlying bug than what is hitting us here, which looks like it's related to how we prepare the desktop environment for the tests.
Flags: needinfo?(mh+mozilla)
|
|
Assignee | |
Comment 63•6 years ago
|
||
Back in the day we had hacky *-upd images building on top of base images which were uploaded to the Docker Hub/Registry. We could upload the last good desktop1604-test image somewhere (or reference an artifact via taskgraph shenanigans) and layer our new customizations on top of that. Super hacky. But it would unblock others. If we go with this approach, we'll be introducing yet another out-of-repo dependency on image generation that could fail at any point in the future if the base image disappears. This could e.g. impact release or ESR image regeneration several months from now. That risk is on par - but is likely slightly greater than - our current reliance on 3rd party servers for providing .deb packages. Also, it doesn't fix the underlying issue. Eventually someone will want to upgrade to a newer system package version and we could be in a bind due to wonky incompatibilities. I remember this scenario (involving valgrind?) that caused us significant headaches 1+ year ago. It's much better to fix the underlying issue now instead of kicking the can down the road. And it may be easier to fix the underlying issue, as layering hacks on Docker image building has costs. We abandoned the old approach for a reason.
|
|
||
Updated•6 years ago
|
Blocks: 1507012
|
||
Comment 64•6 years ago
|
||
Wander: do you have any docker expertise you could bring to bear here? It's blocking the deployment of hg 4.8
Flags: needinfo?(wcosta)
|
||
Comment 65•6 years ago
|
||
Something tells me that it could be related to the udev upgrade. The diff between the version is not small, see https://gist.github.com/rail/51c1293a1c7c9a35e199a95d1232d97d. This package may affect ALL the things. :)
|
||
Comment 66•6 years ago
|
||
(In reply to Chris Cooper [:coop] pronoun: he from comment #64) > Wander: do you have any docker expertise you could bring to bear here? It's > blocking the deployment of hg 4.8 Previous comments from :gps and :glandium were correct. I remember when working on migration, I had to put things in the derived images because the simple act of rebuilding desktop1604-test was enough to break tests.
Flags: needinfo?(wcosta)
|
|
||
Comment 67•6 years ago
|
||
Also we can try using `xenial-*` tags from https://hub.docker.com/r/library/ubuntu/tags/ instead of using "FROM: ubuntu:16.04".
|
||
Comment 68•6 years ago
|
||
(In reply to Gregory Szorc [:gps] from comment #61) > > But converting all images to Debian isn't sufficient: we would still incur a > dependency on a 3rd party service - a 3rd party service that has > historically been unreliable. (Bug 1461802 tracks this.) There has been talk > of standing up our own package mirror or proxy to alleviate the 3rd party > service instability. I seriously barked up this tree last year. I even have > some formal proposals somewhere. We did end up making something very similar to your recommendation, actually. It's specifically for our infrastructure, but we can look at either expanding its scope or standing up something similar for CI. It's pretty simple, with an S3 bucket, lambda function, and an ec2 instance. > Regardless of what we do in the medium or long term, we need to fix the > Docker image as-is because we'll likely be unable to reproduce the previous > state of the image, since various package versions have disappeared from Apt > package repos. I'd like to think the owner should be the image owner, which > are the people responsible for the test infrastructure. It isn't fair to > them that others have created this mess and they don't exactly have the > ability to easily transition to a deterministic and reliable image building > process :/ Process is the other big problem, IMO. We don't roll out changes to the hardware images without first running it through our staging systems and verifying that tests are green. I would expect that we would do something similar with docker images. I'd also expect that should be able to roll back docker images, but that appears to not be the case?
|
|
||
Comment 69•6 years ago
|
||
Docker image changes occur in try pushes, so no need for staging. The issue here is that we need to make changes to the docker image, the original sources (apt packages) are no longer available, and what is available causes test failures.
|
|
||
Comment 71•6 years ago
|
||
(In reply to Rail Aliiev [:rail] ⌚️ET from comment #67) > Also we can try using `xenial-*` tags from > https://hub.docker.com/r/library/ubuntu/tags/ instead of using "FROM: > ubuntu:16.04". I played with these, but it didn't help.
|
|
||
Comment 72•6 years ago
|
||
(In reply to Rail Aliiev [:rail] ⌚️ET from comment #67) > Also we can try using `xenial-*` tags from > https://hub.docker.com/r/library/ubuntu/tags/ instead of using "FROM: > ubuntu:16.04". That's an interesting idea, but would probably require some package pinning to avoid some of the packages from the original docker image being upgraded.
|
|
Assignee | |
Comment 73•6 years ago
|
||
In order to be deterministic over time, we need something storing snapshots of the Apt repository package indices and for files referenced by those snapshots to be available for all of time. There are tools like https://www.aptly.info/ that would allow us to e.g. host things in an S3 bucket. I have experimented with technical solutions to this problem - including standing up Apt mirrors and performing snapshots with ZFS/Btrfs and exposing those snapshots over HTTP - similar to what archive.debian.org does. Any solution we roll out needs to live "forever" since code under version control will forever reference that service to build Docker images. The stumbling block in the past was finding a team willing to be the owner of the infrastructure.
|
|
||
Comment 74•6 years ago
|
||
(In reply to Gregory Szorc [:gps] from comment #73) > In order to be deterministic over time, we need something storing snapshots > of the Apt repository package indices and for files referenced by those > snapshots to be available for all of time. > > There are tools like https://www.aptly.info/ that would allow us to e.g. > host things in an S3 bucket. I have experimented with technical solutions to > this problem - including standing up Apt mirrors and performing snapshots > with ZFS/Btrfs and exposing those snapshots over HTTP - similar to what > archive.debian.org does. Any solution we roll out needs to live "forever" > since code under version control will forever reference that service to > build Docker images. Yup; Jake originally looked at using btrfs but we ended up going a different route with the s3 bucket. I'll try and dig up his design doc and get it to you. > The stumbling block in the past was finding a team > willing to be the owner of the infrastructure. I'm fairly certain that will fall to either myself or Habib; I think we just need to hash a few things out. News as I get it, don't take this as gospel, void where prohibited, etc :-)
|
|
Assignee | |
Comment 75•6 years ago
|
||
We decided to create a one-off image using the last known good base image of desktop1604-test as a workaround. I've filed bug 1511527 to track unforking the image. I'm actively working on this. So assigning to me. When I started work an hour or two ago, I thought I'd be done by now. But I'm hitting issues with Docker where changes in an upper image layer matching those in the base layer seem to be hitting bugs in Docker (specifically its storage drivers). Docker is a real piece of work...
Assignee: nobody → gps
Status: NEW → ASSIGNED
|
|
Assignee | |
Updated•6 years ago
|
Component: WebRTC → Task Configuration
Product: Core → Firefox Build System
|
|
Assignee | |
Comment 76•6 years ago
|
||
It is only used by this image. No need to have it hang out in recipes. Note: this commit landing in isolation will result in the building of a bad Docker image. The commit after this that copies the ubuntu1604-test image is necessary to prevent task bustage.
|
|
Assignee | |
Comment 77•6 years ago
|
||
DO NOT LAND UNTIL indygreg/ REFERENCE IS REMOVED FROM Dockerfile! The desktop1604-test image doesn't build deterministically, primarily due to not pinning APT package indices. Rebuilding it from scratch today results in at least 2 problems causing test failures. One has to due with a renamed media device. Another is not yet determined but is causing the Android emulator to fail. Various people have spent several hours trying to debug the failures. There are some leads. But no obvious solution is in sight. Various code landings are blocked on this. Enough is enough. This commit creates a copy of the desktop1604-test image and modifies it so it inherits from a base image that contains the last good build of the image. Other minimal modifications were made to enable the image to build with a populated base image. References to the old image have been updated to point to this new image. This is a gross hack. But it gets the job done. It should unblock various code landings. The base image was imported from task K-qJkvIqQQ-EFK8-4zg_nA. The intent is to undo this hack ASAP by fixing the base image. This is tracked by bug 1511527. As part of developing this patch, I ran into at least two different issues building the Docker image using the last known good image as a base. On my desktop machine using btrfs for Docker storage, the image failed to build due to a "failed to export image: failed to create image: failed to get layer XXX: layer does not exist" error. In CI, I ran into separate issues where some `rm` invocations didn't work. Why, I have no clue. I ran a `docker export | docker import` of a running container with the good image to produce a new Docker image with just the filesystem contents. This had the effect of squashing the original Docker image into a single layer. For reasons I can't explain, this made the image build in CI. Welcome to the wonderful world of Docker bugs, everyone.
|
||
Updated•6 years ago
|
Attachment #9029096 -
Attachment is obsolete: true
|
|
||
Updated•6 years ago
|
Attachment #9029097 -
Attachment description: Bug 1503756 - Create desktop1604-test-upd image to work around non-deterministic rebuilding; r?dustin → Bug 1503756 - Inherit from working desktop1604-test image to work around non-deterministic rebuilding; r?dustin
|
|
||
Comment 78•6 years ago
|
||
Pushed by gszorc@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/12750da9341c Inherit from working desktop1604-test image to work around non-deterministic rebuilding; r=dustin
|
|
Assignee | |
Comment 79•6 years ago
|
||
The workaround landed and I /think/ I relanded or tried to land all patches in bugs depending on this one. Please check blocked bugs for activity.
|
||
Comment 80•6 years ago
|
||
| bugherder | ||
https://hg.mozilla.org/mozilla-central/rev/12750da9341c
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox65:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 65
|
||
Updated•6 years ago
|
Target Milestone: Firefox 65 → mozilla65
|
||
Comment 81•6 years ago
|
||
| bugherder uplift | ||
https://hg.mozilla.org/releases/mozilla-esr60/rev/68843d2182e8
status-firefox-esr60:
--- → fixed
You need to log in
before you can comment on or make changes to this bug.
Description
•