1585944 - Intermittent netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 199] Created just one session with the proxy - 5 == 1

Status: RESOLVED DUPLICATE of bug 1584743

(Core :: Networking, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2019-10-03T11:06:23.013Z] 11:06:23 INFO - TEST-START | netwerk/test/unit/test_http2-proxy.js
[task 2019-10-03T11:06:23.793Z] 11:06:23 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_http2-proxy.js | xpcshell return code: 0
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - TEST-INFO took 780ms
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - >>>>>>>
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - running event loop
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - netwerk/test/unit/test_http2-proxy.js | Starting setup
[task 2019-10-03T11:06:23.793Z] 11:06:23 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | setup - [setup : 140] "50360" != null
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | setup - [setup : 144] 50790 != null
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - "Initial proxy session count = 0"
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - (xpcshell/head.js) | test setup finished (2)
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - netwerk/test/unit/test_http2-proxy.js | Starting proxy_success_one_session
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - (xpcshell/head.js) | test proxy_success_one_session pending (2)
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Unexpected content-type "null"" {file: "resource://services-settings/Utils.jsm" line: 120}]
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - fetchLatestChanges@resource://services-settings/Utils.jsm:120:15
[task 2019-10-03T11:06:23.794Z] 11:06:23 INFO - asyncsync@resource://services-settings/RemoteSettingsClient.jsm:372:37
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - get@resource://services-settings/RemoteSettingsClient.jsm:325:22
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - asyncaddObserver@resource://gre/modules/UrlClassifierSkipListService.jsm:39:63
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - registerAndRunSkipListObserver@resource://gre/modules/UrlClassifierSkipListService.jsm:126:28
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - _do_main@Z:\task_1570099316\build\tests\xpcshell\head.js:246:6
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - _execute_test@Z:\task_1570099316\build\tests\xpcshell\head.js:573:5
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - @-e:1:1
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - "
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Unexpected content-type "null"" {file: "resource://services-settings/Utils.jsm" line: 120}]
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - fetchLatestChanges@resource://services-settings/Utils.jsm:120:15
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - asyncsync@resource://services-settings/RemoteSettingsClient.jsm:372:37
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - get@resource://services-settings/RemoteSettingsClient.jsm:325:22
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - asyncaddObserver@resource://gre/modules/UrlClassifierSkipListService.jsm:39:63
[task 2019-10-03T11:06:23.795Z] 11:06:23 INFO - registerAndRunSkipListObserver@resource://gre/modules/UrlClassifierSkipListService.jsm:126:28
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - _do_main@Z:\task_1570099316\build\tests\xpcshell\head.js:246:6
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - _execute_test@Z:\task_1570099316\build\tests\xpcshell\head.js:573:5
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - @-e:1:1
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - "
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Unexpected content-type "null"" {file: "resource://services-settings/Utils.jsm" line: 120}]
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - fetchLatestChanges@resource://services-settings/Utils.jsm:120:15
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - asyncsync@resource://services-settings/RemoteSettingsClient.jsm:372:37
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - get@resource://services-settings/RemoteSettingsClient.jsm:325:22
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - asyncaddObserver@resource://gre/modules/UrlClassifierSkipListService.jsm:39:63
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - registerAndRunSkipListObserver@resource://gre/modules/UrlClassifierSkipListService.jsm:126:28
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - _do_main@Z:\task_1570099316\build\tests\xpcshell\head.js:246:6
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - _execute_test@Z:\task_1570099316\build\tests\xpcshell\head.js:573:5
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - @-e:1:1
[task 2019-10-03T11:06:23.796Z] 11:06:23 INFO - "
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 191] 0 == 0
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 192] 200 == 200
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 193] ["random-request-1"] == true
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 194] ["You Win!"] == true
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 195] 0 == 0
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 196] 200 == 200
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 197] ["random-request-2"] == true
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - TEST-PASS | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 198] ["You Win!"] == true
[task 2019-10-03T11:06:23.797Z] 11:06:23 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_http2-proxy.js | proxy_success_one_session - [proxy_success_one_session : 199] Created just one session with the proxy - 5 == 1
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - Z:/task_1570099316/build/tests/xpcshell/tests/netwerk/test/unit/test_http2-proxy.js:proxy_success_one_session:199
[task 2019-10-03T11:06:23.797Z] 11:06:23 INFO - exiting test
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - _abort_failed_test@Z:\task_1570099316\build\tests\xpcshell\head.js:789:20
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - do_report_result@Z:\task_1570099316\build\tests\xpcshell\head.js:890:5
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - Assert<@Z:\task_1570099316\build\tests\xpcshell\head.js:67:21
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - equal@resource://testing-common/Assert.jsm:275:8
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - proxy_success_one_session@Z:/task_1570099316/build/tests/xpcshell/tests/netwerk/test/unit/test_http2-proxy.js:199:10
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - async*run_next_test/_run_next_test/<@Z:\task_1570099316\build\tests\xpcshell\head.js:1565:22
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - _run_next_test@Z:\task_1570099316\build\tests\xpcshell\head.js:1565:38
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - run@Z:\task_1570099316\build\tests\xpcshell\head.js:733:9
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - _do_main@Z:\task_1570099316\build\tests\xpcshell\head.js:246:6
[task 2019-10-03T11:06:23.798Z] 11:06:23 INFO - _execute_test@Z:\task_1570099316\build\tests\xpcshell\head.js:573:5
[task 2019-10-03T11:06:23.799Z] 11:06:23 INFO - @-e:1:1
[task 2019-10-03T11:06:23.799Z] 11:06:23 INFO - exiting test
[task 2019-10-03T11:06:23.799Z] 11:06:23 INFO - PID 20628 | JavaScript strict warning: resource://testing-common/httpd.js, line 945: ReferenceError: reference to undefined property "result"
[task 2019-10-03T11:06:23.799Z] 11:06:23 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "result"" {file: "resource://testing-common/httpd.js" line: 945}]"
[task 2019-10-03T11:06:23.799Z] 11:06:23 INFO - <<<<<<<

Comment 1

[Honza Bambas (:mayhemer)]

Isn't this just another variant of the already filed bug 1584743?
Is the test running really sequentially? According the ini it should:
https://searchfox.org/mozilla-central/rev/35cc00a25c4471993fdaa5761952bd3afd4f1731/netwerk/test/unit/xpcshell.ini#440

Comment 2

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

SInce the proxy is browser-wide, I wonder if it's actually other things that are triggering it. Captive portal should be disabled during xpcshell-test, but other things such as the UrlClassifierSkipListService still seem to be active.
I suppose we could log the proxy requests in moz-http2.js - and we should be able to figure out what's causing the mismatch.

Comment 3

[Honza Bambas (:mayhemer)]

It's also quite possible that the test as I wrote it makes bad assumptions about exclusive use and the number of sessions may be non testable. I believe your patch for creating an h2 proxy on the server per-test might fix this well.

Comment 4

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

That patch landed in bug 1582515, and did not fix this.

Comment 5

[Intermittent Failures Robot]

2 failures in 4292 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform breakdown:

• windows10-64-shippable: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1585944&startday=2019-09-30&endday=2019-10-06&tree=all

Comment 6

[Intermittent Failures Robot]

3 failures in 3801 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 2

Platform breakdown:

• windows10-64: 1
• windows10-64-shippable: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1585944&startday=2019-10-07&endday=2019-10-13&tree=all

Comment 7

[Intermittent Failures Robot]

1 failures in 3964 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1585944&startday=2019-10-14&endday=2019-10-20&tree=all

Comment 8

[Intermittent Failures Robot]

2 failures in 4182 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1585944&startday=2019-10-21&endday=2019-10-27&tree=all

Comment 9

[Intermittent Failures Robot]

3 failures in 4314 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-beta: 2

Platform breakdown:

• windows7-32-shippable: 1
• windows10-64-shippable: 1
• windows7-32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1585944&startday=2019-10-28&endday=2019-11-03&tree=all

Comment 10

[Honza Bambas (:mayhemer)]

Duplicate of bug 1584743?

Comment 11

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

Most likely. Hasn't happened in a while anyway.