1917901 - Assertion failure: !mODATarget, at netwerk/protocol/http/HttpChannelChild.cpp

Status: RESOLVED FIXED

(Core :: Networking, defect, P2)

Description

[Tom Ritter [:tjr]]

From checkout

changeset:   835960:ebf0e33ba93e
fxtree:      central
user:        Sandor Molnar <[e-mail]>
date:        Tue Sep 10 09:09:35 2024 +0300
summary:     Backed out changeset ebe6cedc1f12 (bug 1905611) for causing reftest failures. CLOSED TREE

1. Do a debug build
2. Go to https://ritter.vg/ (I use it as a test page because I know how its configured and what it does)
3. Hit 'End' to scroll to the end.
4. Middle click the red like slides are available here to open a pdf in a new tab

[Child 1091656, Main Thread] WARNING: '!ClientIsValidCreationURL(mClientInfo.PrincipalInfo(), aArgs.url())', file /home/tom/Documents/moz/mozilla-unified-7/dom/clients/manager/ClientSource.cpp:65
[1091656] Assertion failure: !mODATarget, at /home/tom/Documents/moz/mozilla-unified-7/netwerk/protocol/http/HttpChannelChild.cpp:3047
#01: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x5a93150]
#02: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x6271489]
#03: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x6270a21]
#04: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x616a16e]
#05: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x536e816]
#06: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x606c43e]
#07: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x6052ec8]
#08: ???[/home/tom/Documents/moz/mozilla-unified-7/obj-x86_64-pc-linux-gnu/dist/bin/libxul.so +0x6054506]

Happens on every run

Comment 1

[edgul]

Added by Bug 1756010, Jesup can you take a look?

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

PdfStreamConverter.sys.mjs:1175 calls OnStartRequest:

    var proxy = {
      onStartRequest() {
        listener.onStartRequest(aRequest);
      },

The object has previously received StartRequest via RecvOnStartRequest() (which comes from the parent process)

Submitted to pernosco, though the above is probably enough to figure this out.

Do we not have any PDF tests in CI that run on debug?

Valentin, thoughts on why this is happening with PDFConverter? Looks like starting at 1074 it's reusing aRequest, which may be the issue here

Comment 3

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

I think this may be a duplicate of bug 1887783.
Most likely this is the same code path as https://bugzilla.mozilla.org/show_bug.cgi?id=1887783#c3.

Sunil, can we incorporate this as a test case? And maybe dupe to 1887783 once we confirm it's the same cause? Thanks!

Comment 4

[Sunil Mayya]

valentin, randell,
I reproduced the issue locally and checked the logs.
The problem here is we are are retargetting when a ODA is already in progress.

44027 [Child 13511: Main Thread]: D/nsHttp HttpChannelChild::OnStartRequest [this=73ba7ff79700]
44028 [Child 13511: Main Thread]: D/nsHttp HttpBaseChannel::SetApplyConversion [this=73ba7ff79738 value=1]
44029 [Child 13511: Main Thread]: D/nsHttp HttpChannelChild::DoOnStartRequest [this=73ba7ff79700]
44030 [Parent 13256: Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=7e7a37fc8700 request=7e7a38c636b0 offset=0 count=32394]
44031 [Parent 13256: Main Thread]: D/nsHttp   requestFromCache: 0 mFirstResponseSource: 0
44032 [Parent 13256: Main Thread]: D/nsHttp sending progress and status notification [this=7e7a37fc8700 status=4b0006 progress=32394/-1]
44033 [Parent 13256: Main Thread]: D/nsHttp ParentChannelListener::OnDataAvailable [this=7e7a38cf45e0]
44034 [Parent 13256: Main Thread]: D/nsHttp HttpChannelParent::OnDataAvailable [this=7e7a3cb6c1c0 aRequest=7e7a37fc8750 offset=0 count=32394]
44035 [Parent 13256: Main Thread]: D/nsHttp HttpBackgroundChannelParent::OnTransportAndData [this=7e7a38cdc7e0]
44036 [Parent 13256: IPDL Background]: D/nsHttp HttpBackgroundChannelParent::OnTransportAndData [this=7e7a38cdc7e0]
44037 [Child 13511: Socket Thread]: D/nsHttp HttpBackgroundChannelChild::RecvOnTransportAndData [this=73ba7e8f5880, aDataFromSocketProcess=0, mFirstODASource=1]
44038 [Child 13511: Socket Thread]: D/nsHttp HttpChannelChild::ProcessOnTransportAndData [this=73ba7ff79700]
44039 [Child 13511: Main Thread]: D/nsHttp HttpBaseChannel::SetResponseHeader [this=73ba7ff79738 header="Content-Security-Policy" value="" merge=0]
44040 [Child 13511: Main Thread]: D/nsHttp HttpBaseChannel::SetResponseHeader [this=73ba7ff79738 header="Content-Security-Policy-Report-Only" value="" merge=0]
44041 [Child 13511: Main Thread]: D/nsHttp HttpBaseChannel::SetResponseHeader [this=73ba7ff79738 header="Refresh" value="" merge=0]
44042 [Child 13511: Main Thread]: D/nsHttp HttpBaseChannel::DoApplyContentConversions [this=73ba7ff79738]
44043 [Child 13511: Main Thread]: D/nsHttp nsHttpHandler::IsAceptableEncoding gzip https=1 1
44044 [Child 13511: Main Thread]: D/nsHttp nsHttpCompresssConv 73ba7ed25f80 ctor
44045 [Child 13511: Main Thread]: D/nsHttp nsHttpCompresssConv 73ba7ed25f80 AsyncConvertData gzip uncompressed mode 0
44046 [Child 13511: Main Thread]: D/nsHttp converter removed 'gzip' content-encoding
44047 [Child 13511: Main Thread]: D/nsHttp MaybeRetarget: Retargeting to background thread: Length -1

******************** First retargetting happens here****************************************************
44048 [Child 13511: Main Thread]: D/nsHttp HttpChannelChild::RetargetDeliveryTo [this=73ba7ff79700, aNewTarget=73ba7ff80880]

44049 [Child 13511: BackgroundThreadPool #1]: D/nsHttp HttpChannelChild::OnTransportAndData [this=73ba7ff79700]
44050 [Child 13511: BackgroundThreadPool #1]: D/nsHttp HttpChannelChild::DoOnDataAvailable [this=73ba7ff79700]
44051 [Child 13511: BackgroundThreadPool #1]: D/nsHttp nsHttpCompressConv 73ba7ed25f80 OnDataAvailable aSourceOffset:0 count:32394
44052 [Child 13511: Main Thread]: D/nsHttp HttpChannelChild::DoOnStatus [this=73ba7ff79700]
44053 [Child 13511: BackgroundThreadPool #1]: D/nsHttp nsHttpCompressConv 73ba7ed25f80 do_OnDataAvailable mDispatchToMainThread 1 count 33725

******************** Progress updates and ODA on  main thread data happens here****************************************************
44054 [Child 13511: Main Thread]: D/nsHttp HttpChannelChild::DoOnProgress [this=73ba7ff79700]
44055 [Child 13511: Main Thread]: D/nsHttp nsHttpCompressConv Calling OnDataAvailable on Mainthread

44056 [Child 13511, Main Thread] WARNING: '!ClientIsValidCreationURL(mClientInfo.PrincipalInfo(), aArgs.url())', file /home/smayya/workspace/mozilla-unified/dom/clients/manager/Client      Source.cpp:65

******************** We are re-targetting during a ODA****************************************************
44057 [Child 13511: Main Thread]: D/nsHttp HttpChannelChild::RetargetDeliveryTo [this=73ba7ff79700, aNewTarget=73ba81c04580]

I think this is the problem here. We need to allow re-targetting only before OnDataAvailable.

We need to further check why we are re-targetting during OnDataAvailable.

Hence, root-cause is not same as 1887783.

Comment 5

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

Thanks for looking into this Sunil.
I'm wondering if the fix should go in HttpChannelChild::RetargetDeliveryTo or if nsHTTPCompressConv::CheckListenerChain should throw if nsHTTPCompressConv::OnDataAvailable was called 🤔

Comment 6

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Bug 1917901: Make it ok to retarget OnDataAvailable multiple times until the first ODA is received r=#necko-reviewers!

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/34295cdf7c5a
Make it ok to retarget OnDataAvailable multiple times until the first ODA is received r=necko-reviewers,kershaw

Comment 8

[Serban Stanca [:SerbanS]]

Backed out for causing multiple failures.

• Backout link
• Push with failures

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b5d9c8b42014
Make it ok to retarget OnDataAvailable multiple times until the first ODA is received r=necko-reviewers,kershaw

Comment 10

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/b5d9c8b42014

Comment 11

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/mozilla-central/rev/efb1596265e9
Backed out changeset b5d9c8b42014 for causing crashes. ( Bug 1924737 ) a=backout

Comment 12

[Maxx Crawford [:maxx]]

Attachment: WIP: Backed out changeset b5d9c8b42014 (Bug 1917901) for causing crashes. ( Bug 1924737 ) a=backout

Comment 13

[Rebeca Tudor]

Attachment: Backed out changeset b5d9c8b42014 (Bug 1917901) for causing crashes. ( Bug 1924737 ) a=backout

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

The issue is that FetchDriver calls RetargetDelivertyTo() on a channel that has already been retargeted to an nsHTTPCompressConv background-thread, apparently for https://www.redditstatic.com/shreddit/en-US/shreddit-post-flair-1eaa5c8a.js

This happens only on certain URLs, including https://www.reddit.com/r/firefox/comments/1g4fb5w/firefox_is_much_better_than_chrome/
Loading that URL causes the crash pretty much 100% of the time for me, though not under rr -- the timing changes probably cause it not to fail.
Running on different HW may make this particular URL not crash, or be intermittent.

Why is FetchDriver reusing a channel?

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

The solution is to not retarget in FetchDriver::OnStartRequest if the channel has already been retargeted (such as by background decompression)

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f9ccd9f31b9c
Make it ok to retarget OnDataAvailable multiple times until the first ODA is received r=necko-reviewers,kershaw

Comment 17

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/f9ccd9f31b9c

Comment 18

[amarc]

Backed out changeset f9ccd9f31b9c (Bug 1917901) for causing networking crashes : https://hg.mozilla.org/mozilla-central/rev/9e9cd26f20ec21c86b0728e32981411c8b8f6716

Comment 19

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

I also think the condition might be incorrect, because if mGotDataAvailable == true, but mODATarget == false, we still attempt to retarget, which we probably shouldn't.

Could we change the condition to something like:

if (mODATarget == aNewTarget)  {
  // Same target
  return NS_OK;
} else if (mODATarget) {
  // We already retargetted (valentin: unclear if this should be allowed)
  return NS_ERROR_ALREADY_INITIALIZED;
} else if (mGotDataAvailable) {
  // Too late to retarget now.
  return NS_ERROR_FAILURE;
}

RetargetDeliveryToImpl(aNewTarget, lock);

Also, I think we should add a test that attempts to retarget twice, so we make sure this code is covered.

Comment 20

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

There are 101 crash reports from 76 installs at the moment, e.g. bp-6a4ce452-8da5-459f-9d13-a29780241121

Comment 21

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

Since the crash volume is low (less than 15 per week), the severity is downgraded to S3. Feel free to change it back if you think the bug is still critical.

For more information, please visit BugBot documentation.

Comment 22

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

The bug is linked to a topcrash signature, which matches the following criterion:

• Top 10 desktop browser crashes on nightly

:jesup, could you consider increasing the severity of this top-crash bug?

For more information, please visit BugBot documentation.

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/438d3b92415d
Make it ok to retarget OnDataAvailable multiple times until the first ODA is received r=necko-reviewers,kershaw

Comment 24

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/438d3b92415d