Autopause logs

[Oekn5w]

The redirection is not necessary and might be the cause to reported problems. Also wrapping the logging to corresponding functions

[Oekn5w]

@eihns and @MoustacheMonkey, can you please build this container and see, if the logging issue is resolved. As I mentioned in #531 I don't know enough to reproduce this issue on my system

[itzg]

I built and pushed an image of this PR's changes to itzg/minecraft-server:test-pr-539

[itzg]

Looks good especially since I wasn't totally understanding the "terminal-mc" bits. Let's see how testing goes for others.

[CurlyFlow]

Working perfectly, i dont know if it has something to do because im using unraid. Btw, any news for porting it to unraid template? :D

[Autopause loop] MC Server listening for connections - stopping in 600 seconds
[02:29:02] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:02] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:02] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:02] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:05] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:05] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:05] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:05] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:05] [Server thread/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-2/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-2/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-7/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-7/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-4/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-7/INFO]: Preparing spawn area: 0%
[02:29:08] [Worker-6/INFO]: Preparing spawn area: 0%
[02:29:09] [Server thread/INFO]: Time elapsed: 7926 ms
[02:29:09] [Server thread/INFO]: Done (10.479s)! For help, type "help"
[02:29:09] [Server thread/INFO]: Starting remote control listener
[02:29:09] [Server thread/INFO]: Thread RCON Listener started
[02:29:09] [RCON Listener #1/INFO]: RCON running on 0.0.0.0:25575
[Autopause loop] No client connected since startup / knocked - stopping
[02:39:02] [RCON Listener #1/INFO]: Thread RCON Client /127.0.0.1 started
[02:39:02] [Server thread/INFO]: [Rcon: Saved the game]
[02:39:02] [RCON Client /127.0.0.1 #2/INFO]: Thread RCON Client /127.0.0.1 shutting down
[2020-05-23T02:39:02+0200] [Autopause] Pausing Java process
[02:50:23] [Server thread/WARN]: Can't keep up! Is the server overloaded? Running 681028ms or 13620 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[02:50:31] [User Authenticator #1/INFO]: UUID of player XXX
[02:50:31] [Server thread/INFO]: XXX
[02:50:31] [Server thread/INFO]: XXX joined the game
[Autopause loop] Client connected - waiting for disconnect
[02:50:39] [Server thread/INFO]: XXX lost connection: Disconnected
[02:50:39] [Server thread/INFO]: XXX left the game
[Autopause loop] All clients disconnected - stopping in 3600 seconds

[Oekn5w]

Mmh, it's missing the resume action log from knockd, directly after pausing there should be a similar entry about resuming

[CurlyFlow]

Only "problem" i see now is the running ticks behind thing. How does he know that? Is it time? Could it be paused without these "normal" "error" (so that normal crash detection doenst get broken?)

[itzg]

@eihns yeah, it's always going to report that since with every tick it probably tracks the current time with this and then when un-pausing it can tell a bunch of time has passed since it last recorded a game tick.

[itzg]

This update is now pushed to the main image itzg/minecraft-server:latest

[CurlyFlow]

@eihns yeah, it's always going to report that since with every tick it probably tracks the current time with this and then when un-pausing it can tell a bunch of time has passed since it last recorded a game tick.

Yes, i know, maybe manipulate time? Would that be possible? Like freeze time also? i guess time isnt very important inside the docker!?

[MoustacheMonkey]

Logging is working, thanks for the fix!

[Autopause loop] MC Server listening for connections - stopping in 600 seconds
[10:06:59] [Server-Worker-7/INFO]: Preparing spawn area: 0%
_..redacted.._
[10:07:04] [Server thread/INFO]: Time elapsed: 7911 ms
[10:07:04] [Server thread/INFO]: Done (9.054s)! For help, type "help"
[10:07:04] [Server thread/INFO]: Starting remote control listener
[10:07:04] [RCON Listener #1/INFO]: RCON running on 0.0.0.0:25575
[Autopause loop] No client connected since startup / knocked - stopping
[10:16:59] [RCON Listener #1/INFO]: Rcon connection from: /127.0.0.1
[10:16:59] [Server thread/INFO]: [Rcon: Saved the game]
[2020-05-23T10:16:59+0200] [Autopause] Pausing Java process
[10:29:58] [Server thread/WARN]: Can't keep up! Is the server overloaded? Running 778529ms or 15570 ticks behind
[Autopause loop] Client connected - waiting for disconnect
[10:30:00] [User Authenticator #1/INFO]: UUID of player _Redacted_ is _Redacted_
[10:30:00] [Server thread/INFO]: _Redacted_ [/_Redacted_] logged in with entity id 125 at (248.5, 71.0, -121.5)
[10:30:00] [Server thread/INFO]: _Redacted_ joined the game
[10:30:09] [Server thread/INFO]: _Redacted_ lost connection: Disconnected
[10:30:09] [Server thread/INFO]: _Redacted_ left the game
[Autopause loop] All clients disconnected - stopping in 3600 seconds
[Autopause loop] No client reconnected - stopping
[11:30:22] [RCON Listener #1/INFO]: Rcon connection from: /127.0.0.1
[11:30:22] [Server thread/INFO]: [Rcon: Saved the game]
[2020-05-23T11:30:22+0200] [Autopause] Pausing Java process