Closed Bug 1753853 Opened 2 years ago Closed 2 years ago

Intermittent linux ccov /webdriver/tests/bidi/log/entry_added/console.py | test_level[error-error] - AssertionError

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(firefox-esr91 unaffected, firefox97 unaffected, firefox98 wontfix, firefox99 fixed)

Status:
RESOLVED FIXED
Milestone:
99 Branch
Tracking Flags:
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: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=366856195&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ABgufW6XSamzQlNdYXn_Gw/runs/0/artifacts/public/logs/live_backing.log

[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - TEST-PASS | /webdriver/tests/bidi/log/entry_added/console.py | test_level[debug-debug] 
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/log/entry_added/console.py | test_level[error-error] - AssertionError
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f566de674a8>
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - current_session = <Session 330b61d5-ae3e-4692-af07-576e02698b0e>
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7f566d60e0d0>
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - log_method = 'error', expected_level = 'error'
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     @pytest.mark.asyncio
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     @pytest.mark.parametrize("log_method, expected_level", [
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("assert", "error"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("debug", "debug"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("error", "error"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("info", "info"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("log", "info"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("table", "info"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("trace", "debug"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         ("warn", "warning"),
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     ])
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     async def test_level(bidi_session,
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -                          current_session,
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -                          wait_for_event,
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -                          log_method,
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -                          expected_level):
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         await bidi_session.session.subscribe(events=["log.entryAdded"])
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         on_entry_added = wait_for_event("log.entryAdded")
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         # TODO: To be replaced with the BiDi implementation of execute_script.
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         if log_method == 'assert':
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -             # assert has to be called with a first falsy argument to trigger a log.
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -             current_session.execute_script("console.assert(false, 'foo')")
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         else:
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -             current_session.execute_script(f"console.{log_method}('foo')")
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -         event_data = await on_entry_added
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO -     
[task 2022-02-05T22:28:27.079Z] 22:28:27     INFO - >       assert_console_entry(event_data, text="foo", level=expected_level, method=log_method)
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f566de674a8>
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO - current_session = <Session 330b61d5-ae3e-4692-af07-576e02698b0e>
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO - event_data = {'args': [{'type': 'string',
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -            'value': 'Enabling content scripts for these URLs:'},
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -           None],
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -  'level': 'debug',
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -  'method': 'debug',
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -  'realm': None,
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -  'text': 'Enabling content scripts for these URLs: '
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -          '*://*.stackblitz.com/*,*://*.stackblitz.io/*',
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -  'timestamp': 1644100103866,
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO -  'type': 'console'}
[task 2022-02-05T22:28:27.080Z] 22:28:27     INFO - expected_level = 'error'
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - log_method = 'error'
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - on_entry_added = <Future finished result={'args': [{'type': 'string', 'value': 'Enabling con...r these URLs:'}, None], 'level': 'debug', 'method': 'debug', 'realm': None, ...}>
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7f566d60e0d0>
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/console.py:69: 
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/__init__.py:45: in assert_console_entry
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO -     assert_base_entry(entry, level, text, time_start, time_end, stacktrace)
[task 2022-02-05T22:28:27.081Z] 22:28:27     INFO -         args       = None
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -         entry      = {'args': [{'type': 'string',
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -            'value': 'Enabling content scripts for these URLs:'},
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -           None],
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -  'level': 'debug',
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -  'method': 'debug',
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -  'realm': None,
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -  'text': 'Enabling content scripts for these URLs: '
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -          '*://*.stackblitz.com/*,*://*.stackblitz.io/*',
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -  'timestamp': 1644100103866,
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -  'type': 'console'}
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -         level      = 'error'
[task 2022-02-05T22:28:27.082Z] 22:28:27     INFO -         method     = 'error'
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -         realm      = None
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -         stacktrace = None
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -         text       = 'foo'
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -         time_end   = None
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -         time_start = None
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO - entry = {'args': [{'type': 'string', 'value': 'Enabling content scripts for these URLs:'}, None], 'level': 'debug', 'method': 'debug', 'realm': None, ...}
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO - level = 'error', text = 'foo', time_start = None, time_end = None
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO - stacktrace = None
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -     def assert_base_entry(entry,
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -                           level=None,
[task 2022-02-05T22:28:27.083Z] 22:28:27     INFO -                           text=None,
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -                           time_start=None,
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -                           time_end=None,
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -                           stacktrace=None):
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -         assert "level" in entry
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -         assert isinstance(entry["level"], str)
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -         if level is not None:
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - >           assert entry["level"] == level
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - E           AssertionError
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - entry      = {'args': [{'type': 'string',
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -            'value': 'Enabling content scripts for these URLs:'},
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -           None],
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -  'level': 'debug',
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -  'method': 'debug',
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -  'realm': None,
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -  'text': 'Enabling content scripts for these URLs: '
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -          '*://*.stackblitz.com/*,*://*.stackblitz.io/*',
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -  'timestamp': 1644100103866,
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO -  'type': 'console'}
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - level      = 'error'
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - stacktrace = None
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - text       = 'foo'
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - time_end   = None
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - time_start = None
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - 
[task 2022-02-05T22:28:27.084Z] 22:28:27     INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/__init__.py:10: AssertionError
[task 2022-02-05T22:28:27.087Z] 22:28:27     INFO - ........
[task 2022-02-05T22:28:27.087Z] 22:28:27     INFO - TEST-OK | /webdriver/tests/bidi/log/entry_added/console.py | took 8706ms
Assignee: nobody → jdescottes
Status: NEW → RESOLVED
Closed: 2 years ago
status-firefox99: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 99 Branch
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.