1647950 - Intermittent ASSERTION: Did not receive all required callbacks!: 'NS_FAILED(mResult) || mExpectedCallbacks == 0', file /netwerk/base/nsAsyncRedirectVerifyHelper.cpp | assertion count 1 is more than expected 0 assertions

Status: RESOLVED FIXED

(Core :: DOM: Service Workers, defect)

Description

[Treeherder Bug Filer]

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

---

task 2020-06-23T22:59:35.345Z] 22:59:35 INFO - TEST-START | /fetch/range/sw.https.window.html
[task 2020-06-23T22:59:35.352Z] 22:59:35 INFO - Closing window 27
[task 2020-06-23T22:59:36.083Z] 22:59:36 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.146Z] 22:59:36 INFO - PID 5576 | [Child 1908, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.153Z] 22:59:36 INFO - PID 5576 | [Child 1908, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.200Z] 22:59:36 INFO - PID 5576 | [Child 1908, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:36.200Z] 22:59:36 INFO - PID 5576 | [Child 1908, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:36.307Z] 22:59:36 INFO - PID 5576 | [Child 1908, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:36.354Z] 22:59:36 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.354Z] 22:59:36 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: 'mProgress != Progress::ShutdownCompleted', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerShutdownState.cpp, line 57
[task 2020-06-23T22:59:36.357Z] 22:59:36 INFO - PID 5576 | [Parent 3896, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerController.cpp, line 446
[task 2020-06-23T22:59:36.357Z] 22:59:36 INFO - PID 5576 | [Parent 3896, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerControllerParent.cpp, line 108
[task 2020-06-23T22:59:36.377Z] 22:59:36 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.392Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: Failed to acquire a DXGI adapter for enumerating outputs.: file /builds/worker/checkouts/gecko/gfx/thebes/DeviceManagerDx.cpp, line 146
[task 2020-06-23T22:59:36.392Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: Failed to acquire a DXGI adapter for checking hardware stretching support.: file /builds/worker/checkouts/gecko/gfx/thebes/DeviceManagerDx.cpp, line 207
[task 2020-06-23T22:59:36.393Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: DWM not enabled, falling back to software vsync: file /builds/worker/checkouts/gecko/gfx/thebes/gfxWindowsPlatform.cpp, line 1941
[task 2020-06-23T22:59:36.408Z] 22:59:36 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.408Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 861
[task 2020-06-23T22:59:36.423Z] 22:59:36 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.483Z] 22:59:36 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:36.490Z] 22:59:36 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:36.593Z] 22:59:36 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:36.768Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 485
[task 2020-06-23T22:59:36.768Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4281
[task 2020-06-23T22:59:36.771Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4281
[task 2020-06-23T22:59:36.892Z] 22:59:36 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.927Z] 22:59:36 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.927Z] 22:59:36 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:36.986Z] 22:59:36 INFO - PID 3256 | [2036, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1136
[task 2020-06-23T22:59:37.026Z] 22:59:37 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:37.061Z] 22:59:37 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:37.240Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.240Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: 'mProgress != Progress::ShutdownCompleted', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerShutdownState.cpp, line 57
[task 2020-06-23T22:59:37.244Z] 22:59:37 INFO - PID 5576 | [Parent 3896, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerController.cpp, line 446
[task 2020-06-23T22:59:37.244Z] 22:59:37 INFO - PID 5576 | [Parent 3896, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerControllerParent.cpp, line 108
[task 2020-06-23T22:59:37.259Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.294Z] 22:59:37 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.294Z] 22:59:37 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.313Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] ###!!! ASSERTION: Did not receive all required callbacks!: 'NS_FAILED(mResult) || mExpectedCallbacks == 0', file /builds/worker/checkouts/gecko/netwerk/base/nsAsyncRedirectVerifyHelper.cpp, line 58
[task 2020-06-23T22:59:37.388Z] 22:59:37 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:37.388Z] 22:59:37 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:37.403Z] 22:59:37 INFO - PID 5576 | [Child 3500, MediaPDecoder #1] WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x80004004 (NS_ERROR_ABORT): file /builds/worker/checkouts/gecko/dom/media/wave/WaveDemuxer.cpp, line 541
[task 2020-06-23T22:59:37.403Z] 22:59:37 INFO - PID 5576 | [Child 3500, MediaDecoderStateMachine #1] WARNING: Decoder=6c7e430 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp, line 376
[task 2020-06-23T22:59:37.403Z] 22:59:37 INFO - PID 5576 | [Child 3500, MediaDecoderStateMachine #1] WARNING: Decoder=6c7e430 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp, line 3470
[task 2020-06-23T22:59:37.642Z] 22:59:37 INFO - PID 3256 | [2036, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4279
[task 2020-06-23T22:59:37.697Z] 22:59:37 INFO - PID 3256 | [Parent 2036, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 1568
[task 2020-06-23T22:59:37.736Z] 22:59:37 INFO - PID 3256 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1592950419\appdata\local\temp\tmpsdxdzs\runtests_leaks_5304_tab_pid5956.log
[task 2020-06-23T22:59:37.736Z] 22:59:37 INFO - PID 3256 | [5956, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 244
[task 2020-06-23T22:59:37.776Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.776Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: 'mProgress != Progress::ShutdownCompleted', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerShutdownState.cpp, line 57
[task 2020-06-23T22:59:37.796Z] 22:59:37 INFO - PID 5576 | [Parent 3896, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.796Z] 22:59:37 INFO - PID 5576 | [Parent 3896, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerController.cpp, line 446
[task 2020-06-23T22:59:37.797Z] 22:59:37 INFO - PID 5576 | [Parent 3896, IPDL Background] WARNING: 'aResult.IsReject()', file /builds/worker/checkouts/gecko/dom/workers/remoteworkers/RemoteWorkerControllerParent.cpp, line 108
[task 2020-06-23T22:59:37.824Z] 22:59:37 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.831Z] 22:59:37 INFO - PID 5576 | [Child 3500, Main Thread] WARNING: '!window', file /builds/worker/checkouts/gecko/dom/cache/CacheStorage.cpp, line 572
[task 2020-06-23T22:59:37.891Z] 22:59:37 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:37.891Z] 22:59:37 INFO - PID 5576 | [Child 3500, DOM Worker] WARNING: '!rv', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerOp.cpp, line 282
[task 2020-06-23T22:59:37.958Z] 22:59:37 INFO - PID 3256 | [Child 5956, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 861
[task 2020-06-23T22:59:37.985Z] 22:59:37 INFO - PID 3256 | [Child 5956, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 485
[task 2020-06-23T22:59:38.081Z] 22:59:38 INFO - Got chrome assert count 1
[task 2020-06-23T22:59:38.096Z] 22:59:38 INFO - PID 3256 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1592950419\appdata\local\temp\tmpsdxdzs\runtests_leaks_5304_tab_pid5664.log
[task 2020-06-23T22:59:38.096Z] 22:59:38 INFO - PID 3256 | [5664, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 244
[task 2020-06-23T22:59:38.106Z] 22:59:38 INFO - TEST-UNEXPECTED-FAIL | /fetch/range/sw.https.window.html | assertion count 1 is more than expected 0 assertions
[task 2020-06-23T22:59:38.106Z] 22:59:38 INFO - .........

Comment 2

[Intermittent Failures Robot]

13 failures in 5252 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• try: 2

Platform breakdown:

• windows7-32: 8
• linux1804-64: 1
• android-em-7-0-x86_64: 3
• windows10-64-qr: 1

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

Comment 4

[Cosmin Sabou [:CosminS]]

Jens, do you think you can redirect this someone? It looks like it's happening only on service workers wpt tests. Thank you.

Comment 11

[Intermittent Failures Robot]

20 failures in 954 pushes (0.021 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 3
• autoland: 17

Platform breakdown:

• macosx1014-64: 4
• linux1804-64-qr: 2
• windows7-32: 4
• linux1804-64: 3
• android-em-7-0-x86_64: 3
• linux1804-64-tsan: 2
• windows10-64: 2

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

Comment 12

[Jens Stutte [:jstutte]]

It seems, we want to remove a nsAsyncRedirectVerifyHelper while it still expects to receive some callback (or at least the relative counter is not == 0). At least I assume from here that mResult must be NS_OK (because we would have crashed earlier in debug otherwise).

Valentin, is this a strong invariant and how can we check, who is causing the violation (without stack traces as we use NS_ASSERTION here) ?
(until we understand this, I leave the component assignment as is)

Comment 13

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

Honza knows this code a little better.

Judging by the failure reports, this is caused by something that landed on the 24th, got backed out, then landed again on the 30th.

Comment 14

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

(In reply to Valentin Gosu [:valentin] (he/him) from comment #13)

Judging by the failure reports, this is caused by something that landed on the 24th, got backed out, then landed again on the 30th.

Bug 1633935 seems like a likely candidate for a regressor. Junior, do you think it may be related?

Comment 15

[Junior [inactive]]

It could be related to this patch.
https://hg.mozilla.org/mozilla-central/rev/045271cd2ca6

Now OnStartRequest is sent via PBackground, so it would be racy with the main thread IPC.
Therefore, we will wait for CompleteRedirectSetup to continue the OnStartRequest for redirection.

That say, if some check must be done before OnStartRequest, it should be done before HttpChannelChild::Redirect3Complete.

Comment 18

[Intermittent Failures Robot]

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

This is the #29 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:

• mozilla-central: 7
• autoland: 36
• try: 2
• mozilla-esr68: 2

Platform breakdown:

• macosx1014-64: 10
• linux1804-64-qr: 6
• windows7-32: 12
• linux1804-64: 9
• android-em-7-0-x86_64: 5
• linux1804-64-tsan: 2
• windows10-64: 2
• windows10-64-qr: 1

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

Comment 20

[Intermittent Failures Robot]

32 failures in 5265 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

** 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:

• try: 4
• autoland: 25
• mozilla-esr68: 1
• mozilla-central: 2

Platform breakdown:

• linux1804-64: 7
• windows7-32: 18
• linux1804-64-qr: 1
• macosx1014-64: 5
• windows10-64: 1

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

Comment 26

[Honza Bambas (:mayhemer)]

Junior, it looks like you understand what needs to be done here when reading your comment 15. Can you either take this bug or rephrase comment 15 so it's more clear what to do?

Thanks.

Comment 27

[Junior [inactive]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2bc2672e45811b5409b5e57a22a16fa9a5d168c9&selectedTaskRun=WI2CcyqKQQOiGnKIpzSCRw.0

This patch could mitigate the orange. I'll ask for review once I'm more confident with interception code.

Comment 28

[Intermittent Failures Robot]

33 failures in 4014 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

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

Platform breakdown:

• macosx1014-64: 4
• windows7-32: 13
• linux1804-64: 8
• linux1804-64-qr: 8

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

Comment 29

[Junior [inactive]]

Unfortunately, there are still failures e.g.,
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=310455505&repo=try&lineNumber=25136

comment 15 might be not relevant since the assertion is in the parent process.

Comment 30

[Junior [inactive]]

this patch is a work around and shows HttpChannelParent doesn't receive RecvRedirect2Verify to do the OnRedirectVerifyCallback for the service workers failure.

treeherder link:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e00fa8ba31bff7a3017c69668bc000857398fc72&selectedTaskRun=XSZn9OYYRuG4uRHcErfdXQ.0

Here's an example to show the warning.
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=310495399&repo=try&lineNumber=7794

Comment 35

[Junior [inactive]]

This is interesting. The parent received cancel right after StartRedirect and SendRedirect1Begin
and RecvRedirect2Verify never come back.

2020-07-23 04:27:39.563601 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::AsyncOnChannelRedirect [this=0x7f7f7be44820, old=0x7f7f7bca8850, new=0x7f7f7deae050, flags=4]
2020-07-23 04:27:39.563605 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::StartRedirect [this=0x7f7f7be44820, newChannel=0x7f7f7deae050 callback=0x7f7f719bcc50]
2020-07-23 04:27:39.563610 UTC - [Parent 20090: Main Thread]: V/nsHttp Registered 0x7f7f7deae050 channel under id=554
2020-07-23 04:27:40.053243 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::RecvCancel [this=0x7f7f7be44820]
2020-07-23 04:27:40.053252 UTC - [Parent 20090: Main Thread]: D/nsHttp HttpAsyncAborter::AsyncAbort [this=0x7f7f7bca8800 status=804b0002]
2020-07-23 04:27:40.053315 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::OnStartRequest [this=0x7f7f7be44820, aRequest=0x7f7f7bca8850]
2020-07-23 04:27:40.053399 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::OnStopRequest: [this=0x7f7f7be44820 aRequest=0x7f7f7bca8850 status=804b0002]
2020-07-23 04:27:40.054 ⁃ HttpChannelParent ⁃ 7f7f7be44c10 ⁃ created
2020-07-23 04:27:40.055 ⁃ nsHttpChannel ⁃ 7f7f7df76000 ⁃ connected ⁃ status=n/a ⁃ http-status=n/a ⁃ url=https://web-platform.test:8443/html/semantics/embedded-content/the-img-element/image-1.jpg
2020-07-23 04:27:40.056 ⁃ HttpChannelChild ⁃ 7f87cc3aa000 ⁃ created ⁃ url=https://web-platform.test:8443/html/semantics/embedded-content/the-img-element/image-1.jpg ⁃ status=n/a
2020-07-23 04:27:40.057052 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=0x7f7f7be44820 bgParent=0x7f7f719ba980]
2020-07-23 04:27:40.059857 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::OnBackgroundParentDestroyed [this=0x7f7f7be44820]
2020-07-23 04:27:40.059 ⁃ HttpChannelParent ⁃ 7f7f7cd1eac0 ⁃ created
2020-07-23 04:27:40.059961 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=0x7f7f7be44820 bgParent=(nil)]
2020-07-23 04:27:40.059964 UTC - [Parent 20090: Main Thread]: V/nsHttp Destroying HttpChannelParent [this=0x7f7f7be44820]

Let's see what happen in child

2020-07-23 04:27:39.552360 UTC - [Child 29246: Socket Thread]: V/nsHttp HttpBackgroundChannelChild::Init [this=0x7f87ca238c90 httpChannel=0x7f87ca24e000 channelId=125610613538836]
2020-07-23 04:27:39.552385 UTC - [Child 29246: Socket Thread]: V/nsHttp HttpChannelChild::OnBackgroundChildReady [this=0x7f87ca24e000, bgChild=0x7f87ca238c90]
2020-07-23 04:27:40.053058 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::Cancel [this=0x7f87ca24e000, status=804b0002]
2020-07-23 04:27:40.053085 UTC - [Child 29246: Main Thread]: V/nsHttp 0x7f87ca24e000 called from script: https://web-platform.test:8443/html/semantics/embedded-content/the-img-element/list-of-available-images-matching.https.html:49:6
2020-07-23 04:27:40.054255 UTC - [Child 29246: Socket Thread]: V/nsHttp HttpChannelChild::ProcessOnStartRequest [this=0x7f87ca24e000]
2020-07-23 04:27:40.054315 UTC - [Child 29246: Socket Thread]: V/nsHttp HttpChannelChild::ProcessOnStopRequest [this=0x7f87ca24e000]
2020-07-23 04:27:40.054986 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::RecvRedirect1Begin [this=0x7f87ca24e000]
2020-07-23 04:27:40.054 ⁃ HttpChannelParent ⁃ 7f7f7be44c10 ⁃ created
2020-07-23 04:27:40.055 ⁃ nsHttpChannel ⁃ 7f7f7df76000 ⁃ connected ⁃ status=n/a ⁃ http-status=n/a ⁃ url=https://web-platform.test:8443/html/semantics/embedded-content/the-img-element/image-1.jpg
2020-07-23 04:27:40.056583 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::RecvOnStartRequestSent [this=0x7f87ca24e000]
2020-07-23 04:27:40.056640 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::OnStartRequest [this=0x7f87ca24e000]
2020-07-23 04:27:40.056756 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::DoPreOnStopRequest [this=0x7f87ca24e000 status=804b0002]
2020-07-23 04:27:40.056844 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::DoOnStopRequest [this=0x7f87ca24e000]
2020-07-23 04:27:40.056886 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::CleanupBackgroundChannel [this=0x7f87ca24e000 bgChild=0x7f87ca238c90]
2020-07-23 04:27:40.056919 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::Redirect1Begin [this=0x7f87ca24e000]
2020-07-23 04:27:40.056935 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::SetupRedirect [this=0x7f87ca24e000]
2020-07-23 04:27:40.056 ⁃ HttpChannelChild ⁃ 7f87cc3aa000 ⁃ created ⁃ url=https://web-platform.test:8443/html/semantics/embedded-content/the-img-element/image-1.jpg ⁃ status=n/a
2020-07-23 04:27:40.057052 UTC - [Parent 20090: Main Thread]: V/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=0x7f7f7be44820 bgParent=0x7f7f719ba980]
2020-07-23 04:27:40.057463 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::RecvDeleteSelf [this=0x7f87ca24e000]
2020-07-23 04:27:40.057595 UTC - [Child 29246: Main Thread]: V/nsHttp HttpChannelChild::OnRedirectVerifyCallback [this=0x7f87ca24e000]
2020-07-23 04:27:40.057611 UTC - [Child 29246: Main Thread]: V/nsHttp Destroying HttpChannelChild @0x7f87ca24e000

Cancel by the web script right after init.
Receive the OnStart/Stop by aborter, and then receive the Redirect1Begin without return Redirect2Verify back.

So, I proposed fail the HttpChannelChild::SetupRedirect if HttpChannelChild::Cancel is called

Comment 36

[Junior [inactive]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6a6917a0729f4901d5d547b9a1f546b890bba258

Comment 37

[Junior [inactive]]

The assertion happens only on the canceled channel.
I'll wait for honza, who knows async redirection, to review this.

Comment 38

[Junior [inactive]]

Attachment: Bug 1647950 - stop redirect setup if the channel is canceled in child, r=mayhemer

In child process, if the channel starts to setupRedirect after cancelled, we should
fail the redirection setup and fail the redirect check.

Comment 39

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 11
• mozilla-central: 6
• try: 1

Platform breakdown:

• linux1804-64-qr: 13
• macosx1014-64: 2
• linux1804-64: 2
• windows7-32: 1

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

Comment 40

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 8
• autoland: 8
• mozilla-beta: 1

Platform breakdown:

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

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

Comment 41

[Honza Bambas (:mayhemer)]

Looks like there is actually nothing for me to do here :)

Comment 42

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/706fd7c55ac6
stop redirect setup if the channel is canceled in child, r=mayhemer,necko-reviewers

Comment 43

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/706fd7c55ac6

Comment 44

[Ryan VanderMeulen [:RyanVM]]

Please nominate this for Beta uplift when you get a chance.

Comment 45

[Junior [inactive]]

Comment on attachment 9166020 [details]
Bug 1647950 - stop redirect setup if the channel is canceled in child, r=mayhemer

Beta/Release Uplift Approval Request

• User impact if declined: leakage for those http request canceled by script and intercpeted by service worker
• Is this code covered by automated tests?: Yes
• 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): small and non-risky change
• String changes made/needed:

Comment 46

[Junior [inactive]]

The regressor Bug 1633935 is backout in 79

Comment 47

[Julien Cristau [:jcristau]]

Comment on attachment 9166020 [details]
Bug 1647950 - stop redirect setup if the channel is canceled in child, r=mayhemer

approved for 80.0b6

Comment 48

[Julien Cristau [:jcristau]]

https://hg.mozilla.org/releases/mozilla-beta/rev/89618ef0c11a

Comment 49

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform breakdown:

• macosx1014-64: 1
• linux1804-64-qr: 1

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

Comment 51

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-qr: 1

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