Sdk: dart:io websocket readyState / closeCode / closeReason doesn't changed after connection failed or closed

[nailgilaziev]

Dart VM version: 1.24.3 (Wed Dec 13 23:26:59 2017) on "macos_x64"
dart:io used for Flutter, but I think is a general problem.

Background info:
App sends string messages to echo server and displays returned response.
WebSocket configured to send Ping Pong Messages.
All works fine - messages sended and received.
To emulate bad network conditions I use Apple Network Link Conditioner with 100% packet loss profile.
full code snippet for flutter here - https://pastebin.com/wLfAkS5N

UPD: updated code available in comment below

---

Problem is next:
Firstly, with good network conditions we are succesfully connected to our ws server. ws is connected and messages sended and received fine.
If we print now

print("ws ready state = ${ws.readyState}");
print("ws close code = ${ws.closeCode}");

we saw this:

ws ready state = 1
ws close code  = null

After we are switch our network to 100% packet loss profile.
Because we already configured ws heartbit by ws.pingInterval = new Duration(seconds: 10);
in some point in future we get an error in this callback:

ws.done.then((v) {
          setState(() {
            ex = new Exception("Connection is done with v=$v");
            print("DONE");
          });
        });

But ws ready state and close code is not changed!!!

ws ready state = 1
ws close code  = null

[ivk1800]

The issue is that the connection is not immediately closed if pong not received, but after a short delay. The question is, why do we need a ping interval, if it is useless?

[nailgilaziev]

in this flutter/issue another case when ready state and close code is't change

[nailgilaziev]

Another observation: (I run code on iOS)
1) ws connection established
2) data go up and down - all is ok
3) switch on Network Link Conditioner with 100% loss profile
4) after ~ping pong period ws.done.then called
5) we see that readyState and closeCode doesn't changed to proper values (topic of this issue)
6) but if we wait for a long time (sometimes 4 minutes, sometimes faster, sometimes longer) we see that ws.listen.onDone called! Currently is took a ~9 min to happen! (19:31:50 - 19:40:33)

Logs

flutter: 2019-07-01 19:30:57.758862   connect to ws://echo.websocket.org requested
flutter: 2019-07-01 19:30:58.612289   connect successfully established
flutter: 2019-07-01 19:31:11.430809   sended hi
flutter: 2019-07-01 19:31:11.738323   ws.listen received = hi
flutter: 2019-07-01 19:31:50.085875   ws.done.then with details:
readyState:1 closeCode:null closeReason:null
flutter: 2019-07-01 19:40:33.174776   ws.listen.onDone called. ws state is:
readyState:1 closeCode:1001 closeReason:null

Code for reproducing issue:

• you can run a year old code from body of this issue
• or can use code that I rewrite today for this logs. code

Flutter 1.7.12-pre.43 • channel master • https://github.com/flutter/flutter.git
Framework • revision ddd5ccd011 (3 hours ago) • 2019-07-01 08:28:34 -0700
Engine • revision e96900df2f
Tools • Dart 2.4.0
MacOS Mojave 10.14.5 (18F203)
iPhone 6 plus 12.3.1

[nailgilaziev]

Something similar (long waiting time before event) happens too when writing to a dead websocket.
Issue description available here - https://github.com/dart-lang/web_socket_channel/issues/62
Issue occurred when using websocketchannel package but I think it reproducible even in pure dart.io so maybe it is interconnected

[nailgilaziev]

@sortie please pay attention to this one-year old issue as one of the maintainer of dart:io.
I spent a lot of time to find out how mature is the implementation of websockets in flutter / dart one year ago and nowadays. But things not moving on... for this last year.
Main question: is it possible to use it in flutter production, where we will meet with an unstable connection, and other cases with mobile/wifi networks and switсhing between them. In this case we need to build reliable connection mechanism that can work at that environment.
While testing I found a lot of behaviour which does not work in the best way.
I report issues and think that they all intersect with each other. Some issues references to each other, some of them no.

Thanks a lot for your time!

[fzyzcjy]

@nailgilaziev Hi is it mature enough now (after half a year again) to be used for production environment, which needs very strong reliability? Thanks!

[sortie]

@ZichangG Might you want to take a look at this issue? I personally rely on the dart:io WebSocket implementation, would be good to get any unreliability fixed.

[fzyzcjy]

@sortie @ZichangG Thanks very much!

[zichangg]

@nailgilaziev
I landed a change about a month ago. https://github.com/dart-lang/sdk/commit/d8f5ca49c5a899356e641bdfa0a1ac171ec60db6

With that change, the closeCode should be updated whenever pingpong heartbeats fail.

I'll fix the readyState part later.

[zichangg]

@nailgilaziev Can you do a verification on your side? Since last update was a year ago.

[nailgilaziev]

I can confirm, that now closeCode behaves as expected!

[nailgilaziev]

only one moment: when you manually close connection the ws.done.then callback doesn't get closeCode

flutter: 2020-04-18 12:20:51.346183   manual disconnect pressed
flutter: 2020-04-18 12:20:51.374499   ws.done.then with details:
readyState:1 closeCode:null closeReason:null                   <<<<<HERE
flutter: 2020-04-18 12:20:51.375108   ws closed successfully
flutter: 2020-04-18 12:20:51.630410   ws.listen.onDone called. ws state is:
readyState:3 closeCode:1000 closeReason:bye

try with this flutter code(same as year ago)

[nailgilaziev]

another good news, that strange behaviour described above is gone

Another observation: (I run code on iOS)

1. ws connection established
2. data go up and down - all is ok
3. switch on Network Link Conditioner with 100% loss profile
4. after ~ping pong period ws.done.then called
5. we see that readyState and closeCode doesn't changed to proper values (topic of this issue)
6. but if we wait for a long time (sometimes 4 minutes, sometimes faster, sometimes longer) we see that ws.listen.onDone called! Currently is took a _~9 min_ to happen! (19:31:50 - 19:40:33)

Logs

flutter: 2019-07-01 19:30:57.758862   connect to ws://echo.websocket.org requested
flutter: 2019-07-01 19:30:58.612289   connect successfully established
flutter: 2019-07-01 19:31:11.430809   sended hi
flutter: 2019-07-01 19:31:11.738323   ws.listen received = hi
flutter: 2019-07-01 19:31:50.085875   ws.done.then with details:
readyState:1 closeCode:null closeReason:null
flutter: 2019-07-01 19:40:33.174776   ws.listen.onDone called. ws state is:
readyState:1 closeCode:1001 closeReason:null

currently no ~9 min lag before ws.listen.onDone callback called.
Calling order of ws.done.then and ws.listen.onDone changed, but now no lag, it executes immediatelly

flutter: 2020-04-18 12:27:21.885556   connect to ws://echo.websocket.org requested
flutter: 2020-04-18 12:27:22.428586   connect successfully established
flutter: 2020-04-18 12:27:31.077906   sended hi
flutter: 2020-04-18 12:27:31.332716   ws.listen received = hi
<<<<100% loss profile activated here>>>>
flutter: 2020-04-18 12:28:03.009949   ws.listen.onDone called. ws state is:
readyState:1 closeCode:1001 closeReason:null
flutter: 2020-04-18 12:28:03.012706   ws.done.then with details:
readyState:1 closeCode:1001 closeReason:null

[nailgilaziev]

I do a big testing in flutter repository with ws and maybe results will be intested here https://github.com/flutter/flutter/issues/35272#issuecomment-615840192

[zichangg]

only one moment: when you manually close connection the ws.done.then callback doesn't get closeCode

flutter: 2020-04-18 12:20:51.346183   manual disconnect pressed
flutter: 2020-04-18 12:20:51.374499   ws.done.then with details:
readyState:1 closeCode:null closeReason:null                   <<<<<HERE
flutter: 2020-04-18 12:20:51.375108   ws closed successfully
flutter: 2020-04-18 12:20:51.630410   ws.listen.onDone called. ws state is:
readyState:3 closeCode:1000 closeReason:bye

try with this flutter code(same as year ago)

I don't have a flutter set up at home to reproduce. I guess this is because the done is returned earlier than CloseCode being updated.
Close() will set up a 5 secs timer to update CloseCode and immediately close the underlying sink. Once sink is closed, done should be returned but it is possibly CloseCode is not updated.