msh crashes when emulating ping

Nannk commented 1 year ago

Current Behavior (🐛 Bug)

Msh crashes wth runtime error after minecraft server is stopped by msh when 0 players are present.

Occured 2 times in 1 month. First time msh would not restart at all. Fetching the latest version(for that time - 2.4.4) helped. The second time it was able to restart after the crash.

Note: im running it as a systemd service, so no stdinput is available: msh outputs on start: 2023/02/03 09:44:48 [error *** ] GetInput: stdin unavailable, exiting input goroutine

Expected Behavior

Msh still running after server shutdown.

Steps to Reproduce

Disconnect from the server for msh to shut it down. Seems to occur randomly.

MSH Logs

Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [info  *** ] retrieving  player count...
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [info  *** ] 0 online players - method for player count: server info
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [serv  **  ] terminal execute: stop        (origin: StopMS)
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [serv  **  ] [10:06:46] [Server thread/INFO]: Stopping the server
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [info  *** ] MINECRAFT SERVER IS STOPPING!
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [serv  **  ] [10:06:46] [Thread-15/INFO]: Voice UDP server stopped
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [serv  **  ] [10:06:46] [Server thread/INFO]: Stopping server
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [serv  **  ] [10:06:46] [Server thread/INFO]: Saving players
Feb 01 10:06:46 server msh[1445]: 2023/02/01 10:06:46 [serv  **  ] [10:06:46] [Server thread/INFO]: Saving worlds
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:overworld
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:the_end
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:the_nether
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: ThreadedAnvilChunkStorage: All dimensions are saved
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Unloading addons...
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Unloaded addons
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Unloading instance: net.dv8tion.jda.internal.JDAImpl@20ca29b6
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Unloading listener: de.erdbeerbaerlp.dcintegration.common.DiscordEventListener@49dacae0
Feb 01 10:06:48 server msh[1445]: 2023/02/01 10:06:48 [serv  **  ] [10:06:48] [Server thread/INFO]: Thread RCON Listener stopped
Feb 01 10:06:49 server msh[1445]: 2023/02/01 10:06:49 [info  *** ] MINECRAFT SERVER IS OFFLINE!
Feb 02 22:40:35 server msh[1445]: panic: runtime error: slice bounds out of range [:-1]
Feb 02 22:40:35 server msh[1445]: goroutine 286 [running]:
Feb 02 22:40:35 server msh[1445]: internal_1poll.FD.Write
Feb 02 22:40:35 server msh[1445]:         ../../../src/libgo/go/internal/poll/fd_unix.go:274
Feb 02 22:40:35 server msh[1445]: net.netFD.Write
Feb 02 22:40:35 server msh[1445]:         ../../../src/libgo/go/net/fd_posix.go:73
Feb 02 22:40:35 server msh[1445]: net.conn.Write
Feb 02 22:40:35 server msh[1445]:         ../../../src/libgo/go/net/net.go:195
Feb 02 22:40:35 server msh[1445]: msh/lib/conn.getPing
Feb 02 22:40:35 server msh[1445]:         /var/Minecraft/build/minecraft-server-hibernation/lib/conn/conn-prot.go:150
Feb 02 22:40:35 server msh[1445]: msh_1lib_1conn.HandleClientSocket
Feb 02 22:40:35 server msh[1445]:         /var/Minecraft/build/minecraft-server-hibernation/lib/conn/conn.go:43
Feb 02 22:40:35 server msh[1445]: created by main.main
Feb 02 22:40:35 server msh[1445]:         /var/Minecraft/build/minecraft-server-hibernation/minecraft-server-hibernation.go:72 +0x441
Feb 02 22:40:35 server systemd[1]: minecraftserver.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Feb 02 22:40:35 server systemd[1]: minecraftserver.service: Failed with result 'exit-code'.

MSH-Version

2.4.4

Operating system

Ubuntu 22.04.1 LTS

System architecture?

AMD64

Minecraft Version

1.19.3

Minecraft Server Software?

Fabric

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

Would you mind keep testing with the latest version?

v2.4.4 is quite old now, v2.4.12 would be best

Might be kinda similar to #156 even though this time the panic seems to be generated from golang internal package in this case.

Setting log level to 4 might be of great help as we would see the ping packet data that is causing trouble, but since you tell me its very rare you might endup with some gb worth of data logs LOL.

Nannk commented 1 year ago

Ill update asap.

(apparently i didnt update at all because i pulled the repo, but didnt build)

gekigek99 commented 1 year ago

@Nannk any updates?

gekigek99 commented 1 year ago

I'll close the issue for now, feel free to reopen it again if you experience again this problem.

Nannk commented 1 year ago

There were no instances of it happening again. Ill notify you if it will.

Nannk commented 1 year ago

got this today:

Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [info  ≡≡≡ ] performing scheduled ms soft freeze
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [info  ≡≡≡ ] 0 online players - method for player count: server info
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [info  ≡≡  ] ms command: stop        (origin: resumeStopMS)
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [serv ≡≡  ] [15:59:11] [Server thread/INFO]: Stopping the server
Feb 27 15:59:11 nannkserver msh[1289]: 
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [info  ≡≡≡ ] MINECRAFT SERVER IS STOPPING!
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [serv ≡≡  ] [15:59:11] [Thread-9/INFO]: Voice UDP server stopped
Feb 27 15:59:11 nannkserver msh[1289]: 
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [serv ≡≡  ] [15:59:11] [Server thread/INFO]: Stopping server
Feb 27 15:59:11 nannkserver msh[1289]: 
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [serv ≡≡  ] [15:59:11] [Server thread/INFO]: Saving players
Feb 27 15:59:11 nannkserver msh[1289]: 
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [serv ≡≡  ] [15:59:11] [Server thread/INFO]: Saving worlds
Feb 27 15:59:11 nannkserver msh[1289]: 
Feb 27 15:59:11 nannkserver msh[1289]: 2023/02/27 15:59:11 [serv ≡≡  ] [15:59:11] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:overworld
Feb 27 15:59:11 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:the_end
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:the_nether
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: ThreadedAnvilChunkStorage: All dimensions are saved
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Unloading addons...
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Unloaded addons
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Unloading instance: net.dv8tion.jda.internal.JDAImpl@2c65443d
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Unloading listener: de.erdbeerbaerlp.dcintegration.common.DiscordEventListener@4d2e9647
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:12 nannkserver msh[1289]: 2023/02/27 15:59:12 [serv ≡≡  ] [15:59:12] [Server thread/INFO]: Thread RCON Listener stopped
Feb 27 15:59:12 nannkserver msh[1289]: 
Feb 27 15:59:13 nannkserver msh[1289]: 2023/02/27 15:59:13 [info  ≡≡≡ ] MINECRAFT SERVER IS OFFLINE!
Feb 27 16:29:48 nannkserver msh[1289]: 2023/02/27 16:29:48 [warn  ≡≡≡≡] sgmMgr: msh (v2.4.12) is running an unofficial release [01f000]
Feb 27 19:27:32 nannkserver msh[1289]: panic: runtime error: slice bounds out of range [2:1]
Feb 27 19:27:32 nannkserver msh[1289]: goroutine 183909 [running]:
Feb 27 19:27:32 nannkserver msh[1289]: msh/lib/conn.getPing({0x7d93a8, 0xc000114170})
Feb 27 19:27:32 nannkserver msh[1289]:         /var/Minecraft/build/minecraft-server-hibernation/lib/conn/conn-prot.go:188 +0x2c6
Feb 27 19:27:32 nannkserver msh[1289]: msh/lib/conn.HandlerClientConn({0x7d93a8, 0xc000114170})
Feb 27 19:27:32 nannkserver msh[1289]:         /var/Minecraft/build/minecraft-server-hibernation/lib/conn/conn.go:87 +0xc71
Feb 27 19:27:32 nannkserver msh[1289]: created by main.main
Feb 27 19:27:32 nannkserver msh[1289]:         /var/Minecraft/build/minecraft-server-hibernation/minecraft-server-hibernation.go:81 +0x392
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Failed with result 'exit-code'.
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Consumed 1h 47.101s CPU time.
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Consumed 1h 47.101s CPU time.

gekigek99 commented 1 year ago

What commit are you using?

Since it's a network thing, is it possible to set loglevel to 4 (record each sing packet) and only keep the last 1000 logs lines? (To not generate an enormous file)

Nannk commented 1 year ago

I set log file size to 2G with journalctl -u minecraftserver.service --vacuum-size=2G

the commit:

>> git log --name-status HEAD^..HEAD
commit 1e2972906697e73fe5480a01a71b02b62b9428fd (HEAD -> dev, origin/dev)
Author: gekigek99 <53654579+gekigek99@users.noreply.github.com>
Date:   Sun Feb 12 23:11:46 2023 +0100

    msh: added vendor folder

gekigek99 commented 1 year ago

I'll see if I can reproduce: I have an idea but the logs containing the packet would be resolutive (95% sure)

after server is stopped

means that a command was given to msh or msh was shutting ms down by itself?
are you sure that the stopping of the ms is correlated with this error? (cause the explanation that I'm thinking of right now has nothing to do with ms shutting down but with a faulty ping packet)

Nannk commented 1 year ago

Im not sure it is correlated with server stopping, because both times it happened it was after some time after the server was stopped. (I dont have the logs from the first crash, thus not sure if it was immediately after shutdown.) You can see that in the logs i provided above. But im sure that every time crash happened, the server was down. Msh was shutting down the server due to inactivity.

Ill provide the logs when i get the crash again.

gekigek99 commented 1 year ago

sorry for the silly question, it's clear from the logs:

Feb 27 15:59:13 nannkserver msh[1289]: 2023/02/27 15:59:13 [info  ≡≡≡ ] MINECRAFT SERVER IS OFFLINE!
Feb 27 16:29:48 nannkserver msh[1289]: 2023/02/27 16:29:48 [warn  ≡≡≡≡] sgmMgr: msh (v2.4.12) is running an unofficial release [01f000]
Feb 27 19:27:32 nannkserver msh[1289]: panic: runtime error: slice bounds out of range [2:1]

the times are very far apart

But im sure that every time crash happened, the server was down.

this is because getPing() is only called when server is offline

Ill provide the logs when i get the crash again.

ok perfect, they are the only ones that can clear what's happening

Nannk commented 1 year ago

uff didnt know about syslog and now its 10Gigabytes

gekigek99 commented 1 year ago

ahah LOL anyway just managed to reproduce it, it was what I was thinking: it should be an easy fix.

But... having the connection bytes log would allow for not only solving the problem but also understand better this variant (msh can analyze the ping packet and not make the request fail as an unknown packet)

just to be clear, I reproduced this log (not the one in the first message of the issue):

Feb 27 19:27:32 nannkserver msh[1289]: panic: runtime error: slice bounds out of range [2:1]
Feb 27 19:27:32 nannkserver msh[1289]: goroutine 183909 [running]:
Feb 27 19:27:32 nannkserver msh[1289]: msh/lib/conn.getPing({0x7d93a8, 0xc000114170})
Feb 27 19:27:32 nannkserver msh[1289]:         /var/Minecraft/build/minecraft-server-hibernation/lib/conn/conn-prot.go:188 +0x2c6
Feb 27 19:27:32 nannkserver msh[1289]: msh/lib/conn.HandlerClientConn({0x7d93a8, 0xc000114170})
Feb 27 19:27:32 nannkserver msh[1289]:         /var/Minecraft/build/minecraft-server-hibernation/lib/conn/conn.go:87 +0xc71
Feb 27 19:27:32 nannkserver msh[1289]: created by main.main
Feb 27 19:27:32 nannkserver msh[1289]:         /var/Minecraft/build/minecraft-server-hibernation/minecraft-server-hibernation.go:81 +0x392
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Failed with result 'exit-code'.
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Consumed 1h 47.101s CPU time.
Feb 27 19:27:32 nannkserver systemd[1]: minecraftserver.service: Consumed 1h 47.101s CPU time.

gekigek99 commented 1 year ago

fixed in 9247fae817fbe84943c1d654372a90ddf9562235

I know what the packet causing the issue contained, but now I would still like to see the connection bytes after the fix.

(msh should not crash anymore but might receive a second (and correct) ping packet, interpreting it as a client request with a "client request unknown" error)

gekigek99 commented 1 year ago

forgot to consider that the 99% of cases there are normal pings LOL ( [9 1 0 0 0 0 0 89 73 114] )

fixed in 22b0877179ec84e208f8f93f015373d0142c4099

gekigek99 commented 1 year ago

closing the issue

@Nannk if you find the error reoccurring please reopen the issue

melgu commented 1 year ago

When can we expect the 2.5.0 update with this fix, if I may ask?

gekigek99 commented 1 year ago

I finished every bugfix and improvement I wanted to do before 2.5.0

Unless a bug comes out, I would say that it will be published within next week.

In the meantime, you can download the latest build here.

If you are hosting servers and need support we can chat on the discord server.

Nannk commented 1 year ago

Server did not crash in those 3 weeks, i will update to stable and stop writing detailed logs.

gekware / minecraft-server-hibernation