search

itzg / docker-minecraft-server

Docker image that provides a Minecraft Server that will automatically download selected version at startup
https://docker-minecraft-server.readthedocs.io/
Apache License 2.0
9.89k stars 1.57k forks source link

Autopause being interrupted on an hourly basis #861

Closed mhbates closed 3 years ago

mhbates commented 3 years ago

Has anyone else experienced this? It started happening somewhat recently, probably in the last few months. Something is waking the server up about once an hour. I know that it could be something just knocking, but the Rcon line and the occasional bit about a client connecting (and no other info besides that, so likely not an actual client/player) has me thinking something else is going on. Any help is appreciated!

I think it's safe to ignore the HikariPool lines, that looks like it's just a thread watcher that one of my plugins uses.

EDIT: Looking at it again, it seems like the Rcon lines are just the final items before the server pauses again. So I guess my question is, how can I figure out what's knocking the server, and more importantly, why does it occasionally show a client as connecting, without any further information?

[11:12:06 WARN]: Can't keep up! Is the server overloaded? Running 3409884ms or 68197 ticks behind
[11:12:06 WARN]: [com.wfector.lib.hikari.pool.HikariPool] HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=56m51s399ms962µs170ns).
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - stopping
[11:14:08 INFO]: Thread RCON Client /127.0.0.1 started
[11:14:08 INFO]: [Rcon: Saved the game]
[11:14:08 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2021-05-11T11:14:08-0700] [Autopause] Pausing Java process
[12:12:21 WARN]: Can't keep up! Is the server overloaded? Running 3492368ms or 69847 ticks behind
[12:12:21 WARN]: [com.wfector.lib.hikari.pool.HikariPool] HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=58m14s84ms61µs724ns).
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - stopping
[12:14:22 INFO]: Thread RCON Client /127.0.0.1 started
[12:14:22 INFO]: [Rcon: Saved the game]
[12:14:22 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2021-05-11T12:14:22-0700] [Autopause] Pausing Java process
[13:08:41 WARN]: Can't keep up! Is the server overloaded? Running 3258930ms or 65178 ticks behind
[13:08:41 WARN]: [com.wfector.lib.hikari.pool.HikariPool] HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=54m20s510ms926µs815ns).
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] Client connected - waiting for disconnect
[Autopause loop] All clients disconnected - stopping in 300 seconds
[Autopause loop] No client reconnected - stopping
[13:14:03 INFO]: Thread RCON Client /127.0.0.1 started
[13:14:03 INFO]: [Rcon: Saved the game]
[13:14:03 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2021-05-11T13:14:03-0700] [Autopause] Pausing Java process
itzg commented 3 years ago

Do you happen to have an mc-backup container running alongside this?

mhbates commented 3 years ago

Do you happen to have an mc-backup container running alongside this?

No, I don't. By the way, the server is whitelist only, and whenever a player does join, it shows that in the log, with their name and so on. The "Client connected" thing is puzzling.

github-actions[bot] commented 3 years ago

This issue is stale because it has been open 30 days with no activity. Please add a comment describing the reason to keep this issue open.

kocane commented 2 years ago

@mhbates did you solve this? I seem to have the same issue.

mhbates commented 2 years ago

I did not unfortunately. I just ended up disabling autopause since the server was basically kept awake anyway.

kocane commented 2 years ago

@mhbates Hm, alright. Shame, I don't mind lowering that idle CPU usage.

@itzg Do you have any idea how this can be troubleshooted? My log looks similar.

[2022-08-26T04:15:00+02:00] [Autopause] Pausing Java process
[04:25:24 WARN]: Can't keep up! Is the server overloaded? Running 624169ms or 12483 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
@mhbates  Hm, alright. Shame, I don't mind lowering that idle CPU usage.
@itzg Do you have any idea how this can be troubleshooted? My log looks like this:
[2022-08-26T04:15:00+02:00] [Autopause] Pausing Java process
[04:25:24 WARN]: Can't keep up! Is the server overloaded? Running 624169ms or 12483 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[04:27:28 INFO]: Thread RCON Client /127.0.0.1 started
[04:27:28 INFO]: [Rcon: Saved the game]
[04:27:28 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T04:27:28+02:00] [Autopause] Pausing Java process
[05:19:03 WARN]: Can't keep up! Is the server overloaded? Running 3094787ms or 61895 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[05:21:07 INFO]: Thread RCON Client /127.0.0.1 started
[05:21:07 INFO]: [Rcon: Saved the game]
[05:21:07 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T05:21:07+02:00] [Autopause] Pausing Java process
[06:12:47 WARN]: Can't keep up! Is the server overloaded? Running 3099477ms or 61989 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[06:14:52 INFO]: Thread RCON Client /127.0.0.1 started
[06:14:52 INFO]: [Rcon: Saved the game]
[06:14:52 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T06:14:52+02:00] [Autopause] Pausing Java process
[07:06:15 WARN]: Can't keep up! Is the server overloaded? Running 3082985ms or 61659 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[07:08:20 INFO]: Thread RCON Client /127.0.0.1 started
[07:08:20 INFO]: [Rcon: Saved the game]
[07:08:20 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T07:08:20+02:00] [Autopause] Pausing Java process
[07:59:43 WARN]: Can't keep up! Is the server overloaded? Running 3083291ms or 61665 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[08:01:43 INFO]: Thread RCON Client /127.0.0.1 started
[08:01:43 INFO]: [Rcon: Saved the game]
[08:01:43 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T08:01:43+02:00] [Autopause] Pausing Java process
[08:12:45 WARN]: Can't keep up! Is the server overloaded? Running 661919ms or 13238 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[04:27:28 INFO]: Thread RCON Client /127.0.0.1 started
[04:27:28 INFO]: [Rcon: Saved the game]
[04:27:28 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T04:27:28+02:00] [Autopause] Pausing Java process
[05:19:03 WARN]: Can't keep up! Is the server overloaded? Running 3094787ms or 61895 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[05:21:07 INFO]: Thread RCON Client /127.0.0.1 started
[05:21:07 INFO]: [Rcon: Saved the game]
[05:21:07 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T05:21:07+02:00] [Autopause] Pausing Java process
[06:12:47 WARN]: Can't keep up! Is the server overloaded? Running 3099477ms or 61989 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[06:14:52 INFO]: Thread RCON Client /127.0.0.1 started
[06:14:52 INFO]: [Rcon: Saved the game]
[06:14:52 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T06:14:52+02:00] [Autopause] Pausing Java process
[07:06:15 WARN]: Can't keep up! Is the server overloaded? Running 3082985ms or 61659 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[07:08:20 INFO]: Thread RCON Client /127.0.0.1 started
[07:08:20 INFO]: [Rcon: Saved the game]
[07:08:20 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T07:08:20+02:00] [Autopause] Pausing Java process
[07:59:43 WARN]: Can't keep up! Is the server overloaded? Running 3083291ms or 61665 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout
[Autopause loop] No client connected since startup / knocked - pausing
[08:01:43 INFO]: Thread RCON Client /127.0.0.1 started
[08:01:43 INFO]: [Rcon: Saved the game]
[08:01:43 INFO]: Thread RCON Client /127.0.0.1 shutting down
[2022-08-26T08:01:43+02:00] [Autopause] Pausing Java process
[08:12:45 WARN]: Can't keep up! Is the server overloaded? Running 661919ms or 13238 ticks behind
[Autopause loop] Server was knocked - waiting for clients or timeout

I don't have any tools running and there's only one other guy who knows about the server.

itzg commented 2 years ago

I just noticed the address of the knocker can be passed to the resume script. So, I'll adjust the code to log that and that will help.

kocane commented 2 years ago

I just noticed the address of the knocker can be passed to the resume script. So, I'll adjust the code to log that and that will help.

Awesome, thanks. Is there a way for me to enable it already now?

itzg commented 2 years ago

Oh no, this issue fell of my radar. Thanks for the ping @kocane and I'll post here when the debug info is available.

itzg commented 2 years ago

@kocane the latest image will now show the IP address of the knocker. If the origin was external, the address may not be useful due to NAT'ing within the docker network bridge.

kocane commented 2 years ago

@kocane the latest image will now show the IP address of the knocker. If the origin was external, the address may not be useful due to NAT'ing within the docker network bridge.

Thanks! Works exactly like it should and I found the culprit.

kocane commented 2 years ago

@itzg I'm still seeing some random wakeups (but far fewer now) once in a while. Looking at the IPs it's typically port scanners. I don't suppose there's much to do about that aside from IP whitelisting in the firewall? Could the autopause function be made so it takes 2 knocks on the server, within a small time frame, before it reacts? Maybe it's just overcomplicating it.

itzg commented 2 years ago

Could the autopause function be made so it takes 2 knocks on the server, within a small time frame, before it reacts? Maybe it's just overcomplicating it.

Yes could be done, but the usability of that seems annoying.

urwrstkn8mare commented 2 years ago

Hi, I'm having the exact same thing, how do I see the IP addresses?

urwrstkn8mare commented 2 years ago

Oh, I restarted the container, and it works now. Turns out it's someone from Paris (https://whatismyipaddress.com/ip/163.172.139.143) and has a history of trying to join/ping Minecraft server. I'm guessing this can't be fixed, but is there some sort of IP blacklist that the container can use that lies before the knock detector thing?

RomanSonnik commented 4 months ago

I dont have ip information in docker-compose container [02:17:49] [Server thread/WARN]: Can't keep up! Is the server overloaded? Running 3240ms or 64 ticks behind mc-1 | [02:17:49] [RCON Client /0:0:0:0:0:0:0:1 #43/INFO]: Thread RCON Client /0:0:0:0:0:0:0:1 shutting down mc-1 | [2024-07-15T02:17:49+00:00] [Autopause] Pausing Java process mc-1 | [02:20:13] [Server thread/WARN]: Can't keep up! Is the server overloaded? Running 129193ms or 2583 ticks behind mc-1 | [Autopause loop] Server was knocked - waiting for clients or timeout mc-1 | [Autopause loop] No client connected since startup / knocked - pausing mc-1 | [02:22:16] [RCON Listener #1/INFO]: Thread RCON Client /0:0:0:0:0:0:0:1 started

kawazoe commented 1 month ago

@itzg Hello. I know this issue has been closed for a while, but I'm getting the same problem and I don't see any info about the incoming IP in the logs. Was this feature removed?

itzg commented 1 month ago

Yes, knockd was never correctly providing the remote IP address, so I removed it from logging since it was misleading.