1640724 - Intermittent netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking status - 2152398878 == 0

Status: RESOLVED FIXED

(Core :: Networking: DNS, defect, P2)

Description

[Treeherder Bug Filer]

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

---

[task 2020-05-25T18:20:05.757Z] 18:20:05 INFO - TEST-START | netwerk/test/unit/test_trr_case_sensitivity.js
[task 2020-05-25T18:20:38.683Z] 18:20:38 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_trr_case_sensitivity.js | xpcshell return code: 0
[task 2020-05-25T18:20:38.683Z] 18:20:38 INFO - TEST-INFO took 32922ms
[task 2020-05-25T18:20:38.683Z] 18:20:38 INFO - >>>>>>>
[task 2020-05-25T18:20:38.683Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 2924
[task 2020-05-25T18:20:38.683Z] 18:20:38 INFO - PID 5549 | start!
[task 2020-05-25T18:20:38.683Z] 18:20:38 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - running event loop
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - PID 5549 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 375
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - netwerk/test/unit/test_trr_case_sensitivity.js | Starting test_trr_casing
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - (xpcshell/head.js) | test test_trr_casing pending (2)
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002 (NS_NOINTERFACE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 673
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2020-05-25T18:20:38.684Z] 18:20:38 INFO - PID 5549 | port = 57921
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] 44 == 44
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 42] "<h1> 404 Path not found: /test?bla=some</h1>" == "<h1> 404 Path not found: /test?bla=some</h1>"
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking that this is the correct callback - true == true
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking status - 0 == 0
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking result for a.example.com - "1.2.3.4" == "1.2.3.4"
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking that this is the correct callback - true == true
[task 2020-05-25T18:20:38.685Z] 18:20:38 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking status - 2152398878 == 0
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - -e:null:1
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - exiting test
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - PID 5549 | JavaScript error: /Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js, line 833: NS_ERROR_ABORT:
[task 2020-05-25T18:20:38.685Z] 18:20:38 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT: " {file: "/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js" line: 833}]
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - _abort_failed_test@/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js:833:20
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - do_report_result@/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js:934:5
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - Assert<@/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js:73:21
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - equal@resource://testing-common/Assert.jsm:275:8
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - onLookupComplete@/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/tests/netwerk/test/unit/head_trr.js:144:12
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - _do_main@/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js:248:6
[task 2020-05-25T18:20:38.686Z] 18:20:38 INFO - _execute_test@/Users/cltbld/tasks/task_1590428687/build/tests/xpcshell/head.js:577:5
[task 2020-05-25T18:20:38.687Z] 18:20:38 INFO - @-e:1:1
[task 2020-05-25T18:20:38.687Z] 18:20:38 INFO - "
[task 2020-05-25T18:20:38.687Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-05-25T18:20:38.687Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp, line 3370
[task 2020-05-25T18:20:38.687Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-05-25T18:20:38.688Z] 18:20:38 INFO - PID 5549 | [5549, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-05-25T18:20:38.688Z] 18:20:38 INFO - <<<<<<<

Comment 1

[Valentin Gosu [:valentin] (he/him)]

Seems like the test is racy.

Comment 2

[Intermittent Failures Robot]

17 failures in 1051 pushes (0.016 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16
• mozilla-central: 1

Platform breakdown:

• macosx1014-64: 4
• linux1804-64: 3
• macosx1014-64-shippable: 5
• linux1804-64-shippable-qr: 1
• windows7-32-shippable: 2
• linux1804-64-shippable: 2

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

Comment 3

[Intermittent Failures Robot]

53 failures in 5458 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

This is the #17 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: 43
• mozilla-central: 5
• try: 4
• comm-central: 1

Platform breakdown:

• macosx1014-64: 14
• macosx1014-64-shippable: 13
• linux1804-64: 8
• windows7-32-shippable: 7
• linux1804-64-shippable: 4
• linux1804-64-qr: 2
• linux1804-64-shippable-qr: 3
• linux1804-64-asan: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1640724&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 4

[Intermittent Failures Robot]

26 failures in 950 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 22
• mozilla-beta: 1
• mozilla-central: 3

Platform breakdown:

• linux1804-64-qr: 1
• macosx1014-64: 2
• macosx1014-64-shippable: 2
• linux1804-64-shippable-qr: 11
• linux1804-64-shippable: 6
• linux1804-64: 3
• windows7-32-shippable: 1

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

Comment 5

[Atila Butkovits]

There are 75 failures in the last 7 days on linux1804-64 opt,debug; inux1804-64-shippable opt; macosx1014-64 debug
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305274742&repo=mozilla-central&lineNumber=5119

''' [task 2020-06-05T22:46:43.760Z] 22:46:43 INFO - TEST-START | netwerk/test/unit/test_trr_case_sensitivity.js
[task 2020-06-05T22:47:14.084Z] 22:47:14 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_trr_case_sensitivity.js | xpcshell return code: 0
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-INFO took 30322ms
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - >>>>>>>
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - PID 19571 | start!
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - running event loop
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - netwerk/test/unit/test_trr_case_sensitivity.js | Starting test_trr_casing
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - (xpcshell/head.js) | test test_trr_casing pending (2)
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - PID 19571 | port = 34504
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] 44 == 44
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 42] "<h1> 404 Path not found: /test?bla=some</h1>" == "<h1> 404 Path not found: /test?bla=some</h1>"
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking that this is the correct callback - true == true
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking status - 0 == 0
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking result for a.example.com - "1.2.3.4" == "1.2.3.4"
[task 2020-06-05T22:47:14.084Z] 22:47:14 INFO - TEST-PASS | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking that this is the correct callback - true == true
[task 2020-06-05T22:47:14.084Z] 22:47:14 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_trr_case_sensitivity.js | test_trr_casing - [test_trr_casing : 1] Checking status - 2152398878 == 0'''

Comment 6

[Intermittent Failures Robot]

35 failures in 875 pushes (0.04 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 27
• mozilla-central: 4
• try: 3
• mozilla-beta: 1

Platform breakdown:

• linux1804-64-shippable: 8
• windows7-32-shippable: 2
• linux1804-64-shippable-qr: 16
• linux1804-64-qr: 3
• linux1804-64: 4
• macosx1014-64: 2

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

Comment 7

[Intermittent Failures Robot]

106 failures in 4949 pushes (0.021 failures/push) were associated with this bug in the last 7 days.

This is the #10 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 82
• comm-central: 1
• try: 11
• mozilla-central: 10
• mozilla-beta: 2

Platform breakdown:

• windows7-32-shippable: 4
• linux1804-64-shippable: 25
• macosx1014-64: 11
• linux1804-64: 13
• linux1804-64-shippable-qr: 40
• macosx1014-64-shippable: 6
• linux1804-64-qr: 5
• windows7-32: 1
• linux1804-64-devedition: 1

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

Comment 8

[Valentin Gosu [:valentin] (he/him)]

I'm actively working on the bug. I should be able to figure it out in the next day or so.

Comment 9

[Valentin Gosu [:valentin] (he/him)]

Attachment: Bug 1640724 - head_trr.js: Emit DoH response when we got all the bytes instead of "end" event r=dragana

This patch is a workaround for an issue that causes an intermittent failure
in test_trr_case_sensitivity.js.
I was able to reproduce the bug locally with some logging, but not with
nsHttp:5 or under rr, which made it difficult to diagnose the root cause.
What I was able to determine using logging and timestamps in the nodejs code
is that we would not get the "end" event for a request, to which we were
reacting to send back the DoH response. The request has a timer, and
eventually that timer would fire and cancel the request. At that point
we would see the "end" event in nodejs but it's too late to actually process
the response.

It's not clear if this was a bug in Firefox's HTTP2 implementation
(maybe the end isn't signaled properly) or in nodejs.

This fix makes it so we send back the response when the number of bytes
specified in contentLength reaches the server.
We should investigate in a follow-up bug if there's another Necko bug
involved here.

Comment 10

[Valentin Gosu [:valentin] (he/him)]

Attachment: repro_decrypt.pcapng

Comment 11

[Valentin Gosu [:valentin] (he/him)]

Comment on attachment 9154997 [details]
repro_decrypt.pcapng

Wanted to attach it in bug 1644206 instead.

Comment 12

[Intermittent Failures Robot]

17 failures in 890 pushes (0.019 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 10
• try: 3
• mozilla-beta: 1
• mozilla-central: 3

Platform breakdown:

• macosx1014-64-shippable: 1
• linux1804-64-shippable: 4
• linux1804-64-shippable-qr: 5
• linux1804-64: 5
• linux1804-64-devedition: 1
• windows7-32-shippable: 1

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

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/af65ea1369ff
head_trr.js: Emit DoH response when we got all the bytes instead of "end" event r=dragana,necko-reviewers

Comment 14

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/af65ea1369ff

Comment 15

[Andreea Pavel [:apavel]]

Shows up on mozilla-beta: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305961333&repo=mozilla-beta&lineNumber=8504

Comment 16

[Valentin Gosu [:valentin] (he/him)]

Comment on attachment 9154923 [details]
Bug 1640724 - head_trr.js: Emit DoH response when we got all the bytes instead of "end" event r=dragana

Beta/Release Uplift Approval Request

• User impact if declined: No user impact. This is a test-only change that works around a bug in the nodejs HTTP2 implementation that causes intermittent failures in xpcshell-tests
• Is this code covered by automated tests?: Unknown
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): Only affects the failure of test_trr_case_sensitivity.js in automation.
• String changes made/needed:

Comment 17

[Julien Cristau [:jcristau] (back August 18)]

Comment on attachment 9154923 [details]
Bug 1640724 - head_trr.js: Emit DoH response when we got all the bytes instead of "end" event r=dragana

This can land a=test-only.

Comment 18

[Julien Cristau [:jcristau] (back August 18)]

Actually those tests are now disabled in beta and we don't have bug 1641496 there, so we might be better off leaving things as they are?

Comment 19

[Valentin Gosu [:valentin] (he/him)]

Attachment: Bug 1640724 - [beta] head_trr.js: Emit DoH response when we got all the bytes instead of "end" event a=test-only

This patch is a workaround for an issue that causes an intermittent failure
in test_trr_case_sensitivity.js.
I was able to reproduce the bug locally with some logging, but not with
nsHttp:5 or under rr, which made it difficult to diagnose the root cause.
What I was able to determine using logging and timestamps in the nodejs code
is that we would not get the "end" event for a request, to which we were
reacting to send back the DoH response. The request has a timer, and
eventually that timer would fire and cancel the request. At that point
we would see the "end" event in nodejs but it's too late to actually process
the response.

It's not clear if this was a bug in Firefox's HTTP2 implementation
(maybe the end isn't signaled properly) or in nodejs.

This fix makes it so we send back the response when the number of bytes
specified in contentLength reaches the server.
We should investigate in a follow-up bug if there's another Necko bug
involved here.

Comment 20

[Valentin Gosu [:valentin] (he/him)]

(In reply to Julien Cristau [:jcristau] from comment #18)

Actually those tests are now disabled in beta and we don't have bug 1641496 there, so we might be better off leaving things as they are?

This addresses the failures xpcshell-test and verify failures on all platforms. It should stay disabled for socket-process.

Comment 21

[Intermittent Failures Robot]

21 failures in 5211 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• try: 4
• mozilla-beta: 3
• mozilla-central: 3

Platform breakdown:

• macosx1014-64-shippable: 1
• linux1804-64: 5
• linux1804-64-shippable: 4
• linux1804-64-shippable-qr: 5
• linux1804-64-devedition: 1
• windows7-32-shippable: 1
• macosx1014-64: 2
• windows7-32: 1
• windows7-32-devedition: 1

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

Comment 22

[Julien Cristau [:jcristau] (back August 18)]

https://hg.mozilla.org/releases/mozilla-beta/rev/6260a9205148