A second Secure WebSocket connection to the same localhost server fails

RESOLVED INVALID

Status

()

Core
Networking: WebSockets
RESOLVED INVALID
2 years ago
a year ago

People

(Reporter: George Wayland, Unassigned)

Tracking

45 Branch
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [necko-next])

Attachments

(3 attachments)

(Reporter)

Description

2 years ago
User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/55.0.2883.75 Safari/537.36

Steps to reproduce:

User agent: "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:45.0) Gecko/20100101 Firefox/45.0"

Steps to reproduce:
Client makes a secure WebSocket connection.
        this.socket = new WebSocket(  'wss://localhost:7010/gts');

A message is sent from client to server, and a message is sent from server to client. The client then closes the connection.
        this.socket.close( 1000, "done");

After several seconds, another connection is attempted to the same server.  



Actual results:

The connection fails after 20 seconds with the following in the console;
    Firefox can’t establish a connection to the server at wss://localhost:7010/gts

Additional notes:
    An immediate retry of the connection will succeed.
    If Firefox is closed and re-opened after the first connection, the second connection will succeed.
    Same sequence run under Chrome 55.0.2883.75, IE 11, or Edge succeeds.




Expected results:

Connection should succeed.

Updated

2 years ago
Component: Untriaged → Networking: WebSockets
Product: Firefox → Core

Comment 1

2 years ago
George, could you provide a testcase (live demo if need be)?
Flags: needinfo?(george.wayland)
(Reporter)

Comment 2

2 years ago
(In reply to Loic from comment #1)
> George, could you provide a testcase (live demo if need be)?

I wish that I could. I think the issue may be related to the localhost address handling.
Is there logging that I could enable to capture what is going on?

Comment 3

2 years ago
Patrick, could you advice the reporter about logging network requests, please.
Flags: needinfo?(george.wayland) → needinfo?(mcmanus)
https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging

but also include nsWebSocket:5 in the MOZ_LOG variable
Flags: needinfo?(mcmanus)
(Reporter)

Comment 5

2 years ago
Created attachment 8832589 [details]
Log file fflogs-main.zip

Log file attached with successful connection followed by failure.
(Reporter)

Comment 6

2 years ago
The log files are from a run under Developer Edition 53.0a2 (2017-02-01) (64-bit).
Can you take a look?
Flags: needinfo?(michal.novotny)
Whiteboard: [necko-next]
The connection times out after 20 seconds. There is no response to the upgrade request. From the log I can see that we successfully write 547 bytes to the socket:

2017-02-01 18:08:39.568000 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::Write [this=1f05b288 count=547]
2017-02-01 18:08:39.568000 UTC - [Socket Thread]: D/nsSocketTransport   calling PR_Write [count=547]
2017-02-01 18:08:39.568000 UTC - [Socket Thread]: D/nsSocketTransport   PR_Write returned [n=547]

Then we want to read from it, but there is no data, so we call AsyncWait():

2017-02-01 18:08:39.585000 UTC - [Socket Thread]: D/nsSocketTransport nsSocketInputStream::OnSocketReady [this=1f05b2017-02-01 18:08:39.585000 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 17998400 reentrantFlag=0
2017-02-01 18:08:39.585000 UTC - [Socket Thread]: D/nsSocketTransport nsSocketInputStream::Read [this=1f05b250 count=32768]
2017-02-01 18:08:39.585000 UTC - [Socket Thread]: D/nsSocketTransport   calling PR_Read [count=32768]
2017-02-01 18:08:39.586000 UTC - [Socket Thread]: D/nsSocketTransport   PR_Read returned [n=-1]
2017-02-01 18:08:39.586000 UTC - [Socket Thread]: D/nsSocketTransport JIMB: ReleaseFD_Locked: mFDref = 2
2017-02-01 18:08:39.586000 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 132f3600 trans->ws rv=0 n=0 socketin=80470007
2017-02-01 18:08:39.586000 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=132f3600]
2017-02-01 18:08:39.586000 UTC - [Socket Thread]: D/nsSocketTransport nsSocketInputStream::AsyncWait [this=1f05b250]

But OnSocketReadable() is not called and websocket is timed out:

2017-02-01 18:08:59.516000 UTC - [Main Thread]: D/nsWebSocket WebSocketChannel::Notify() c761800 [cf9cbc0]
2017-02-01 18:08:59.516000 UTC - [Main Thread]: D/nsWebSocket WebSocketChannel:: Connection Timed Out
2017-02-01 18:08:59.516000 UTC - [Main Thread]: D/nsWebSocket WebSocketChannel::AbortSession() c761800 [reason 804b000e] stopped = 0
2017-02-01 18:08:59.516000 UTC - [Main Thread]: D/nsWebSocket WebSocketChannel::StopSession() c761800 [804b000e]

Looks like the server doesn't respond. Honza, can you read more from the log?

WebSocketChannel c761800
nsHttpChannel 101c3800
nsHttpTransaction 17998400
nsSocketOutputStream 1f05b288
nsSocketInputStream 1f05b250
Flags: needinfo?(michal.novotny) → needinfo?(honzab.moz)
(Reporter)

Comment 9

a year ago
Created attachment 8841698 [details]
Trace of first websocket connection, works.
(Reporter)

Comment 10

a year ago
Created attachment 8841701 [details]
Second WebSocket connection that fails.

Comparing to the first, at line 86 the client under Firefox sends application data before the SSL handshake has completed. In the first trace the server is sending Change Cipher Spec.
(In reply to George Wayland from comment #10)
> Created attachment 8841701 [details]
> Second WebSocket connection that fails.
> 
> Comparing to the first, at line 86 the client under Firefox sends
> application data before the SSL handshake has completed. In the first trace
> the server is sending Change Cipher Spec.

Dragana, could this have anything to do with false start?
Flags: needinfo?(honzab.moz) → needinfo?(dd.mozilla)
false start can be easily tested.

George, can you go to about:config and search for security.ssl.enable_false_start. Set it to false and test if your test works.
Thank you
Flags: needinfo?(dd.mozilla) → needinfo?(george.wayland)
(Reporter)

Comment 13

a year ago
Yes, I do not see the failure when false start is set to false. Then, when I toggle to true, it fails.
Flags: needinfo?(george.wayland)
Thanks.
George, which server are you using?

ekr, please see last 2 comments and pcaps. The server does not respond to data send using false start.
Flags: needinfo?(ekr)
(Reporter)

Comment 15

a year ago
TooTallNate, https://github.com/TooTallNate/Java-WebSocket
I am satisfied this is a server issue, where it is not handling TLS False Start.
Not us, so closing.
Status: UNCONFIRMED → RESOLVED
Last Resolved: a year ago
Flags: needinfo?(ekr)
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.