Closed
Bug 1753907
Opened 2 years ago
Closed 2 years ago
Intermittent linux ccov /webdriver/tests/bidi/log/entry_added/stacktrace.py | test_console_entry_sync_callstack[debug-False] - AssertionError
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(firefox-esr91 unaffected, firefox97 unaffected, firefox98 wontfix, firefox99 fixed)
RESOLVED
FIXED
99 Branch
| Tracking | Status | |
|---|---|---|
| firefox-esr91 | --- | unaffected |
| firefox97 | --- | unaffected |
| firefox98 | --- | wontfix |
| firefox99 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: jdescottes)
References
Details
(Keywords: assertion, intermittent-failure)
Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=366892037&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Ucr4OjztQxCA3CrdybhHHw/runs/0/artifacts/public/logs/live_backing.log
[task 2022-02-06T23:04:07.688Z] 23:04:07 INFO - TEST-PASS | /webdriver/tests/bidi/log/entry_added/stacktrace.py | test_console_entry_sync_callstack[assert-True]
[task 2022-02-06T23:04:07.688Z] 23:04:07 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/log/entry_added/stacktrace.py | test_console_entry_sync_callstack[debug-False] - AssertionError
[task 2022-02-06T23:04:07.688Z] 23:04:07 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f96786cd940>
[task 2022-02-06T23:04:07.688Z] 23:04:07 INFO - current_session = <Session 7b014d39-2213-4535-bfc3-79eb20a32f5f>
[task 2022-02-06T23:04:07.688Z] 23:04:07 INFO - inline = <function inline.<locals>.inline at 0x7f96798496a8>
[task 2022-02-06T23:04:07.689Z] 23:04:07 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7f9679849268>
[task 2022-02-06T23:04:07.689Z] 23:04:07 INFO - log_method = 'debug', expect_stack = False
[task 2022-02-06T23:04:07.689Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.689Z] 23:04:07 INFO - @pytest.mark.asyncio
[task 2022-02-06T23:04:07.690Z] 23:04:07 INFO - @pytest.mark.parametrize("log_method, expect_stack", [
[task 2022-02-06T23:04:07.690Z] 23:04:07 INFO - ("assert", True),
[task 2022-02-06T23:04:07.690Z] 23:04:07 INFO - ("debug", False),
[task 2022-02-06T23:04:07.690Z] 23:04:07 INFO - ("error", True),
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - ("info", False),
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - ("log", False),
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - ("table", False),
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - ("trace", True),
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - ("warn", True),
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - ])
[task 2022-02-06T23:04:07.691Z] 23:04:07 INFO - async def test_console_entry_sync_callstack(bidi_session,
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - current_session,
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - inline,
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - wait_for_event,
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - log_method,
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - expect_stack):
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - if log_method == 'assert':
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - # assert has to be called with a first falsy argument to trigger a log.
[task 2022-02-06T23:04:07.692Z] 23:04:07 INFO - url = inline(f"""
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - <script>
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - function foo() {{ console.{log_method}(false, "cheese"); }}
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - function bar() {{ foo(); }}
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - bar();
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - </script>
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - """)
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - else:
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - url = inline(f"""
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - <script>
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - function foo() {{ console.{log_method}("cheese"); }}
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - function bar() {{ foo(); }}
[task 2022-02-06T23:04:07.693Z] 23:04:07 INFO - bar();
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - </script>
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - """)
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - await bidi_session.session.subscribe(events=["log.entryAdded"])
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - on_entry_added = wait_for_event("log.entryAdded")
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - if (expect_stack):
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - expected_stack = [
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - {"columnNumber": 42, "functionName": "foo", "lineNumber": 4, "url": url},
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - {"columnNumber": 34, "functionName": "bar", "lineNumber": 5, "url": url},
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - {"columnNumber": 17, "functionName": "", "lineNumber": 6, "url": url},
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - ]
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - else:
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - expected_stack = None
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - current_session.url = url
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - event_data = await on_entry_added
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - assert_console_entry(
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - event_data,
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - method=log_method,
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - text="cheese",
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - > stacktrace=expected_stack,
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - )
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f96786cd940>
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - current_session = <Session 7b014d39-2213-4535-bfc3-79eb20a32f5f>
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - event_data = {'args': [{'type': 'string',
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - 'value': 'Registering redirect listener for requestStorageAccess '
[task 2022-02-06T23:04:07.694Z] 23:04:07 INFO - 'helper'},
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - None],
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - 'level': 'debug',
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - 'method': 'debug',
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - 'realm': None,
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - 'text': 'Registering redirect listener for requestStorageAccess helper '
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - '[object Object]',
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - 'timestamp': 1644188642830,
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - 'type': 'console'}
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - expect_stack = False
[task 2022-02-06T23:04:07.695Z] 23:04:07 INFO - expected_stack = None
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - inline = <function inline.<locals>.inline at 0x7f96798496a8>
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - log_method = 'debug'
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - on_entry_added = <Future finished result={'args': [{'type': 'string', 'value': 'Registering ...Access helper'}, None], 'level': 'debug', 'method': 'debug', 'realm': None, ...}>
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - url = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++++++++++%3Cscript%3E%0A++++++++++++++++function+foo%28%29+%7B+console.debug%28%22cheese%22%29%3B+%7D%0A++++++++++++++++function+bar%28%29+%7B+foo%28%29%3B+%7D%0A++++++++++++++++bar%28%29%3B%0A++++++++++++%3C%2Fscript%3E%0A++++++++++++&mime=text%2Fhtml&charset=UTF-8'
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7f9679849268>
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/stacktrace.py:62:
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/__init__.py:45: in assert_console_entry
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - assert_base_entry(entry, level, text, time_start, time_end, stacktrace)
[task 2022-02-06T23:04:07.696Z] 23:04:07 INFO - args = None
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - entry = {'args': [{'type': 'string',
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'value': 'Registering redirect listener for requestStorageAccess '
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'helper'},
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - None],
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'level': 'debug',
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'method': 'debug',
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'realm': None,
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'text': 'Registering redirect listener for requestStorageAccess helper '
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - '[object Object]',
[task 2022-02-06T23:04:07.697Z] 23:04:07 INFO - 'timestamp': 1644188642830,
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - 'type': 'console'}
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - level = None
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - method = 'debug'
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - realm = None
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - stacktrace = None
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - text = 'cheese'
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - time_end = None
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - time_start = None
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.698Z] 23:04:07 INFO - entry = {'args': [{'type': 'string', 'value': 'Registering redirect listener for requestStorageAccess helper'}, None], 'level': 'debug', 'method': 'debug', 'realm': None, ...}
[task 2022-02-06T23:04:07.699Z] 23:04:07 INFO - level = None, text = 'cheese', time_start = None, time_end = None
[task 2022-02-06T23:04:07.699Z] 23:04:07 INFO - stacktrace = None
[task 2022-02-06T23:04:07.699Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.699Z] 23:04:07 INFO - def assert_base_entry(entry,
[task 2022-02-06T23:04:07.699Z] 23:04:07 INFO - level=None,
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - text=None,
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - time_start=None,
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - time_end=None,
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - stacktrace=None):
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - assert "level" in entry
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - assert isinstance(entry["level"], str)
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - if level is not None:
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - assert entry["level"] == level
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - assert "text" in entry
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - assert isinstance(entry["text"], str)
[task 2022-02-06T23:04:07.700Z] 23:04:07 INFO - if text is not None:
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - > assert entry["text"] == text
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - E AssertionError
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - entry = {'args': [{'type': 'string',
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'value': 'Registering redirect listener for requestStorageAccess '
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'helper'},
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - None],
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'level': 'debug',
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'method': 'debug',
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'realm': None,
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'text': 'Registering redirect listener for requestStorageAccess helper '
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - '[object Object]',
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'timestamp': 1644188642830,
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - 'type': 'console'}
[task 2022-02-06T23:04:07.701Z] 23:04:07 INFO - level = None
[task 2022-02-06T23:04:07.702Z] 23:04:07 INFO - stacktrace = None
[task 2022-02-06T23:04:07.702Z] 23:04:07 INFO - text = 'cheese'
[task 2022-02-06T23:04:07.702Z] 23:04:07 INFO - time_end = None
[task 2022-02-06T23:04:07.702Z] 23:04:07 INFO - time_start = None
[task 2022-02-06T23:04:07.702Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.702Z] 23:04:07 INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/__init__.py:15: AssertionError
[task 2022-02-06T23:04:07.703Z] 23:04:07 INFO -
[task 2022-02-06T23:04:07.703Z] 23:04:07 INFO - TEST-PASS | /webdriver/tests/bidi/log/entry_added/stacktrace.py | test_console_entry_sync_callstack[error-True]
|
||
Comment 1•2 years ago
|
||
There are additional log entries from console API returned which look like:
{"method":"log.entryAdded","params":{"type":"console","method":"debug","realm":null,"args":[{"type":"string","value":"Registe ... l":"debug","text":"Registering redirect listener for requestStorageAccess helper [object Object]","timestamp":1644188634415}}
This is coming from the webcompat extension:
https://searchfox.org/mozilla-central/rev/855b2af753bc01bf27fc1b9f2d0184a0a440773d/browser/extensions/webcompat/lib/shims.js#491
Julian, any idea why we are getting these given that we actually do not allow entries from chrome scope?
Flags: needinfo?(jdescottes)
|
|
||
Comment 2•2 years ago
|
||
This actually seems to have been regressed by the landing of bug 1752292 (wpt downstream sync):
https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=wd1%2Cccov
I'll file a new bug soon to that I can mark all the failing tests depending on it.
status-firefox97:
--- → unaffected
status-firefox98:
--- → affected
Flags: needinfo?(jdescottes)
Regressed by: 1752292
Summary: Intermittent /webdriver/tests/bidi/log/entry_added/stacktrace.py | test_console_entry_sync_callstack[debug-False] - AssertionError → Intermittent linux ccov /webdriver/tests/bidi/log/entry_added/stacktrace.py | test_console_entry_sync_callstack[debug-False] - AssertionError
Whiteboard: [webdriver:triage]
| Comment hidden (Intermittent Failures Robot) |
|
Assignee | |
Comment 4•2 years ago
|
||
Nevertheless, the log seems to come from a webextension https://searchfox.org/mozilla-central/source/browser/extensions/webcompat/lib/shims.js#491, I wonder if for some reason we are not filtering them out properly.
|
|
Assignee | |
Comment 5•2 years ago
|
||
Actually considering our browsing context filtering is mostly excluding contexts from the parent process, it's not too surprising that we get webextension messages. We probably need to exclude webextension contexts in https://searchfox.org/mozilla-central/rev/072f9e6b7f10a00e12d0a02ac713431d0a7ee368/remote/shared/messagehandler/transports/FrameContextUtils.jsm#31-42
|
|
Assignee | |
Comment 6•2 years ago
|
||
Basically I think we can add the following method to the helper and check it on top of isParentContext.
isExtensionContext (browsingContext) {
if (browsingContext instanceof CanonicalBrowsingContext) {
return browsingContext.currentWindowGlobal.documentPrincipal.isAddonOrExpandedAddonPrincipal;
}
return browsingContext.window.document.nodePrincipal.isAddonOrExpandedAddonPrincipal;
}
|
|
||
Updated•2 years ago
|
Whiteboard: [webdriver:triage]
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Updated•2 years ago
|
Assignee: nobody → jdescottes
Status: NEW → RESOLVED
Closed: 2 years ago
status-firefox99:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 99 Branch
|
||
Updated•2 years ago
|
|
||
Comment 9•1 year ago
|
||
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.
Description
•