1746757 - Intermittent logs too big to parse: "try again to get alt svc mapping"

Status: RESOLVED FIXED

(Core :: Networking, defect, P3)

Description

[Andreea Pavel [:apavel]]

Treeherder link: https://treeherder.mozilla.org/jobs?repo=mozilla-beta&selectedTaskRun=AaEDZIOlQKiZnv-6XI80ig.0&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=d0c2c69f1b51c51f3fb0e6b2063ebcb639779e65

Failure log: https://firefoxci.taskcluster-artifacts.net/AaEDZIOlQKiZnv-6XI80ig/0/public/logs/live_backing.log

[task 2021-12-18T20:35:11.271Z] 20:35:11     INFO -  TEST-START | netwerk/test/unit/test_http3.js
[task 2021-12-18T20:40:11.273Z] 20:40:11  WARNING -  TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_http3.js | Test timed out
[task 2021-12-18T20:40:11.273Z] 20:40:11     INFO -  TEST-INFO took 300001ms
[task 2021-12-18T20:40:11.273Z] 20:40:11     INFO -  >>>>>>>
[task 2021-12-18T20:40:11.274Z] 20:40:11     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-12-18T20:40:11.275Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | run_test - [run_test : 63] "45710" != null
[task 2021-12-18T20:40:11.275Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | run_test - [run_test : 64] "45710" != ""
[task 2021-12-18T20:40:11.276Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | run_test - [run_test : 66] "44633" != null
[task 2021-12-18T20:40:11.276Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | run_test - [run_test : 67] "44633" != ""
[task 2021-12-18T20:40:11.276Z] 20:40:11     INFO -  PID 1538 | starting test number 0
[task 2021-12-18T20:40:11.277Z] 20:40:11     INFO -  PID 1538 | test_https_alt_svc()
[task 2021-12-18T20:40:11.277Z] 20:40:11     INFO -  (xpcshell/head.js) | test pending (2)
[task 2021-12-18T20:40:11.277Z] 20:40:11     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-12-18T20:40:11.277Z] 20:40:11     INFO -  running event loop
[task 2021-12-18T20:40:11.278Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStartRequest - [testOnStartRequest : 153] true == true
[task 2021-12-18T20:40:11.278Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStartRequest - [testOnStartRequest : 155] 0 == 0
[task 2021-12-18T20:40:11.278Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStartRequest - [testOnStartRequest : 157] 200 == 200
[task 2021-12-18T20:40:11.280Z] 20:40:11     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStopRequest - [testOnStopRequest : 201] 0 == 0
[task 2021-12-18T20:40:11.280Z] 20:40:11     INFO -  PID 1538 | routed is NA

[task 2021-12-18T20:40:13.367Z] 20:40:13     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStopRequest - [testOnStopRequest : 201] 0 == 0
[task 2021-12-18T20:40:13.367Z] 20:40:13     INFO -  PID 1538 | routed is NA
[task 2021-12-18T20:40:13.367Z] 20:40:13     INFO -  PID 1538 | poll later for alt svc mapping
[task 2021-12-18T20:40:13.368Z] 20:40:13     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStopRequest - [testOnStopRequest : 222] true == true
[task 2021-12-18T20:40:13.368Z] 20:40:13     INFO -  (xpcshell/head.js) | test pending (2)
[task 2021-12-18T20:40:13.369Z] 20:40:13     INFO -  (xpcshell/head.js) | test finished (2)
[task 2021-12-18T20:40:13.369Z] 20:40:13     INFO -  <<<<<<<
[task 2021-12-18T20:40:13.369Z] 20:40:13     INFO -  xpcshell return code: None
[task 2021-12-18T20:40:13.370Z] 20:40:13     INFO -  netwerk/test/unit/test_http3.js | Process still running after test!
[task 2021-12-18T20:40:13.370Z] 20:40:13     INFO -  >>>>>>>
[task 2021-12-18T20:40:13.370Z] 20:40:13     INFO -  PID 1538 | ExceptionHandler::GenerateDump cloned child 1563
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  PID 1538 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  <<<<<<<
[task 2021-12-18T20:40:13.371Z] 20:40:13  WARNING -  TEST-UNEXPECTED-FAIL | Received SIGINT (control-C), so stopped run. (Use --keep-going to keep running tests after killing one with SIGINT)
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  Retrying tests that failed when run in parallel.

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

The issue is the log spam which follows afterwards which bloats the log to a quarter gigabyte. The timeout is tracked in bug 1713142.

[task 2021-12-18T20:40:13.368Z] 20:40:13     INFO -  TEST-PASS | netwerk/test/unit/test_http3.js | testOnStopRequest - [testOnStopRequest : 222] true == true
[task 2021-12-18T20:40:13.368Z] 20:40:13     INFO -  (xpcshell/head.js) | test pending (2)
[task 2021-12-18T20:40:13.369Z] 20:40:13     INFO -  (xpcshell/head.js) | test finished (2)
[task 2021-12-18T20:40:13.369Z] 20:40:13     INFO -  <<<<<<<
[task 2021-12-18T20:40:13.369Z] 20:40:13     INFO -  xpcshell return code: None
[task 2021-12-18T20:40:13.370Z] 20:40:13     INFO -  netwerk/test/unit/test_http3.js | Process still running after test!
[task 2021-12-18T20:40:13.370Z] 20:40:13     INFO -  >>>>>>>
[task 2021-12-18T20:40:13.370Z] 20:40:13     INFO -  PID 1538 | ExceptionHandler::GenerateDump cloned child 1563
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  PID 1538 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  <<<<<<<
[task 2021-12-18T20:40:13.371Z] 20:40:13  WARNING -  TEST-UNEXPECTED-FAIL | Received SIGINT (control-C), so stopped run. (Use --keep-going to keep running tests after killing one with SIGINT)
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  Retrying tests that failed when run in parallel.
[task 2021-12-18T20:40:13.371Z] 20:40:13     INFO -  TEST-START | netwerk/test/unit/test_http3_progress.js
[task 2021-12-18T20:45:13.165Z] 20:45:13  WARNING -  TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_http3_progress.js | Test timed out
[task 2021-12-18T20:45:13.165Z] 20:45:13     INFO -  TEST-INFO took 300018ms
[task 2021-12-18T20:45:13.165Z] 20:45:13     INFO -  >>>>>>>
[task 2021-12-18T20:45:13.166Z] 20:45:13     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-12-18T20:45:13.166Z] 20:45:13     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-12-18T20:45:13.166Z] 20:45:13     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-12-18T20:45:13.166Z] 20:45:13     INFO -  running event loop
[task 2021-12-18T20:45:13.166Z] 20:45:13     INFO -  netwerk/test/unit/test_http3_progress.js | Starting setup
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  TEST-PASS | netwerk/test/unit/test_http3_progress.js | setup - [setup : 108] "44633" != null
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  TEST-PASS | netwerk/test/unit/test_http3_progress.js | setup - [setup : 108] "44633" != ""
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | routed is NA
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | try again to get alt svc mapping
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | results=falserouted is 0
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | try again to get alt svc mapping
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | results=falserouted is NA
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | try again to get alt svc mapping
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | results=falserouted is NA
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | try again to get alt svc mapping
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | results=falserouted is NA
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | try again to get alt svc mapping
[task 2021-12-18T20:45:13.167Z] 20:45:13     INFO -  PID 1566 | results=falserouted is NA

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1746757&startday=2021-12-13&endday=2021-12-19&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• mozilla-beta: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1746757&startday=2021-12-20&endday=2021-12-26&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1
• mozilla-central: 1
• autoland: 2

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1746757&startday=2022-01-03&endday=2022-01-09&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• try: 1

Platform and build breakdown:

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

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• mozilla-beta: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1746757&startday=2022-01-17&endday=2022-01-23&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1746757&startday=2022-02-21&endday=2022-02-27&tree=all