1648712 - Intermittent dom/base/test/chrome/test_bug884693.xhtml | Got expected message count - got 1, expected +0

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Treeherder Bug Filer]

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

---

Looks to be very high in frequency.

INFO - TEST-START | dom/base/test/chrome/test_bug884693.xhtml
[task 2020-06-26T07:34:02.260Z] 07:34:02     INFO - TEST-INFO | started process screencapture
[task 2020-06-26T07:34:02.389Z] 07:34:02     INFO - TEST-INFO | screencapture: exit 0
[task 2020-06-26T07:34:02.390Z] 07:34:02     INFO - Buffered messages logged at 07:34:02
[task 2020-06-26T07:34:02.390Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.390Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.390Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.390Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.390Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.391Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.392Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.392Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.392Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.392Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.393Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.393Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.393Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.393Z] 07:34:02     INFO - Buffered messages finished
[task 2020-06-26T07:34:02.394Z] 07:34:02     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count - got 1, expected +0
[task 2020-06-26T07:34:02.394Z] 07:34:02     INFO - SimpleTest.is@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:492:14
[task 2020-06-26T07:34:02.394Z] 07:34:02     INFO - runTest/</xhr.onload@chrome://mochitests/content/chrome/dom/base/test/chrome/test_bug884693.xhtml:38:13
[task 2020-06-26T07:34:02.394Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.394Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.394Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.395Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.395Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.395Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.395Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.396Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.396Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.396Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.396Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message: no root element found 
[task 2020-06-26T07:34:02.416Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Correct responseText returned 
[task 2020-06-26T07:34:02.416Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message count 
[task 2020-06-26T07:34:02.417Z] 07:34:02     INFO - TEST-PASS | dom/base/test/chrome/test_bug884693.xhtml | Got expected message: syntax error 
[task 2020-06-26T07:34:02.417Z] 07:34:02     INFO - GECKO(2547) | MEMORY STAT | vsize 7722MB | residentFast 375MB | heapAllocated 126MB
[task 2020-06-26T07:34:02.421Z] 07:34:02     INFO - TEST-OK | dom/base/test/chrome/test_bug884693.xhtml | took 373ms

Comment 1

[Dorel Luca [:dluca]]

Junior: Could this bug be happening because bug 1633935 was backed out?

Retriggers show the failure likely stared there:
https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&searchStr=os%2Cx%2C10.14%2Cdebug%2Cmochitests%2Cwithout%2Ce10s%2Ctest-macosx1014-64%2Fdebug-mochitest-chrome-1proc-2%2Cm-1proc%28c2%29&fromchange=0acc9e36ffadbc798ef9f4ab04df5f232b2520f4&tochange=9d89fc475692b20011929c1dc8bb8f5ff8fe8809&selectedTaskRun=XYsacUXgTOiJg9r26nOQfA.0

Could you please look into it?

Comment 2

[Junior [inactive]]

Hello Lina,

I see there's an unexpected console message
Got console messages [JavaScript Error: "Unknown event: ["jsonfile", "load", "broadcastlisteners"]"]

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307673425&repo=try&lineNumber=1182
(a) Is this caused by dom push?
(b) If yes, the test is to load some empty resource and to ensure we don't have console error.
Should I disable pref ("dom.push.connection.enabled") for the unrelated tests?

Thanks.

Comment 3

[Junior [inactive]]

disabling pref doesn't work
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307685124&repo=try

Comment 4

[Lina Butler (ex-Mozilla)]

Oh, I didn't know we record event telemetry for jsonfile now. And it looks like disabling the pref won't work because the service gets initialized as soon as PushBroadcastService.jsm is loaded. The error is coming from telemetry, here.

I don't remember how PushBroadcastService works anymore and if there would be knock-on effects from removing initializing right away—I think there would be a lot of test fixing we'd have to do 😕 This is hacky, but can you have the test filter out messages starting with Unknown event: ? That would be the easiest way to get this fixed without changing lots of other (super sketchy) code...

Comment 5

[Junior [inactive]]

(In reply to :Lina Cambridge from comment #4)

Oh, I didn't know we record event telemetry for jsonfile now. And it looks like disabling the pref won't work because the service gets initialized as soon as PushBroadcastService.jsm is loaded. The error is coming from telemetry, here.

I don't remember how PushBroadcastService works anymore and if there would be knock-on effects from removing initializing right away—I think there would be a lot of test fixing we'd have to do 😕 This is hacky, but can you have the test filter out messages starting with Unknown event: ? That would be the easiest way to get this fixed without changing lots of other (super sketchy) code...

Thanks, I'm thinking of filtering them out as well.

I managed to get the log and it looks something wrong.

0 load() ["resource://gre/modules/JSONFile.jsm":234:25]
1 InterpretGeneratorResume(gen = "[object Object]", val = "Unix error 2 during operation open on file /tmp/tmpTbfwHU.mozrunner/broadcast-listeners.json (No such file or directory)", kind = ""throw"") ["se
lf-hosted":1242:0]
2 AsyncFunctionThrow(val = "Unix error 2 during operation open on file /tmp/tmpTbfwHU.mozrunner/broadcast-listeners.json (No such file or directory)") ["self-hosted":688:0]
    this = [object Object]

Comment 6

[Lina Butler (ex-Mozilla)]

Hmmm, could it be initializing before it has a profile directory—like, this is empty?

Comment 7

[Junior [inactive]]

Attachment: Bug 1648712 - prevent false alarm of console message from dom telemetry push, r=lina

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/239e544e54d0
prevent false alarm of console message from dom telemetry push, r=lina

Comment 9

[Intermittent Failures Robot]

45 failures in 806 pushes (0.056 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 45

Platform breakdown:

• macosx1014-64: 44
• linux1804-64-asan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1648712&startday=2020-06-26&endday=2020-06-26&tree=all

Comment 10

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/239e544e54d0

Comment 11

[Intermittent Failures Robot]

74 failures in 5252 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #15 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 74

Platform breakdown:

• macosx1014-64: 73
• linux1804-64-asan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1648712&startday=2020-06-22&endday=2020-06-28&tree=all