search

spring / uberserver

uberserver, a matchmaking/chat lobby server for the spring rts project
https://springrts.com/wiki/Uberserver
Other
33 stars 38 forks source link

Slow (>10sec) to connect #363

Closed rosscosack closed 4 years ago

rosscosack commented 4 years ago

Uberserver on BAR server (road-flag.bnr.la) is slow to accept user connection attempt from springlobby (only; Chobby is immediate). Log shows uberserver acknowledges connection attempt immediately (when tailed), then in this instance there is a 24 sec delay until connection

2020-01-07 21:24:00 INFO  Protocol._new:280  [7] Client connected from <IP>:51086
2020-01-07 21:24:24 INFO  Protocol._SendLoginInfo:1039  [7] <rossco> logged in (access=admin).

Full Log

delay as reported by SL is (in this instance) 14sec (has been approx 26 often lately)

[20:16:45] ** Server ** Connecting to server road-flag.bnr.la:8200...
[20:16:59] ** Server ** Connected to road-flag.bnr.la:8200.

There seems to be an issue with my implementation of uberserver; connections to the BA server springfightclub and official server happen immediately.

Network lag is not an issue, there is very little lag from player to host (host is on same server as uberserver)

I have tried several different versions of uberserver, currently I'm on a258db83 and I have tried release 0.38 1fa86d61

I tried creating server.key certification (although it isn't mentioned in the docs) using certificate.py and it didn't fix it.

SSL has me the most suspicious, it is possible I have done something wrong here and it is not a uberserver problem but am unsure how to proceed.

abma commented 4 years ago

atm i can only guess: is dns configured probably at the server?

i.e. reverse lookups work correct?

rosscosack commented 4 years ago

I think so, ping road-flag and road-flag.bnr.la resolve immediately from the server and client. Is this what you mean by reverse lookup?

abma commented 4 years ago

reverse lookup is i.e.: "dig -x 185.143.163.228"

should return immediately sth. like that: ;; ANSWER SECTION: 228.163.143.185.in-addr.arpa. 86245 IN PTR 185.143.163.228.r.toneticgroup.pl.

is the load on the server maybe high? i.e. db access could lead to delays, too if the server is swapping.

"free -m" is your friend

from the logfile some logins seems instant, i.e.:

2020-01-07 01:54:04 INFO Protocol._new:280 [19] Client connected from .... 2020-01-07 01:54:05 INFO Protocol._SendLoginInfo:1039 [19] <...> logged in (access=user).

are you using sqlite or mysql as db backend?

abma commented 4 years ago

just some other guess:

64 bytes from road-flag.bnr.la (112.213.34.51): icmp_seq=30 ttl=51 time=316 ms

is the server connected via some DSL/Cable/WiFi connection? the latency is very high. or is it just in a country far away from here? :-)

when a client connects a lot of packets are sent in both directions: this could explain the delay.

i.e. 30 * 300 ms are already 9 seconds delay. idk how many packets are sent to connect, but IMHO a lot:

some incomplete list tcp handshake 3 server greeting 2 (TASServer ... + ACK) STLS maybe 10 LOGIN 2 LOGININFO maybe 40 USERLIST maybe 30

its not this easy, as i.e. the tcp window size heavily influences this. but this maybe gives an idea whats the reason for the delay.

abma commented 4 years ago

road-flag.bnr.la seems to use TLS 1.3 vs springrts.com TLS 1.2.

idk what changed with TLS 1.3, maybe some new bug?!

maybe the server has to few entropy available, maybe it blocks because of that?

output of dmesg maybe gives a hint.

rosscosack commented 4 years ago

Dig response is fine 

;; ANSWER SECTION:
51.34.213.112.in-addr.arpa. 43102 IN    PTR road-flag.bnr.la.

free -m

              total        used        free      shared  buff/cache   available
Mem:            733         281         220           5         231         329
Swap:             0           0           0

Regarding the immediate connections, this could be from Chobby - Chobby is immediate (which make me think there are no server performance issues)

Using a mysql db

the server is in Australia (as am I), there does not appear to be network issues, when I connect to springfightclub in US it's immediate

rosscosack commented 4 years ago

road-flag.bnr.la seems to use TLS 1.3 vs springrts.com TLS 1.2.

idk what changed with TLS 1.3, maybe some new bug?!

maybe the server has to few entropy available, maybe it blocks because of that?

output of dmesg maybe gives a hint.

I think you are right dmesg.txt

rosscosack commented 4 years ago

Are you able to determine the version of springfightclub.com:8200 or tell me how because if it's TLS 1.2 then this would firm up that this is our issue

rosscosack commented 4 years ago

Disabling UFW did not work, I mis-read the dmesg log, it's just the firewall

[09:08:25] ** Server ** Connecting to server road-flag.bnr.la:8200...
[09:08:40] ** Server ** Connected to road-flag.bnr.la:8200.
rosscosack commented 4 years ago

springfightclub is TLS 1.2 so I think this is the issue. The version at road-flag is from the latest ubuntu archives, should look into how to downgrade or should springlobby be updated?

rosscosack commented 4 years ago

installing libssl-dev NOT fix it

The following packages will be REMOVED:
  libcurl-openssl1.0-dev libssl1.0-dev
The following NEW packages will be installed:
  libssl-dev
silentwings commented 4 years ago

Perhaps worth noting that Chobby does not use TLS when it connects. This is the only relevent difference I can think of between Chobby/SL connections.

rosscosack commented 4 years ago

makes sense thanks

rosscosack commented 4 years ago

Could SL be waiting for a timeout before trying TLS 1.3 OR uberserver waits for a TLS1.3 timeout before accepting TLS 1.2?

silentwings commented 4 years ago

An idea:

turn on the debug prints at https://github.com/spring/uberserver/blob/master/Client.py#L126 https://github.com/spring/uberserver/blob/master/Client.py#L219 and use the latest commit (in which i added timing info to them), then get a server.log of the delay happening and post that here.

Seeing the times at which the various commands are being sent may show if TLS is to blame or not.

Also, turn them off afterwards, they will spew info into the logfile.

silentwings commented 4 years ago

Result of doing the above on my local uberserver (but airbnb wifi...) is here uberserver: https://pastebin.com/KKYFFKd9. SpringLobby: https://pastebin.com/bLeQPaU6

It shows a delay after uberserver sends (the second) TASSERVER in response to STLS. Springlobby then sits and wait for approx 25 secs until SpringLobby sends a PING and only then does SpringLobby send a LOGIN

Note that >PONG appears before <LOGIN because the uberserver log is viewed from the server side in processed order of commands; in fact SpringLobby is almost certainly sending the LOGIN immediately after the PING (and not in response to the PONG)

I checked afterwards that Uberservers Chat.transport.StartTLS() function completes basically instantly in response to STLS and before (the second) TASSERVER is sent. This suggests to me that the TLS connection is already complete at this point?

So: maybe SL is basically forgetting to send LOGIN, for some reason related to the TLS 1.3 setup, and then somehow sending PING makes it remember.

It's using TLS1.3, but when I connect to springrts.com it uses TLS1.2 (and there is no delay).

silentwings commented 4 years ago

Note that sending TASSERVER twice is not a bug https://springrts.com/dl/LobbyProtocol/ProtocolDescription.html#STLS:client

edit: replaced previous post, was incorrect

abma commented 4 years ago

could be this: https://github.com/openssl/openssl/issues/7327

abma commented 4 years ago

meh, seems to be a bug in springlobby, the test client instantly returns "PONG" when using tls1.3:

https://github.com/spring/uberserver/commit/5ff6ffe11f4511486d7eec068518b669e128ac87