Open Bug 1627094 Opened 4 years ago Updated 11 months ago

Intermittent toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Categories

(Core :: Privacy: Anti-Tracking, defect, P2)

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(1 file)

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


[task 2020-04-02T20:14:24.282Z] 20:14:24 INFO - TEST-START | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js
[task 2020-04-02T20:23:44.974Z] 20:23:44 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | No console messages should be generated -
[task 2020-04-02T20:23:44.974Z] 20:23:44 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Checking cookie blocking notifications -
[task 2020-04-02T20:23:44.975Z] 20:23:44 INFO - Removing the tab
[task 2020-04-02T20:23:44.976Z] 20:23:44 INFO - Leaving test bound
[task 2020-04-02T20:23:44.977Z] 20:23:44 INFO - Entering test bound
[task 2020-04-02T20:23:44.977Z] 20:23:44 INFO - Cleaning up.
[task 2020-04-02T20:23:44.978Z] 20:23:44 INFO - Buffered messages logged at 20:23:44
[task 2020-04-02T20:23:44.979Z] 20:23:44 INFO - Leaving test bound
[task 2020-04-02T20:23:44.979Z] 20:23:44 INFO - Buffered messages finished
[task 2020-04-02T20:23:44.980Z] 20:23:44 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2020-04-02T20:23:44.980Z] 20:23:44 INFO - TEST-FAIL | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Assertion count 72 is greater than expected range 0-0 assertions. -
[task 2020-04-02T20:23:44.981Z] 20:23:44 INFO - GECKO(1221) | MEMORY STAT | vsize 3101MB | residentFast 394MB | heapAllocated 131MB
[task 2020-04-02T20:23:44.982Z] 20:23:44 INFO - TEST-OK | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | took 560119ms

I see many assertions in the log:

###!!! ASSERTION: OnDataAvailable implementation consumed no data: 'Error', file /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp, line 608

But automation does not treat them as unexpected failures.

INFO - TEST-FAIL | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Assertion count 72 is greater than expected range 0-0 assertions. -

Is this intentional?

In the past week we had 47 occurrences, all on linux1804-64 debug.
Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=303463035&repo=autoland&lineNumber=18136

[task 2020-05-23T09:20:22.556Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Doesn't yet have storage access - true == true -
[task 2020-05-23T09:20:22.557Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Blob has been created - true == true -
[task 2020-05-23T09:20:22.561Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Blob URL has been created - true == true -
[task 2020-05-23T09:20:22.561Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Worker has been created - true == true -
[task 2020-05-23T09:20:22.562Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Should have storage access now - true == true -
[task 2020-05-23T09:20:22.562Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Worker has been created - true == true -
[task 2020-05-23T09:20:22.562Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | No console messages should be generated -
[task 2020-05-23T09:20:22.563Z] 09:20:22 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | Checking cookie blocking notifications -
[task 2020-05-23T09:20:22.563Z] 09:20:22 INFO - Removing the tab
[task 2020-05-23T09:20:22.564Z] 09:20:22 INFO - Leaving test bound
[task 2020-05-23T09:20:22.564Z] 09:20:22 INFO - Entering test bound
[task 2020-05-23T09:20:22.565Z] 09:20:22 INFO - Cleaning up.
[task 2020-05-23T09:20:22.565Z] 09:20:22 INFO - Buffered messages logged at 09:20:21
[task 2020-05-23T09:20:22.567Z] 09:20:22 INFO - Leaving test bound
[task 2020-05-23T09:20:22.568Z] 09:20:22 INFO - Buffered messages finished
[task 2020-05-23T09:20:22.571Z] 09:20:22 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2020-05-23T09:20:22.571Z] 09:20:22 INFO - GECKO(1247) | MEMORY STAT | vsize 3121MB | residentFast 398MB | heapAllocated 131MB
[task 2020-05-23T09:20:22.575Z] 09:20:22 INFO - TEST-OK | toolkit/components/antitracking/test/browser/browser_blockingMessaging.js | took 544417ms
[task 2020-05-23T09:20:22.575Z] 09:20:22 INFO - GECKO(1247) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fab68ef7c00 == 3 [pid = 1530] [id = {411c5222-15ec-40d1-9b6c-4e45925baac4}]
[task 2020-05-23T09:20:22.575Z] 09:20:22 INFO - GECKO(1247) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (0x7fab676cd820) [pid = 1530] [serial = 1422] [outer = (nil)]
[task 2020-05-23T09:20:22.575Z] 09:20:22 INFO - GECKO(1247) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (0x7fab6b65ec00) [pid = 1530] [serial = 1423] [outer = 0x7fab676cd820]
[task 2020-05-23T09:20:22.575Z] 09:20:22 INFO - checking window state

Whiteboard: [stockwell needswork]
Flags: needinfo?(senglehardt)
Whiteboard: [stockwell needswork] → [stockwell needswork:owner]
Severity: normal → S3
Flags: needinfo?(senglehardt)
Priority: P5 → P2

Tim, would you mind to take a look?

Flags: needinfo?(tihuang)

Sure.

Assignee: nobody → tihuang
Flags: needinfo?(tihuang)
Pushed by ccoroiu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b0d6c1da3d32
Disable browser_blockingMessaging.js on Linux asan and Linux 18.04 debug r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Assignee: tihuang → nobody
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: