Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=430335488&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/f0BM7H39QD6gP0KXFe3x3A/runs/0/artifacts/public/logs/live_backing.log
DEBUG: Completed blocker Transaction (6) for phase content-prefs.sqlite#0: waiting for clients
[task 2023-09-26T10:50:55.665Z] 10:50:55 INFO - 1695725455664 Marionette DEBUG 2 -> [0,24,"WebDriver:ExecuteScript",{"script":"const [idb, store, key, value] = arguments;\n window.wrappedJSObject.addDataIntoIDB(idb, store, key, value);","args":["IDBTest","IDBTestStore","textKey","test_IDB_Encryption_PBM"],"newSandbox":true,"sandbox":"default","line":94,"filename":"tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py"}]
[task 2023-09-26T10:50:55.677Z] 10:50:55 INFO - 1695725455677 RemoteAgent TRACE WebDriverProcessData actor created for PID 29952
[task 2023-09-26T10:50:55.687Z] 10:50:55 INFO - 1695725455687 Marionette TRACE [14] MarionetteCommands actor created for window id 6442450945
[task 2023-09-26T10:50:55.711Z] 10:50:55 INFO - 1695725455711 Marionette DEBUG 2 <- [1,24,null,{"value":null}]
[task 2023-09-26T10:50:55.713Z] 10:50:55 INFO - 1695725455712 Marionette DEBUG 2 -> [0,25,"Marionette:GetContext",{}]
[task 2023-09-26T10:50:55.714Z] 10:50:55 INFO - 1695725455713 Marionette DEBUG 2 <- [1,25,null,{"value":"content"}]
[task 2023-09-26T10:50:55.715Z] 10:50:55 INFO - 1695725455715 Marionette DEBUG 2 -> [0,26,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-09-26T10:50:55.716Z] 10:50:55 INFO - 1695725455716 Marionette DEBUG 2 <- [1,26,null,{"value":null}]
[task 2023-09-26T10:50:55.718Z] 10:50:55 INFO - 1695725455717 Marionette DEBUG 2 -> [0,27,"WebDriver:ExecuteAsyncScript",{"script":"const [url, resolve] = arguments;\n\n function getOrigin() {\n return new Promise((res ... Origin()\n .then((result) => resolve(result))\n .catch((error) => resolve(null));","args":["http://127.0.0.1:43470^privateBrowsingId=1"],"newSandbox":false,"sandbox":"default","scriptTimeout":null,"line":158,"filename":"tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py"}]
[task 2023-09-26T10:50:55.720Z] 10:50:55 INFO - 1695725455720 Marionette TRACE [12] MarionetteCommands actor created for window id 26
[task 2023-09-26T10:50:55.748Z] 10:50:55 INFO - 1695725455747 Marionette DEBUG 2 <- [1,27,null,{"value":null}]
[task 2023-09-26T10:50:55.751Z] 10:50:55 INFO - 1695725455750 Marionette DEBUG 2 -> [0,28,"Marionette:SetContext",{"value":"content"}]
[task 2023-09-26T10:50:55.751Z] 10:50:55 INFO - 1695725455750 Marionette DEBUG 2 <- [1,28,null,{"value":null}]
[task 2023-09-26T10:50:55.753Z] 10:50:55 INFO - 1695725455753 Marionette DEBUG 2 -> [0,29,"Marionette:GetContext",{}]
[task 2023-09-26T10:50:55.754Z] 10:50:55 INFO - 1695725455753 Marionette DEBUG 2 <- [1,29,null,{"value":"content"}]
[task 2023-09-26T10:50:55.756Z] 10:50:55 INFO - 1695725455755 Marionette DEBUG 2 -> [0,30,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-09-26T10:50:55.756Z] 10:50:55 INFO - 1695725455756 Marionette DEBUG 2 <- [1,30,null,{"value":null}]
[task 2023-09-26T10:50:55.758Z] 10:50:55 INFO - 1695725455758 Marionette DEBUG 2 -> [0,31,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2023-09-26T10:50:55.923Z] 10:50:55 INFO - 1695725455922 Marionette DEBUG 2 <- [1,31,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4XuzdCbgkZ1kv8O9MSILJJGEJkE0SFiGAICJgcr1XUQQBJYhRFAIRL1sIKGHxkU1ikM3LL ... QIECAAAECBAgQIECAAAECBAgUAQdg0ZMlQIAAAQIECBAgQIAAAQIECBAgcC7gADwfSD0CBAgQIECAAAECBAgQIECAAAECRWCHVRroUvdOtAAAAABJRU5ErkJggg=="}]
[task 2023-09-26T10:50:55.933Z] 10:50:55 INFO - 1695725455933 Marionette DEBUG 2 -> [0,32,"Marionette:SetContext",{"value":"content"}]
[task 2023-09-26T10:50:55.933Z] 10:50:55 INFO - 1695725455933 Marionette DEBUG 2 <- [1,32,null,{"value":null}]
[task 2023-09-26T10:50:55.935Z] 10:50:55 INFO - 1695725455935 Marionette DEBUG 2 -> [0,33,"Marionette:GetContext",{}]
[task 2023-09-26T10:50:55.935Z] 10:50:55 INFO - 1695725455935 Marionette DEBUG 2 <- [1,33,null,{"value":"content"}]
[task 2023-09-26T10:50:55.937Z] 10:50:55 INFO - 1695725455937 Marionette DEBUG 2 -> [0,34,"Marionette:SetContext",{"value":"content"}]
[task 2023-09-26T10:50:55.937Z] 10:50:55 INFO - 1695725455937 Marionette DEBUG 2 <- [1,34,null,{"value":null}]
[task 2023-09-26T10:50:55.939Z] 10:50:55 INFO - 1695725455938 Marionette DEBUG 2 -> [0,35,"WebDriver:GetPageSource",{}]
[task 2023-09-26T10:50:55.941Z] 10:50:55 INFO - 1695725455940 Marionette DEBUG 2 <- [1,35,null,{"value":"<html><head>\n\t\t<script>\n\t\t\tasync function ensureIDB(name, ver, store) {\n\t\t\t\treturn new Promise((resolve, reject) => {\n\t\t\t\t\tle ... \n\t\t\t\t}));\n\n\t\t\t\tcloseIDB(db)\n\t\t\t};\n\n\t\t\tfunction closeIDB(db) {\n\t\t\t\tdb.close();\n\t\t\t}\n\t\t</script>\n\t</head>\n<body>\n</body></html>"}]
[task 2023-09-26T10:50:55.942Z] 10:50:55 INFO - 1695725455942 Marionette DEBUG 2 -> [0,36,"Marionette:SetContext",{"value":"content"}]
[task 2023-09-26T10:50:55.942Z] 10:50:55 INFO - 1695725455942 Marionette DEBUG 2 <- [1,36,null,{"value":null}]
[task 2023-09-26T10:50:56.017Z] 10:50:56 INFO - TEST-UNEXPECTED-FAIL | dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py IDBEncryptionPBM.test_ensure_encrpted_sqlite_data | AssertionError
[task 2023-09-26T10:50:56.017Z] 10:50:56 INFO - Traceback (most recent call last):
[task 2023-09-26T10:50:56.017Z] 10:50:56 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 197, in run
[task 2023-09-26T10:50:56.018Z] 10:50:56 INFO - testMethod()
[task 2023-09-26T10:50:56.018Z] 10:50:56 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py", line 97, in test_ensure_encrpted_sqlite_data
[task 2023-09-26T10:50:56.019Z] 10:50:56 INFO - self.ensureInvariantHolds(lambda _: self.sqliteWALReleased())
[task 2023-09-26T10:50:56.019Z] 10:50:56 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py", line 184, in ensureInvariantHolds
[task 2023-09-26T10:50:56.020Z] 10:50:56 INFO - message=f"operation did not yield success even after waiting {maxWaitTime}s time",
[task 2023-09-26T10:50:56.020Z] 10:50:56 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/wait.py", line 131, in until
INFO - rv = condition(self.marionette)
[task 2023-09-26T10:50:56.021Z] 10:50:56 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py", line 97, in <lambda>
[task 2023-09-26T10:50:56.022Z] 10:50:56 INFO - self.ensureInvariantHolds(lambda _: self.sqliteWALReleased())
[task 2023-09-26T10:50:56.022Z] 10:50:56 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py", line 175, in sqliteWALReleased
[task 2023-09-26T10:50:56.023Z] 10:50:56 INFO - if not os.path.exists(self.getIDBStoragePath()):
[task 2023-09-26T10:50:56.023Z] 10:50:56 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py", line 117, in getIDBStoragePath
[task 2023-09-26T10:50:56.024Z] 10:50:56 INFO - self.marionette.absolute_url("")[:-1] + "^privateBrowsingId=1"
[task 2023-09-26T10:50:56.024Z] 10:50:56 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/dom/indexedDB/test/marionette/test_IDB_encryption_PBM.py", line 161, in getFullOriginMetadata
[task 2023-09-26T10:50:56.024Z] 10:50:56 INFO - assert res is not None
[task 2023-09-26T10:50:56.025Z] 10:50:56 INFO - TEST-INFO took 1800ms
[task 2023-09-26T10:50:56.026Z] 10:50:56 INFO - 1695725455945 Marionette DEBUG 2 -> [0,37,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-09-26T10:50:56.026Z] 10:50:56 INFO - 1695725455945 Marionette DEBUG 2 <- [1,37,null,{"value":null}]
[task 2023-09-26T10:50:56.027Z] 10:50:56 INFO - 1695725455946 Marionette DEBUG 2 -> [0,38,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-09-26T10:50:56.027Z] 10:50:56 INFO - 1695725455946 Marionette DEBUG 2 <- [1,38,null,{"value":null}]
[task 2023-09-26T10:50:56.028Z] 10:50:56 INFO - 1695725455947 Marionette DEBUG 2 -> [0,39,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-09-26T10:50:56.029Z] 10:50:56 INFO - 1695725455947 Marionette DEBUG 2 <- [1,39,null,{"value":null}]
[task 2023-09-26T10:50:56.029Z] 10:50:56 INFO - 1695725455948 Marionette DEBUG 2 -> [0,40,"Marionette:GetContext",{}]
[task 2023-09-26T10:50:56.030Z] 10:50:56 INFO - 1695725455948 Marionette DEBUG 2 <- [1,40,null,{"value":"content"}]
[task 2023-09-26T10:50:56.030Z] 10:50:56 INFO - 1695725455949 Marionette DEBUG 2 -> [0,41,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-09-26T10:50:56.031Z] 10:50:56 INFO - 1695725455949 Marionette DEBUG 2 <- [1,41,null,{"value":null}]
[task 2023-09-26T10:50:56.032Z] 10:50:56 INFO - 1695725455950 Marionette DEBUG 2 -> [0,42,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.importESModule(\n \"resource://gre/modules/Preferences.sys.mjs\"\n ... guments[2];\n\n prefs = new Preferences({defaultBranch: defaultBranch});\n prefs.set(pref, value);","args":["dom.indexedDB.privateBrowsing.enabled",true,false],"newSandbox":true,"sandbox":"default","line":903,"filename":"../../venv/lib/python3.7/site-packages/marionette_driver/marionette.py"}]
[task 2023-09-26T10:50:56.032Z] 10:50:56 INFO - 1695725455954 Marionette DEBUG 2 <- [1,42,null,{"value":null}]
<...>
Description
•