jammsen
[Bug Report] Player detection loop
You understand that if you dont provide clear information on your "Problem", "Software and Hardware-Setup" and the "Steps to reproduce" your issue will be closed without any help, because your not willing to do your part?
- [X] Yes i do!
You understand that im not a Game-Dev or Game-Server-Dev and my support is primary for the Docker-Image and somewhat limited to the Game-Server?
- [X] Yes i do!
Current behavior
Since the new update, it seems the player detection will sometimes loop join/leave announcements. After looking into the logs, it seems this happens when it fails to connect via RCON.
Log example:
[2025-01-06 07:55:09] [LOG] RCON executed the command. showplayers
[07:55:24]: Player Jad has left the server.
cli: execute: auth: rcon: rcon: read packet size: EOF
> RCON:
[2025-01-06 07:55:39] [LOG] RCON executed the command. showplayers
[07:55:39]: Player Jad has joined the server.
[2025-01-06 07:55:39] [LOG] RCON executed the command. broadcast [07:55:39] Jad joined the server
cli: execute: rcon: read tcp 127.0.0.1:38976->127.0.0.1:25575: i/o timeout
> RCON: Broadcasted: [07:55:39] Jad joined the ser
Upon error cli: execute: auth: rcon: rcon: read packet size: EOF it announces the leave, then will "re-announce" the join.
When it times out with the error cli: execute: rcon: read tcp 127.0.0.1:38976->127.0.0.1:25575: i/o timeout it will repeat the join announcement.
A screenshot example of 1 user being in game:
Desired behavior
Account for RCON connection failures and avoid false or spam join/leave announcements.
Links to screenshots
No response
Steps to reproduce
Steps to reproduce the behavior: Unsure if this is a specific issue on my end (although I don't see any changes, errors, or resource issues), or a new issue with the latest Palworld update.
Software setup
- OS: Linux
- Docker: Branch - develop
Hardware setup
N/A
Additional context
No response
Hey @Jadiction - A restart of the image or the server fixes the issue right?
Not sure on how to accurately test this though, normally it should not even timeout, its a local connection for rconcli to the system, because its inside the container too.
Very weird, can you provide player-numbers, activity and Hardware-Infos please?
Hey @Jadiction - A restart of the image or the server fixes the issue right?
I think it helps for a little, but I don't restart the server often.
Not sure on how to accurately test this though, normally it should not even timeout, its a local connection for rconcli to the system, because its inside the container too.
I wouldn't think it would time out either, but it's somehow managing to do so, that's why I thought it may be a (new) Palworld issue. Perhaps the server has FPS stall times where it fails to reach the RCON connection in time.
Very weird, can you provide player-numbers, activity and Hardware-Infos please?
I've seen it during player numbers being around 1-3. In my example above there was only 1. Currently 2 are online and the issue persists.
Relevant hardware: CPU - Intel® Core™ i7-5930K CPU @ 3.50GHz | Temperature: 36 °C Memory - 64 GiB DDR4 (50% usage)
@Jadiction - I have tried to implement a specific fix for this edge-case, can you please tryout the latest develop tag and tell me if that fixes it for you?
@Jadiction - I have tried to implement a specific fix for this edge-case, can you please tryout the latest develop tag and tell me if that fixes it for you?
Thanks for the update. With my testing, it looks like it runs into an error when loading:
/includes/playerdetection.sh: line 64: player_data: bad array subscript
Hey @Jadiction - Yeah that was down to a mechanic i didnt catch, sorry.
Looks like its only on broadcast, not on showplayers, but something gets weird and confused, after that error.
Seems like that base problem is on rcon-cli side, see the list of issues related to the same problem:
- https://github.com/gorcon/rcon-cli/issues?q=cli%3A+execute%3A+rcon%3A+read+tcp++i%2Fo+timeout
- https://github.com/gorcon/rcon-cli/issues/36
- https://github.com/gorcon/rcon-cli/issues/32
- https://github.com/gorcon/rcon-cli/issues/40
- https://github.com/gorcon/rcon-cli/issues/30
Not sure if its getting fixed by outdead because the issue is rather old.
I have now implemented an even more complex workaround, not happy with that, but i think i saved it kinda, by putting it behind the ENV-Var RCON_PLAYER_DEBUG=false/true see Env-Var-Docs.
New develop tag is done cooking, feel free to test it with RCON_PLAYER_DEBUG set to true and false please and deliver detailed feedback on this please.
Hi @jammsen
With the latest develop version, I got a double join announcement. When this happens, the command output is empty.
With the logs below, you can see it successfully sees me in the server and continues normally, then on the next iteration, it gets a blank command output and believes no players are on the server. It then announces the join (at a later time from initial join)
Hi @jammsen
With the latest develop version, I got a double join announcement. When this happens, the command output is empty.
With the logs below, you can see it successfully sees me in the server and continues normally, then on the next iteration, it gets a blank command output and believes no players are on the server. It then announces the join (at a later time from initial join)
Could you please mark what you in the full screenshot or so? Im confused on what you mean by this explaination and i did read it 3 times and still am not really sure what you mean, sorry.
@jammsen
I'm guessing when it fails to connect to RCON, it gives an empty player list (as shown in the 2nd iteration of the debug messages) so it thinks no players are in the server. Then it iterates again and announces everyone in the server.
This is something persistent as of right now as well:
(In this screenshot, it actually shows the I/O timeout error, which may be more helpful)
We can see
Box 1: Both players were successfully shown in game (nobody left)
Box 2: The second iteration fails to connect and gets an empty command_output
Box 3: Third iteration (re-)announces the players that were already in game since it believed no players were in the server due to the failed connection in box 2
(In this screenshot, it actually shows the I/O timeout error, which may be more helpful)
No it actually makes it more confusing, also i did already cover the I/O Timeout error here - https://github.com/jammsen/docker-palworld-dedicated-server/issues/287#issuecomment-2581121698 - Its a problem itself with rconcli on "broadcast", not really sure what i should be able to do, if the software simply doesnt do it cleanly.
I'm guessing when it fails to connect to RCON, it gives an empty player list (as shown in the 2nd iteration of the debug messages) so it thinks no players are in the server. Then it iterates again and announces everyone in the server.
No it shouldnt be able to do that, because of https://github.com/jammsen/docker-palworld-dedicated-server/blob/develop/includes/playerdetection.sh#L27-L43 - It checks if the exit-code is good and then checks if the CSV header line is in there and then reads new player data, if the command is weird it unsets current_players in Line 37, which might cause this behavior not sure how this could be reproduced though. WHICH would explain the behavior you are describing, i can just comment out Line 37 and you try again to "bug" it.
But please understand that THAT behavior has nothing to do with
[2025-01-06 07:55:39] [LOG] RCON executed the command. broadcast [07:55:39] Jad joined the server
cli: execute: rcon: read tcp 127.0.0.1:38976->127.0.0.1:25575: i/o timeout
One is on gathering players and one is on sending infos about the announces. Announcing however doesnt fiddle around with the data in current_players. 1 Problem does cause announcing to much and 1 Problem is that the announce isnt exited cleanly and that is up to outdead to fix, not me. (Also the announce goes through but reports an non clean shutdown error or so, im not into go, no idea why that is!)
Please keep thoose 2 things seperated.
@Jadiction - Baking is done, its on the develop image, when are you available to join Discord so we can test this out together?
The Timeout with rconcli seems to be a Palworld rconcli thing, also known already, See theese: https://github.com/thijsvanloef/palworld-server-docker/issues/492 https://github.com/gorcon/rcon-cli/issues/35
Also here in the documentation of Palworld: https://tech.palworldgame.com/api/rcon/#notes
@Jadiction - Baking is done, its on the develop image, when are you available to join Discord so we can test this out together?
I updated the container and so far haven't seen the issue. I have joined the Discord and I will keep you updated.
Currently it seems removing current_players=() when the exit status for command_output isn't 0 is the fix.
This fix is now on :latest, if you find anything regarding things, feel free to write here or on Discord again, then we can reopen this issue.
As discussed on Discord, below are the debug logs with the latest issue where when the last player leaves a server, it shows they left on the next user join.
[2025-01-14 19:32:34] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid
nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
Exitcode was: 0
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
Debug: command_output = ''
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:32:59] [LOG] nyaa rawr x3~~ left the server. (User id: steam_76561198057402155)
(Where user actually left)
[2025-01-14 19:33:04] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:33:20] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:33:35] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:33:50] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:34:05] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:34:20] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
[2025-01-14 19:34:35] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid'
Exitcode was: 0
Debug: No player data available.
Debug: current_players = nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155
For-Loop-Debug: player_info = 'nyaa rawr x3~~,383A36C0000000000000000000000000,76561198057402155'
(I connect to server)
[2025-01-14 19:34:39] [LOG] Jad connected the server. (User id: steam_76561198037606614)
[2025-01-14 19:34:45] [LOG] Jad joined the server. (User id: steam_76561198037606614)
[2025-01-14 19:34:51] [LOG] RCON executed the command. showplayers
Debug: command_output = 'name,playeruid,steamid
Jad,5B5A0B9F000000000000000000000000,76561198037606614'
Exitcode was: 0
Debug: current_players = Jad,5B5A0B9F000000000000000000000000,76561198037606614
Debug: current_players = Jad,5B5A0B9F000000000000000000000000,76561198037606614
For-Loop-Debug: player_info = 'Jad,5B5A0B9F000000000000000000000000,76561198037606614'
[19:34:51]: Player Jad has joined the server.
[2025-01-14 19:34:51] [LOG] RCON executed the command. broadcast [19:34:51] Jad joined the server
cli: execute: rcon: read tcp 127.0.0.1:35672->127.0.0.1:25575: i/o timeout
> RCON: Broadcasted: [19:34:51] Jad joined the ser
[19:35:01]: Player nyaarawrx3 has left the server.
[2025-01-14 19:35:01] [LOG] RCON executed the command. broadcast [19:35:01] nyaarawrx3 left the server
cli: execute: rcon: read tcp 127.0.0.1:56688->127.0.0.1:25575: i/o timeout
> RCON: Broadcasted: [19:35:01] nyaarawrx3 left the ser
Broadcasts my join, then his leave from 2025-01-14 19:32:59
@Jadiction - Can you check if this is still a problem after the latest update from a few minutes ago please?
@Jadiction - Can you check if this is still a problem after the latest update from a few minutes ago please?
Yes, I updated to the latest (develop branch) and the issue is persistent.
Why cant i reproduce this here ... im really confused, can you provide a detailed description of your setup and the settings and your docker-compose+env please?
Why cant i reproduce this here ... im really confused, can you provide a detailed description of your setup and the settings and your docker-compose+env please?
I haven't been able to try this in a while, but from my replication in the logs earlier, someone was online alone, then left. I join a few minutes later and it waited to show the player left message until after I joined. I haven't looked myself, but my guess is maybe the script only runs when it sees >= 1 player, so once the last person leaves the server, it keeps them stored until the next player joins, then it sees them as offline and removes them cache.
The issue: It displays the user xxxx (last person to leave) left (potentially way later) once another person joins. If my guess above is correct, when it reaches 0 players, it needs to clear the online players cache.
This is running on Unraid (Linux). All my settings can be found here:
docker run
-d
--name='Palworld'
--net='palworld'
--pids-limit 2048
-e TZ="America/Chicago"
-e HOST_OS="Unraid"
-e HOST_HOSTNAME="Server"
-e HOST_CONTAINERNAME="Palworld"
-e 'BACKUP_PATH'='/backups'
-e 'ALWAYS_UPDATE_ON_START'='true'
-e 'STEAMCMD_VALIDATE_FILES'='true'
-e 'BACKUP_ENABLED'='false'
-e 'BACKUP_CRON_EXPRESSION'='0 * * * *'
-e 'BACKUP_RETENTION_POLICY'='true'
-e 'BACKUP_RETENTION_AMOUNT_TO_KEEP'='72'
-e 'RESTART_ENABLED'='true'
-e 'RESTART_CRON_EXPRESSION'='0 4 */3 * *'
-e 'WEBHOOK_ENABLED'='false'
-e 'WEBHOOK_DEBUG_ENABLED'='false'
-e 'WEBHOOK_URL'='[Redacted]'
-e 'WEBHOOK_INFO_TITLE'='Info'
-e 'WEBHOOK_INFO_DESCRIPTION'='Server information'
-e 'WEBHOOK_INFO_COLOR'='2849520'
-e 'WEBHOOK_INSTALL_TITLE'='Installing server'
-e 'WEBHOOK_INSTALL_DESCRIPTION'='Server is being installed'
-e 'WEBHOOK_INSTALL_COLOR'='2849520'
-e 'WEBHOOK_RESTART_TITLE'='Server is restarting soon'
-e 'WEBHOOK_RESTART_DESCRIPTION'='Restarting in 15 minutes'
-e 'WEBHOOK_RESTART_COLOR'='15593515'
-e 'WEBHOOK_START_TITLE'='Server is starting'
-e 'WEBHOOK_START_DESCRIPTION'='The gameserver is starting'
-e 'WEBHOOK_START_COLOR'='2328576'
-e 'WEBHOOK_STOP_TITLE'='Server has been stopped'
-e 'WEBHOOK_STOP_DESCRIPTION'='The gameserver has been stopped'
-e 'WEBHOOK_STOP_COLOR'='7413016'
-e 'WEBHOOK_UPDATE_TITLE'='Updating server'
-e 'WEBHOOK_UPDATE_DESCRIPTION'='Server is being updated'
-e 'WEBHOOK_UPDATE_COLOR'='2849520'
-e 'SERVER_SETTINGS_MODE'='rcononly'
-e 'MULTITHREAD_ENABLED'='true'
-e 'COMMUNITY_SERVER'='true'
-e 'TZ'='America/Chicago'
-e 'ADMIN_PASSWORD'='[Redacted]'
-e 'SERVER_PASSWORD'='[Redacted]'
-e 'RCON_ENABLED'='true'
-e 'RCON_PLAYER_DETECTION'='true'
-e 'RCON_PLAYER_DETECTION_STARTUP_DELAY'='60'
-e 'RCON_PLAYER_DETECTION_CHECK_INTERVAL'='15'
-e 'RCON_PORT'='25575'
-e 'WEBHOOK_CONTENT_TITLE'=''
-e 'RCON_PLAYER_DEBUG'='true'
-l net.unraid.docker.managed=dockerman
-l net.unraid.docker.icon='https://raw.githubusercontent.com/ich777/docker-templates/master/ich777/images/palworld.png'
-p '25575:25575/tcp'
-p '8211:8211/udp'
-p '8212:8212/tcp'
-v '/mnt/user/Palworld/Server':'/palworld':'rw'
-v '/mnt/user/Backups/Palworld':'/backups':'rw'
--memory="25g"
--memory-swap=-1
--restart unless-stopped 'jammsen/palworld-dedicated-server:develop'
I haven't been able to try this in a while, but from my replication in the logs earlier, someone was online alone, then left. I join a few minutes later and it waited to show the player left message until after I joined. I haven't looked myself, but my guess is maybe the script only runs when it sees >= 1 player, so once the last person leaves the server, it keeps them stored until the next player joins, then it sees them as offline and removes them cache.
The issue: It displays the user
xxxx(last person to leave) left (potentially way later) once another person joins. If my guess above is correct, when it reaches 0 players, it needs to clear the online players cache.
You dont need to assume anything, this is OSS, the code is right here: https://github.com/jammsen/docker-palworld-dedicated-server/blob/develop/includes/playerdetection.sh
You can just used a LLM to let it explain to you.
I cant fix a problem i cant reproduce and therefore test and try it out.