Players are sometimes invisible when logging back in after a timeout

[CC-Odin]

Server version

Velocity 3.5.0-SNAPSHOT (git-7e01491e-b574) & Paper version 1.21.11-110

TAB version

5.5.0

Plugin list

Have reproduced with each of the following in a test environment with no other plugins installed:

• TAB-v5.4.0
• TAB-v5.5.0
• TAB-6.0.0-SNAPSHOT+2008

Describe the bug

Have been trying to pin this down since at least October where under very specific circumstances players can end up in this pseudo-spectator or "ghost" mode as players on the server have been calling it.

the requirements are very specific:

• it only occurs when the previous connection is in the process of timing out but has not yet done so
• it requires triggering a duplicate login error in both Velocity and Paper
• i'm reasonably certain that the player needs to be in unloaded chunks with no other players nearby when logging back in (or at least that's the only time I've seen it trigger)
• the tablist for that player won't show any headers, footers or server name details when in this state
• the tablist for that player may show them in spectator (but not always)
• the tablist for any other player will not show the player once triggered, but sometimes they will briefly appear in the tablist after logging back in before they disappear
• once triggered, any currently logged in player won't be able to see them but any new players connecting to the server after that will

Expected behavior

Players should not be in ghost mode : )

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.

Additional info

Log entries from Velocity for the most recent time I triggered 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)

The following screenshots show the progression of the player being in ghost mode and how the tab list is broken in various ways as both players progressively relog.

• Odin's view in ghost mode
  

• DungeonLackey's view while Odin is in ghost mode
  

• DungeonLackey's view after relogging (note that Odin's server description is missing)
  

• DungeonLackey's view after Odin relogs as well
  

Checklist

• I am running latest version of the plugin
• I have read the wiki to make sure it's not an issue with configuration
• I ticked all of the boxes without actually reading them
• I have read the Compatibility wiki page and am not trying to run the plugin on an unsupported server version / platform
• I am willing to cooperate to get this issue resolved faster, including providing any additional information requested or testing new builds

[NEZNAMY]

Are you sure TAB is causing this issue? Version 5.4.0 was only using Velocity API, not even any internals. Could it be linked to a specific feature, such as global palyerlist? Can you try with all features disabled in the config? If it still keeps happening, try adding pipeline-injection: false into your config and try again (this functionality was added on velocity in 5.5.0).

[CC-Odin]

WIll do some more testing and see if I can still reproduce it without TAB, but so far I hadn't been able to do that.

It's worth noting that there is often the case that after reconnecting both players are initially shown in the tab list, and then it's only after a subsequent delay that the user logging back in disappears. Looking at the log examples I provided, you can see there is a 28 second delay between the duplicate login kick message at 22:29:10 and then a subsequent disconnected and read timeout at 22:29:38.

Like I said it is hard to trigger this, but is it possible that with this specific sequence of events when the original connection is being torn down due to the duplicate login that TAB is actually cleaning up the new login instead when the subsequent disconnect/timeout events happen?

[NEZNAMY]

Unless you enabled global playerlist, TAB is not in charge of adding / removing players at all. Even then, it doesn't affect players on the same server (because the server already does that), but only other servers, which isn't your case.
That's why I don't know which functionality could cause this even in theory.

[CC-Odin]

Global playerlist is enabled so that the tab list will show players on both our survival and creative servers

[NEZNAMY]

Can you try without it? When you were timed out, were both players on the same server?

[CC-Odin]

Both players were on the same proxy and server. Will try it without the global player list and see if that prevents the issue from occurring.

Worth noting that when I set Velocity to not kick players that are already logged in, then the duplicate connection to the proxy gets kicked for already being logged in and then I'm unable to trigger the ghost mode as the existing connection to the server and to the proxy are always properly timed out completely before the subsequent login can happen at all. (ie. there is never a sustained duplicate login on either the proxy or the server)

[CC-Odin]

Okay, will be trying without global player list next but this time I caught exactly what I was describing above.

[13:50:37 INFO]: [connected player] Odin__AllFather (/...:55459) has connected
[13:50:37 INFO]: [connected player] Odin__AllFather (/...:50943) has disconnected: multiplayer.disconnect.duplicate_login
[13:50:37 INFO]: [server connection] Odin__AllFather -> survival has connected
[13:50:37 INFO]: [connected player] Odin__AllFather (/...:50943): kicked from server survival: multiplayer.disconnect.duplicate_login
[13:50:37 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[13:50:37 INFO]: [connected player] Odin__AllFather (/...:50943) has disconnected: You were kicked from survival: multiplayer.disconnect.duplicate_login

Checked the tab list for DungeonLackey and both players showed as online as expected. Left the tab list up on the screen and waited until the following log entries appeared.

[13:50:50 INFO]: [connected player] Odin__AllFather (/...:50943) has disconnected: An internal error occurred in your connection.
[13:50:50 ERROR]: [connected player] Odin__AllFather (/...:50943): read timed out

And then on cue, Odin disappears from DungeonLackey's tab list right as those messages are shown in the Velocity logs.

[CC-Odin]

With global player list disabled, when the same sequence of log events occurs the player does not go in to ghost mode, but, when the disconnected/timeout message appears the player count drops from 2 to 1.

[CC-Odin]

Dropping the timeout in Velocity from the default 30 seconds to 20 seconds (which I believe then matches the internal timeout from Paper itself back to Velocity) makes it incredibly hard to trigger it as the timing then seems to need to be even more precise.

If the ghost mode issue is being caused by TAB firing it's disconnect / cleanup routines a second time when the belated internal error disconnect / read time out by Velocity fires off whatever events that triggers, is the issue with TAB actually that it's doing something it's not supposed to because it's not actually expecting a second disconnect event from Velocity for the still logged in user?

[CC-Odin]

Got some debug output that will helpfully shed some light on it. The final login here at 18:05:08 there doesn't appear to be a TAB join event, and then the TAB quit event fires after the second disconnect / timeout event.

I suspect that whatever out of order weirdness is occurring here is actually coming from Velocity itself as it is possible to trigger this strange disconnect behavior in Velocity with no plugins at all, and that TAB simply never anticipates this situation which results in whatever player state tracking it is doing end up in the inconsistent state we end up in.

[18:02:10 INFO]: [connected player] Odin__AllFather (/...:57940) has connected
[18:02:10 INFO]: [server connection] Odin__AllFather -> survival has connected
[18:02:13 INFO] [TAB]: [DEBUG] Player join of Odin__AllFather processed in 2ms
[18:02:41 INFO]: [connected player] Odin__AllFather (/...:60266) has connected
[18:02:41 INFO]: [connected player] Odin__AllFather (/...:57940) has disconnected: multiplayer.disconnect.duplicate_login
[18:02:41 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[18:02:41 INFO] [TAB]: [DEBUG] Player quit of Odin__AllFather processed in 0ms
[18:02:41 INFO]: [server connection] Odin__AllFather -> survival has connected
[18:02:44 INFO] [TAB]: [DEBUG] Player join of Odin__AllFather processed in 1ms
[18:03:21 INFO]: [connected player] Odin__AllFather (/...:62088) has connected
[18:03:21 INFO]: [connected player] Odin__AllFather (/...:60266) has disconnected: multiplayer.disconnect.duplicate_login
[18:03:21 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[18:03:21 INFO] [TAB]: [DEBUG] Player quit of Odin__AllFather processed in 0ms
[18:03:21 INFO]: [server connection] Odin__AllFather -> survival has connected
[18:03:24 INFO] [TAB]: [DEBUG] Player join of Odin__AllFather processed in 0ms
[18:04:14 INFO]: [connected player] Odin__AllFather (/...:52900) has connected
[18:04:14 INFO]: [connected player] Odin__AllFather (/...:62088) has disconnected: multiplayer.disconnect.duplicate_login
[18:04:14 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[18:04:14 INFO] [TAB]: [DEBUG] Player quit of Odin__AllFather processed in 0ms
[18:04:14 INFO]: [server connection] Odin__AllFather -> survival has connected
[18:04:17 INFO] [TAB]: [DEBUG] Player join of Odin__AllFather processed in 0ms
[18:04:44 INFO]: [connected player] Odin__AllFather (/...:56794) has connected
[18:04:44 INFO]: [connected player] Odin__AllFather (/...:52900) has disconnected: multiplayer.disconnect.duplicate_login
[18:04:44 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[18:04:44 INFO] [TAB]: [DEBUG] Player quit of Odin__AllFather processed in 0ms
[18:04:44 INFO]: [server connection] Odin__AllFather -> survival has connected
[18:04:46 INFO] [TAB]: [DEBUG] Player join of Odin__AllFather processed in 0ms

[18:05:08 INFO]: [connected player] Odin__AllFather (/...:56979) has connected
[18:05:08 INFO]: [connected player] Odin__AllFather (/...:56794) has disconnected: multiplayer.disconnect.duplicate_login
[18:05:08 INFO]: [server connection] Odin__AllFather -> survival has connected
[18:05:08 INFO]: [connected player] Odin__AllFather (/...:56794): kicked from server survival: multiplayer.disconnect.duplicate_login
[18:05:08 INFO]: [server connection] Odin__AllFather -> survival has disconnected
[18:05:08 INFO]: [connected player] Odin__AllFather (/...:56794) has disconnected: You were kicked from survival: multiplayer.disconnect.duplicate_login
[18:05:22 INFO]: [connected player] Odin__AllFather (/...:56794) has disconnected: An internal error occurred in your connection.
[18:05:22 ERROR]: [connected player] Odin__AllFather (/...:56794): read timed out
[18:05:22 INFO] [TAB]: [DEBUG] Player quit of Odin__AllFather processed in 0ms

[CC-Odin]

Okay, last comment before you get a chance to absorb all of this : )

https://mclo.gs/7MDizAq

Added some extra logging of the Velocity player events and the most interesting detail is actually what isn't apparent from the log itself. 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, but only appeared approximately 10 seconds later despite having the same timestamp.

I hope some (any?) of this is helpful for you.

[NEZNAMY]

Looking at the code I found this: https://github.com/NEZNAMY/TAB/blob/master/shared/src/main/java/me/neznamy/tab/shared/features/globalplayerlist/GlobalPlayerList.java#L119-L125

I am actually not checking if the server is the same or not, because even if it is, removing action gets blocked if the entry no longer exists. Could it be that the player joined in, but quit was called after player joined in? And then join again in TAB, but it didn't re-add the player due to same server check? This is the only scenario I can think of.

If this is it, I can obviously add the check on quit processing, but I'm not sure if the issue you found isn't affecting more than just this.

[CC-Odin]

I'm convinced that it's an edge case in how Velocity handles duplicate logins when Velocity itself flags the duplicate login but also receives the duplicate login event back from the server, and then clearly Velocity is getting confused about whether or not it should (or needs to) fire off the disconnect chain.

Maybe something where it recognizes the duplicate login, but then when it goes to check the connection to the server it sees that it's been disconnect (because Paper sent the duplicate login event) and that interrupts the normal / expected flow of events.

Adding the check on quit processing to TAB is a solid workaround in the meantime, and dropping the connection timeout value in Velocity to maybe 18 seconds so that the available window of time where this can happen should be zero, but I'll report it to Velocity as well and see what they have to say as the underlying issue really does seem to be improper duplication connection handling in this edge case.

Is commit ac59973 likely to resolve this? Just let me know when I should retest and I'll try to trigger it again.