Closed Bug 1744966 Opened 1 year ago Closed 1 year ago

Intermittent /webdriver/tests/bidi/log_entry_added/ | test_console_log_cached_messages[javascript_error] - assert 4 == 3


(Remote Protocol :: WebDriver BiDi, defect, P2)



(firefox-esr91 unaffected, firefox95 unaffected, firefox96 unaffected, firefox97 fixed)

97 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox95 --- unaffected
firefox96 --- unaffected
firefox97 --- fixed


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




(Keywords: intermittent-failure, regression, Whiteboard: [bidi-m2-mvp])


(1 file)

The test seems to fail for javascript errors (not console api messages), at the last step of test_console_log_cached_messages.
The events array looks like:

[task 2021-12-08T10:36:57.232Z] 10:36:57     INFO - STDOUT: events     = [{'level': 'error',
[task 2021-12-08T10:36:57.232Z] 10:36:57     INFO -   'text': 'Error: cached_message',
[task 2021-12-08T10:36:57.232Z] 10:36:57     INFO -   'timestamp': 1638959814747,
[task 2021-12-08T10:36:57.232Z] 10:36:57     INFO -   'type': 'javascript'},
[task 2021-12-08T10:36:57.232Z] 10:36:57     INFO -  {'level': 'error',
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'text': 'Error: live_message',
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'timestamp': 1638959815319,
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'type': 'javascript'},
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -  {'level': 'error',
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'text': 'Error: cached_message',
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'timestamp': 1638959814747,
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'type': 'javascript'},
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -  {'level': 'error',
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'text': 'Error: cached_message_2',
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'timestamp': 1638959815345,
[task 2021-12-08T10:36:57.233Z] 10:36:57     INFO -   'type': 'javascript'}]

So we can see we have Error: cached_message twice

Everything happens with the same window global here.

  • log 'Error: cached_message'
  • subscribe and check we get 'Error: cached_message' -> this works
  • unsubscribe / subscribe and check we don't get 'Error: cached_message' again -> this works
  • log 'Error: live_message' and check we get it -> this works
  • unsubscribe
  • log 'Error: cached_message_2'
  • subscribe and check we get 'Error: cached_message_2' -> this fails because here we also received 'Error: cached_message' again, with the same timestamp as the first one.

All of this happens with the same ConsoleListener, and the same log module. So I think the key I used for my weakset to check if a message had already been emitted is not reliable.

In the WeakSet, I add the message object we received from the observer. But I'm guessing that if nothing else keeps the reference to this object alive, then it's going to be GC'd / deleted at some point and the next call to get cached messages will recreate a new nsIScriptError.

If that's correct, I see several things we could try:

  • use a Set instead of a WeakSet (with all the concerns implied by this)
  • request to have an explicit uuid on those messages

Can reproduce in mochitests by forcing a GC.

Assignee: nobody → jdescottes

Set release status flags based on info from the regressing bug 1731574

Pushed by
[bidi] Keep already emitted messages in a Set instead of a WeakSet to avoid emitting duplicate messages after GC r=webdriver-reviewers,whimboo

Regression from a P2 bug from Milestone 2. As such we should count that bug for M2 as well. Complexity wise this looks like 2 points.

Points: --- → 2
Whiteboard: [bidi-m2-mvp]
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → 97 Branch
Priority: P5 → P2
You need to log in before you can comment on or make changes to this bug.