1300672 - Websocket connection fails

Status: RESOLVED INCOMPLETE

(Core :: Networking: WebSockets, defect, P3)

Description

[Sergio]

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

Steps to reproduce:

After update Firefox 48.0, is not possible to make a connection to my websocket server.
To test the connection :
1-go to https://www.websocket.org/echo.html
2: add in location :wss://slabon.es:80/jwsPrivate_plugin/jWebSocket
3:Check the Use secure WebSocket (TLS) option
4:Click Connect


Actual results:

In the log window said ERROR:undefined.
The message my websocket server prints is TCPConnector$ClientProcessor: Client not accepted on port 56219 due to handshake issues


Expected results:

If you make the same test under Chrome the connection is OK.

Comment 1

[Sergio]

The problem was the openssl version installed in my server.
After upgrading it, it worked perfectly.

Comment 2

[Sergio]

Again it is not working. My server is updated.

Comment 3

[Dragana Damjanovic [:dragana]]

Michal, can you take a look?

Comment 4

[Sergio]

In order to add more information, this behaviour only happens in some scenarios.
For example accesing from a Windows 7 SP1 fails but if we try to connect with Windows 7 or 8 it works.
I though this could be related with certificates or similar.
Thanks

Comment 5

[Michal Novotny [:michal]]

Attachment: log.txt

I was able to reproduce it several times in a row and now I'm not able to reproduce it anymore. I have a nspr log (sync,timestamp,nsHttp:5,nsWebSocket:5) which shows that the problem is not at websocket level. For some reason there is no http response to the upgrade request. Patrick, can you read something useful from the log? (nsHttpChannel 1158e800, nsHttpTransaction 14087c00)

Comment 6

[Sergio]

Any update about this? The problem persists.

Comment 7

[Michal Novotny [:michal]]

Honza, can you have a look at the log? See comment #5.

Anyway, AFAICS this is not a problem in WebSocket channel.

Comment 8

[Honza Bambas (:mayhemer)]

Looks like TLS session fails to negotiate.  pipnss:5 module would be good to have.  This can well be a problem on the server.  Are you using default settings for PSM?

Comment 9

[Michal Novotny [:michal]]

(In reply to Honza Bambas (:mayhemer) from comment #8)
> Are you using default settings for PSM?

Yes, I used new profile. In the end I wasn't able to reproduce it anymore, but I'll give it another try if I can reproduce it now with pipnss logging.

Comment 10

[Michal Novotny [:michal]]

Attachment: log2

Log with MOZ_LOG=sync,timestamp,nsWebSocket:5,nsHttp:5,pipnss:5, see nsHttpChannel bbfa7800, nsHttpTransaction baee8400

Comment 11

[Honza Bambas (:mayhemer)]

ssl is negotiated:

2016-12-02 18:21:04.748635 UTC - [Socket Thread]: D/pipnss [cdd4d620] nsNSSSocketInfo::SetHandshakeCompleted

then we wrote the request:

2016-12-02 18:21:04.749074 UTC - [Socket Thread]: V/pipnss [cdd4d620] wrote 551 bytes

the server gracefully closes the connection:

2016-12-02 18:21:04.796611 UTC - [Socket Thread]: V/pipnss [cdd4d620] read 0 bytes

why?  no idea from the log.

If you have taste and time to investigate more, please add nsSocketTransport:5 to MOZ_LOG and then set SSLDEBUGFILE=/somefile and SSLTRACE=100

Or you can try wireshark with reference to SSLKEYLOGFILE nss produces.

Comment 12

[Sergio]

Hi again!

Any advance regarding this issue? It's very frustrating because sometimes Firefox can connect our websocket server but not in many other times.

Thanks for your effort !

Comment 13

[Sergio]

Can I help in any way? Do you need more information from my side?

Comment 14

[Patrick McManus [:mcmanus]]

I notice you're running wss on port 80, which is a little weird and might be the root of the issue. Does it work ok on another port?

Comment 15

[Patrick McManus [:mcmanus]]

The STR (using websocket.org) WFM using both FF51 and FF54.

Is this still an issue for you?

I think you will need to add a wireshark capture and the emphemeral key https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSS/Key_Log_Format to take the next step. But if the server is simply closing the connection, you'll need to persue that with the server.

Comment 16

[Michal Novotny [:michal]]

Attachment: logs

(In reply to Honza Bambas (:mayhemer) from comment #11)
> If you have taste and time to investigate more, please add
> nsSocketTransport:5 to MOZ_LOG and then set SSLDEBUGFILE=/somefile and
> SSLTRACE=100

I was able to reproduce it again. There are 2 attempts to connect and both failed:

1)
WebSocketChannel bc10e000
nsHttpChannel bc10e800

2)
WebSocketChannel bba18800
nsHttpChannel bba1c800

Interesting is that it seems to be session dependent, i.e. if it succeeds for the first time after starting FF it succeeds every time and if it fails for the first time it fails every time.

Comment 17

[Sergio]

Yes, this is the behaviour. 
Using developer tools I have seen that when it works,  FF sends 2 request:
The first one is an Upgrade
The second one is a keep-alive, Upgrade

But when it fails, only the keep-alive,Upgrade request is send, but not the first one.

Comment 18

[Sergio]

Sorry, I am mistaken. The upgrade is the response.

Comment 19

[Sergio]

I have seen this behavior.

Take a look at our server side:

 InputStream lIn = aClientSocket.getInputStream();
 BufferedReader bufferedReader = new BufferedReader(new InputStreamReader(lIn), 1);
 String line;
        while ((line = bufferedReader.readLine()) != null) {
            System.out.println(line);
 }

In the firsline we received the request from the browser and we are printing it to see it.
In case of Chrome, we received 2 request.
The first one it seems "empty", because no line is printed.
The second one prints this:

GET /jwsPrivate_plugin/jWebSocket HTTP/1.1
Host: 192.168.1.44:80
Connection: Upgrade
Pragma: no-cache
Cache-Control: no-cache
Upgrade: websocket
Origin: file://
Sec-WebSocket-Version: 13
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36
Accept-Encoding: gzip, deflate, sdch, br
Accept-Language: es-ES,es;q=0.8
Cookie: JWSSESSIONID=aed85d11d49ba87e1c1756c509e8368c
Sec-WebSocket-Key: lhihWCSb3jDxO2yOeYWVcg==
Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits

In this case the connection works.

Lets see in Firefox:
We receive one request, and when we try to do 

 while ((line = bufferedReader.readLine()) != null) {
            System.out.println(line);
 }

An exception is throw:

java.net.SocketException: Software caused connection abort: recv failed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:152)
	at java.net.SocketInputStream.read(SocketInputStream.java:122)
	at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
	at sun.security.ssl.InputRecord.read(InputRecord.java:480)
	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
	at sun.security.ssl.SSLSocketImpl.waitForClose(SSLSocketImpl.java:1725)
	at sun.security.ssl.HandshakeOutStream.flush(HandshakeOutStream.java:122)
	at sun.security.ssl.Handshaker.sendChangeCipherSpec(Handshaker.java:1005)
	at sun.security.ssl.ServerHandshaker.sendChangeCipherAndFinish(ServerHandshaker.java:1539)
	at sun.security.ssl.ServerHandshaker.clientFinished(ServerHandshaker.java:1499)
	at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:250)
	at sun.security.ssl.Handshaker.processLoop(Handshaker.java:901)
	at sun.security.ssl.Handshaker.process_record(Handshaker.java:837)
	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1023)
	at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1332)
	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:889)
	at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
	at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:126)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:170)
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	at java.io.BufferedReader.fill(BufferedReader.java:154)
	at java.io.BufferedReader.readLine(BufferedReader.java:317)
	at java.io.BufferedReader.readLine(BufferedReader.java:382)
	at org.jwebsocket.tcp.TCPConnector.processHandshake(TCPConnector.java:233)
	at org.jwebsocket.tcp.TCPConnector.access$3(TCPConnector.java:226)
	at org.jwebsocket.tcp.TCPConnector$ClientProcessor.run(TCPConnector.java:355)
	at java.lang.Thread.run(Thread.java:745)

Any idea?

Comment 20

[Sergio]

If I change wss to ws, I received the request from Firefox and it can be proccessed (It's not successfully buy the request is printed)
So the request under wss is corrupted or something like that

Comment 21

[Sergio]

I have download the Nightly version 52.0b7 (32-bit) and i can't reproduce the error. So something is different between version 51 and Nightly.

Comment 22

[Honza Bambas (:mayhemer)]

(In reply to Sergio from comment #21)
> I have download the Nightly version 52.0b7 (32-bit) and i can't reproduce
> the error. So something is different between version 51 and Nightly.

Sergio, please see https://bugzilla.mozilla.org/show_bug.cgi?id=1335440#c12.  Maybe check if that is the different (a preference in about:config flip) we are looking for here.  If so, this is then a duplicate of bug 1335440.

Thanks!

Comment 23

[Sergio]

Hi! I changed the flag in about:config, restarted Firefox  but the problem is still there.

Thanks

Comment 24

[Honza Bambas (:mayhemer)]

Clearly I'm not able to get to this...

Comment 25

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258