1363372 - Crash in mozilla::net::HttpChannelParentListener::GetInterface [tfo overlapped IO]

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Marcia Knous [:marcia]]

This bug was filed from the Socorro interface and is 
report bp-3d8d232d-4f9f-477f-a4bc-0ef2c0170509.
=============================================================

Seen while looking at nightly crash stats - crashes started using 20170506030204: http://bit.ly/2pZWDxU. All crashes are on Windows 10.

Possible regression range based on Build ID: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0b255199db9d6a6f189b89b7906f99155bde3726&tochange=37a5b7f6f101df2eb292b1b6baaf1540c9920e20

ni on dragana since her checkin is in the regression range.

Comment 1

[Dragana Damjanovic [:dragana]]

There are 3 different crashes:

0 	xul.dll 	mozilla::net::HttpChannelParentListener::GetInterface(nsID const&, void**) 	netwerk/protocol/http/HttpChannelParentListener.cpp:133
1 	xul.dll 	NS_QueryNotificationCallbacks<mozilla::net::nsHttpChannel>(mozilla::net::nsHttpChannel*, nsID const&, void**) 	netwerk/base/nsNetUtil.h:578
2 	xul.dll 	mozilla::net::nsHttpChannel::SetDoNotTrack() 	netwerk/protocol/http/nsHttpChannel.cpp:8727
3 	xul.dll 	mozilla::net::nsHttpChannel::BeginConnect() 	netwerk/protocol/http/nsHttpChannel.cpp:6080
4 	xul.dll 	mozilla::net::nsHttpChannel::OnProxyAvailable(nsICancelable*, nsIChannel*, nsIProxyInfo*, nsresult) 	netwerk/protocol/http/nsHttpChannel.cpp:6577
5 	xul.dll 	mozilla::net::nsAsyncResolveRequest::DoCallback() 	netwerk/base/nsProtocolProxyService.cpp:250
6 	xul.dll 	mozilla::net::nsAsyncResolveRequest::OnQueryComplete(nsresult, nsCString const&, nsCString const&) 	netwerk/base/nsProtocolProxyService.cpp:212
7 	xul.dll 	mozilla::net::ExecuteCallback::Run() 	netwerk/base/nsPACMan.cpp:81

This one is happening before we actually make a transaction or even SpeculativeConnect, therefore TFO can not be the problem here. There is also a crash on 53 with this signature. There are 4 crashes in 55, this is happening after proxy get resolved, I think this is not TFO issue.


The second crash:
0 	xul.dll 	mozilla::net::HttpChannelParentListener::GetInterface(nsID const&, void**) 	netwerk/protocol/http/HttpChannelParentListener.cpp:133
1 	xul.dll 	NS_QueryNotificationCallbacks<mozilla::net::HttpBaseChannel>(mozilla::net::HttpBaseChannel*, nsID const&, void**) 	netwerk/base/nsNetUtil.h:578
2 	xul.dll 	mozilla::net::HttpBaseChannel::GetInnerDOMWindow() 	netwerk/protocol/http/HttpBaseChannel.cpp:3903
3 	xul.dll 	mozilla::net::nsHttpChannel::ProcessResponse() 	netwerk/protocol/http/nsHttpChannel.cpp:2026
4 	xul.dll 	mozilla::net::nsHttpChannel::OnStartRequest(nsIRequest*, nsISupports*) 	netwerk/protocol/http/nsHttpChannel.cpp:6829
5 	xul.dll 	nsInputStreamPump::OnStateStart() 	netwerk/base/nsInputStreamPump.cpp:531
6 	xul.dll 	nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) 	netwerk/base/nsInputStreamPump.cpp:433
7 	xul.dll 	nsInputStreamReadyEvent::Run() 	xpcom/io/nsStreamUtils.cpp:96

There is also a crach with 54 with this signature as well.
7 in 55. There is a nsInputStreamPump on the stack, maybe this is a dup of bug 1362978.



The third:
0 	xul.dll 	mozilla::net::HttpChannelParentListener::GetInterface(nsID const&, void**) 	netwerk/protocol/http/HttpChannelParentListener.cpp:133
1 	xul.dll 	NS_QueryNotificationCallbacks(nsIInterfaceRequestor*, nsILoadGroup*, nsID const&, void**) 	netwerk/base/nsNetUtil.h:616
2 	xul.dll 	mozilla::net::nsHttpChannel::OnTransportStatus(nsITransport*, nsresult, __int64, __int64) 	netwerk/protocol/http/nsHttpChannel.cpp:7519
3 	xul.dll 	nsTransportStatusEvent::Run() 	netwerk/base/nsTransportUtils.cpp:78

5 crashes in 55. I will audit TFO code to see if we always remove Event listener from socketTransport. I was sure we do, but I will check again.


The fourth:
 0 	xul.dll 	mozilla::net::HttpChannelParentListener::GetInterface(nsID const&, void**) 	netwerk/protocol/http/HttpChannelParentListener.cpp:133
1 	xul.dll 	NS_QueryNotificationCallbacks<mozilla::net::nsHttpChannel>(mozilla::net::nsHttpChannel*, nsID const&, void**) 	netwerk/base/nsNetUtil.h:578
2 	xul.dll 	mozilla::net::nsHttpChannel::SetPriority(int) 	netwerk/protocol/http/nsHttpChannel.cpp:6447
3 	xul.dll 	mozilla::net::HttpChannelParent::RecvSetPriority(short const&) 	netwerk/protocol/http/HttpChannelParent.cpp:660
4 	xul.dll 	mozilla::net::PHttpChannelParent::OnMessageReceived(IPC::Message const&) 	obj-firefox/ipc/ipdl/PHttpChannelParent.cpp:1083

This one really does not look like TFO code. I do not think TFO code can trigger this patch: HttpChannelParent receives a SetPriority from the child.

Comment 2

[Marcia Knous [:marcia]]

ni on marcia for followup here. Need to figure out what to do with these crashes since we turned the feature off.

Also what does necko-next in the whiteboard mean?

Comment 3

[Honza Bambas (:mayhemer)]

(In reply to Marcia Knous [:marcia - use ni] from comment #2)
> ni on marcia for followup here. Need to figure out what to do with these
> crashes since we turned the feature off.

I would first confirm TFO relation.

> 
> Also what does necko-next in the whiteboard mean?

Triaged as "P2" necko bug - not to be worked on right now, but not moved entirely to backlog.  please don't mess with this, thanks.

Comment 4

[Dragana Damjanovic [:dragana]]

some of this crashes are not related to TFO, but they are low volume. TFO made the crash volume go up, so I will consider this TFO crash for now.

Comment 5

[Marcia Knous [:marcia]]

(In reply to Marcia Knous [:marcia - use ni] from comment #2)
> ni on marcia for followup here. Need to figure out what to do with these
> crashes since we turned the feature off.
> 
> Also what does necko-next in the whiteboard mean?

TFO was turned on again in Bug 1367390, we will keep these crashes open until Dragana evaluates whether they should be closed or not.

Comment 6

[Dragana Damjanovic [:dragana]]

There are 3 crashes with TFO second try. I will keep the bug open.

Comment 7

[Julien Cristau [:jcristau]]

TFO crash, setting 55 to disabled.

Comment 8

[Dragana Damjanovic [:dragana]]

Interesting fact:
this signature crashes at 0x1f3c0000120 (or 0x268c0000120 ...) always ending at c0000120
bug 1362978 crashes at 0xc0000120

Comment 9

[Dragana Damjanovic [:dragana]]

It is always connected with a socket being readable.

in TCPFastOpenLayer in TCPFastOpenRecv function there is code that check if mFirstPacketBufLen is 0. I have change code so mFirstPacketBufLen should never ever be not zero here. I will add assertion.

The rest of TCPFastOpenRecv does not do anything special just calls a layer below.

Comment 10

[Dragana Damjanovic [:dragana]]

In a search for a bug I will make a patch that send just a small amount of data in syn packet (only 10bytes).
I tried to do a test that send 0 byte, but that one failed on talos tests, actually crashes with an empty dump file. Honza also tried to reproduce it locally but it was not failing :(

Comment 11

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=34b024af9e88e9aabc04cda807e754a3348099a4

Comment 12

[Dragana Damjanovic [:dragana]]

Attachment: bug_test_tfo3.patch

I am out of other ideas.

I would like to run this patch only for a day to see if it influence crashes or not.

This patch send only a small number of bytes in a syn packet.

(there is some additional info in comment 10)

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/bdcd3e78b4c0
Test tfo: send only small part of tfo data. r=mcmanus

Comment 14

[Dragana Damjanovic [:dragana]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/bdcd3e78b4c051dd383a26ea4172b0ccdb62feaf
Bug 1363372 - Test tfo: send only small part of tfo data. r=mcmanus

Comment 15

[Dragana Damjanovic [:dragana]]

Attachment: bug_test_tfo3_revert.patch

This is the revert patch.

Comment 16

[Ryan VanderMeulen (PTO, back July 27)]

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

Comment 17

[Calixte Denizet (:calixte)]

The crash is still there and the numbers increased the 07-20 so just after the patch landed [1].
The signature is ranked #11 in top-crashers (#8 for windows top-crashers).

[1] https://crash-stats.mozilla.com/signature/?product=Firefox&release_channel=nightly&version=56.0a1&signature=mozilla%3A%3Anet%3A%3AHttpChannelParentListener%3A%3AGetInterface&date=%3E%3D2017-04-26T09%3A58%3A01.000Z&date=%3C2017-07-26T09%3A58%3A01.000Z&_columns=date&_columns=product&_columns=version&_columns=build_id&_columns=platform&_columns=reason&_columns=address&_columns=install_time&_sort=-build_id&_sort=-date&page=1#graphs

Comment 18

[Dragana Damjanovic [:dragana]]

(In reply to Calixte Denizet (:calixte) from comment #17)
> The crash is still there and the numbers increased the 07-20 so just after
> the patch landed [1].
> The signature is ranked #11 in top-crashers (#8 for windows top-crashers).
> 
> [1]
> https://crash-stats.mozilla.com/signature/
> ?product=Firefox&release_channel=nightly&version=56.
> 0a1&signature=mozilla%3A%3Anet%3A%3AHttpChannelParentListener%3A%3AGetInterfa
> ce&date=%3E%3D2017-04-26T09%3A58%3A01.000Z&date=%3C2017-07-26T09%3A58%3A01.
> 000Z&_columns=date&_columns=product&_columns=version&_columns=build_id&_colum
> ns=platform&_columns=reason&_columns=address&_columns=install_time&_sort=-
> build_id&_sort=-date&page=1#graphs

TFO will be turned off before Nightly freeze next week. With TFO off all this crashes are going away.

I am try to get one more patch to try it out until next week. I think I now know what is the problem, but, in any case, I will turn off TFO before next week.

Comment 19

[Dragana Damjanovic [:dragana]]

Attachment: bug_tfo_socket_closeissue.patch

Comment 21

[Dragana Damjanovic [:dragana]]

Attachment: bug_tfo_socket_closeissue.patch

Comment 22

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=715b1c9315921c3210ff977c36290b176b195f70

Comment 23

[Honza Bambas (:mayhemer)]

Comment on attachment 8891443 [details] [diff] [review]
bug_tfo_socket_closeissue.patch

Review of attachment 8891443 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with comments fixed

::: netwerk/base/nsSocketTransport2.cpp
@@ +3451,5 @@
>      }
>  
> +#if defined(_WIN64) && defined(WIN95)
> +    bool canClose = false;
> +    if (gHttpHandler->GetFastOpenNotSupported()) {

can this change in runtime?  maybe don't check for this, PR_FileDesc2PlatformOverlappedIOHandle will not return anything when the pref was disabled during the socket creation (and vise versa).

@@ +3455,5 @@
> +    if (gHttpHandler->GetFastOpenNotSupported()) {
> +      LPOVERLAPPED ol = nullptr;
> +      if (PR_FileDesc2PlatformOverlappedIOHandle(aFd, &ol) == PR_SUCCESS) {
> +        SOCKET_LOG(("nsSocketTransport::CloseSocket - we have an overlapped "
> +                    "structure=%p aFd=%d\n", ol, aFd));

aFd=%p

::: netwerk/base/nsSocketTransportService2.cpp
@@ +1692,5 @@
> +void
> +nsSocketTransportService::AddOverlappedPendingSocket(PRFileDesc *aFd)
> +{
> +    MOZ_ASSERT(gHttpHandler->GetFastOpenNotSupported());
> +    SOCKET_LOG(("STS AddOverlappedPendingSocket append aFd=%d\n", *aFd));

%p and aFd?

@@ +1693,5 @@
> +nsSocketTransportService::AddOverlappedPendingSocket(PRFileDesc *aFd)
> +{
> +    MOZ_ASSERT(gHttpHandler->GetFastOpenNotSupported());
> +    SOCKET_LOG(("STS AddOverlappedPendingSocket append aFd=%d\n", *aFd));
> +    mOverlappedPendingSockets.AppendElement(aFd);

a thread assertion would be good to add

@@ +1699,5 @@
> +
> +void
> +nsSocketTransportService::CheckOverlappedPendingSocketsAreDone()
> +{
> +    if (!gHttpHandler->GetFastOpenNotSupported()) {

can this change at runtime?  I think check for the array length (or simply nothing) would be better

please add thread assertions as well here

@@ +1704,5 @@
> +      return;
> +    }
> +
> +    SOCKET_LOG(("STS CheckOverlappedPendingSocketsAreDone\n"));
> +    for (int i = mOverlappedPendingSockets.Length() - 1; i >= 0; i--) {

better is, but up to you:

for (size_t i = Length(); i > 0;) {
  --i;

  ...code...
}

::: netwerk/protocol/http/nsHttpHandler.cpp
@@ +276,5 @@
> +  bool allowed = false;
> +  int inx = 0;
> +  nsCCharSeparatedTokenizer tokenizer(aVersion, '.');
> +  while ((inx < 2) && tokenizer.hasMoreTokens()) {
> +    nsAutoCString token(tokenizer.nextToken());

(would be nice to rewrite this one day with mozilla::Tokenizer)

::: netwerk/protocol/http/nsHttpHandler.h
@@ +176,5 @@
>      // Fast Open at run time, so if we get error PR_NOT_IMPLEMENTED_ERROR it
>      // means that Fast Open is not supported and we will set mFastOpenSupported
>      // to false.
>      void SetFastOpenNotSupported() { mFastOpenSupported = false; }
> +    bool GetFastOpenNotSupported() { return mFastOpenSupported; };

is the *Not* in the name correct?

Comment 24

[Dragana Damjanovic [:dragana]]

(In reply to Honza Bambas (:mayhemer) from comment #23)
> Comment on attachment 8891443 [details] [diff] [review]
> bug_tfo_socket_closeissue.patch
> 
> Review of attachment 8891443 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> r+ with comments fixed
> 
> ::: netwerk/base/nsSocketTransport2.cpp
> @@ +3451,5 @@
> >      }
> >  
> > +#if defined(_WIN64) && defined(WIN95)
> > +    bool canClose = false;
> > +    if (gHttpHandler->GetFastOpenNotSupported()) {
> 
> can this change in runtime?  maybe don't check for this,
> PR_FileDesc2PlatformOverlappedIOHandle will not return anything when the
> pref was disabled during the socket creation (and vise versa).
> 

I added the check because I am checking at run time if nspr has the right version, if FileDesc2PlatformOverlappedIOHandle is present.
I forgot one situation that this can change at runtime by switching the operating system pref on and off. Therefore I separated this 2 in my next patch.

> 
> @@ +1693,5 @@
> > +nsSocketTransportService::AddOverlappedPendingSocket(PRFileDesc *aFd)
> > +{
> > +    MOZ_ASSERT(gHttpHandler->GetFastOpenNotSupported());
> > +    SOCKET_LOG(("STS AddOverlappedPendingSocket append aFd=%d\n", *aFd));
> > +    mOverlappedPendingSockets.AppendElement(aFd);
> 
> a thread assertion would be good to add
> 

add

> @@ +1699,5 @@
> > +
> > +void
> > +nsSocketTransportService::CheckOverlappedPendingSocketsAreDone()
> > +{
> > +    if (!gHttpHandler->GetFastOpenNotSupported()) {
> 
> can this change at runtime?  I think check for the array length (or simply
> nothing) would be better
> 
> please add thread assertions as well here
> 

added and now GetFastOpenNotSupported changed to OSAndLibSupportsFastOpen and cannot change at runtime.


> ::: netwerk/protocol/http/nsHttpHandler.h
> @@ +176,5 @@
> >      // Fast Open at run time, so if we get error PR_NOT_IMPLEMENTED_ERROR it
> >      // means that Fast Open is not supported and we will set mFastOpenSupported
> >      // to false.
> >      void SetFastOpenNotSupported() { mFastOpenSupported = false; }
> > +    bool GetFastOpenNotSupported() { return mFastOpenSupported; };
> 
> is the *Not* in the name correct?

changed to OSAndLibSupportsFastOpen.

Comment 25

[Dragana Damjanovic [:dragana]]

Attachment: bug_tfo_socket_closeissue.patch

Comment 26

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=87dcacc53a86423265f11a2a23f6ef195605b304

Comment 27

[Dragana Damjanovic [:dragana]]

there is soe problem with windows on try that is independent of my change, i will try it again later today.

Comment 28

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=7b2ded510a25e051c63f84631b1f7e26d99f4520

Comment 32

[Patrick McManus [:mcmanus]]

Comment on attachment 8891515 [details] [diff] [review]
bug_tfo_socket_closeissue.patch

Review of attachment 8891515 [details] [diff] [review]:
-----------------------------------------------------------------

::: netwerk/base/nsSocketTransport2.cpp
@@ +1278,5 @@
>          if (NS_FAILED(rv)) {
>              SOCKET_LOG(("  error pushing io layer [%u:%s rv=%" PRIx32 "]\n", i, mTypes[i],
>                          static_cast<uint32_t>(rv)));
>              if (fd) {
> +                CloseSocket(fd, mSocketTransportService); 

whitespace nit

::: netwerk/base/nsSocketTransportService2.cpp
@@ +1045,5 @@
> +    // leak FDs.
> +    CheckOverlappedPendingSocketsAreDone();
> +    if (mOverlappedPendingSockets.Length()) {
> +        PRIntervalTime delay = PR_MillisecondsToInterval(500);
> +        PR_Sleep(delay); // wait another 500ms.

I know this is shutdown, but we can't really do this. can we just leak them - or better yet only do the slow clean up when the tests are accounting for it like nsHostResolver.ccp:704 (which has a similar problem - you can't interrupt getaddrinfo() and you want to shut down)

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3e01e416c117
Revert test tfo: send only small part of tfo data. r=mayhemer

Comment 34

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/3e01e416c117

Comment 36

[Dragana Damjanovic [:dragana]]

Attachment: bug_tfo_socket_closeissue3.patch

Comment 37

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=17584a4f9540fe87278b64fe56e902bd741add16

Comment 38

[Dragana Damjanovic [:dragana]]

Comment on attachment 8892980 [details] [diff] [review]
bug_tfo_socket_closeissue3.patch

François, ccan you please review the telemetry part.

Comment 39

[François Marier [:francois]]

Comment on attachment 8892980 [details] [diff] [review]
bug_tfo_socket_closeissue3.patch

Review of attachment 8892980 [details] [diff] [review]:
-----------------------------------------------------------------

This is Category 1 data (https://wiki.mozilla.org/Firefox/Data_Collection#Data_Collection_Categories).

datareview+ with comments

::: toolkit/components/telemetry/Scalars.yaml
@@ +818,5 @@
> +  overlapped_io_canceled_before_finished:
> +    bug_numbers:
> +      - 1363372
> +    description: >
> +      Count the number of socket that use overlapped io and are canceled before

nit: "sockets"

@@ +824,5 @@
> +      TCP Fast Open is used.)
> +    expires: "58"
> +    kind: uint
> +    notification_emails:
> +      - [e-mail]

We now ask for the email address of a real person too. You can keep necko in there, but please add your own to the list.

@@ +838,5 @@
> +        connectEx when TCP Fast Open is used.)
> +      expires: "58"
> +      kind: uint
> +      notification_emails:
> +        - [e-mail]

ditto

Comment 40

[Patrick McManus [:mcmanus]]

Comment on attachment 8892980 [details] [diff] [review]
bug_tfo_socket_closeissue3.patch

Review of attachment 8892980 [details] [diff] [review]:
-----------------------------------------------------------------

sorry - can't review that trainwreck of a try run :) https://treeherder.mozilla.org/#/jobs?repo=try&revision=17584a4f9540fe87278b64fe56e902bd741add16

Comment 41

[Dragana Damjanovic [:dragana]]

(In reply to Patrick McManus [:mcmanus] from comment #40)
> Comment on attachment 8892980 [details] [diff] [review]
> bug_tfo_socket_closeissue3.patch
> 
> Review of attachment 8892980 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> sorry - can't review that trainwreck of a try run :)
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=17584a4f9540fe87278b64fe56e902bd741add16

You have not seen win10 test. This is all normal :)

win8 is sccache error that exist for couple of days. And the failure of xcpshell tests is caused by TFO (I have almost ready patch for bug 1386719)

Comment 47

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d77b4d6c322d
Wait until OVERLAPPED structure return a result before distroying a socket. r=mcmanus

Comment 48

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 49

[Dragana Damjanovic [:dragana]]

ok this path is getting hit:

https://telemetry.mozilla.org/new-pipeline/dist.html#!cumulative=0&end_date=2017-08-12&keys=__none__!__none__!__none__&max_channel_version=nightly%252F57&measure=SCALARS_NETWORK.TCP.OVERLAPPED_IO_CANCELED_BEFORE_FINISHED&min_channel_version=nightly%252F56&processType=*&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2017-08-12&table=0&trim=1&use_submission_date=0

that means this is a plausible explanation for TFO crashes.


I still do not see any crashes, but it is a bit early to be completely sure.

Comment 50

[Dragana Damjanovic [:dragana]]

This one is fixed. there is not crashes in 57.