WaterdogPE / WaterdogPE

Brand new proxy server for Minecraft: Bedrock Edition
https://waterdog.dev
GNU General Public License v2.0
274 stars 84 forks source link

[BUG] Rare memory leak in PlayerManager #266

Open BrandPVP opened 1 year ago

BrandPVP commented 1 year ago

Describe the bug Some players are not disconnected properly and their instance is stuck in PlayerManager forever. I'll show an example of a random buggy player.

  1. A player with a bad connection or glitched client joins the server.

    2023-05-13 08:17:18.702 [Bedrock Listener - #3] DEBUG - [/100.100.100.100:33330] <-> Received first data
    2023-05-13 08:17:23.361 [Bedrock Listener - #3] INFO  - [/100.100.100.100:33330|Vogy] <-> Upstream has connected (protocol=567 version=1.19.60)
    2023-05-13 08:17:23.368 [Bedrock Listener - #3] INFO  - Encryption enabled for /100.100.100.100:33330
  2. After 10 seconds, the player got timed out somehow (maybe it's a client bug). Notice it does not say "Upstream has disconnected: disconnect.timeout", only this

    2023-05-13 08:17:33.921 [RakNet Listener - #0] DEBUG - Disconnecting RakNet Session (0.0.0.0/0.0.0.0:19132 => /100.100.100.100:33330) due to TIMED_OUT
  3. The player tries to join the server again after a minute. The IP is the same, the port is different:

    2023-05-13 08:18:49.094 [Bedrock Listener - #0] DEBUG - [/100.100.100.100:44193] <-> Received first data
    2023-05-13 08:18:50.153 [Bedrock Listener - #0] INFO  - [/100.100.100.100:44193|Vogy] <-> Upstream has connected (protocol=567 version=1.19.60)
  4. An important detail: my server does not have XBOX authorization, so I made a simple plugin (nothing else) that prohibits connection to the proxy if a player with the same nickname is already connected to it.

    private void onPlayerAuth(PlayerAuthenticatedEvent event) {
        var nick = event.getLoginData().getDisplayName().toLowerCase();
    
        for (var player : getProxy().getPlayers().values()) {
            if (player.getName().toLowerCase().equals(nick)) {
                event.setCancelled();
                event.setCancelReason("Player with your nickname is already on the server!");
                return;
            }
        }
    }
  5. So, when the player [/100.100.100.100:44193|Vogy] tries to join the server again, he gets kicked with the message "Player with your nickname is already on the server!" over and over. The old connection [/100.100.100.100:33330|Vogy] is stuck in the proxy list forever even though the 'old' player has been timed out and left the server.

  6. I didn't mention, I tried to debug everything about the old connection, maybe this will help:

    private void onPlayerAuth(PlayerAuthenticatedEvent event) {
        var nick = event.getLoginData().getDisplayName().toLowerCase();
    
        for (var player : getProxy().getPlayers().values()) {
            if (player.getName().toLowerCase().equals(nick)) {
                event.setCancelled();
                event.setCancelReason("Player with your nickname is already on the server!");
    
               // DEBUG LOGGING
    
                String where = "unknown";
                if (player.getConnectingServer() != null) {
                    where = "pending [" + player.getConnectingServer().getServerName() + "]";
                } else if (player.getServerInfo() != null) {
                    where = player.getServerInfo().getServerName();
                }
    
                getLogger().warn("Player {} tried to connect but this nickname is already connected to: {}, connected client address: {}", player.getName(), where, player.getAddress().toString());
    
                getLogger().warn("Pending servers: " + player.getPendingServers().size());
    
                getLogger().warn("oldplayer.getConnection().isConnected(): " + player.getConnection().isConnected());
                getLogger().warn("oldplayer.getConnection().isLogging(): " + player.getConnection().isLogging());
                getLogger().warn("oldplayer.getConnection().isSubClient(): " + player.getConnection().isSubClient());
    
                getLogger().warn("getPeer().isConnected(): " + player.getConnection().getPeer().isConnected());
                getLogger().warn("getPeer().isConnecting(): " + player.getConnection().getPeer().isConnecting());
                getLogger().warn("getPeer().isSplitScreen(): " + player.getConnection().getPeer().isSplitScreen());
                getLogger().warn("getPeer().isSharable(): " + player.getConnection().getPeer().isSharable());
    
                Channel channel = player.getConnection().getPeer().getChannel();
                getLogger().warn("getPeer().getChannel().isRegistered(): " + channel.isRegistered());
                getLogger().warn("getPeer().getChannel().isActive(): " + channel.isActive());
                getLogger().warn("getPeer().getChannel().isOpen(): " + channel.isOpen());
                getLogger().warn("getPeer().getChannel().isWritable(): " + channel.isWritable());
    
                return;
            }
        }
    }

The logs with debug about the old connection:

(From paragraph 3)
2023-05-13 08:18:49.094 [Bedrock Listener - #0] DEBUG - [/100.100.100.100:44193] <-> Received first data
2023-05-13 08:18:50.153 [Bedrock Listener - #0] INFO  - [/100.100.100.100:44193|Vogy] <-> Upstream has connected (protocol=567 version=1.19.60)

(Debug logs)
2023-05-13 08:18:50.156 [Bedrock Listener - #0] WARN  [Plugin] - Player Vogy tried to connect but this nickname is already connected to: unknown, connected client address: /100.100.100.100:33330

2023-05-13 08:18:50.156 [Bedrock Listener - #0] WARN  [Plugin] - Pending servers: 0
2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - oldplayer.getConnection().isConnected(): false
2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - oldplayer.getConnection().isLogging(): true
2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - oldplayer.getConnection().isSubClient(): false

2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().isConnected(): false
2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().isConnecting(): false
2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().isSplitScreen(): false
2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().isSharable(): false

2023-05-13 08:18:50.157 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().getChannel().isRegistered(): false
2023-05-13 08:18:50.158 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().getChannel().isActive(): false
2023-05-13 08:18:50.158 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().getChannel().isOpen(): false
2023-05-13 08:18:50.158 [Bedrock Listener - #0] WARN  [Plugin] - getPeer().getChannel().isWritable(): false

Only 1 proxy instance and only 1 downstream server is used.

Platform Information:

Alemiz112 commented 1 year ago

Hi, can you provide more information about WDPE version you are using?

BrandPVP commented 1 year ago

I use 2.0 (this https://github.com/WaterdogPE/WaterdogPE/commit/ae9ff192fb65652c5c63a44fec57e9b43d810e1a)