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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: jdescottes [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=360518706&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FVgepd3gQuiAWqOfty4tvQ/runs/0/artifacts/public/logs/live_backing.log

---

Comment 1

[Julian Descottes [:jdescottes]]

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

Comment 2

[Julian Descottes [:jdescottes]]

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

Comment 3

[Julian Descottes [:jdescottes]]

Can reproduce in mochitests by forcing a GC.

Comment 4

[Julian Descottes [:jdescottes]]

Attachment: Bug 1744966 - [bidi] Keep already emitted messages in a Set instead of a WeakSet to avoid emitting duplicate messages after GC

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/28139e453b66
[bidi] Keep already emitted messages in a Set instead of a WeakSet to avoid emitting duplicate messages after GC r=webdriver-reviewers,whimboo

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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.

Comment 8

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/28139e453b66

Comment 9

[Intermittent Failures Robot]

6 failures in 3319 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• mozilla-central: 2

Platform and build breakdown:

• linux1804-64-qr: 3
  • debug: 3
• linux1804-64-asan-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1744966&startday=2021-12-06&endday=2021-12-12&tree=all