Closed Bug 1580976 Opened 1 year ago Closed 1 year ago

Intermittent netwerk/test/unit/test_trr.js | test1 - [test1 : 125] "127.0.0.1" == "2.2.2.2"

Categories

(Core :: Networking, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla71
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox67 --- unaffected
firefox68 --- unaffected
firefox69 --- unaffected
firefox70 --- unaffected
firefox71 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [necko-triaged])

Attachments

(1 file)

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=266399457&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/bJQ1DN22SSyulnHybuGbhw/runs/0/artifacts/public/logs/live_backing.log


INFO -  TEST-START | netwerk/test/unit/test_trr.js
[task 2019-09-12T21:01:54.785Z] 21:01:54  WARNING -  TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_trr.js | xpcshell return code: 0
[task 2019-09-12T21:01:54.785Z] 21:01:54     INFO -  TEST-INFO took 2293ms
[task 2019-09-12T21:01:54.786Z] 21:01:54     INFO -  >>>>>>>
[task 2019-09-12T21:01:54.786Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2632
[task 2019-09-12T21:01:54.787Z] 21:01:54     INFO -  PID 13318 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-12T21:01:54.787Z] 21:01:54     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-09-12T21:01:54.790Z] 21:01:54     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2019-09-12T21:01:54.790Z] 21:01:54     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-09-12T21:01:54.791Z] 21:01:54     INFO -  running event loop
[task 2019-09-12T21:01:54.791Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/workspace/build/src/dom/media/CubebUtils.cpp, line 384
[task 2019-09-12T21:01:54.792Z] 21:01:54     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2019-09-12T21:01:54.792Z] 21:01:54     INFO -  netwerk/test/unit/test_trr.js | Starting setup
[task 2019-09-12T21:01:54.793Z] 21:01:54     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2019-09-12T21:01:54.793Z] 21:01:54     INFO -  PID 13318 | start!
[task 2019-09-12T21:01:54.794Z] 21:01:54     INFO -  TEST-PASS | netwerk/test/unit/test_trr.js | setup - [setup : 34] "45279" != null
[task 2019-09-12T21:01:54.795Z] 21:01:54     INFO -  TEST-PASS | netwerk/test/unit/test_trr.js | setup - [setup : 35] "45279" != ""
[task 2019-09-12T21:01:54.795Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/extensions/permissions/nsPermissionManager.cpp, line 2883
[task 2019-09-12T21:01:54.796Z] 21:01:54     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2019-09-12T21:01:54.796Z] 21:01:54     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2019-09-12T21:01:54.797Z] 21:01:54     INFO -  (xpcshell/head.js) | test setup finished (2)
[task 2019-09-12T21:01:54.797Z] 21:01:54     INFO -  netwerk/test/unit/test_trr.js | Starting test1
[task 2019-09-12T21:01:54.798Z] 21:01:54     INFO -  (xpcshell/head.js) | test test1 pending (2)
[task 2019-09-12T21:01:54.798Z] 21:01:54     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2019-09-12T21:01:54.799Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002: file /builds/worker/workspace/build/src/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 661
[task 2019-09-12T21:01:54.799Z] 21:01:54     INFO -  TEST-PASS | netwerk/test/unit/test_trr.js | test1 - [test1 : 114] true == true
[task 2019-09-12T21:01:54.800Z] 21:01:54     INFO -  TEST-PASS | netwerk/test/unit/test_trr.js | test1 - [test1 : 123] 0 == 0
[task 2019-09-12T21:01:54.802Z] 21:01:54  WARNING -  TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_trr.js | test1 - [test1 : 125] "127.0.0.1" == "2.2.2.2"
[task 2019-09-12T21:01:54.802Z] 21:01:54     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/netwerk/test/unit/test_trr.js:onLookupComplete:125
[task 2019-09-12T21:01:54.802Z] 21:01:54     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:246
[task 2019-09-12T21:01:54.802Z] 21:01:54     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:573
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  -e:null:1
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  exiting test
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 | JavaScript error: /builds/worker/workspace/build/tests/xpcshell/head.js, line 789: NS_ERROR_ABORT:
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT: " {file: "/builds/worker/workspace/build/tests/xpcshell/head.js" line: 789}]"
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 3114
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 | [13318, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 | nsStringStats
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => mAllocCount:          10811
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => mReallocCount:            0
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => mFreeCount:           10811
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => mShareCount:           8337
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => mAdoptCount:            216
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => mAdoptFreeCount:        216
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  PID 13318 |  => Process ID: 13318, Thread ID: 140350973846656
[task 2019-09-12T21:01:54.803Z] 21:01:54     INFO -  <<<<<<<
[task 2019-09-12T21:01:54.806Z] 21:01:54     INFO -  TEST-START | netwerk/test/unit/test_esni_dns_fetch.js
[task 2019-09-12T21:01:57.092Z] 21:01:57  WARNING -  TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_esni_dns_fetch.js | xpcshell return code: 0
[task 2019-09-12T21:01:57.093Z] 21:01:57     INFO -  TEST-INFO took 2280ms
[task 2019-09-12T21:01:57.093Z] 21:01:57     INFO -  >>>>>>>
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2632
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  PID 13340 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  TEST-PASS | netwerk/test/unit/test_esni_dns_fetch.js | run_test - [run_test : 20] "45279" != null
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  TEST-PASS | netwerk/test/unit/test_esni_dns_fetch.js | run_test - [run_test : 21] "45279" != ""
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/extensions/permissions/nsPermissionManager.cpp, line 2883
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  (xpcshell/head.js) | test pending (2)
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  PID 13340 | starting test 0
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  (xpcshell/head.js) | test pending (3)
[task 2019-09-12T21:01:57.094Z] 21:01:57     INFO -  (xpcshell/head.js) | test MAIN run_test finished (3)
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  running event loop
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/workspace/build/src/dom/media/CubebUtils.cpp, line 384
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002: file /builds/worker/workspace/build/src/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 661
[task 2019-09-12T21:01:57.095Z] 21:01:57  WARNING -  TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_esni_dns_fetch.js | onLookupByTypeComplete - [onLookupByTypeComplete : 77] false == true
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/netwerk/test/unit/test_esni_dns_fetch.js:onLookupByTypeComplete:77
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:246
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:573
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  -e:null:1
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  exiting test
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  PID 13340 | JavaScript error: /builds/worker/workspace/build/tests/xpcshell/head.js, line 789: NS_ERROR_ABORT:
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT: " {file: "/builds/worker/workspace/build/tests/xpcshell/head.js" line: 789}]"
[task 2019-09-12T21:01:57.095Z] 21:01:57     INFO -  PID 13340 | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 3114
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 | [13340, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 | nsStringStats
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => mAllocCount:          10650
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => mReallocCount:            0
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => mFreeCount:           10650
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => mShareCount:           8185
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => mAdoptCount:            191
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => mAdoptFreeCount:        191
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  PID 13340 |  => Process ID: 13340, Thread ID: 140477192799360
[task 2019-09-12T21:01:57.096Z] 21:01:57     INFO -  <<<<<<<
[task 2019-09-12T21:01:57.103Z] 21:01:57     INFO -  TEST-START | security/manager/ssl/tests/unit/test_intermediate_preloads.js

I think this might be related to node update.
From the log, the moz-http2 server is already dead before shutting it down.

[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  Node moz-http2 server shutting down ...
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  Node server moz-http2 already dead -6
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  Process stderr
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  (node:1086) ExperimentalWarning: The http2 module is an experimental API.
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  (node:1086) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  (node:1086) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  (node:1086) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  (node:1086) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -  /usr/local/bin/node[1086]: ../src/tls_wrap.cc:604:virtual int node::TLSWrap::DoWrite(node::WriteWrap*, uv_buf_t*, size_t, uv_stream_t*): Assertion `(ssl_) != (nullptr)' failed.
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   1: node::Abort() [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   2: 0x8c25db [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   3: node::TLSWrap::DoWrite(node::WriteWrap*, uv_buf_t*, unsigned long, uv_stream_s*) [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   4: node::http2::Http2Session::SendPendingData() [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   5: node::http2::Http2Stream::RstStream(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   6: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   7: 0xad710c [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   8: v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) [/usr/local/bin/node]
[task 2019-09-12T21:02:04.840Z] 21:02:04     INFO -   9: 0x7455a3842fd

Junior, could you take a look?

Flags: needinfo?(juhsu)

Looks like it's a known issue of v8 node.
https://github.com/nodejs/node/issues/22923

We might have some server fix for workaround since it's not expected have a node update recently.

Flags: needinfo?(juhsu)

test_http2-proxy.js hits a known issue of v8.11.3 node in comment 3.
However the work around doesn't work (see patch below). Maybe different issues with same syndrome.

It's a permanent issue, at least my local linux/mac. The reason of intermittent treeherder is that test_http2-proxy.js is the last test who needs node.
xpcshell is happy even if node crashes.
In this case, test_trr is going to retry, and the node crashes before the retry.

v8.13 node works for me.

--- a/testing/xpcshell/moz-http2/moz-http2.js
+++ b/testing/xpcshell/moz-http2/moz-http2.js
@@ -1193,16 +1193,26 @@ if (http2_internal) {
 
   proxy.on('stream', (stream, headers) => {
     if (headers[':method'] !== 'CONNECT') {
       // Only accept CONNECT requests
       stream.close(http2.constants.NGHTTP2_REFUSED_STREAM);
       return;
     }
 
+    if (stream.session && !stream.session.goawayOverritten) {
+      stream.session.goawayOverritten = true;
+      stream.session.prevGoaway = stream.session.goaway;
+      stream.session.goaway = function (errorCode, lastStreamID, opaqueData) {
+        if (!this.closed) {
+          this.prevGoaway(errorCode, lastStreamID, opaqueData);
+        }
+      }
+    }
+
     const target = headers[':authority'];
 
     const authorization_token = headers['proxy-authorization'];
     if ('authorization-token' != authorization_token || target == '407.example.com:443') {
       stream.respond({ ':status': 407 });
       // Deliberately send no Proxy-Authenticate header
       stream.end();
       return;

Bug 1547823 is about upgrading node to 10.
node 8 is End-of-life on the end of 2019, upgrade should happen before that.

Thanks for the thorough investigation Junior.
I only see a couple of failures last week. Let's see if this spikes in which case we'll have to look for a better workaround.
Hopefully we can upgrade node soon.

Depends on: 1547823
Whiteboard: [necko-triaged]

Thanks; yes, would be great to update Node again ASAP.

See Also: → 1582030
Pushed by valentin.gosu@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/a6a8310a3f76
Check that moz-http2.js is working before running test_trr.js r=JuniorHsu
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla71
Assignee: nobody → valentin.gosu
You need to log in before you can comment on or make changes to this bug.