connection count (0) different from list command player count (10) [00f500]

A-wels commented 1 year ago

Current Behavior (🐛 Bug)

When nobody is on the Server, the following warning shows:

2023/02/13 10:26:28 [warn  ≡≡≡ ] countPlayerSafe: connection count (0) different from list command player count (10) [00f500]
2023/02/13 10:26:28 [info  ≡≡≡ ] 10 online players - method for player count: list command

The server never hibernates because of this.

Expected Behavior

The server hibernates after the timeout.

Steps to Reproduce

Start msh (Version: Commit a670db43b9ae17ef2a3fbdc638e9e4b6e575e30a) Connect to the server Disconnect from the server Observe message

The following Plugins are installed on the server:

Essentials
Harbor
GrimAC
ProtocolLib
ServerBackup
LuckPerms
Waypoints
Orebfuscator
EssentialsX

The /list command ingame shows 1 Player (when only I am connected)

Update: The EssentialsX plugin takes over and changes the list command. I'd like to be assigned to this issue and try my hand at fixing it :)

MSH Logs

╔═════════════════════════════════════════════╗
║  _ __ ___  ___| |__                         ║
║ | '_ ` _ \/ __| '_ \                        ║
║ | | | | | \__ \ | | | v2.4.12               ║
║ |_| |_| |_|___/_| |_| -------               ║
║ Copyright (C) 2019-2022 gekigek99           ║
║ github: https://github.com/gekigek99        ║
║ remember to give a star to this repository! ║
╚═════════════════════════════════════════════╝
2023/02/13 10:24:19 [info  ≡   ] checking OS support...
2023/02/13 10:24:19 [info  ≡   ] loading config...
2023/02/13 10:24:19 [info  ≡   ] reading config file: "/home/alex/mc/minecraft-server-hibernation/msh-config.json"
2023/02/13 10:24:19 [info  ≡   ] msh instance file exists
2023/02/13 10:24:19 [info  ≡   ] msh instance loaded is healthy
2023/02/13 10:24:19 [info  ≡≡≡≡] setting log level to: 1
2023/02/13 10:24:19 [info  ≡≡≡ ] eula.txt exist and is set to true
» 2023/02/13 10:24:19 [info  ≡≡≡ ] listening for new clients connections        on 0.0.0.0:25565 ...
2023/02/13 10:24:29 [info  ≡≡≡ ] MINECRAFT SERVER IS STARTING!
2023/02/13 10:24:48 [info  ≡≡≡ ] MINECRAFT SERVER IS ONLINE!
2023/02/13 10:24:49 [info  ≡≡≡ ] A CLIENT CONNECTED TO THE SERVER! (join req) - 1 active connections
2023/02/13 10:24:55 [info  ≡≡≡ ] A CLIENT DISCONNECTED FROM THE SERVER! (join req) - 0 active connections
2023/02/13 10:25:03 [info  ≡≡≡ ] A CLIENT CONNECTED TO THE SERVER! (join req) - 1 active connections
2023/02/13 10:25:03 [info  ≡≡≡ ] A CLIENT DISCONNECTED FROM THE SERVER! (join req) - 0 active connections
2023/02/13 10:25:05 [info  ≡≡≡ ] A CLIENT CONNECTED TO THE SERVER! (join req) - 1 active connections
2023/02/13 10:25:35 [info  ≡≡≡ ] performing scheduled ms soft freeze
2023/02/13 10:25:35 [warn  ≡≡≡ ] countPlayerSafe: connection count (1) different from list command player count (10) [00f500]
2023/02/13 10:25:35 [info  ≡≡≡ ] 10 online players - method for player count: list command
2023/02/13 10:25:58 [info  ≡≡≡ ] A CLIENT DISCONNECTED FROM THE SERVER! (join req) - 0 active connections
2023/02/13 10:26:28 [info  ≡≡≡ ] performing scheduled ms soft freeze
2023/02/13 10:26:28 [warn  ≡≡≡ ] countPlayerSafe: connection count (0) different from list command player count (10) [00f500]
2023/02/13 10:26:28 [info  ≡≡≡ ] 10 online players - method for player count: list command

MSH-Version

2.4.12

Operating system

Ubunto 20.0.4

System architecture?

AMD64

Minecraft Version

1.19.3 Purpur Server

Minecraft Server Software?

Other (Add to Minecraft Version)

Is there an existing issue for this?

[X] I have searched the existing issues before opening this issue.
[X] I have provided all relevant details.

gekigek99 commented 1 year ago

I saw your pr, let's discuss there

can you send a log in which also the log of the server is shown (logelevel 2 in config)

A-wels commented 1 year ago

This is the log with loglevel set to 2

╔═════════════════════════════════════════════╗
║  _ __ ___  ___| |__                         ║
║ | '_ ` _ \/ __| '_ \                        ║
║ | | | | | \__ \ | | | v2.4.12               ║
║ |_| |_| |_|___/_| |_| -------               ║
║ Copyright (C) 2019-2022 gekigek99           ║
║ github: https://github.com/gekigek99        ║
║ remember to give a star to this repository! ║
╚═════════════════════════════════════════════╝
2023/02/17 12:00:26 [info  ≡   ] checking OS support...
2023/02/17 12:00:26 [info  ≡   ] loading config...
2023/02/17 12:00:26 [info  ≡   ] reading config file: "/home/alex/Development/minecraft/minecraft-server-hibernation-fork/msh-config.json"
2023/02/17 12:00:26 [info  ≡   ] msh instance file exists
2023/02/17 12:00:26 [info  ≡   ] msh instance loaded is healthy
2023/02/17 12:00:26 [info  ≡≡≡≡] setting log level to: 2
2023/02/17 12:00:26 [info  ≡≡≡ ] eula.txt exist and is set to true
2023/02/17 12:00:26 [warn  ≡≡≡ ] loadRuntime: could not execute 'java -version' command [03f002]
2023/02/17 12:00:26 [info  ≡≡≡ ] listening for new clients connections  on 0.0.0.0:25565 ...
2023/02/17 12:00:32 [info  ≡≡≡ ] MINECRAFT SERVER IS STARTING!
2023/02/17 12:00:33 [serv ≡≡  ] Starting org.bukkit.craftbukkit.Main
2023/02/17 12:00:33 [serv ≡≡  ] System Info: Java 17 (OpenJDK 64-Bit Server VM 17.0.6+10) Host: Linux 5.10.167-1-MANJARO (amd64)
2023/02/17 12:00:33 [serv ≡≡  ] Loading libraries, please wait...
2023/02/17 12:00:33 [serv ≡≡  ] 2023-02-17 12:00:33,665 ServerMain WARN Advanced terminal features are not available in this environment
2023/02/17 12:00:35 [serv ≡≡  ] [12:00:35 INFO]: Building unoptimized datafixer
2023/02/17 12:00:36 [serv ≡≡  ] [12:00:36 INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
2023/02/17 12:00:37 [serv ≡≡  ] [12:00:37 INFO]: Loaded 7 recipes
2023/02/17 12:00:38 [serv ≡≡  ] [12:00:38 INFO]: Starting minecraft server version 1.19.3
2023/02/17 12:00:38 [serv ≡≡  ] [12:00:38 INFO]: Loading properties
2023/02/17 12:00:38 [serv ≡≡  ] [12:00:38 INFO]: This server is running Purpur version git-Purpur-1895 (MC: 1.19.3) (Implementing API version 1.19.3-R0.1-SNAPSHOT) (Git: 8a0e601 on HEAD)
2023/02/17 12:00:38 [serv ≡≡  ] [12:00:38 INFO]: Server Ping Player Sample Count: 12
2023/02/17 12:00:38 [serv ≡≡  ] [12:00:38 INFO]: Using 4 threads for Netty based IO
2023/02/17 12:00:38 [serv ≡≡  ] [12:00:38 INFO]: [ChunkTaskScheduler] Chunk system is using 1 I/O threads, 3 worker threads, and gen parallelism of 3 threads
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 WARN]: [Pufferfish] SIMD operations are available for your server, but are not configured!
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 WARN]: [Pufferfish] To enable additional optimizations, add "--add-modules=jdk.incubator.vector" to your startup flags, BEFORE the "-jar".
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 WARN]: [Pufferfish] If you have already added this flag, then SIMD operations are not supported on your JVM or CPU.
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 WARN]: [Pufferfish] Debug: Java: 17.0.6, test run: true
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 INFO]: Default game type: SURVIVAL
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 INFO]: Generating keypair
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 INFO]: Starting Minecraft server on *:25555
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 INFO]: Using epoll channel type
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 INFO]: Paper: Using libdeflate (Linux x86_64) compression from Velocity.
2023/02/17 12:00:39 [serv ≡≡  ] [12:00:39 INFO]: Paper: Using OpenSSL 3.0.x (Linux x86_64) cipher from Velocity.
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Waypoints] Loading 1 libraries... please wait
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Waypoints] Loaded library /home/alex/Development/minecraft/2023-java/libraries/org/jetbrains/kotlin/kotlin-stdlib-jdk8/1.8.0/kotlin-stdlib-jdk8-1.8.0.jar
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Waypoints] Loaded library /home/alex/Development/minecraft/2023-java/libraries/org/jetbrains/kotlin/kotlin-stdlib/1.8.0/kotlin-stdlib-1.8.0.jar
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Waypoints] Loaded library /home/alex/Development/minecraft/2023-java/libraries/org/jetbrains/kotlin/kotlin-stdlib-common/1.8.0/kotlin-stdlib-common-1.8.0.jar
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Waypoints] Loaded library /home/alex/Development/minecraft/2023-java/libraries/org/jetbrains/annotations/13.0/annotations-13.0.jar
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Waypoints] Loaded library /home/alex/Development/minecraft/2023-java/libraries/org/jetbrains/kotlin/kotlin-stdlib-jdk7/1.8.0/kotlin-stdlib-jdk7-1.8.0.jar
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [ServerBackup] Loading ServerBackup v2.9.3
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [LuckPerms] Loading LuckPerms v5.4.60
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [spark] Loading spark v1.10.30
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [Essentials] Loading Essentials v2.20.0-dev+41-4dc994d
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [EssentialsChat] Loading EssentialsChat v2.20.0-dev+41-4dc994d
2023/02/17 12:00:40 [serv ≡≡  ] [12:00:40 INFO]: [ProtocolLib] Loading ProtocolLib v5.0.0-SNAPSHOT-b612
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [Waypoints] Loading Waypoints v3.5.7
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [Orebfuscator] Loading Orebfuscator v5.3.2
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [Harbor] Loading Harbor v1.6.3
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [GrimAC] Loading GrimAC v2.3.35
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [GrimAC] Loading PacketEvents...
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: Server permissions file permissions.yml is empty, ignoring it
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [LuckPerms] Enabling LuckPerms v5.4.60
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]:         __    
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]:   |    |__)   LuckPerms v5.4.60
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]:   |___ |      Running on Bukkit - Purpur
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: 
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [LuckPerms] Loading configuration...
2023/02/17 12:00:41 [serv ≡≡  ] [12:00:41 INFO]: [LuckPerms] Loading storage provider... [H2]
2023/02/17 12:00:42 [serv ≡≡  ] [12:00:42 INFO]: [LuckPerms] Loading internal permission managers...
2023/02/17 12:00:42 [serv ≡≡  ] [12:00:42 INFO]: [LuckPerms] Performing initial data load...
2023/02/17 12:00:42 [serv ≡≡  ] [12:00:42 INFO]: [LuckPerms] Successfully enabled. (took 826ms)
2023/02/17 12:00:42 [serv ≡≡  ] [12:00:42 INFO]: [ProtocolLib] Enabling ProtocolLib v5.0.0-SNAPSHOT-b612
2023/02/17 12:00:42 [serv ≡≡  ] [12:00:42 INFO]: Preparing level "world"
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: Preparing start region for dimension minecraft:overworld
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: Time elapsed: 205 ms
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: Preparing start region for dimension minecraft:the_nether
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: Time elapsed: 35 ms
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: Preparing start region for dimension minecraft:the_end
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: Time elapsed: 26 ms
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: [ServerBackup] Enabling ServerBackup v2.9.3
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: [ServerBackup] ServerBackup: Plugin enabled.
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: [ServerBackup] ServerBackup: Searching for updates...
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: [spark] Enabling spark v1.10.30
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: [spark] Using Paper ServerTickStartEvent for tick monitoring
2023/02/17 12:00:43 [serv ≡≡  ] [12:00:43 INFO]: [spark] Starting background profiler...
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] Enabling Essentials v2.20.0-dev+41-4dc994d
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] Attempting to convert old kits in config.yml to new kits.yml
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] No kits found to migrate.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] Loaded 38132 items from items.json.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] Using locale de_DE
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] ServerListPingEvent: Spigot iterator API
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] Starting Metrics. Opt-out using the global bStats config.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 WARN]: [Essentials] Detected supported permissions plugin LuckPerms without Vault installed.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 WARN]: [Essentials] Features such as chat prefixes/suffixes and group-related functionality will not work until you install Vault.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Essentials] Using superperms-based permissions.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [EssentialsChat] Enabling EssentialsChat v2.20.0-dev+41-4dc994d
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [EssentialsChat] Secure signed chat and previews are enabled.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [EssentialsChat] Starting Metrics. Opt-out using the global bStats config.
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Waypoints] Enabling Waypoints v3.5.7
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Waypoints] Current database schema version: 3. Required database schema version: 3
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Orebfuscator] Enabling Orebfuscator v5.3.2
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [Harbor] Enabling Harbor v1.6.3
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [GrimAC] Enabling GrimAC v2.3.35
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [GrimAC] Registering singular bukkit event... (PistonEvent)
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [GrimAC] Registering packets...
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [GrimAC] Registering tick schedulers...
2023/02/17 12:00:44 [serv ≡≡  ] [12:00:44 INFO]: [GrimAC] [ACF] Enabled Asynchronous Tab Completion Support!
2023/02/17 12:00:45 [serv ≡≡  ] [12:00:45 INFO]: Running delayed init tasks
2023/02/17 12:00:45 [serv ≡≡  ] [12:00:45 INFO]: [Essentials] Fetching version information...
2023/02/17 12:00:45 [serv ≡≡  ] [12:00:45 INFO]: Done (6.634s)! For help, type "help"
2023/02/17 12:00:45 [info  ≡≡≡ ] MINECRAFT SERVER IS ONLINE!
2023/02/17 12:00:45 [serv ≡≡  ] [12:00:45 INFO]: [ServerBackup] ServerBackup: No updates found. The server is running the latest version.
2023/02/17 12:01:01 [info  ≡≡≡ ] A CLIENT CONNECTED TO THE SERVER! (join req) - 1 active connections
2023/02/17 12:01:02 [serv ≡≡  ] [12:01:02 INFO]: UUID of player VainCinder is 42b27d07-943f-4e38-a393-a6149d9fcea8
2023/02/17 12:01:02 [serv ≡≡  ] [12:01:02 INFO]: VainCinder joined the game
2023/02/17 12:01:02 [serv ≡≡  ] [12:01:02 INFO]: VainCinder[/127.0.0.1:40278] logged in with entity id 109 at ([world]-1879.5235654408548, -9.130227831278894, 1107.6753780483768)
2023/02/17 12:01:04 [info  ≡≡≡ ] A CLIENT DISCONNECTED FROM THE SERVER! (join req) - 0 active connections
2023/02/17 12:01:04 [serv ≡≡  ] [12:01:04 INFO]: VainCinder lost connection: Disconnected
2023/02/17 12:01:04 [serv ≡≡  ] [12:01:04 INFO]: VainCinder left the game
2023/02/17 12:01:34 [info  ≡≡≡ ] performing scheduled ms soft freeze
2023/02/17 12:01:34 [info  ≡≡  ] ms command: list       (origin: getPlayersByListCom)
2023/02/17 12:01:34 [serv ≡≡  ] [12:01:34 INFO]: [Essentials] CONSOLE issued server command: /list 
2023/02/17 12:01:34 [serv ≡≡  ] [12:01:34 INFO]: Es sind 0 von maximal 15 Spielern online.
2023/02/17 12:01:35 [warn  ≡≡≡ ] countPlayerSafe: connection count (0) different from list command player count (12) [00f500]
2023/02/17 12:01:35 [info  ≡≡≡ ] 12 online players - method for player count: list command

gekigek99 commented 1 year ago

Weird how getPlayersByServInfo is not tried before getPlayersByListCom...

gekigek99 commented 1 year ago

fixed in f6df8efea777ae70bde4f7d48b5dd9364d049b5c

gekware / minecraft-server-hibernation