1719502 - WebSocket is closed after a short time.

Status: RESOLVED INCOMPLETE

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

Description

[daemon]

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

Steps to reproduce:

0. Start a WS instance (not from webworkers)
1. Wait for a while without any data inout (2-4 min, but actually is random)
2. Server pushes some data

---

Error-unexpected stuff goes here
• Server cannot sends the message (to FF only), becasue of timeout. Then will try to close the connection. Weird stuff is , FF will catch the close event after a while(e.g. 1 min, by 1006 error)

Error happens almost 100% on production, where IO could not be as tough as local. In local-dev environment(where IO is supercool), producing the error is kind of impossible.

---

I think it's mostly related to IO stuff, so I'm going to try to tweak our server IO connectors to see if something help.

Actual results:

WebSocket gets closed,(also issue related to IO in server-side) once some small data is pushed from server to the client.

I have no issue with the Chrome at all(even chrome mobile), and I'm not sure if it's related to our server, but still investigate. Surprising, chrome works very well, only FF has this issue.

If nothing is being sent from the other peer, WS instance won't be closed, but as soon as some data is there, data is missed ,and I get the error.

Very weird stuff, is about when the peer sends some data soon the connection is created, FF works as expected.

I would have some very early messages from the server as soon as the socket is opened, but after a while no more message is sent, and the error comes. It seems FF ignores reading ws socket after a while for some reason.

Expected results:

Keeping the ws open, and receiving the data as expected.

Comment 1

[BugBot [:suhaib / :marco]]

The Bugbug bot thinks this bug should belong to the 'Core::Networking: WebSockets' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Comment 2

[Dragana Damjanovic [:dragana]]

Can you make a http log? The instruction to create a log are here.

Please use this list:
MOZ_LOG=timestamp,rotate:200,nsHttp:5,nsSocketTransport:5,nsHostResolver:5,nsWebSocket:5

The log may contain cookies and all url you are visiting, therefore I recommend to use a new profile and not to log into sites if possible. You can also send the log to me via email instead of attaching it to the bug.

Comment 3

[daemon]

Attachment: 20210707-fflog.zip

The FF network log as asked, removed some data from the log.

How did it go

0. Loading two tabs, same address(two separated WS for each) (3:35 PM EDT)
    a.  server accepts the requests, proper handshake and all good
1. Server pushes(first) some data (3:36 PM EDT)
    b. both ws got the message successfully, but mind no any received message by inspect element.
--(idle for 2 min)--
2. Server pushes another message (3:38 PM EDT)
    a. non of ws got the messages, no error in client so far
    b. server finds the ws peer as problem due to send-timeout, tries to close connections, ws sessions are not longer valid in server side.
    c. FF(both tabs) still thinks the ws instances are open, indicating idle state in inspect element
--(around 5 min later)--
3. FF still sees the ws instance idle and valid, since they are not
--(around 6 min later, 3:46 PM EDT)--
4. FF finds the ws instances invalid/closed, error code 1006.

---

During the test, there were two chrome client instances as well, they both got the messages properly, in time, no error.

Comment 4

[Kershaw Chang [:kershaw]]

From what I see from the log, at 2021-07-08 19:36 the websocket channel received something and then the socket returned a would block error.

2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::OnInputStreamReady() 21d3b000
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport nsSocketInputStream::Read [this=2273ee78 count=2048]
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport   calling PR_Read [count=2048]
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport   PR_Read returned [n=58]
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=2273ec00 status=804b0006]
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::OnInputStreamReady: read 58 rv 0
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::ProcessInput 21d3b000 [58 0]
2021-07-08 19:36:28.423000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::ProcessInput: payload 56 avail 56
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::ProcessInput: Frame accumulated - opcode 1
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::ProcessInput: received deflated frame
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel:: deflated text frame received
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel:: message successfully inflated [origLength=56, newLength=55]
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket Added new msg received for <<??DOMAIN??>>
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport nsSocketInputStream::Read [this=2273ee78 count=2048]
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport   calling PR_Read [count=2048]
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport   PR_Read returned [n=-1]
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Main Thread]: D/nsWebSocket WebSocketChannelParent::OnMessageAvailable() 311d99e0
2021-07-08 19:36:28.424000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::OnInputStreamReady: read 0 rv 80470007

After 10 mins, the socket was closed with NS_ERROR_NET_RESET.

2021-07-08 19:46:38.435000 UTC - [Parent 4540: Socket Thread]: D/nsWebSocket WebSocketChannel::OnInputStreamReady() 21d3b000
2021-07-08 19:46:38.435000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport nsSocketInputStream::Read [this=2273ee78 count=2048]
2021-07-08 19:46:38.435000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport   calling PR_Read [count=2048]
2021-07-08 19:46:38.435000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport   PR_Read returned [n=-1]
2021-07-08 19:46:38.435000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport ErrorAccordingToNSPR [in=-5961 out=804b0014]
2021-07-08 19:46:38.435000 UTC - [Parent 4540: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnMsgInputClosed [this=2273ec00 reason=804b0014]

It's not clear to me why Firefox didn't receive the second message from the server. Maybe a wireshark capture can help to clarify.

Comment 5

[daemon]

As soon as I find some time, I will do some more low-level logging. Not sure if it's even possible to log since it's secure(wss)

I tried more run, and each time vary results. But eventually, the timeout 1006:error will be there for FF only, very weird.

As I checked the server errors, I realized, sometimes FF gets the close-error on time, and sometimes very late(like 4 min later).

I'm still not sure if the underlying socket is closed by server once the close signal is sent(should be). Need to check that, but it seems FF sort of ignore listening for socket for a reason?! More like blocking IO mode.

Anyway thank you so much.
Code bliss us all!

Comment 6

[Kershaw Chang [:kershaw]]

Add a ni flag to indicate this bug is waiting for more information.

Comment 7

[daemon]

Sorry for delay, I've been too busy on developing.

But I could had some small tests as well.
As I thought server-related could be an issue, I also tried a low-level IO handling(better performance), over native(java), and still the same. Still no matter if one, or multiple tabs(websockets) are opened, suddenly so soon, or later the ws goes into idle mode, and same routine(error) as explained.

For recent late tests, FF v90.0.x were used, same error. I still could not repeat the error with chrome yet(same machine/OS as FF).

Thanks again, I really like this bug gets fixed(I hope it's not a FF bug), sorry I'm a little busy, but once I find some time for excessive debugging, I will do some dedicated IO networking, to see if I could find the issue eventually.

Comment 8

[Kershaw Chang [:kershaw]]

Keep the ni flag. We'll try to debug this when we have more information. Thanks.

Comment 9

[daemon]

Ok, so I just got a simple chat-like server-client coding, to see if I could simulate the error, and hopefully no, FF works very well so far for almost 1 hour.

So I'm kind of a little happy the issue could be related to my work in production, rather FF. I should have this test earlier before I open this bug, I'm really sorry.

The code: https://github.com/911992/jsr356_340

At the client-side, I use almost the same approach/logic as shared with the repo above, but server-side is a little more complicated. Still it's a mystery why only FF.

The deployment of the repo could be found at https://yorkee.xyz:17443/ (secure). It's running at the same production server.

I try to investigate at the server side soon, and I hope find something. Will update this bug as well.

Thank you again guys, have a wonderful day.
Code bliss us all.

Comment 10

[Valentin Gosu [:valentin]]

If I understand your previous comment correctly, the bug is still happening, right?

Comment 11

[daemon]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #10)

If I understand your previous comment correctly, the bug is still happening, right?

unfortunately true, and it's really interesting.

I'm really sorry, I'm too busy for at-least a month, but indeed I would like to perform a low-level network monitoring(as wireshark asked) as soon as I find a good free time.

Recently also tried both NIO and IO(blocking) data push from the server, /w, and /wo stream flushing, still same result.

Comment 12

[daemon]

Micro report
Recently I experienced the issue on localhost(devl env) as well, so it makes me worry now more.
No recieve of pushed message from server, while WS is still known as open in FF. (and yes, no issues with chrome yet, so I think server is kind of good)
FF v: 94.0.1, and 94.0.12
Once I find more free time, I will take more time on FF dedicatedly for sure.

Comment 13

[Kershaw Chang [:kershaw]]

I'll try to have a look.

Comment 14

[BugBot [:suhaib / :marco]]

Redirect a needinfo that is pending on an inactive user to the triage owner.
:dragana, since the bug has high priority, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 15

[Kershaw Chang [:kershaw]]

(In reply to Kershaw Chang [:kershaw] from comment #13)

I'll try to have a look.

Didn't have a change to look at this.
I think we can close this bug, since the reporter is inactive for a while and we don't have enough information to debug this.