Closed Bug 1814281 Opened 3 years ago Closed 1 year ago

Intermittent toolkit/components/cleardata/tests/marionette/test_moved_origin_directory_cleanup.py | single tracking bug

Categories

(Toolkit :: Data Sanitization, defect, P5)

Product:
Toolkit
Component:
Data Sanitization
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
127 Branch
Tracking Flags:
Tracking Status
firefox-esr115 --- wontfix
firefox119 --- wontfix
firefox120 --- wontfix
firefox125 --- wontfix
firefox126 --- fixed
firefox127 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: saschanaz)

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell unknown])

Attachments

(4 files, 2 obsolete files)

Bug 1814281 - Give longer timeout value for test_ensure_cleanup_at_crashed_restart r=smaug,#dom-storage-reviewers
48 bytes, text/x-phabricator-request
Details | Review
Bug 1814281 - Make sure the pref is written before crash in cleanup test r=smaug
48 bytes, text/x-phabricator-request
Details | Review
Bug 1814281 - Add more logs to confirm sanitization runs r=pbz
48 bytes, text/x-phabricator-request
Details | Review
Bug 1814281 - Wait until cookie-saved-on-disk r=valentin
48 bytes, text/x-phabricator-request
dmeehan
: approval-mozilla-beta+
Details | Review

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

[task 2023-01-31T21:03:05.966Z] 21:03:05     INFO -  DEBUG: Adding blocker JSON store: writing data for 'shieldpreferenceexperiments' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-01-31T21:03:07.930Z] 21:03:07     INFO -  1675198987931	Marionette	DEBUG	2 -> [0,3,"Marionette:GetContext",{}]
[task 2023-01-31T21:03:07.930Z] 21:03:07     INFO -  1675198987931	Marionette	DEBUG	2 <- [1,3,null,{"value":"content"}]
[task 2023-01-31T21:03:07.932Z] 21:03:07     INFO -  1675198987932	Marionette	DEBUG	2 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-01-31T21:03:07.933Z] 21:03:07     INFO -  1675198987932	Marionette	DEBUG	2 <- [1,4,null,{"value":null}]
[task 2023-01-31T21:03:07.933Z] 21:03:07     INFO -  1675198987933	Marionette	DEBUG	2 -> [0,5,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2023-01-31T21:03:07.936Z] 21:03:07     INFO -  1675198987936	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 8292
[task 2023-01-31T21:03:07.937Z] 21:03:07     INFO -  1675198987937	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2023-01-31T21:03:07.972Z] 21:03:07     INFO -  1675198987972	Marionette	DEBUG	2 <- [1,5,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAP/CAYAAACf8GEBAAAgAElEQVR4XuzdC5hlZXkn+q/6fuMOcrFFVBCdQURUwIDG63kYfY7iiRpNSKIYY5TEW4yXeZ4xmMk5i ... YAQIECBAgQIAAAQIECBAgQIAAgYKAA7Cwko4ECBAgQIAAAQIECBAgQIAAAQIETgEH4AknRoAAAQIECBAgQIAAAQIECBAgQKAgMGKaFzw+qPXIAAAAAElFTkSuQmCC"}]
[task 2023-01-31T21:03:07.973Z] 21:03:07     INFO -  1675198987973	Marionette	DEBUG	2 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2023-01-31T21:03:07.974Z] 21:03:07     INFO -  1675198987973	Marionette	DEBUG	2 <- [1,6,null,{"value":null}]
[task 2023-01-31T21:03:07.974Z] 21:03:07     INFO -  1675198987974	Marionette	DEBUG	2 -> [0,7,"Marionette:GetContext",{}]
[task 2023-01-31T21:03:07.974Z] 21:03:07     INFO -  1675198987974	Marionette	DEBUG	2 <- [1,7,null,{"value":"content"}]
[task 2023-01-31T21:03:07.975Z] 21:03:07     INFO -  1675198987975	Marionette	DEBUG	2 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2023-01-31T21:03:07.975Z] 21:03:07     INFO -  1675198987975	Marionette	DEBUG	2 <- [1,8,null,{"value":null}]
[task 2023-01-31T21:03:07.976Z] 21:03:07     INFO -  1675198987976	Marionette	DEBUG	2 -> [0,9,"WebDriver:GetPageSource",{}]
[task 2023-01-31T21:03:07.979Z] 21:03:07     INFO -  1675198987979	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 7408
[task 2023-01-31T21:03:07.980Z] 21:03:07     INFO -  1675198987980	Marionette	TRACE	[3] MarionetteCommands actor created for window id 2147483649
[task 2023-01-31T21:03:07.982Z] 21:03:07     INFO -  1675198987981	Marionette	DEBUG	2 <- [1,9,null,{"value":"<html><head></head><body></body></html>"}]
[task 2023-01-31T21:03:07.982Z] 21:03:07     INFO -  1675198987982	Marionette	DEBUG	2 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2023-01-31T21:03:07.982Z] 21:03:07     INFO -  1675198987982	Marionette	DEBUG	2 <- [1,10,null,{"value":null}]
[task 2023-01-31T21:03:07.988Z] 21:03:07    ERROR -  TEST-UNEXPECTED-ERROR | toolkit/components/cleardata/tests/marionette/test_moved_origin_directory_cleanup.py MovedOriginDirectoryCleanupTestCase.test_ensure_cleanup_at_crashed_restart | marionette_driver.errors.TimeoutException: Timed out after 5.1 seconds with message: to-be-removed subdirectory must disappear
[task 2023-01-31T21:03:07.988Z] 21:03:07     INFO -  Traceback (most recent call last):
[task 2023-01-31T21:03:07.988Z] 21:03:07     INFO -    File "Z:\task_167519286477438\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2023-01-31T21:03:07.988Z] 21:03:07     INFO -      testMethod()
[task 2023-01-31T21:03:07.989Z] 21:03:07     INFO -    File "Z:\task_167519286477438\build\tests\marionette\tests\toolkit\components\cleardata\tests\marionette\test_moved_origin_directory_cleanup.py", line 57, in test_ensure_cleanup_at_crashed_restart
[task 2023-01-31T21:03:07.989Z] 21:03:07     INFO -      Wait(self.marionette).until(
[task 2023-01-31T21:03:07.989Z] 21:03:07     INFO -    File "Z:\task_167519286477438\build\venv\lib\site-packages\marionette_driver\wait.py", line 153, in until
[task 2023-01-31T21:03:07.990Z] 21:03:07     INFO -      raise errors.TimeoutException(
[task 2023-01-31T21:03:07.990Z] 21:03:07     INFO -  TEST-INFO took 25375ms
[task 2023-01-31T21:03:07.990Z] 21:03:07     INFO -  1675198987988	Marionette	DEBUG	2 -> [0,11,"WebDriver:DeleteSession",{}]
[task 2023-01-31T21:03:07.990Z] 21:03:07     INFO -  1675198987989	Marionette	TRACE	[1] MarionetteCommands actor destroyed for window id 2
[task 2023-01-31T21:03:07.990Z] 21:03:07     INFO -  1675198987989	Marionette	TRACE	[3] MarionetteCommands actor destroyed for window id 2147483649
[task 2023-01-31T21:03:07.991Z] 21:03:07     INFO -  1675198987991	Marionette	DEBUG	2 <- [1,11,null,{"value":null}]
[task 2023-01-31T21:03:07.991Z] 21:03:07     INFO -  1675198987991	Marionette	DEBUG	Closed connection 2
[task 2023-01-31T21:03:08.948Z] 21:03:08     INFO -  TEST-START | toolkit/components/cleardata/tests/marionette/test_moved_origin_directory_cleanup.py MovedOriginDirectoryCleanupTestCase.test_ensure_cleanup_by_quit

First occurrence in this range: range of retriggers and backfills

Any chance this could be caused by Bug 1809526?
Kagami, can you take a look please?
Thank you.

Flags: needinfo?(krosylight)
Whiteboard: [retriggered]
Flags: needinfo?(krosylight)

Not "caused" but is just failing to see the cause. Maybe it just needs more time? (But why?)

Assignee: nobody → krosylight
Summary: Intermittent toolkit/components/cleardata/tests/marionette/test_moved_origin_directory_cleanup.py MovedOriginDirectoryCleanupTestCase.test_ensure_cleanup_at_crashed_restart | single tracking bug → Intermittent toolkit/components/cleardata/tests/marionette/test_moved_origin_directory_cleanup.py | single tracking bug

Restarting may take longer than the default 5 seconds, so try giving more time for this case.

Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/c6daae4f66b5 Give longer timeout value for test_ensure_cleanup_at_crashed_restart r=smaug

https://hg.mozilla.org/mozilla-central/rev/c6daae4f66b5

Status: NEW → RESOLVED
Closed: 2 years ago
status-firefox120: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 120 Branch

This is still happening., here is a recent failure log
Could we give a bit more timeout? It's failing with under 1 sec timeout (I can make a patch to adjust the timeout, if you want)

Status: RESOLVED → REOPENED
Flags: needinfo?(krosylight)
Resolution: FIXED → ---
Target Milestone: 120 Branch → ---

Is the frequency decreased, though? If not I don't think giving longer timeout would do anything, maybe the cleanup is just not happening at all? 🤔

Flags: needinfo?(krosylight) → needinfo?(smolnar)

The graph doesn't seem like it did the work, hmm.

Flags: needinfo?(smolnar)
Attachment #9386543 - Attachment is obsolete: true

Update

There have been 31 total failures within the last 7 days:

  • 1 failure on Linux 18.04 x64 WebRender opt
  • 8 failures on Windows 11 x86 22H2 WebRender opt/ debug
  • 3 failures on Windows 11 x86 22H2 WebRender Shippable opt
  • 3 failures on Windows 11 x64 22H2 CCov WebRender opt
  • 14 failures on Windows 11 x64 22H2 WebRender opt/ debug
  • 2 failures on Windows 11 x64 22H2 WebRender Shippable opt

Recent log: https://treeherder.mozilla.org/logviewer?job_id=450643396&repo=autoland&lineNumber=87117

Kagami, can you take a look at this please?
Thank you.

Flags: needinfo?(krosylight)
Whiteboard: [retriggered] → [retriggered][stockwell needswork:owner]
Attached file WIP: Bug 1814281 (obsolete) —
Attachment #9391351 - Attachment is obsolete: true
Attachment #9391352 - Attachment description: WIP: Bug 1814281 - Make sure the pref is written before crash in cleanup test r=smaug → Bug 1814281 - Make sure the pref is written before crash in cleanup test r=smaug
Flags: needinfo?(krosylight)
Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/47d63b182999 Make sure the pref is written before crash in cleanup test r=smaug

Now I think this is not just a failure to actually trigger startup cleanup but the startup cleanup is failing to remove the directory or somehow skipping storage cleanup. 🤔

Flags: needinfo?(krosylight)
Flags: needinfo?(krosylight)
Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/e042b908afea Add more logs to confirm sanitization runs r=pbz
[task 2024-04-12T21:30:32.092Z] 21:30:32     INFO -  console.log: Sanitizer: "Running sanitization for:" ["cache", "cookies", "offlineApps", "history", "formdata", "downloads", "sessions"]
[task 2024-04-12T21:30:32.161Z] 21:30:32     INFO -  console.log: Sanitizer: "Sanitizing 0 principals"
[task 2024-04-12T21:30:32.173Z] 21:30:32     INFO -  console.log: Sanitizer: "Sanitizing 0 principals"
[task 2024-04-12T21:30:32.288Z] 21:30:32     INFO -  console.error: "C:\\Users\\task_171295605263694\\AppData\\Local\\Temp\\tmpetfmj1io.mozrunner" "" 0 ".purge.bg_rm" ""
[task 2024-04-12T21:30:32.293Z] 21:30:32     INFO -  console.warn: "Skipping Glean as no metrics id is passed"
[task 2024-04-12T21:30:32.617Z] 21:30:32     INFO -  console.log: Sanitizer: "All sanitizations are complete"

Sanitizing zero principals???? 🤔

In success case:

 0:11.12 TEST_START: toolkit/components/cleardata/tests/marionette/test_moved_origin_directory_cleanup.py MovedOriginDirectoryCleanupTestCase.test_ensure_cleanup_at_crashed_restart
 0:11.31 INFO Application command: D:/gecko/obj-x86_64-pc-windows-msvc\dist\bin\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\sasch\AppData\Local\Temp\tmpmb4bhqzd.mozrunner
*** You are running in headless mode.
1713177594819   Marionette      INFO    Marionette enabled
1713177595384   Marionette      INFO    Listening on port 2828
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
*** You are running in background task mode. ***
*** You are running in headless mode.
console.log: Sanitizer: "Pending sanitizations:" []
console.error: "C:\\Users\\sasch\\AppData\\Local\\Temp\\tmpmb4bhqzd.mozrunner" "" 0 ".purge.bg_rm" ""
console.warn: "Skipping Glean as no metrics id is passed"
console.error: ({})
 0:21.71 INFO Application command: D:/gecko/obj-x86_64-pc-windows-msvc\dist\bin\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\sasch\AppData\Local\Temp\tmpmb4bhqzd.mozrunner
*** You are running in headless mode.
1713177604607   Marionette      INFO    Marionette enabled
1713177605154   Marionette      INFO    Listening on port 2828
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
*** You are running in background task mode. ***
*** You are running in headless mode.
console.log: Sanitizer: "Pending sanitizations:" [{id:"shutdown", itemsToClear:["cache", "cookies", "offlineApps", "history", "formdata", "downloads", "sessions"], options:{}}, {id:"newtab-container", itemsToClear:[], options:{}}]
console.log: Sanitizer: "Running sanitization for:" ["cache", "cookies", "offlineApps", "history", "formdata", "downloads", "sessions"]
console.error: "C:\\Users\\sasch\\AppData\\Local\\Temp\\tmpmb4bhqzd.mozrunner" "" 0 ".purge.bg_rm" ""
console.warn: "Skipping Glean as no metrics id is passed"
console.log: Sanitizer: "Sanitizing 1 principals"
console.log: Sanitizer: "Checking principal: https://example.local/"
console.log: Sanitizer: "Cookie not allowed."
console.log: Sanitizer: "Sanitizing principal: https://example.local/"
console.log: Sanitizer: "Sanitizing 1 principals"
console.log: Sanitizer: "Checking principal: https://example.local/"
console.log: Sanitizer: "Cookie not allowed."
console.log: Sanitizer: "Sanitizing principal: https://example.local/"
console.log: Sanitizer: "All sanitizations are complete"
console.error: ({})
 0:31.62 TEST_END: PASS

Probably the work item is to check where the principal is created and make sure it's stored before triggering crash.

Hi Valentin, do you know well about Services.cookies?

My test uses it to store a principal but sometimes it seems it doesn't end up being in the storage quick enough; any idea how to make sure it goes to the storage? 👀

Perhaps I should use Services.qms.initializePersistentOrigin instead, though.

Flags: needinfo?(valentin.gosu)

You can use an observer notification to await for the cookie to be persisted to disk. We do that here

Hope this helps.

Flags: needinfo?(valentin.gosu)
Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/342488f68e70 Wait until cookie-saved-on-disk r=valentin

autoland failure is reduced from ~20 to 3 where only one is after landing the fix; it had weird file permission failure that looks random. Looks quite good that maybe worth uplifting to reduce beta failures?

Comment on attachment 9396657 [details]
Bug 1814281 - Wait until cookie-saved-on-disk r=valentin

Beta/Release Uplift Approval Request

  • User impact if declined: No impact, only the intermittent failure robot (and who watches it) will be angry with the test failures.
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: Yes
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: None
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Test only change.
  • String changes made/needed:
  • Is Android affected?: No
Attachment #9396657 - Flags: approval-mozilla-beta?
Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 year ago
status-firefox120: affected → wontfix
status-firefox125: --- → wontfix
status-firefox126: --- → affected
status-firefox127: --- → fixed
status-firefox-esr115: --- → wontfix
Resolution: --- → FIXED
Target Milestone: --- → 127 Branch

Comment on attachment 9396657 [details]
Bug 1814281 - Wait until cookie-saved-on-disk r=valentin

Approved for 126.0b5

Attachment #9396657 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
See Also: → 1895836
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: