PaperMC / PaperMC/Velocity

Possible edge case with duplicate logins causing disconnect to not fire until the original connection times out

Open
#1,727 3 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

type: bug
Dominant language
Java
Stars
2.3k
Forks
959
Avg merge
5d 10h
Merged PRs (30d)
2

Description

Expected Behavior

When a player logs in that is already logged in, the orginal connection should be disconnected correctly before connecting the player to the server again.

Actual Behavior

In rare cases with the duplicate_login event, if you time it correctly a second duplicate_login event is received from the server itself at the same time. This causes the original connection to be disconnected from the server but not from Velocity, and it's only 10-12 seconds later when the original connection times out in Velocity that the disconnect event is finally fired which then causes unexpected behavior with any plugin that does not expect this.

Steps to Reproduce

Players with high latency connections or otherwise poor connections have been the most impacted by this, as they're more likely to be disconnected and then try to reconnect before their previous connection has timed out.

I've been simulating that using a VPN to interrupt the client's connection to the server, disconnecting from the VPN and then reconnecting back to the server within 15 to 18 seconds in order for the previous connection to have not yet timed out on either Velocity or Paper.

Actually timing this correctly is tricky but I've discussed it extensively on https://github.com/NEZNAMY/TAB/issues/1611 and have reliably reproduced this now dozens of times both with plugins and with no plugins on either Velocity or Paper.

You know you've triggered it when you see the following sequence of events where the duplicate_login is recognized by Velocity twice due to being also recognized by Paper.

Log entries from Velocity and Paper for one of times that I was able to trigger this:

[22:28:43 INFO]: [server connection] Odin__AllFather -> survival has connected
[22:29:10 INFO]: [connected player] Odin__AllFather (/...:62847) has connected
[22:29:10 INFO]: [connected player] Odin__AllFather (/...:55974) has disconnected: multiplayer.disconnect.duplicate_login
[22:29:10 INFO]: [server connection] Odin__AllFather -> survival has connected
[22:29:10 INFO]: [connected player] Odin__AllFather (/...:55974): kicked from server survival: multiplayer.disconnect.duplicate_login
[22:29:10 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[22:29:10 INFO]: [connected player] Odin__AllFather (/...:55974) has disconnected: You were kicked from survival: multiplayer.disconnect.duplicate_login
[22:29:38 INFO]: [connected player] Odin__AllFather (/...:55974) has disconnected: An internal error occurred in your connection.
[22:29:38 ERROR]: [connected player] Odin__AllFather (/...:55974): read timed out

Log entries from Paper:
[22:28:46 INFO]: Odin__AllFather[/...:49006] logged in with entity id 890 at ([world]292.5046250253844, 74.0, 408.6292741456509)
[22:29:10 INFO]: UUID of player Odin__AllFather is 5de43472-a66c-4190-9ac7-6c12f6e87d91
[22:29:10 INFO]: Odin__AllFather lost connection: You logged in from another location
[22:29:10 INFO]: Odin__AllFather left the game
[22:29:12 INFO]: Odin__AllFather joined the game
[22:29:12 INFO]: Odin__AllFather[/...:50254] logged in with entity id 1069 at ([world]292.5046250253844, 74.0, 408.6292741456509)

Plugin List

[10:33:44 INFO]: Plugins: velocity, tab, velocity-logger

NOTE: I'm aware that the logs I've shown at times include TAB and a custom velocity logger, but that's purely for visibility of event sequencing. The underlying duplicate login and delayed / belated timeout behavior can also be reliably produced when there is no plugins present at all.

Velocity Version

[10:29:43 INFO]: Velocity 3.5.0-SNAPSHOT (git-7e01491e-b574)

Additional Information

https://mclo.gs/7MDizAq

Added some extra logging of the Velocity player events and it shows two things in particular, one apparent and one not just from reading the log.

The first is that the original connection is never explicitly disconnected, and instead it times out when the 30 second Velocity timeout expires at 19:12:57 approximately 10 seconds after the player was reconnected to the server again at 19:12:47.

The second is less obvious but the last two entries that show the timestamp 19:12:57 didn't actually appear in the log at the same time as the other entries above it, and only appeared approximately 10 seconds later despite having the same timestamp.

Looking through other issues, it's possible that there is could be related to (or at least similar to) issues reported in https://github.com/PaperMC/Velocity/issues/1696 and in https://github.com/PaperMC/Velocity/issues/1013

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by tracing duplicate_login handling and the connection timeout/disconnect event sequence in Velocity, using the reported VPN timing and logs to reproduce the race. Done should mean the original connection is disconnected promptly and its disconnect event is emitted without waiting for the timeout, including when duplicate_login is received twice.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
backend, networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
42/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.