Websocket connection fails

RESOLVED INCOMPLETE

Status

()

P3
normal
RESOLVED INCOMPLETE
2 years ago
6 months ago

People

(Reporter: sergio.puertas, Unassigned)

Tracking

48 Branch
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

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/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.

Updated

2 years ago
Component: Untriaged → Networking: WebSockets
Product: Firefox → Core
Summary: Websocket connectios fails → Websocket connection fails
(Reporter)

Comment 1

2 years ago
The problem was the openssl version installed in my server.
After upgrading it, it worked perfectly.
Status: UNCONFIRMED → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → INVALID
(Reporter)

Comment 2

2 years ago
Again it is not working. My server is updated.
Status: RESOLVED → UNCONFIRMED
Resolution: INVALID → ---
Michal, can you take a look?
Flags: needinfo?(michal.novotny)
Whiteboard: [necko-active]
(Reporter)

Comment 4

2 years ago
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
Assignee: nobody → michal.novotny
Status: UNCONFIRMED → NEW
Ever confirmed: true
Flags: needinfo?(michal.novotny)
Created attachment 8794777 [details]
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)
Flags: needinfo?(mcmanus)
(Reporter)

Comment 6

2 years ago
Any update about this? The problem persists.
Honza, can you have a look at the log? See comment #5.

Anyway, AFAICS this is not a problem in WebSocket channel.
Assignee: michal.novotny → nobody
Flags: needinfo?(honzab.moz)
Whiteboard: [necko-active]
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?
Flags: needinfo?(honzab.moz)
(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.
Flags: needinfo?(mcmanus)
Whiteboard: [necko-active]
Created attachment 8816509 [details]
log2

Log with MOZ_LOG=sync,timestamp,nsWebSocket:5,nsHttp:5,pipnss:5, see nsHttpChannel bbfa7800, nsHttpTransaction baee8400
Flags: needinfo?(honzab.moz)
Assignee: nobody → honzab.moz
Flags: needinfo?(honzab.moz)
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.
Assignee: honzab.moz → michal.novotny
(Reporter)

Comment 12

2 years ago
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 !
(Reporter)

Comment 13

2 years ago
Can I help in any way? Do you need more information from my side?
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?
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.
Created attachment 8838326 [details]
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.
Flags: needinfo?(honzab.moz)
(Reporter)

Comment 17

2 years ago
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.
(Reporter)

Comment 18

2 years ago
Sorry, I am mistaken. The upgrade is the response.
(Reporter)

Comment 19

2 years ago
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?
(Reporter)

Comment 20

2 years ago
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
(Reporter)

Comment 21

2 years ago
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.
(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!
Flags: needinfo?(sergio.puertas)
(Reporter)

Comment 23

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

Thanks
Assignee: michal.novotny → nobody
Whiteboard: [necko-active] → [necko-backlog]
Clearly I'm not able to get to this...
Flags: needinfo?(honzab.moz)
Status: NEW → RESOLVED
Last Resolved: 2 years ago6 months ago
Resolution: --- → INCOMPLETE
Whiteboard: [necko-backlog]
Flags: needinfo?(sergio.puertas)
You need to log in before you can comment on or make changes to this bug.