Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ClientWebsocket KeepAliveInterval keeps spawning more keep alive messages in some cases #69684

Closed
JKorf opened this issue May 23, 2022 · 2 comments
Closed

ClientWebsocket KeepAliveInterval keeps spawning more keep alive messages in some cases #69684

JKorf opened this issue May 23, 2022 · 2 comments
Assignees
@CarnaViire
Labels
area-System.Net
Milestone
7.0.0

Comments

@JKorf
Copy link

JKorf commented May 23, 2022 •
edited
Loading

Description

Creating a websocket connection to a websocket server with the KeepAliveInterval option set will start sending increasingly more ping message over time, resulting in using more and more network capacity.
Even though the amount of messages can be very low, the network usage will increase to use up multiple mbits of up/download speed, while nothing is being actively send and receive is only a few bytes every second.
A lower KeepAliveInterval, say 1 second, will show the issue faster, though it is also present at intervals of 1 minutes.

Maybe related: #65998, another KeepAliveInterval issue

Reproduction Steps

Create a ClientWebSocket, connect to server and watch network usage. See gist and wireshark logs. Issue is not present on all server implementations

Gist to reproduce: https://gist.github.com/JKorf/0c7789dce19e3639ece83db737c227a0

Wireshark logs: keepalive-full.zip

Expected behavior

The KeepAliveInterval should correctly send 1 ping message per timestamp, no more

Actual behavior

Increasingly more ping messages are send, eating up all network

Regression?

No response

Known Workarounds

Setting KeepAliveInterval to TimeSpan.Zero will fix the issue, network usage is stable.

Configuration

Dotnet 6
Windows 10,
x64

Other information

No response
@ghost ghost added the untriaged New issue has not been triaged by the area owner label May 23, 2022
@dotnet-issue-labeler dotnet-issue-labeler bot added area-System.Net and removed untriaged New issue has not been triaged by the area owner labels May 23, 2022
@ghost
Copy link

ghost commented May 23, 2022

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

Description

Creating a websocket connection to a websocket server with the KeepAliveInterval option set will start sending increasingly more ping message over time, resulting in using more and more network capacity.
Even though the amount of messages can be very low, the network usage will increase to use up multiple mbits of up/download speed, while nothing is being actively send and receive is only a few bytes every second.
A lower KeepAliveInterval, say 1 second, will show the issue faster, though it is also present at intervals of 1 minutes.

Maybe related: #65998, another KeepAliveInterval issue

Reproduction Steps

Create a ClientWebSocket, connect to server and watch network usage. See gist and wireshark logs.

Gist to reproduce: https://gist.github.com/JKorf/0c7789dce19e3639ece83db737c227a0

Wireshark logs: keepalive-full.zip

Expected behavior

The KeepAliveInterval should correctly send 1 ping message per timestamp, no more

Actual behavior

Increasingly more ping messages are send, eating up all network

Regression?

No response

Known Workarounds

Setting KeepAliveInterval to TimeSpan.Zero will fix the issue, network usage is stable.

Configuration

Dotnet 6
Windows 10,
x64

Other information

No response

Author: JKorf
Assignees: -
Labels:

area-System.Net
Milestone: -

@MihaZupan MihaZupan added the untriaged New issue has not been triaged by the area owner label Jun 6, 2022
@CarnaViire
Copy link
Member

Thanks for the repro, @JKorf. However, as I've suspected, and it's the server which is spamming us with PINGs -- and per protocol, we have to respond. Nothing we can do about it, sorry. Closing.

some logs... 
  [15:55:26.7698944] START
  Sending 65
  Send done
  Received data in 197: {"topic":"realtimes","event":"sub","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"code":"0","msg":"Success"}
  [15:55:27.7830537] SEND KEEPALIVE PONG
  [15:55:27.9551362] RECEIVED PING, REPLY PONG
  [15:55:28.1236731] RECEIVED PING, REPLY PONG
  [15:55:28.2909969] RECEIVED PING, REPLY PONG
  [15:55:28.4587206] RECEIVED PING, REPLY PONG
  [15:55:28.6269221] RECEIVED PING, REPLY PONG
  [15:55:28.7809450] SEND KEEPALIVE PONG
  [15:55:28.7949109] RECEIVED PING, REPLY PONG
  [15:55:28.9497424] RECEIVED PING, REPLY PONG
  [15:55:28.9632245] RECEIVED PING, REPLY PONG
  Received data in 2073: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819729706,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21537.69","v":"5623.324661","qv":"116626760.37996042","m":"0.049
  "}}
  Received data in 23: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819729729,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21539.74","v":"5623.520136","qv":"116630970.65563692","m":"0.0491"
  }}
  Received data in 8: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819729729,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21539.74","v":"5623.520136","qv":"116630970.65563692","m":"0.0491"}
  }
  Received data in 30: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819729768,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21537.69","v":"5623.620136","qv":"116633124.42463692","m":"0.049"}
  }
  [15:55:29.1174208] RECEIVED PING, REPLY PONG
  [15:55:29.1310565] RECEIVED PING, REPLY PONG
  Received data in 110: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819729878,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21537.69","v":"5623.626945","qv":"116633271.07476813","m":"0.049"
  }}
  Received data in 30: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819729910,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21537.69","v":"5623.720136","qv":"116635278.19363692","m":"0.049"}
  }
  [15:55:29.2861843] RECEIVED PING, REPLY PONG
  [15:55:29.2986394] RECEIVED PING, REPLY PONG
  [15:55:29.4545640] RECEIVED PING, REPLY PONG
  [15:55:29.4671085] RECEIVED PING, REPLY PONG
  [15:55:29.6245318] RECEIVED PING, REPLY PONG
  [15:55:29.6352047] RECEIVED PING, REPLY PONG
  [15:55:29.7817946] SEND KEEPALIVE PONG
  [15:55:29.7927434] RECEIVED PING, REPLY PONG
  [15:55:29.8022870] RECEIVED PING, REPLY PONG
  Received data in 680: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819730587,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21546.89","v":"5623.721819","qv":"116635314.45705279","m":"0.0494
  "}}
  [15:55:29.9503227] RECEIVED PING, REPLY PONG
  [15:55:29.9603176] RECEIVED PING, REPLY PONG
  [15:55:29.9698562] RECEIVED PING, REPLY PONG
  [15:55:30.1197573] RECEIVED PING, REPLY PONG
  [15:55:30.1279133] RECEIVED PING, REPLY PONG
  [15:55:30.1372891] RECEIVED PING, REPLY PONG
  [15:55:30.2877357] RECEIVED PING, REPLY PONG
  [15:55:30.3002947] RECEIVED PING, REPLY PONG
  [15:55:30.3059437] RECEIVED PING, REPLY PONG
  [15:55:30.4559086] RECEIVED PING, REPLY PONG
  [15:55:30.4681479] RECEIVED PING, REPLY PONG
  [15:55:30.4736605] RECEIVED PING, REPLY PONG
  [15:55:30.6232047] RECEIVED PING, REPLY PONG
  [15:55:30.6348822] RECEIVED PING, REPLY PONG
  [15:55:30.6408279] RECEIVED PING, REPLY PONG
  Received data in 841: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819731433,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21538.34","v":"5623.763419","qv":"116636210.45199679","m":"0.049"
  }}
  [15:55:30.7804564] SEND KEEPALIVE PONG
  [15:55:30.7926465] RECEIVED PING, REPLY PONG
  [15:55:30.8023586] RECEIVED PING, REPLY PONG
  [15:55:30.8079447] RECEIVED PING, REPLY PONG
  [15:55:30.9483703] RECEIVED PING, REPLY PONG
  [15:55:30.9613593] RECEIVED PING, REPLY PONG
  [15:55:30.9701522] RECEIVED PING, REPLY PONG
  [15:55:30.9753940] RECEIVED PING, REPLY PONG
  [15:55:31.1162597] RECEIVED PING, REPLY PONG
  [15:55:31.1295627] RECEIVED PING, REPLY PONG
  [15:55:31.1379035] RECEIVED PING, REPLY PONG
  [15:55:31.1432346] RECEIVED PING, REPLY PONG
  [15:55:31.2847489] RECEIVED PING, REPLY PONG
  [15:55:31.2971008] RECEIVED PING, REPLY PONG
  [15:55:31.3058450] RECEIVED PING, REPLY PONG
  [15:55:31.3110232] RECEIVED PING, REPLY PONG
  [15:55:31.4519641] RECEIVED PING, REPLY PONG
  [15:55:31.4654209] RECEIVED PING, REPLY PONG
  [15:55:31.4745139] RECEIVED PING, REPLY PONG
  [15:55:31.4790546] RECEIVED PING, REPLY PONG
  [15:55:31.6195584] RECEIVED PING, REPLY PONG
  [15:55:31.6336026] RECEIVED PING, REPLY PONG
  [15:55:31.6415283] RECEIVED PING, REPLY PONG
  [15:55:31.6467846] RECEIVED PING, REPLY PONG
  [15:55:31.7787404] SEND KEEPALIVE PONG
  [15:55:31.7877886] RECEIVED PING, REPLY PONG
  [15:55:31.8016792] RECEIVED PING, REPLY PONG
  [15:55:31.8087433] RECEIVED PING, REPLY PONG
  [15:55:31.8145726] RECEIVED PING, REPLY PONG
  [15:55:31.9472938] RECEIVED PING, REPLY PONG
  [15:55:31.9553551] RECEIVED PING, REPLY PONG
  [15:55:31.9693061] RECEIVED PING, REPLY PONG
  [15:55:31.9758790] RECEIVED PING, REPLY PONG
  [15:55:31.9864189] RECEIVED PING, REPLY PONG
  Received data in 1324: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819732755,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21546.77","v":"5623.777346","qv":"116636510.53386258","m":"0.049
  4"}}
  [15:55:32.1149637] RECEIVED PING, REPLY PONG
  [15:55:32.1225874] RECEIVED PING, REPLY PONG
  [15:55:32.1373058] RECEIVED PING, REPLY PONG
  [15:55:32.1438077] RECEIVED PING, REPLY PONG
  [15:55:32.1548049] RECEIVED PING, REPLY PONG
  [15:55:32.2828510] RECEIVED PING, REPLY PONG
  [15:55:32.2907694] RECEIVED PING, REPLY PONG
  [15:55:32.3042072] RECEIVED PING, REPLY PONG
  [15:55:32.3179593] RECEIVED PING, REPLY PONG
  [15:55:32.3221338] RECEIVED PING, REPLY PONG
  [15:55:32.4501157] RECEIVED PING, REPLY PONG
  [15:55:32.4591459] RECEIVED PING, REPLY PONG
  [15:55:32.4711155] RECEIVED PING, REPLY PONG
  [15:55:32.4855484] RECEIVED PING, REPLY PONG
  [15:55:32.4895790] RECEIVED PING, REPLY PONG
  [15:55:32.6182524] RECEIVED PING, REPLY PONG
  [15:55:32.6264808] RECEIVED PING, REPLY PONG
  [15:55:32.6390955] RECEIVED PING, REPLY PONG
  [15:55:32.6535340] RECEIVED PING, REPLY PONG
  [15:55:32.6563269] RECEIVED PING, REPLY PONG
  [15:55:32.7755317] SEND KEEPALIVE PONG
  [15:55:32.7860676] RECEIVED PING, REPLY PONG
  [15:55:32.7937159] RECEIVED PING, REPLY PONG
  [15:55:32.8064649] RECEIVED PING, REPLY PONG
  Received data in 721: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819733478,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21536.53","v":"5623.824076","qv":"116637516.93590948","m":"0.0489
  "}}
  Received data in 0: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819733478,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21536.53","v":"5623.824076","qv":"116637516.93590948","m":"0.0489"}
  }
  [15:55:32.8209799] RECEIVED PING, REPLY PONG
  [15:55:32.8238002] RECEIVED PING, REPLY PONG
  Received data in 20: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819733499,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21536.53","v":"5623.824083","qv":"116637517.08666519","m":"0.0489"
  }}
  Received data in 3: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819733501,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21534.35","v":"5623.889083","qv":"116638916.81941519","m":"0.0488"}
  }
  [15:55:32.9443047] RECEIVED PING, REPLY PONG
  [15:55:32.9532734] RECEIVED PING, REPLY PONG
  [15:55:32.9616202] RECEIVED PING, REPLY PONG
  [15:55:32.9741764] RECEIVED PING, REPLY PONG
  [15:55:32.9886738] RECEIVED PING, REPLY PONG
  [15:55:32.9908900] RECEIVED PING, REPLY PONG
  [15:55:33.1120700] RECEIVED PING, REPLY PONG
  [15:55:33.1214306] RECEIVED PING, REPLY PONG
  [15:55:33.1301183] RECEIVED PING, REPLY PONG
  [15:55:33.1415664] RECEIVED PING, REPLY PONG
  Received data in 314: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819733816,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21532.23","v":"5623.954083","qv":"116640316.41436519","m":"0.0487
  "}}
  [15:55:33.1564558] RECEIVED PING, REPLY PONG
  [15:55:33.1581876] RECEIVED PING, REPLY PONG
  [15:55:33.2799033] RECEIVED PING, REPLY PONG
  [15:55:33.2900631] RECEIVED PING, REPLY PONG
  [15:55:33.2982994] RECEIVED PING, REPLY PONG
  [15:55:33.3091060] RECEIVED PING, REPLY PONG
  [15:55:33.3256319] RECEIVED PING, REPLY PONG
  [15:55:33.3265226] RECEIVED PING, REPLY PONG
  [15:55:33.4479450] RECEIVED PING, REPLY PONG
  [15:55:33.4585086] RECEIVED PING, REPLY PONG
  [15:55:33.4662512] RECEIVED PING, REPLY PONG
  [15:55:33.4766301] RECEIVED PING, REPLY PONG
  [15:55:33.4932794] RECEIVED PING, REPLY PONG
  [15:55:33.4941323] RECEIVED PING, REPLY PONG
  [15:55:33.6165031] RECEIVED PING, REPLY PONG
  [15:55:33.6264475] RECEIVED PING, REPLY PONG
  [15:55:33.6333824] RECEIVED PING, REPLY PONG
  [15:55:33.6449429] RECEIVED PING, REPLY PONG
  [15:55:33.6612251] RECEIVED PING, REPLY PONG
  [15:55:33.6613832] RECEIVED PING, REPLY PONG
  Received data in 616: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819734432,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21532.22","v":"5623.970323","qv":"116640666.09761799","m":"0.0487
  "}}
  Received data in 0: {"topic":"realtimes","params":{"symbol":"BTCUSDT","symbolName":"BTCUSDT"},"data":{"t":1655819734432,"s":"BTCUSDT","o":"20531.7","h":"21600","l":"19836.34","c":"21532.22","v":"5623.970323","qv":"116640666.09761799","m":"0.0487"}
  }
  [15:55:33.7747807] SEND KEEPALIVE PONG
  [15:55:33.7849253] RECEIVED PING, REPLY PONG
  [15:55:33.7939819] RECEIVED PING, REPLY PONG
  [15:55:33.8002932] RECEIVED PING, REPLY PONG

P.S.:

Setting KeepAliveInterval to TimeSpan.Zero will fix the issue, network usage is stable.

This is interesting, it seems that the server is reacting strangely to receiving unsolicited PONG -- even though it is perfectly valid per RFC https://datatracker.ietf.org/doc/html/rfc6455#section-5.5.3. I suggest raising an issue to the server, if it's possible.

P.P.S.:

Linking other issue, that may allow to change from unsolicited PONG to PING-PONG behavior just in case... #48729

@ghost ghost removed the untriaged New issue has not been triaged by the area owner label Jun 21, 2022
@karelz karelz added this to the 7.0.0 milestone Jul 19, 2022
@ghost ghost locked as resolved and limited conversation to collaborators Aug 18, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@CarnaViire CarnaViire

Labels
area-System.Net
Projects
None yet
Milestone
7.0.0
Development

No branches or pull requests
4 participants
@CarnaViire @karelz @JKorf @MihaZupan