browser_permissionsPrompt[Allow|Deny|Worker].js fails 100% on multi-core docker containers and 40% on single core

NEW
Unassigned

Status

()

Core
DOM: IndexedDB
2 years ago
2 years ago

People

(Reporter: jmaher, Unassigned)

Tracking

(Blocks: 1 bug)

Trunk
Points:
---

Firefox Tracking Flags

(firefox46 affected)

Details

(Reporter)

Description

2 years ago
in comparing a single core vs multi core docker container for running tests, we find a few tests which have different behaviors (bug 1237024).  In this case I care about:
TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptAllow.js | at least one notification displayed
...
TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptDeny.js | at least one notification displayed
...
TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptWorker.js | at least one notification displayed
...

these are all from this logfile:
https://public-artifacts.taskcluster.net/H6fTTb2dT-SDqqv33XUBYA/0/public/logs/live_backing.log

and a clip from the above linked log:
12:37:52     INFO -  146 INFO TEST-START | dom/indexedDB/test/browser_permissionsPromptWorker.js
12:37:52     INFO -  ++DOCSHELL 0x7f0bf29d7800 == 12 [pid = 1310] [id = 30]
12:37:52     INFO -  ++DOMWINDOW == 23 (0x7f0bf2984c00) [pid = 1310] [serial = 73] [outer = (nil)]
12:37:52     INFO -  ++DOMWINDOW == 24 (0x7f0bf5e70800) [pid = 1310] [serial = 74] [outer = 0x7f0bf2984c00]
12:37:52     INFO -  ++DOMWINDOW == 25 (0x7f0bf6241800) [pid = 1310] [serial = 75] [outer = 0x7f0bf2984c00]
12:37:54     INFO -  Not taking screenshot here: see the one that was previously logged
12:37:54     INFO -  147 INFO checking window state
12:37:54     INFO -  148 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
12:37:54     INFO -  149 INFO creating tab
12:37:54     INFO -  150 INFO loading test page: http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsWorker.html
12:37:54     INFO -  151 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
12:37:54     INFO -  152 INFO Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsWorker.html" line: 0}]
12:37:54     INFO -  153 INFO TEST-PASS | dom/indexedDB/test/browser_permissionsPromptWorker.js | prompt showing -
12:37:54     INFO -  154 INFO TEST-PASS | dom/indexedDB/test/browser_permissionsPromptWorker.js | prompt hidden -
12:37:54     INFO -  155 INFO TEST-PASS | dom/indexedDB/test/browser_permissionsPromptWorker.js | prompt shown -
12:37:54     INFO -  156 INFO triggering main command
12:37:54     INFO -  157 INFO TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptWorker.js | at least one notification displayed -
12:37:54     INFO -  Stack trace:
12:37:54     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/head.js:triggerMainCommand:46
12:37:54     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/browser_permissionsPromptWorker.js:test1/</<:44
12:37:54     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/head.js:registerPopupEventHandler/gActiveListeners[eventName]:17
12:37:54     INFO -  JavaScript error: chrome://mochitests/content/browser/dom/indexedDB/test/head.js, line 48: TypeError: notification is undefined
12:37:54     INFO -  158 INFO Console message: [JavaScript Error: "TypeError: notification is undefined" {file: "chrome://mochitests/content/browser/dom/indexedDB/test/head.js" line: 48}]
12:38:01     INFO -  --DOCSHELL 0x7f0beb526000 == 11 [pid = 1310] [id = 25]
12:38:01     INFO -  --DOCSHELL 0x7f0bf59da000 == 10 [pid = 1310] [id = 28]
12:38:07     INFO -  --DOMWINDOW == 24 (0x7f0bf2227800) [pid = 1310] [serial = 61] [outer = (nil)] [url = about:blank]
12:38:07     INFO -  --DOMWINDOW == 23 (0x7f0bf5e70800) [pid = 1310] [serial = 74] [outer = (nil)] [url = about:blank]
12:38:07     INFO -  --DOMWINDOW == 22 (0x7f0bef7b5800) [pid = 1310] [serial = 60] [outer = (nil)] [url = about:blank]
12:38:07     INFO -  --DOMWINDOW == 21 (0x7f0bebae9000) [pid = 1310] [serial = 68] [outer = (nil)] [url = http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsPrompt.html]
12:38:13     INFO -  --DOMWINDOW == 20 (0x7f0bf6408000) [pid = 1310] [serial = 70] [outer = (nil)] [url = http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsPrompt.html]
12:38:24     INFO -  [1310] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 19827
12:38:24     INFO -  [1310] ###!!! ASSERTION: wrong thread: 'NS_IsMainThread()', file /home/worker/workspace/build/src/netwerk/base/nsIOService.cpp, line 604
12:38:24     INFO -  #01: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #02: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #03: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #04: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #05: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #06: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #07: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #08: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #09: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #10: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #11: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #12: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #13: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #14: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #15: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #16: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #17: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #18: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #19: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #20: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #21: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #22: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #23: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #24: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #25: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #26: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #27: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #28: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #29: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #30: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #31: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:24     INFO -  #32: ??? (/home/worker/workspace/build/application/firefox/libnspr4.so)
12:38:24     INFO -  #33: start_thread (/lib/x86_64-linux-gnu/libpthread.so.0)
12:38:26     INFO -  #34: clone (/lib/x86_64-linux-gnu/libc.so.6)
12:38:26     INFO -  159 INFO Console message: [JavaScript Error: "InvalidStateError" {file: "http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsWorker.js" line: 2}]
12:38:26     INFO -  160 INFO got finished callback
12:38:26     INFO -  Not taking screenshot here: see the one that was previously logged
12:38:26     INFO -  161 INFO TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptWorker.js | First database creation was successful -
12:38:26     INFO -  Stack trace:
12:38:26     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/browser_permissionsPromptWorker.js:test1/</<:30
12:38:26     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/head.js:setFinishedCallback/testPage.testFinishedCallback/<:99
12:38:26     INFO -  Not taking screenshot here: see the one that was previously logged
12:38:26     INFO -  162 INFO TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptWorker.js | No exception -
12:38:26     INFO -  Stack trace:
12:38:26     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/browser_permissionsPromptWorker.js:test1/</<:31
12:38:26     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/head.js:setFinishedCallback/testPage.testFinishedCallback/<:99
12:38:26     INFO -  Not taking screenshot here: see the one that was previously logged
12:38:26     INFO -  163 INFO TEST-UNEXPECTED-FAIL | dom/indexedDB/test/browser_permissionsPromptWorker.js | Correct permission set - Got 0, expected 1
12:38:26     INFO -  Stack trace:
12:38:26     INFO -  chrome://mochikit/content/browser-test.js:test_is:958
12:38:26     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/browser_permissionsPromptWorker.js:test1/</<:32
12:38:26     INFO -  chrome://mochitests/content/browser/dom/indexedDB/test/head.js:setFinishedCallback/testPage.testFinishedCallback/<:99
12:38:26     INFO -  164 INFO creating tab
12:38:26     INFO -  ++DOCSHELL 0x7f0bf5cba800 == 11 [pid = 1310] [id = 31]
12:38:26     INFO -  ++DOMWINDOW == 21 (0x7f0bf6207000) [pid = 1310] [serial = 76] [outer = (nil)]
12:38:26     INFO -  ++DOMWINDOW == 22 (0x7f0bf624a800) [pid = 1310] [serial = 77] [outer = 0x7f0bf6207000]
12:38:26     INFO -  165 INFO loading test page: http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsSharedWorker.html
12:38:26     INFO -  166 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
12:38:26     INFO -  ++DOMWINDOW == 23 (0x7f0bf66e2000) [pid = 1310] [serial = 78] [outer = 0x7f0bf6207000]
12:38:26     INFO -  167 INFO Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsSharedWorker.html" line: 0}]
12:38:26     INFO -  [1310] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 19827
12:38:26     INFO -  168 INFO got finished callback
12:38:26     INFO -  169 INFO TEST-PASS | dom/indexedDB/test/browser_permissionsPromptWorker.js | First database creation was successful -
12:38:26     INFO -  170 INFO TEST-PASS | dom/indexedDB/test/browser_permissionsPromptWorker.js | No exception -
12:38:26     INFO -  171 INFO TEST-PASS | dom/indexedDB/test/browser_permissionsPromptWorker.js | Correct permission set -
12:38:26     INFO -  [1310] ###!!! ASSERTION: wrong thread: 'NS_IsMainThread()', file /home/worker/workspace/build/src/netwerk/base/nsIOService.cpp, line 604
12:38:26     INFO -  #01: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #02: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #03: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #04: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #05: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #06: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #07: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #08: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #09: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #10: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #11: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #12: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #13: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #14: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #15: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #16: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #17: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #18: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #19: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #20: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #21: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #22: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #23: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #24: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #25: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #26: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #27: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #28: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #29: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #30: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #31: ??? (/home/worker/workspace/build/application/firefox/libxul.so)
12:38:26     INFO -  #32: ??? (/home/worker/workspace/build/application/firefox/libnspr4.so)
12:38:26     INFO -  #33: start_thread (/lib/x86_64-linux-gnu/libpthread.so.0)
12:38:26     INFO -  #34: clone (/lib/x86_64-linux-gnu/libc.so.6)
12:38:26     INFO -  ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
12:38:26     INFO -  172 INFO Console message: [JavaScript Error: "InvalidStateError" {file: "http://mochi.test:8888/browser/dom/indexedDB/test/browser_permissionsSharedWorker.js" line: 3}]
12:38:27     INFO -  173 INFO TEST-FAIL | dom/indexedDB/test/browser_permissionsPromptWorker.js | Assertion count 2 is greater than expected range 0-0 assertions. -
12:38:27     INFO -  MEMORY STAT | vsize 1117MB | residentFast 266MB | heapAllocated 64MB
12:38:27     INFO -  174 INFO TEST-OK | dom/indexedDB/test/browser_permissionsPromptWorker.js | took 34908ms


overall this is comparing a new environment (unittests in docker with a potentially incomplete base image) and single core vs multi-core.  Our current unittests run in single core for linux.  This is interesting as we fail all the time in multi-core.

Maybe this is an indication the tests or the indexeddb code in firefox could be cleaned up.
I'm probably missing something but how does the # of cores not make this happen on people's multi-core desktops all the time?
Flags: needinfo?(jmaher)
(Reporter)

Comment 2

2 years ago
a great question, one I don't have an answer for, a few thoughts though:

* buildbot automation (production/try) runs on a single core similar base image
* this comparison was done in a docker image running a custom base image- so different environment.
* developers probably do not run this test all the time, only related browser chrome tests as many failures occur locally, especially in linux.
Flags: needinfo?(jmaher)
I ran ./mach mochitest --run-until-failure dom/indexedDB/test/browser_permissionsPromptWorker.js a few times and never ran into a failure on my multi-core Linux box.

I tried to run the exact docker setup as the tests but I think it's failing because /home/worker doesn't exist. https://tools.taskcluster.net/task-inspector/#H6fTTb2dT-SDqqv33XUBYA/ Do you know what I'm doing wrong?
Flags: needinfo?(jmaher)
(Reporter)

Comment 4

2 years ago
you are ambitious.  The steps there should work, here are some step by step instructions that I use:
docker pull elvis314/desktop-test:0.5.3
# ensure v4l2loopback installed and modprobe is done
docker run -ti \
  --name "${container_name}" \
  -e MOZILLA_BUILD_URL='https://queue.taskcluster.net/v1/task/LjP6zaoJS1Wcfhd4TM_74Q/artifacts/public/build/target.tar.bz2' \
  -e MOZHARNESS_SCRIPT='mozharness/scripts/desktop_unittest.py' \
  -e GECKO_HEAD_REPOSITORY='https://hg.mozilla.org/try/' \
  -e MOZHARNESS_URL='https://queue.taskcluster.net/v1/task/LjP6zaoJS1Wcfhd4TM_74Q/artifacts/public/build/mozharness.zip' \
  -e NEED_PULSEAUDIO='true' \
  -e NEED_WINDOW_MANAGER='true' \
  -e MOZHARNESS_CONFIG='mozharness/configs/unittests/linux_unittest.py mozharness/configs/remove_executables.py
' \
  -e GECKO_HEAD_REV='dc7a5af7556ebbd3cd04e8c1c1ac5f00a1e34bc1' \
  --device /dev/video1:/dev/video1 \
  --device /dev/snd/controlC0:/dev/snd/controlC0 \
  --device /dev/snd/pcmC0D0c:/dev/snd/pcmC0D0c \
  --device /dev/snd/pcmC0D0p:/dev/snd/pcmC0D0p \
  --device /dev/snd/pcmC0D1c:/dev/snd/pcmC0D1c \
  --device /dev/snd/pcmC0D1p:/dev/snd/pcmC0D1p \
  ${image_name}

# ^ NOTE: the above I edited --device to have /dev/video1 instead of video0; the /dev/snd might be different on your system

next I do a lot of hacking to get the data on the system.  If you just run:
bash /home/worker/bin/test.sh --no-read-buildbot-config '--installer-url=https://queue.taskcluster.net/v1/task/LjP6zaoJS1Wcfhd4TM_74Q/artifacts/public/build/target.tar.bz2' '--test-packages-url=https://queue.taskcluster.net/v1/task/LjP6zaoJS1Wcfhd4TM_74Q/artifacts/public/build/test_packages.json' '--download-symbols=ondemand' '--mochitest-suite=browser-chrome-chunked' '--total-chunk=7' '--this-chunk=5'

then when it is done, you can manually go in and run what you are looking for (sorry, it is a lot of steps otherwise).  Here is what I do after things are downloaded:
root # dbus-daemon --system --fork
root # su worker
worker # cd /home/worker/workspace/build
worker # . venv/bin/activate
worker # pulseaudio --fail --daemonize --start
worker # pactl load-module module-null-sink
worker # Xvfb :0 -nolisten tcp -screen 0 1600x1200x24 &
worker # gnome-shell &
worker # x11vnc &
worker # python -u /home/worker/workspace/build/tests/mochitest/runtests.py --appname=/home/worker/workspace/build/application/firefox/firefox --utility-path=tests/bin --extra-profile-file=tests/bin/plugins --symbols-path=https://queue.taskcluster.net/v1/task/U__1NP7EQ0WVtkOcPNwI6A/artifacts/public/build/target.crashreporter-symbols.zip --certificate-path=tests/certs --setpref=webgl.force-enabled=true --use-test-media-devices --browser-chrome dom/indexedDB/test

this seems to reproduce for me.
Flags: needinfo?(jmaher)
I wonder if this could be caused by bug 1245239.
(Reporter)

Comment 6

2 years ago
that could be, we just started looking at increasing the /dev/shm space- might be worth a try after we increase that.
You need to log in before you can comment on or make changes to this bug.