Closed Bug 1753854 Opened 2 years ago Closed 2 years ago

Intermittent linux ccov /webdriver/tests/bidi/log/entry_added/console.py | test_text_with_argument_variation[array of strings] - AssertionError

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

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: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=366857680&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HpbGuzdzRhakhiC5NYxxEQ/runs/0/artifacts/public/logs/live_backing.log


[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - TEST-PASS | /webdriver/tests/bidi/log/entry_added/console.py | test_text_with_argument_variation[empty object] 
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/log/entry_added/console.py | test_text_with_argument_variation[array of strings] - AssertionError
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fb74c192438>
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - current_session = <Session 67452bb0-a0f1-4c15-8f44-c1cffba1413c>
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fb74c126730>
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - log_argument = "['1', '2', '3']", expected_text = '1,2,3'
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO -     @pytest.mark.asyncio
[task 2022-02-05T23:11:52.704Z] 23:11:52     INFO -     @pytest.mark.parametrize("log_argument, expected_text", [
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         ("'TEST'", "TEST"),
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         ("'TWO', 'PARAMETERS'", "TWO PARAMETERS"),
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         ("{}", "[object Object]"),
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         ("['1', '2', '3']", "1,2,3"),
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         ("null, undefined", "null undefined"),
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -     ], ids=[
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         'single string',
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         'two strings',
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         'empty object',
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         'array of strings',
[task 2022-02-05T23:11:52.705Z] 23:11:52     INFO -         'null and undefined',
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -     ])
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -     async def test_text_with_argument_variation(bidi_session,
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -                                                 current_session,
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -                                                 wait_for_event,
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -                                                 log_argument,
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -                                                 expected_text):
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -         await bidi_session.session.subscribe(events=["log.entryAdded"])
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -     
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -         on_entry_added = wait_for_event("log.entryAdded")
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -     
[task 2022-02-05T23:11:52.706Z] 23:11:52     INFO -         # TODO: To be replaced with the BiDi implementation of execute_script.
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO -         current_session.execute_script(f"console.log({log_argument})")
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO -     
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO -         event_data = await on_entry_added
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO -     
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO - >       assert_console_entry(event_data, text=expected_text)
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fb74c192438>
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO - current_session = <Session 67452bb0-a0f1-4c15-8f44-c1cffba1413c>
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO - event_data = {'args': [{'type': 'string', 'value': 'Shimming these'},
[task 2022-02-05T23:11:52.707Z] 23:11:52     INFO -           {'type': 'string', 'value': 'imageset'},
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -           {'type': 'string', 'value': 'URLs:'},
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -           None],
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -  'level': 'debug',
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -  'method': 'debug',
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -  'realm': None,
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -  'text': 'Shimming these imageset URLs: '
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -          '*://track.adform.net/Serving/TrackPoint/*,*://securepubads.g.doubleclick.net/gampad/*ad-blk*,*://pubads.g.doubleclick.net/gampad/*ad-blk*,*://securepubads.g.doubleclick.net/gampad/*xml_vmap1*,*://pubads.g.doubleclick.net/gampad/*xml_vmap1*,*://securepubads.g.doubleclick.net/gampad/*xml_vmap2*,*://pubads.g.doubleclick.net/gampad/*xml_vmap2*,*://securepubads.g.doubleclick.net/gampad/*ad*,*://pubads.g.doubleclick.net/gampad/*ad*,*://www.facebook.com/platform/impression.php*',
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -  'timestamp': 1644102708809,
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO -  'type': 'console'}
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO - expected_text = '1,2,3'
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO - log_argument = "['1', '2', '3']"
[task 2022-02-05T23:11:52.708Z] 23:11:52     INFO - on_entry_added = <Future finished result={'args': [{'type': 'string', 'value': 'Shimming these'}, {'type': 'string', 'value': 'imageset'}, {'type': 'string', 'value': 'URLs:'}, None], 'level': 'debug', 'method': 'debug', 'realm': None, ...}>
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fb74c126730>
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/console.py:37: 
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/__init__.py:45: in assert_console_entry
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO -     assert_base_entry(entry, level, text, time_start, time_end, stacktrace)
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO -         args       = None
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO -         entry      = {'args': [{'type': 'string', 'value': 'Shimming these'},
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO -           {'type': 'string', 'value': 'imageset'},
[task 2022-02-05T23:11:52.709Z] 23:11:52     INFO -           {'type': 'string', 'value': 'URLs:'},
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -           None],
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -  'level': 'debug',
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -  'method': 'debug',
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -  'realm': None,
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -  'text': 'Shimming these imageset URLs: '
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -          '*://track.adform.net/Serving/TrackPoint/*,*://securepubads.g.doubleclick.net/gampad/*ad-blk*,*://pubads.g.doubleclick.net/gampad/*ad-blk*,*://securepubads.g.doubleclick.net/gampad/*xml_vmap1*,*://pubads.g.doubleclick.net/gampad/*xml_vmap1*,*://securepubads.g.doubleclick.net/gampad/*xml_vmap2*,*://pubads.g.doubleclick.net/gampad/*xml_vmap2*,*://securepubads.g.doubleclick.net/gampad/*ad*,*://pubads.g.doubleclick.net/gampad/*ad*,*://www.facebook.com/platform/impression.php*',
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -  'timestamp': 1644102708809,
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -  'type': 'console'}
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -         level      = None
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -         method     = None
[task 2022-02-05T23:11:52.710Z] 23:11:52     INFO -         realm      = None
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO -         stacktrace = None
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO -         text       = '1,2,3'
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO -         time_end   = None
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO -         time_start = None
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO - entry = {'args': [{'type': 'string', 'value': 'Shimming these'}, {'type': 'string', 'value': 'imageset'}, {'type': 'string', 'value': 'URLs:'}, None], 'level': 'debug', 'method': 'debug', 'realm': None, ...}
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO - level = None, text = '1,2,3', time_start = None, time_end = None
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO - stacktrace = None
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.711Z] 23:11:52     INFO -     def assert_base_entry(entry,
[task 2022-02-05T23:11:52.712Z] 23:11:52     INFO -                           level=None,
[task 2022-02-05T23:11:52.712Z] 23:11:52     INFO -                           text=None,
[task 2022-02-05T23:11:52.713Z] 23:11:52     INFO -                           time_start=None,
[task 2022-02-05T23:11:52.713Z] 23:11:52     INFO -                           time_end=None,
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -                           stacktrace=None):
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -         assert "level" in entry
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -         assert isinstance(entry["level"], str)
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -         if level is not None:
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -             assert entry["level"] == level
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -     
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -         assert "text" in entry
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -         assert isinstance(entry["text"], str)
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -         if text is not None:
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO - >           assert entry["text"] == text
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO - E           AssertionError
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO - entry      = {'args': [{'type': 'string', 'value': 'Shimming these'},
[task 2022-02-05T23:11:52.717Z] 23:11:52     INFO -           {'type': 'string', 'value': 'imageset'},
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -           {'type': 'string', 'value': 'URLs:'},
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -           None],
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -  'level': 'debug',
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -  'method': 'debug',
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -  'realm': None,
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -  'text': 'Shimming these imageset URLs: '
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -          '*://track.adform.net/Serving/TrackPoint/*,*://securepubads.g.doubleclick.net/gampad/*ad-blk*,*://pubads.g.doubleclick.net/gampad/*ad-blk*,*://securepubads.g.doubleclick.net/gampad/*xml_vmap1*,*://pubads.g.doubleclick.net/gampad/*xml_vmap1*,*://securepubads.g.doubleclick.net/gampad/*xml_vmap2*,*://pubads.g.doubleclick.net/gampad/*xml_vmap2*,*://securepubads.g.doubleclick.net/gampad/*ad*,*://pubads.g.doubleclick.net/gampad/*ad*,*://www.facebook.com/platform/impression.php*',
[task 2022-02-05T23:11:52.718Z] 23:11:52     INFO -  'timestamp': 1644102708809,
[task 2022-02-05T23:11:52.719Z] 23:11:52     INFO -  'type': 'console'}
[task 2022-02-05T23:11:52.719Z] 23:11:52     INFO - level      = None
[task 2022-02-05T23:11:52.719Z] 23:11:52     INFO - stacktrace = None
[task 2022-02-05T23:11:52.719Z] 23:11:52     INFO - text       = '1,2,3'
[task 2022-02-05T23:11:52.719Z] 23:11:52     INFO - time_end   = None
[task 2022-02-05T23:11:52.719Z] 23:11:52     INFO - time_start = None
[task 2022-02-05T23:11:52.720Z] 23:11:52     INFO - 
[task 2022-02-05T23:11:52.720Z] 23:11:52     INFO - tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/__init__.py:15: AssertionError
[task 2022-02-05T23:11:52.720Z] 23:11:52     INFO - ............
[task 2022-02-05T23:11:52.720Z] 23:11:52     INFO - TEST-OK | /webdriver/tests/bidi/log/entry_added/console.py | took 9597ms
Assignee: nobody → jdescottes
Status: NEW → RESOLVED
Closed: 2 years ago
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.