Bug 1613943 Comment 0 Edit History

Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.

Original comment by

Mike Taylor [:miketaylr]

on 2020-02-07 06:52:30 PST

For some users, after logging into RBC (a Canadian bank), they end up with a blank page.

We're in touch with the site developers who explained the flow like so:

> As a quick summary of the issue:
>
>   * A subset of our clients running Firefox (version 71 or newer) on
>     Windows 10 (but possibly other platforms) experience the issue
>   * The sequence of events is as follows:
>
>       o On successful sign-in, a page is returned with a form element
>         and a script on it that will fetch the client’s account summary
>         (for successful cases the response from /some/action):
>
> <form method=”GET” action=”/some/action” name=”foo”>
>
> <input type=”hidden” name=”somename” value=”YES” />
>
> …(multiple inputs)
>
> </form>
>
> <script language=”JavaScript”>
>
>     document.foo.submit();
>
> </script>
>
>       o The request to /some/action does not complete – it does not
>         appear to even hit our servers
>
>           + In the requests tab, the response code is 0
>           + The number of bytes received is 0
>
>       o This page does have other scripts included in it (and likely
>         some would be blocked by enhanced privacy protections)
>
>   * It appears disabling some of the enhanced privacy protections works
>     for some clients, but not all. 

Adam Stevenson was able to reproduce, and collect some logs.

Dragana took a look at the log and write the following:

> So looking at the log we are sending request to a server (PART1 is where we do PR_Write which writes to the socket).
> The problem is that we are closing connection on our side, probably before the server has read the POST request (that is why the server side do not see the request).

> The reason we are closing the connection is interested (log PART2):
So we read a HTTP2 frame (PR_Read returned [n=9]). This is a data frame which has a "Fin" flag set. The server is just closing that stream, nothing unusual, but something transforms that into 804b0047 error which is NS_ERROR_NET_INTERRUPT. 804b0047 cause us to close the session, because Http2Session thinks that socket is broken.

> There is not enough logging to see what it is. I thought it is nsHttpTransaction that returns NS_ERROR_NET_INTERRUPT, but it is not.
it is happening in this 4 lines:
2020-02-06 18:24:19.704020 UTC - [Parent 7253: Socket Thread]: I/nsHttp Start Processing Data Frame. Session=0x132bda000 Stream ID 0x13 Stream Ptr 0x11877da40 Fin=1 Len=0
2020-02-06 18:24:19.704027 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Stream::WriteSegments 0x11877da40 count=32768 state=4
2020-02-06 18:24:19.704034 UTC - [Parent 7253: Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 0x123c7d000
2020-02-06 18:24:19.704040 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session 0x132bda000 data frame read failure 804b0047

> We may need to add more logging to figure out what is wrong, or use rr. How easy is it to reproduce?

> Unfortunately, this looks like a problem on our end.


> I am adding logging at the end so that I have it somewhere and I do not need to search for it again.
PART 1
2020-02-06 18:24:19.609200 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::OnReadSegment [this=0x13b077c00]
2020-02-06 18:24:19.609211 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::Write [this=0x13a258ec8 count=8383]
2020-02-06 18:24:19.609220 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   calling PR_Write [count=8383]
2020-02-06 18:24:19.609300 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   PR_Write returned [n=8383]


PART 2
2020-02-06 18:24:19.703931 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   calling PR_Read [count=9]
2020-02-06 18:24:19.703970 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   PR_Read returned [n=9]
2020-02-06 18:24:19.703979 UTC - [Parent 7253: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x13a258c00 status=804b0006]
2020-02-06 18:24:19.703987 UTC - [Parent 7253: Socket Thread]: V/nsHttp Http2Session::LogIO 0x132bda000 stream=0x0 id=0x0 [Reading Frame Header]
2020-02-06 18:24:19.703995 UTC - [Parent 7253: Socket Thread]: V/nsHttp 00000000: 00 00 00 00 01 00 00 00 13
2020-02-06 18:24:19.704001 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::WriteSegments[0x132bda000::90] Frame Header Read type 0 data len 0 flags 1 id 0x13
2020-02-06 18:24:19.704008 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0x132bda000 from 1 to 4
2020-02-06 18:24:19.704020 UTC - [Parent 7253: Socket Thread]: I/nsHttp Start Processing Data Frame. Session=0x132bda000 Stream ID 0x13 Stream Ptr 0x11877da40 Fin=1 Len=0
2020-02-06 18:24:19.704027 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Stream::WriteSegments 0x11877da40 count=32768 state=4
2020-02-06 18:24:19.704034 UTC - [Parent 7253: Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 0x123c7d000
2020-02-06 18:24:19.704040 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session 0x132bda000 data frame read failure 804b0047
2020-02-06 18:24:19.704047 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 0x13b077c00 trans->ws rv=804b0047 n=9 socketin=0
2020-02-06 18:24:19.704053 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::CloseTransaction[this=0x13b077c00 trans=0x132bda000 reason=804b0047]
2020-02-06 18:24:19.704059 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::DontReuse 0x13b077c00 spdysession=0x132bda000
2020-02-06 18:24:19.704066 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::DontReuse 0x132bda000
2020-02-06 18:24:19.704072 UTC - [Parent 7253: Socket Thread]: V/nsHttp   closing associated mTransaction
2020-02-06 18:24:19.704079 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::Close 0x132bda000 804B0047
2020-02-06 18:24:19.704085 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::CloseStream 0x132bda000 0x11877da40 0x13 804B004C
2020-02-06 18:24:19.704091 UTC - [Parent 7253: Socket Thread]: I/nsHttp MaybeDecrementConcurrent 0x132bda000 id=0x13 concurrent=2 active=1
2020-02-06 18:24:19.704097 UTC - [Parent 7253: Socket Thread]: I/nsHttp Stream had active partial read frame on close
2020-02-06 18:24:19.704103 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0x132bda000 from 4 to 6
2020-02-06 18:24:19.704109 UTC - [Parent 7253: Socket Thread]: D/nsHttp nsHttpTransaction::Close [this=0x123c7d000 reason=804b004c]
2020-02-06 18:24:19.704115 UTC - [Parent 7253: Socket Thread]: D/nsHttp   already closed
2020-02-06 18:24:19.704122 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::CloseStream 0x132bda000 0x1208988d0 0x17 80004004
2020-02-06 18:24:19.704128 UTC - [Parent 7253: Socket Thread]: I/nsHttp MaybeDecrementConcurrent 0x132bda000 id=0x17 concurrent=1 active=1

Revision 1 by

Mike Taylor [:miketaylr]

on 2020-02-07 06:54:13 PST

For some users, after logging into RBC (a Canadian bank), they end up with a blank page.

We're in touch with the site developers who explained the flow like so:

> As a quick summary of the issue:
>
>   * A subset of our clients running Firefox (version 71 or newer) on
>     Windows 10 (but possibly other platforms) experience the issue
>   * The sequence of events is as follows:
>
>       o On successful sign-in, a page is returned with a form element
>         and a script on it that will fetch the client’s account summary
>         (for successful cases the response from /some/action):
>
> <form method=”GET” action=”/some/action” name=”foo”>
>
> <input type=”hidden” name=”somename” value=”YES” />
>
> …(multiple inputs)
>
> </form>
>
> <script language=”JavaScript”>
>
>     document.foo.submit();
>
> </script>
>
>       o The request to /some/action does not complete – it does not
>         appear to even hit our servers
>
>           + In the requests tab, the response code is 0
>           + The number of bytes received is 0
>
>       o This page does have other scripts included in it (and likely
>         some would be blocked by enhanced privacy protections)
>
>   * It appears disabling some of the enhanced privacy protections works
>     for some clients, but not all. 

Adam Stevenson was able to reproduce, and collect some logs.

Dragana took a look at the log and write the following:

> So looking at the log we are sending request to a server (PART1 is where we do PR_Write which writes to the socket).
> The problem is that we are closing connection on our side, probably before the server has read the POST request (that is why the server side do not see the request).

> The reason we are closing the connection is interested (log PART2):
So we read a HTTP2 frame (PR_Read returned [n=9]). This is a data frame which has a "Fin" flag set. The server is just closing that stream, nothing unusual, but something transforms that into 804b0047 error which is NS_ERROR_NET_INTERRUPT. 804b0047 cause us to close the session, because Http2Session thinks that socket is broken.

> There is not enough logging to see what it is. I thought it is nsHttpTransaction that returns NS_ERROR_NET_INTERRUPT, but it is not.
it is happening in this 4 lines:
2020-02-06 18:24:19.704020 UTC - [Parent 7253: Socket Thread]: I/nsHttp Start Processing Data Frame. Session=0x132bda000 Stream ID 0x13 Stream Ptr 0x11877da40 Fin=1 Len=0
2020-02-06 18:24:19.704027 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Stream::WriteSegments 0x11877da40 count=32768 state=4
2020-02-06 18:24:19.704034 UTC - [Parent 7253: Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 0x123c7d000
2020-02-06 18:24:19.704040 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session 0x132bda000 data frame read failure 804b0047

> We may need to add more logging to figure out what is wrong, or use rr. How easy is it to reproduce?

> Unfortunately, this looks like a problem on our end.


> I am adding logging at the end so that I have it somewhere and I do not need to search for it again.
PART 1
2020-02-06 18:24:19.609200 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::OnReadSegment [this=0x13b077c00]
2020-02-06 18:24:19.609211 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::Write [this=0x13a258ec8 count=8383]
2020-02-06 18:24:19.609220 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   calling PR_Write [count=8383]
2020-02-06 18:24:19.609300 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   PR_Write returned [n=8383]


> PART 2
2020-02-06 18:24:19.703931 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   calling PR_Read [count=9]
2020-02-06 18:24:19.703970 UTC - [Parent 7253: Socket Thread]: D/nsSocketTransport   PR_Read returned [n=9]
2020-02-06 18:24:19.703979 UTC - [Parent 7253: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x13a258c00 status=804b0006]
2020-02-06 18:24:19.703987 UTC - [Parent 7253: Socket Thread]: V/nsHttp Http2Session::LogIO 0x132bda000 stream=0x0 id=0x0 [Reading Frame Header]
2020-02-06 18:24:19.703995 UTC - [Parent 7253: Socket Thread]: V/nsHttp 00000000: 00 00 00 00 01 00 00 00 13
2020-02-06 18:24:19.704001 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::WriteSegments[0x132bda000::90] Frame Header Read type 0 data len 0 flags 1 id 0x13
2020-02-06 18:24:19.704008 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0x132bda000 from 1 to 4
2020-02-06 18:24:19.704020 UTC - [Parent 7253: Socket Thread]: I/nsHttp Start Processing Data Frame. Session=0x132bda000 Stream ID 0x13 Stream Ptr 0x11877da40 Fin=1 Len=0
2020-02-06 18:24:19.704027 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Stream::WriteSegments 0x11877da40 count=32768 state=4
2020-02-06 18:24:19.704034 UTC - [Parent 7253: Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 0x123c7d000
2020-02-06 18:24:19.704040 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session 0x132bda000 data frame read failure 804b0047
2020-02-06 18:24:19.704047 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 0x13b077c00 trans->ws rv=804b0047 n=9 socketin=0
2020-02-06 18:24:19.704053 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::CloseTransaction[this=0x13b077c00 trans=0x132bda000 reason=804b0047]
2020-02-06 18:24:19.704059 UTC - [Parent 7253: Socket Thread]: V/nsHttp nsHttpConnection::DontReuse 0x13b077c00 spdysession=0x132bda000
2020-02-06 18:24:19.704066 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::DontReuse 0x132bda000
2020-02-06 18:24:19.704072 UTC - [Parent 7253: Socket Thread]: V/nsHttp   closing associated mTransaction
2020-02-06 18:24:19.704079 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::Close 0x132bda000 804B0047
2020-02-06 18:24:19.704085 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::CloseStream 0x132bda000 0x11877da40 0x13 804B004C
2020-02-06 18:24:19.704091 UTC - [Parent 7253: Socket Thread]: I/nsHttp MaybeDecrementConcurrent 0x132bda000 id=0x13 concurrent=2 active=1
2020-02-06 18:24:19.704097 UTC - [Parent 7253: Socket Thread]: I/nsHttp Stream had active partial read frame on close
2020-02-06 18:24:19.704103 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0x132bda000 from 4 to 6
2020-02-06 18:24:19.704109 UTC - [Parent 7253: Socket Thread]: D/nsHttp nsHttpTransaction::Close [this=0x123c7d000 reason=804b004c]
2020-02-06 18:24:19.704115 UTC - [Parent 7253: Socket Thread]: D/nsHttp   already closed
2020-02-06 18:24:19.704122 UTC - [Parent 7253: Socket Thread]: I/nsHttp Http2Session::CloseStream 0x132bda000 0x1208988d0 0x17 80004004
2020-02-06 18:24:19.704128 UTC - [Parent 7253: Socket Thread]: I/nsHttp MaybeDecrementConcurrent 0x132bda000 id=0x17 concurrent=1 active=1

Back to Bug 1613943 Comment 0