1777188 - Intermittent security/manager/ssl/tests/unit/test_pinning.js | single tracking bug

Status: RESOLVED INCOMPLETE

(Core :: Security: PSM, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-29T09:06:18.517Z] 09:06:18     INFO -  TEST-START | security/manager/ssl/tests/unit/test_pinning.js
[task 2022-06-29T09:06:19.115Z] 09:06:19  WARNING -  TEST-UNEXPECTED-FAIL | security/manager/ssl/tests/unit/test_pinning.js | xpcshell return code: 0
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  TEST-INFO took 596ms
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  >>>>>>>
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  running event loop
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  security/manager/ssl/tests/unit/test_pinning.js | Starting
[task 2022-06-29T09:06:19.115Z] 09:06:19     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-06-29T09:06:19.117Z] 09:06:19     INFO -  TEST-PASS | security/manager/ssl/tests/unit/test_pinning.js |  - Binary util BadCertAndPinningServer should exist - true == true
[task 2022-06-29T09:06:19.117Z] 09:06:19     INFO -  TEST-PASS | security/manager/ssl/tests/unit/test_pinning.js |  - certificate folder (bad_certs) should exist - true == true
[task 2022-06-29T09:06:19.118Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-06-29T09:06:19.118Z] 09:06:19     INFO -  PID 3590 | sending 'GET / HTTP/1.0
[task 2022-06-29T09:06:19.118Z] 09:06:19     INFO -  PID 3590 | '
[task 2022-06-29T09:06:19.119Z] 09:06:19     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-06-29T09:06:19.119Z] 09:06:19     INFO -  (xpcshell/head.js) | test finished (2)
[task 2022-06-29T09:06:19.119Z] 09:06:19     INFO -  PID 3590 | HTTP/1.0 200 OK
[task 2022-06-29T09:06:19.119Z] 09:06:19     INFO -  PID 3590 | content-type: text/plain
[task 2022-06-29T09:06:19.120Z] 09:06:19     INFO -  PID 3590 | connection: close
[task 2022-06-29T09:06:19.120Z] 09:06:19     INFO -  PID 3590 | server: httpd.js
[task 2022-06-29T09:06:19.120Z] 09:06:19     INFO -  PID 3590 | date: Wed, 29 Jun 2022 09:06:18 GMT
[task 2022-06-29T09:06:19.121Z] 09:06:19     INFO -  PID 3590 | content-length: 3
[task 2022-06-29T09:06:19.121Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2022-06-29T09:06:19.125Z] 09:06:19     INFO -  (xpcshell/head.js) | test finished (2)
[task 2022-06-29T09:06:19.125Z] 09:06:19     INFO -  security/manager/ssl/tests/unit/test_pinning.js | Starting
[task 2022-06-29T09:06:19.125Z] 09:06:19     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-06-29T09:06:19.126Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (3)
[task 2022-06-29T09:06:19.126Z] 09:06:19     INFO -  (xpcshell/head.js) | test finished (3)
[task 2022-06-29T09:06:19.127Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2022-06-29T09:06:19.127Z] 09:06:19     INFO -  security/manager/ssl/tests/unit/test_pinning.js | Starting
[task 2022-06-29T09:06:19.127Z] 09:06:19     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-06-29T09:06:19.128Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2022-06-29T09:06:19.128Z] 09:06:19     INFO -  PID 3590 | found pre-defined host 'unknownissuer.include-subdomains.pinning.example.com'
[task 2022-06-29T09:06:19.129Z] 09:06:19     INFO -  PID 3590 | found pre-defined host 'unknownissuer.include-subdomains.pinning.example.com'
[task 2022-06-29T09:06:19.129Z] 09:06:19     INFO -  PID 3590 | PR_Recv failed: SSL_ERROR_UNKNOWN_CA_ALERT
[task 2022-06-29T09:06:19.129Z] 09:06:19     INFO -  "handling unknownissuer.include-subdomains.pinning.example.com"
[task 2022-06-29T09:06:19.137Z] 09:06:19     INFO -  TEST-PASS | security/manager/ssl/tests/unit/test_pinning.js |  - Actual and expected connection result should match - 2153390067 == 2153390067
[task 2022-06-29T09:06:19.137Z] 09:06:19     INFO -  TEST-PASS | security/manager/ssl/tests/unit/test_pinning.js |  - Actual and expected override bits should match - 1 == 1
[task 2022-06-29T09:06:19.137Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2022-06-29T09:06:19.137Z] 09:06:19     INFO -  (xpcshell/head.js) | test finished (2)
[task 2022-06-29T09:06:19.137Z] 09:06:19     INFO -  security/manager/ssl/tests/unit/test_pinning.js | Starting
[task 2022-06-29T09:06:19.137Z] 09:06:19     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-06-29T09:06:19.138Z] 09:06:19     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2022-06-29T09:06:19.138Z] 09:06:19     INFO -  PID 3590 | found pre-defined host 'unknownissuer.include-subdomains.pinning.example.com'
[task 2022-06-29T09:06:19.138Z] 09:06:19     INFO -  PID 3590 | found pre-defined host 'unknownissuer.include-subdomains.pinning.example.com'
[task 2022-06-29T09:06:19.138Z] 09:06:19     INFO -  "handling unknownissuer.include-subdomains.pinning.example.com"
[task 2022-06-29T09:06:19.138Z] 09:06:19  WARNING -  TEST-UNEXPECTED-FAIL | security/manager/ssl/tests/unit/test_pinning.js |  - Actual and expected connection result should match - 2152398868 == 2153390067
[task 2022-06-29T09:06:19.138Z] 09:06:19     INFO -  -e:null:1
[task 2022-06-29T09:06:19.139Z] 09:06:19     INFO -  exiting test
[task 2022-06-29T09:06:19.139Z] 09:06:19     INFO -  PID 3590 | JavaScript error: /builds/worker/workspace/build/tests/xpcshell/head.js, line 868: NS_ERROR_ABORT
[task 2022-06-29T09:06:19.139Z] 09:06:19     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT" {file: "/builds/worker/workspace/build/tests/xpcshell/head.js" line: 868}]"
[task 2022-06-29T09:06:19.139Z] 09:06:19  WARNING -  TEST-UNEXPECTED-FAIL | security/manager/ssl/tests/unit/test_pinning.js |  - A promise chain failed to handle a rejection: [Exception... "Abort"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: /builds/worker/workspace/build/tests/xpcshell/head.js :: _abort_failed_test :: line 868"  data: no] - stack: _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:868:20
[task 2022-06-29T09:06:19.139Z] 09:06:19     INFO -  do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:969:5
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:75:21
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  proto.report@resource://testing-common/Assert.jsm:228:10
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  equal@resource://testing-common/Assert.jsm:270:8
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  asyncConnectTo/<@/builds/worker/workspace/build/tests/xpcshell/tests/security/manager/ssl/tests/unit/head_psm.js:627:12
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:240:6
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:597:5
[task 2022-06-29T09:06:19.140Z] 09:06:19     INFO -  @-e:1:1
[task 2022-06-29T09:06:19.141Z] 09:06:19     INFO -  Rejection date: Wed Jun 29 2022 09:06:18 GMT+0000 (Coordinated Universal Time) - false == true
[task 2022-06-29T09:06:19.141Z] 09:06:19     INFO -  resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:271
[task 2022-06-29T09:06:19.141Z] 09:06:19     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:598
[task 2022-06-29T09:06:19.141Z] 09:06:19     INFO -  -e:null:1
[task 2022-06-29T09:06:19.141Z] 09:06:19     INFO -  PID 3590 | PR_Recv failed: SSL_ERROR_UNKNOWN_CA_ALERT
[task 2022-06-29T09:06:19.142Z] 09:06:19     INFO -  exiting test
[task 2022-06-29T09:06:19.142Z] 09:06:19     INFO -  <<<<<<<
[task 2022-06-29T09:06:24.776Z] 09:06:24     INFO -  Created a conditioned-profile copy: /tmp/tmp8xcw_ho6/profile
[task 2022-06-29T09:06:24.780Z] 09:06:24     INFO -  TEST-START | security/manager/ssl/tests/unit/test_session_resumption.js

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1777188&startday=2022-06-27&endday=2022-07-03&tree=all

Comment 2

[Natalia Csoregi [:nataliaCs]]

First occurrence in this batch of retriggers/backfills: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=Linux%2C18.04%2Cx64%2CWebRender%2Copt%2CXpcshell%2Ctests%2Cwith%2Ca%2Cconditioned%2Cprofile%2Ctest-linux1804-64-qr%2Fopt-xpcshell-condprof%2CX6&tochange=910652b5335034e44b15635289f56c63f6b0a6c6&fromchange=5956f91b3975ff848ab22b5b2abbd524422ede6d&group_state=expanded&selectedTaskRun=bRka2ef5Q1yImQn-LOQsbA.0

Could it be a fallout of Bug 1769154 but the failure appeared later than that somehow influenced by Bug 696976?
Joel could you take a look please?
Thank you.

Comment 3

[Joel Maher ( :jmaher ) (UTC -8) (PTO back normal Nov 17)]

most likely related to conditioned profiles, thanks for flagging this. I think the failure rate is low enough that we can keep it as an intermittent. I would have disabled 25 more tests if I found all tests that failed >1 time in my try pushes.

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• pine: 1

Platform and build breakdown:

• windows10-64-2004-pinebuild-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1777188&startday=2022-07-04&endday=2022-07-10&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1777188&startday=2022-07-18&endday=2022-07-24&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1777188&startday=2022-07-25&endday=2022-07-31&tree=all

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.