GameServerManagers / GameServerManagers/LinuxGSM
[Bug]: logtimestamp will use the server's start timestamp for every log entry, rather than the time the line occurs at
- Dominant language
- Shell
- Stars
- 4.9k
- Forks
- 864
- PR merge metrics
- No merged PRs in 30d
Description
### User story
As a server administrator, I want accurate timestamps recorded in the console log files.
### Game
Minecraft, Valheim
### Linux distro
Ubuntu 22.04
### Command
command: start
### Further information
The logtimestamp setting appears to re-use the server start timestamp for every log entry, resulting in timestamps that are unreliable. This can most easily be confirmed by servers that already utilize time/datestamps in their log (like Valheim).
This may be a limitation of how tmux works.
Reviewing the code in command_start.sh
```
addtimestamp="gawk '{ print strftime(\\\"[$logtimestampformat]\\\"), \\\$0 }'"
<...>
if [ "${consolelogging}" == "on" ] || [ -z "${consolelogging}" ]; then
if [ "${logtimestamp}" == "on" ]; then
tmux -L "${socketname}" pipe-pane -o -t "${sessionname}" "exec bash -c \"cat | $addtimestamp\" >> '${consolelog}'"
else
tmux -L "${socketname}" pipe-pane -o -t "${sessionname}" "exec cat >> '${consolelog}'"
fi
else
```
given that this is in command_start.sh, this will affect all gameservers.
logs provided show the timestamp added by lgsm, followed by the minecraft native console timestamp, as well as valheim console logs which display not just time, but date, showing a huge disparity between the two.
### Relevant log output
```shell
Minecraft:
[2024-02-04 09:30:56] [11:04:07] [RCON Listener #2/INFO] [minecraft/GenericThread]: Thread RCON Client /127.0.0.1 started
[2024-02-04 09:30:56] [11:04:07] [Server thread/INFO] [minecraft/MinecraftServer]: [Rcon: Automatic saving is now enabled]
[2024-02-04 09:30:56] [11:04:07] [RCON Client /127.0.0.1 #23/INFO] [minecraft/RconClient]: Thread RCON Client /127.0.0.1 shutting down
[2024-02-04 09:30:56] [11:19:01] [RCON Listener #2/INFO] [minecraft/GenericThread]: Thread RCON Client /127.0.0.1 started
[2024-02-04 09:30:56] [11:19:01] [Server thread/INFO] [minecraft/MinecraftServer]: [Rcon: Automatic saving is now disabled]
[2024-02-04 09:30:56] [11:19:01] [RCON Client /127.0.0.1 #24/INFO] [minecraft/RconClient]: Thread RCON Client /127.0.0.1 shutting down
Valheim:
[2024-02-04 09:30:55] 02/12/2024 18:33:38: Sending message to save player profiles
[2024-02-04 09:30:55] 02/12/2024 18:33:38: PrepareSave: clone done in 30ms
[2024-02-04 09:30:55] 02/12/2024 18:33:38: PrepareSave: ZDOExtraData.PrepareSave done in 10 ms
[2024-02-04 09:30:55] 02/12/2024 18:33:38: World save writing starting
[2024-02-04 09:30:55] 02/12/2024 18:33:38: World save writing started
[2024-02-04 09:30:55] 02/12/2024 18:33:38: Saved 83716 ZDOs
[2024-02-04 09:30:55] 02/12/2024 18:33:38: World save writing finishing
[2024-02-04 09:30:55] 02/12/2024 18:33:38: World save writing finished
[2024-02-04 09:30:55] 02/12/2024 18:33:38: World saved ( 201.645ms )
[2024-02-04 09:30:55] 02/12/2024 18:41:42: Connections 0 ZDOS:83716 sent:0 recv:0
[2024-02-04 09:30:55] 02/12/2024 18:48:38: Sending message to save player profiles
[2024-02-04 09:30:55] 02/12/2024 18:48:38: PrepareSave: clone done in 13ms
[2024-02-04 09:30:55] 02/12/2024 18:48:38: PrepareSave: ZDOExtraData.PrepareSave done in 10 ms
[2024-02-04 09:30:55] 02/12/2024 18:48:38: World save writing starting
[2024-02-04 09:30:55] 02/12/2024 18:48:38: World save writing started
[2024-02-04 09:30:55] 02/12/2024 18:48:39: Saved 83716 ZDOs
[2024-02-04 09:30:55] 02/12/2024 18:48:39: World save writing finishing
[2024-02-04 09:30:55] 02/12/2024 18:48:39: World save writing finished
[2024-02-04 09:30:55] 02/12/2024 18:48:39: World saved ( 212.881ms )
```
### Steps to reproduce
1. set `logtimestamp="on"` in `lgsm/config-lgsm/gameserver/*.cfg`
2. start the gameserver
3. review `log/console/gameserver-console.log` and see the same timestamp (server star time) for all console entries regardless of how long has passed.
Contributor guide
Assessment
This issue has not been assessed yet.