Closed Bug 1745514 Opened 3 years ago Closed 2 years ago

Intermittent ASAN TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

Filed by: mlaza [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=360829850&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aTKjz-hBSWG5sqYb-Cwfqw/runs/0/artifacts/public/logs/live_backing.log


[task 2021-12-10T19:58:40.802Z] 19:58:40     INFO - TEST-START | /webdriver/tests/new_session/create_firstMatch.py
[task 2021-12-10T19:58:40.872Z] 19:58:40     INFO - STDOUT: ============================= test session starts ==============================
[task 2021-12-10T19:58:40.874Z] 19:58:40     INFO - STDOUT: platform linux -- Python 3.6.9, pytest-6.1.1, py-1.5.2, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2021-12-10T19:58:40.875Z] 19:58:40     INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2021-12-10T19:58:40.876Z] 19:58:40     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2021-12-10T19:58:40.877Z] 19:58:40     INFO - STDOUT: collecting ... 
[task 2021-12-10T19:58:40.888Z] 19:58:40     INFO - STDOUT: collected 27 items
[task 2021-12-10T19:58:40.889Z] 19:58:40     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[acceptInsecureCerts-False] 
[task 2021-12-10T19:58:47.561Z] 19:58:47     INFO - STDOUT: PASSED
[task 2021-12-10T19:58:53.674Z] 19:58:53     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[acceptInsecureCerts-None] 
[task 2021-12-10T19:59:00.583Z] 19:59:00     INFO - STDOUT: PASSED
[task 2021-12-10T19:59:06.691Z] 19:59:06     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[browserName-None] 
[task 2021-12-10T19:59:13.326Z] 19:59:13     INFO - STDOUT: PASSED
[task 2021-12-10T19:59:19.598Z] 19:59:19     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[browserVersion-None] 
[task 2021-12-10T19:59:26.322Z] 19:59:26     INFO - STDOUT: PASSED
[task 2021-12-10T19:59:32.433Z] 19:59:32     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[platformName-None] 
[task 2021-12-10T19:59:39.167Z] 19:59:39     INFO - STDOUT: PASSED
[task 2021-12-10T20:00:08.096Z] 20:00:08     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[pageLoadStrategy-None] 
[task 2021-12-10T20:00:14.726Z] 20:00:14     INFO - STDOUT: PASSED
[task 2021-12-10T20:00:20.889Z] 20:00:20     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[pageLoadStrategy-none] 
[task 2021-12-10T20:00:27.588Z] 20:00:27     INFO - STDOUT: PASSED
[task 2021-12-10T20:00:56.472Z] 20:00:56     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[pageLoadStrategy-eager] 
[task 2021-12-10T20:01:03.377Z] 20:01:03     INFO - STDOUT: PASSED
[task 2021-12-10T20:01:09.491Z] 20:01:09     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[pageLoadStrategy-normal] 
[task 2021-12-10T20:01:16.208Z] 20:01:16     INFO - STDOUT: PASSED
[task 2021-12-10T20:01:48.325Z] 20:01:48     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[proxy-None] 
[task 2021-12-10T20:01:55.064Z] 20:01:55     INFO - STDOUT: PASSED
[task 2021-12-10T20:02:23.873Z] 20:02:23     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[timeouts-None] 
[task 2021-12-10T20:02:30.584Z] 20:02:30     INFO - STDOUT: PASSED
[task 2021-12-10T20:02:36.811Z] 20:02:36     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[timeouts-value11] 
[task 2021-12-10T20:02:43.440Z] 20:02:43     INFO - STDOUT: PASSED
[task 2021-12-10T20:03:12.276Z] 20:03:12     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[timeouts-value12] 
[task 2021-12-10T20:03:18.982Z] 20:03:18     INFO - STDOUT: PASSED
[task 2021-12-10T20:03:51.143Z] 20:03:51     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[timeouts-value13] 
[task 2021-12-10T20:03:57.757Z] 20:03:57     INFO - STDOUT: PASSED
[task 2021-12-10T20:04:03.953Z] 20:04:03     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[timeouts-value14] 
[task 2021-12-10T20:04:10.599Z] 20:04:10     INFO - STDOUT: PASSED
[task 2021-12-10T20:04:16.838Z] 20:04:16     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[strictFileInteractability-True] 
[task 2021-12-10T20:04:23.528Z] 20:04:23     INFO - STDOUT: PASSED
[task 2021-12-10T20:04:29.700Z] 20:04:29     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[strictFileInteractability-False] 
[task 2021-12-10T20:04:36.432Z] 20:04:36     INFO - STDOUT: PASSED
[task 2021-12-10T20:04:42.571Z] 20:04:42     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[strictFileInteractability-None] 
[task 2021-12-10T20:04:49.150Z] 20:04:49     INFO - STDOUT: PASSED
[task 2021-12-10T20:05:09.338Z] 20:05:09     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[unhandledPromptBehavior-dismiss] 
[task 2021-12-10T20:05:16.167Z] 20:05:16     INFO - STDOUT: PASSED
[task 2021-12-10T20:05:22.349Z] 20:05:22     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[unhandledPromptBehavior-accept] 
[task 2021-12-10T20:05:29.046Z] 20:05:29     INFO - STDOUT: PASSED
[task 2021-12-10T20:05:57.922Z] 20:05:57     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[unhandledPromptBehavior-None] 
[task 2021-12-10T20:06:04.633Z] 20:06:04     INFO - STDOUT: PASSED
[task 2021-12-10T20:06:10.347Z] 20:06:10     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-None] 
[task 2021-12-10T20:06:17.098Z] 20:06:17     INFO - STDOUT: PASSED
[task 2021-12-10T20:06:23.248Z] 20:06:23     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-False] 
[task 2021-12-10T20:06:29.901Z] 20:06:29     INFO - STDOUT: PASSED
[task 2021-12-10T20:06:36.039Z] 20:06:36     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-abc] 
[task 2021-12-10T20:06:42.682Z] 20:06:42     INFO - STDOUT: PASSED
[task 2021-12-10T20:06:48.941Z] 20:06:48     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-123] 
[task 2021-12-10T20:06:55.661Z] 20:06:55     INFO - STDOUT: PASSED
[task 2021-12-10T20:07:01.818Z] 20:07:01     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-value25] 
[task 2021-12-10T20:07:08.627Z] 20:07:08     INFO - STDOUT: PASSED
[task 2021-12-10T20:07:14.715Z] 20:07:14     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-value26] 
[task 2021-12-10T20:07:21.383Z] 20:07:21     INFO - STDOUT: PASSED
[task 2021-12-10T20:07:45.796Z] 20:07:45     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK
[task 2021-12-10T20:07:45.796Z] 20:07:45     INFO - TEST-INFO took 545002ms
[task 2021-12-10T20:07:46.015Z] 20:07:46     INFO - INFO | LeakSanitizer | SUMMARY: AddressSanitizer: 15662 byte(s) leaked in 133 allocation(s).
[task 2021-12-10T20:07:46.015Z] 20:07:46     INFO - LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2021-12-10T20:07:46.015Z] 20:07:46     INFO - This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2021-12-10T20:07:46.016Z] 20:07:46     INFO - Allowed depth was 4
[task 2021-12-10T20:07:46.017Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at mozilla::extensions::AtomSet::Get, mozilla::extensions::MatchPattern::Init, mozilla::extensions::MatchPattern::Constructor, mozilla::extensions::MatchPatternSet::Constructor
[task 2021-12-10T20:07:46.017Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame mozilla::extensions::AtomSet::Get matched a expected leak
[task 2021-12-10T20:07:46.019Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at mozilla::extensions::MatchPattern::Constructor, mozilla::extensions::MatchPatternSet::Constructor, mozilla::dom::MatchPatternSet_Binding::_constructor, EnterJit
[task 2021-12-10T20:07:46.019Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame mozilla::extensions::MatchPattern::Constructor matched a expected leak
[task 2021-12-10T20:07:46.020Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at nsDynamicAtom::Create, nsAtomTable::Atomize, NS_Atomize, mozilla::extensions::AtomSet::AtomSet
[task 2021-12-10T20:07:46.021Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame nsDynamicAtom::Create matched a expected leak
[task 2021-12-10T20:07:46.022Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at XPCWrappedNativeProto::GetNewOrUsed, XPCWrappedNative::GetNewOrUsed, XPCConvert::NativeInterface2JSObject, GetServiceImpl
[task 2021-12-10T20:07:46.022Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame XPCWrappedNativeProto::GetNewOrUsed matched a expected leak
[task 2021-12-10T20:07:46.023Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at XPCNativeSet::NewInstance, XPCNativeSet::GetNewOrUsed, XPCWrappedNative::GetNewOrUsed, XPCConvert::NativeInterface2JSObject
[task 2021-12-10T20:07:46.023Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame XPCNativeSet::NewInstance matched a expected leak
[task 2021-12-10T20:07:46.023Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at XPCNativeSet::NewInstance, XPCNativeSet::GetNewOrUsed, XPCWrappedNativeProto::GetNewOrUsed, XPCWrappedNative::GetNewOrUsed
[task 2021-12-10T20:07:46.023Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame XPCNativeSet::NewInstance matched a expected leak
[task 2021-12-10T20:07:46.023Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at XPCNativeInterface::NewInstance, XPCNativeInterface::GetNewOrUsed, XPCConvert::NativeInterface2JSObject, GetServiceImpl
[task 2021-12-10T20:07:46.024Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame XPCNativeInterface::NewInstance matched a expected leak
[task 2021-12-10T20:07:46.024Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at XPCWrappedNative::GetNewOrUsed, XPCConvert::NativeInterface2JSObject, GetServiceImpl, GetService
[task 2021-12-10T20:07:46.025Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame XPCWrappedNative::GetNewOrUsed matched a expected leak
[task 2021-12-10T20:07:46.025Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at XPCNativeInterface::NewInstance, XPCNativeInterface::GetNewOrUsed, XPCNativeSet::GetNewOrUsed, XPCWrappedNativeProto::GetNewOrUsed
[task 2021-12-10T20:07:46.026Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame XPCNativeInterface::NewInstance matched a expected leak
[task 2021-12-10T20:07:46.027Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at mozilla::extensions::MatchPattern::Constructor, mozilla::extensions::MatchPatternSet::Constructor, mozilla::dom::MatchPatternSet_Binding::_constructor, CallJSNative
[task 2021-12-10T20:07:46.027Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame mozilla::extensions::MatchPattern::Constructor matched a expected leak
[task 2021-12-10T20:07:46.028Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at Alloc, nsTSubstring, nsTSubstring, AssignJSString
[task 2021-12-10T20:07:46.029Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame Alloc matched a expected leak
[task 2021-12-10T20:07:46.029Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at Realloc, nsTArray_base, Compact, mozilla::extensions::AtomSet::SortAndUniquify
[task 2021-12-10T20:07:46.030Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame Realloc matched a expected leak
[task 2021-12-10T20:07:46.031Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at Alloc, nsTSubstring, Gecko_StartBulkWriteCString, nsstring::nsACString::start_bulk_write_impl
[task 2021-12-10T20:07:46.031Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame Alloc matched a expected leak
[task 2021-12-10T20:07:46.032Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at mozilla::extensions::MatchPattern::Init, mozilla::extensions::MatchPattern::Constructor, mozilla::extensions::MatchPatternSet::Constructor, mozilla::dom::MatchPatternSet_Binding::_constructor
[task 2021-12-10T20:07:46.032Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame mozilla::extensions::MatchPattern::Init matched a expected leak
[task 2021-12-10T20:07:46.033Z] 20:07:46     INFO - TEST-FAIL | LeakSanitizer | leak at Alloc, nsTSubstring, nsTSubstring, nsTSubstring
[task 2021-12-10T20:07:46.033Z] 20:07:46     INFO - INFO | LeakSanitizer | Frame Alloc matched a expected leak
[task 2021-12-10T20:07:46.033Z] 20:07:46     INFO - Closing logging queue
[task 2021-12-10T20:07:46.034Z] 20:07:46     INFO - queue closed
[task 2021-12-10T20:07:46.035Z] 20:07:46     INFO - Starting runner
[task 2021-12-10T20:07:46.599Z] 20:07:46     INFO - WebDriver HTTP server listening at http://127.0.0.1:47844/
[task 2021-12-10T20:07:46.600Z] 20:07:46     INFO - TEST-START | /webdriver/tests/new_session/default_values.py

Sadly there are no verbose logs for wdspec tests, but the failures are happening for the following tests:

tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-*]

As such I assume it's related to the leaks related to extensions which is bug 1728821:

leak at mozilla::extensions::AtomSet::Get, mozilla::extensions::MatchPattern::Init

Depends on: 1728821
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK → Intermittent ASAN TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.