Closed Bug 1647950 Opened 4 months ago Closed 3 months ago

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

Categories

(Core :: DOM: Service Workers, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
81 Branch
Tracking Status
firefox-esr68 --- unaffected
firefox-esr78 --- unaffected
firefox79 --- unaffected
firefox80 --- fixed
firefox81 --- fixed

People

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

References

Details

(Keywords: assertion, intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file)

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 - .........

Duplicate of this bug: 1648226
Summary: Intermittent ASSERTION: Did not receive all required callbacks!: 'NS_FAILED(mResult) || mExpectedCallbacks == 0', file /netwerk/base/nsAsyncRedirectVerifyHelper.cpp, /fetch/range/sw.https.window.html | assertion count 1 is more than expected 0 assertions → 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
Duplicate of this bug: 1648831
Component: DOM: Networking → DOM: Service Workers

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

Flags: needinfo?(jstutte)
Duplicate of this bug: 1648230
Duplicate of this bug: 1648364
Duplicate of this bug: 1648383
Duplicate of this bug: 1647998
Duplicate of this bug: 1648071
Duplicate of this bug: 1647980

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)

Flags: needinfo?(jstutte) → needinfo?(valentin.gosu)

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.

Flags: needinfo?(valentin.gosu) → needinfo?(honzab.moz)

(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?

Flags: needinfo?(juhsu)

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.

Flags: needinfo?(juhsu)
Duplicate of this bug: 1649778
Duplicate of this bug: 1649778
Duplicate of this bug: 1650807
Duplicate of this bug: 1651180
Duplicate of this bug: 1651380
Duplicate of this bug: 1650831
Duplicate of this bug: 1650971
Duplicate of this bug: 1651658

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.

Flags: needinfo?(juhsu)

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.

Assignee: nobody → juhsu
Flags: needinfo?(juhsu)
Flags: needinfo?(honzab.moz)

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.

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

Duplicate of this bug: 1652611
Duplicate of this bug: 1652672

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

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

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

Flags: needinfo?(honzab.moz)

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

Flags: needinfo?(honzab.moz)
Pushed by juhsu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/706fd7c55ac6
stop redirect setup if the channel is canceled in child, r=mayhemer,necko-reviewers
Status: NEW → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → 81 Branch

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

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:
Flags: needinfo?(juhsu)
Attachment #9166020 - Flags: approval-mozilla-beta?

The regressor Bug 1633935 is backout in 79

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

approved for 80.0b6

Attachment #9166020 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Duplicate of this bug: 1657539
You need to log in before you can comment on or make changes to this bug.