search

marcsello / minecraftd

Minecraft server daemonizer for systemd compatiblity
MIT License
15 stars 5 forks source link

Console redirection crashes when the minecraft server output is "too fast". #4

Closed marcsello closed 5 years ago

marcsello commented 5 years ago

After a Huge Java exception occured, the output of the server was not visible on the attachable console. The entered commands are received by the server however.

Example:

$ minecraftd
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]
Caused by: java.lang.NoClassDefFoundError: com/sk89q/worldguard/bukkit/WGBukkit
    at me.craftwood.redstoneclockpreventer.RedstoneWGListener.onBlockRedstoneChange(RedstoneWGListener.java:17) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_191]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_191]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_191]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_191]
    at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:304) ~[spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    ... 51 more
[18:32:31 ERROR]: Could not pass event BlockRedstoneEvent to RedstoneClockPreventer v1.3.1
org.bukkit.event.EventException: null
    at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:308) ~[spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:500) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:485) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.BlockRedstoneWire.b(BlockRedstoneWire.java:224) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.BlockRedstoneWire.a(BlockRedstoneWire.java:158) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.BlockRedstoneWire.doPhysics(BlockRedstoneWire.java:353) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.IBlockData.doPhysics(SourceFile:241) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.World.a(World.java:545) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.World.applyPhysics(World.java:494) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
    at net.minecraft.server.v1_13_R2.BlockRedstoneWire.a(BlockRedstoneWire.java:167) [spigot-1.13.2.jar:git-Spigot-078a7f5-7fa173e]
list
list
say hello
marcsello commented 5 years ago

Okay, it seems like, that the issue is not caused by the java exception, more likely the fact, that this exception is repeated over and over for at least 650.000.000 lines (not kidding!) I think that caused some overflow, or deadlock.

marcsello commented 5 years ago

It seems like, some sort of exception is happened there. I've dug up the logs from that day, and found this stacktrace:

Dec 23 22:52:06 celestia minecraftd[27025]: 2018-12-23 22:52:06,336 - INFO: Minecraftd is starting...
Dec 23 22:52:07 celestia minecraftd[27025]: 2018-12-23 22:52:07,213 - INFO: New client connected!
Jan 19 21:40:11 celestia minecraftd[27025]: Traceback (most recent call last):
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/usr/local/bin/minecraftd", line 11, in <module>
Jan 19 21:40:11 celestia minecraftd[27025]:     load_entry_point('minecraftd', 'console_scripts', 'minecraftd')()
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/home/marcsello/minecraftd/minecraftd/__main__.py", line 96, in main
Jan 19 21:40:11 celestia minecraftd[27025]:     rc = runDaemon(cfg)
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/home/marcsello/minecraftd/minecraftd/__main__.py", line 42, in runDaemon
Jan 19 21:40:11 celestia minecraftd[27025]:     lp.passLine(l.decode('utf-8')) # line processor expects strings
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/home/marcsello/minecraftd/minecraftd/lineprocessor.py", line 44, in passLine
Jan 19 21:40:11 celestia minecraftd[27025]:     self._clientSwapper.sendLine(line) # expects utf-8 string
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/home/marcsello/minecraftd/minecraftd/clientswapper.py", line 54, in sendLine
Jan 19 21:40:11 celestia minecraftd[27025]:     self._sendDataToClient(line)
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/home/marcsello/minecraftd/minecraftd/clientswapper.py", line 41, in _sendDataToClient
Jan 19 21:40:11 celestia minecraftd[27025]:     self._client.sendLine(data)
Jan 19 21:40:11 celestia minecraftd[27025]:   File "/home/marcsello/minecraftd/minecraftd/client.py", line 33, in sendLine
Jan 19 21:40:11 celestia minecraftd[27025]:     self.sock.sendall(line.encode('utf-8'))
Jan 19 21:40:11 celestia minecraftd[27025]: BlockingIOError: [Errno 11] Resource temporarily unavailable
Jan 19 21:40:11 celestia minecraftd[27025]: 2019-01-19 21:40:11,904 - INFO: New client connected!
Jan 19 21:40:11 celestia minecraftd[27025]: 2019-01-19 21:40:11,904 - INFO: Previous session terminated
Jan 19 21:40:30 celestia minecraftd[27025]: 2019-01-19 21:40:30,128 - INFO: Client disconnected
Jan 19 21:40:31 celestia minecraftd[27025]: 2019-01-19 21:40:31,495 - INFO: New client connected!
Jan 19 21:40:33 celestia minecraftd[27025]: 2019-01-19 21:40:33,540 - INFO: Client disconnected
Jan 19 21:41:23 celestia minecraftd[27025]: 2019-01-19 21:41:23,081 - INFO: New client connected!
Jan 19 21:46:11 celestia minecraftd[27025]: 2019-01-19 21:46:11,075 - INFO: Client disconnected
Jan 19 21:46:12 celestia minecraftd[27025]: 2019-01-19 21:46:12,100 - INFO: New client connected!
Jan 19 21:46:20 celestia minecraftd[27025]: 2019-01-19 21:46:20,975 - INFO: Client disconnected

I've also created a simple java program that spams this error, to help me debug. With that I was able to produce the following crash:

2019-02-17 02:42:26,746 - INFO: Minecraftd is starting...
2019-02-17 02:42:31,512 - INFO: New client connected!
Traceback (most recent call last):
  File "/usr/lib/python3.5/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib/python3.5/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/marcsello/minecraftd/minecraftd/__main__.py", line 112, in <module>
    main()
  File "/home/marcsello/minecraftd/minecraftd/__main__.py", line 103, in main
    rc = runDaemon(cfg)
  File "/home/marcsello/minecraftd/minecraftd/__main__.py", line 43, in runDaemon
    lp.passLine(l.decode('utf-8')) # line processor expects strings
  File "/home/marcsello/minecraftd/minecraftd/lineprocessor.py", line 45, in passLine
    self._clientSwapper.sendLine(line) # expects utf-8 string
  File "/home/marcsello/minecraftd/minecraftd/clientswapper.py", line 54, in sendLine
    self._sendDataToClient(line)
  File "/home/marcsello/minecraftd/minecraftd/clientswapper.py", line 41, in _sendDataToClient
    self._client.sendLine(data)
  File "/home/marcsello/minecraftd/minecraftd/client.py", line 33, in sendLine
    self.sock.sendall(line.encode('utf-8'))
BlockingIOError: [Errno 11] Resource temporarily unavailable

This error happened just after attaching to the console. With the console detached, it was running fine. But I think when the crash happened, I've left the console attached in a tmux session.

It's visible on the logs however, that the last output visible on the console was around 18:32 and the exception happened at 21:40. But there is a new client message just after the exception, and the exceptions look very similar, so I still assume the crash happens when a client tries to connect.

marcsello commented 5 years ago

Fixed the above exception in 7fa66b6cd61f58247111969890eee1035255db9e. It was caused by the socket's non-blocking nature.

But fixing this revealed another bug related to concurrent threads, So I've opened a new branch for console spam related issue fixing: "spam-fix".

This issue is being worked on as well.

marcsello commented 5 years ago

Fixed everything in #5

Tested the concurrency issue, for about 500 random connect/disconnect. Everything was fine so I can finally close this issue.