search

jpenilla / chesscraft

Paper plugin adding in-world chess matches against players and chess engines (CPUs) to Minecraft
https://modrinth.com/plugin/chesscraft
Apache License 2.0
19 stars 2 forks source link

Stack trace on failed connection to chess server #8

Closed SlimeDog closed 1 year ago

SlimeDog commented 1 year ago

There are any number of reasons why the connection might fail, but in this case it is enforced by NetworkInterceptor. If I disable NetworkInterceptor, the connection succeeds.

Paper 1.19.3-403 ChessCraft 0.1.0 NetworkInterceptor 3.2.1 configured to allow outbound connections to

mode: allow

trusted-plugins:
  - ChessCraft

targets:
  # ChessCraft
  - 'stockfishchess.org'
  - '104.25.158.9'
[09:30:38] [Server thread/INFO]: SlimeDog issued server command: /chess create_board one west
[09:30:47] [Server thread/INFO]: SlimeDog issued server command: /chess set_checkerboard one
[09:31:57] [Server thread/INFO]: SlimeDog issued server command: /chess challenge cpu one white 1500
[09:31:57 WARN]: xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.exceptions.StockfishEngineException: java.io.IOException: Broken pipe
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.sendCommand(UCIEngine.java:67)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.passOption(UCIEngine.java:104)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.<init>(UCIEngine.java:41)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.Stockfish.<init>(Stockfish.java:28)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.StockfishClient.<init>(StockfishClient.java:61)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.StockfishClient$Builder.build(StockfishClient.java:155)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.ChessGame.createStockfishClient(ChessGame.java:379)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.ChessGame.<init>(ChessGame.java:77)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.ChessBoard.startGame(ChessBoard.java:170)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.command.Commands.challengeCpu(Commands.java:221)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.execution.CommandExecutionHandler.executeFuture(CommandExecutionHandler.java:95)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.execution.CommandExecutionCoordinator$SimpleCoordinator.coordinateExecution(CommandExecutionCoordinator.java:123)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.CommandManager.executeCommand(CommandManager.java:189)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.bukkit.BukkitCommand.execute(BukkitCommand.java:116)
[09:31:57 WARN]:        at org.bukkit.command.SimpleCommandMap.dispatch(SimpleCommandMap.java:155)
[09:31:57 WARN]:        at org.bukkit.craftbukkit.v1_19_R2.CraftServer.dispatchCommand(CraftServer.java:930)
[09:31:57 WARN]:        at org.bukkit.craftbukkit.v1_19_R2.command.BukkitCommandWrapper.run(BukkitCommandWrapper.java:64)
[09:31:57 WARN]:        at com.mojang.brigadier.CommandDispatcher.execute(CommandDispatcher.java:264)
[09:31:57 WARN]:        at net.minecraft.commands.CommandDispatcher.performCommand(CommandDispatcher.java:313)
[09:31:57 WARN]:        at net.minecraft.commands.CommandDispatcher.a(CommandDispatcher.java:297)
[09:31:57 WARN]:        at net.minecraft.server.network.PlayerConnection.a(PlayerConnection.java:2288)
[09:31:57 WARN]:        at net.minecraft.server.network.PlayerConnection.lambda$handleChatCommand$20(PlayerConnection.java:2248)
[09:31:57 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.b(IAsyncTaskHandler.java:59)
[09:31:57 WARN]:        at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
[09:31:57 WARN]:        at net.minecraft.server.TickTask.run(TickTask.java:18)
[09:31:57 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.d(IAsyncTaskHandler.java:153)
[09:31:57 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandlerReentrant.d(IAsyncTaskHandlerReentrant.java:24)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.b(MinecraftServer.java:1341)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.d(MinecraftServer.java:197)
[09:31:57 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.x(IAsyncTaskHandler.java:126)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.bh(MinecraftServer.java:1318)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.x(MinecraftServer.java:1311)
[09:31:57 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.c(IAsyncTaskHandler.java:136)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.i_(MinecraftServer.java:1289)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.w(MinecraftServer.java:1177)
[09:31:57 WARN]:        at net.minecraft.server.MinecraftServer.lambda$spin$0(MinecraftServer.java:316)
[09:31:57 WARN]:        at java.base/java.lang.Thread.run(Thread.java:1589)
[09:31:57 WARN]: Caused by: java.io.IOException: Broken pipe
[09:31:57 WARN]:        at java.base/java.io.FileOutputStream.writeBytes(Native Method)
[09:31:57 WARN]:        at java.base/java.io.FileOutputStream.write(FileOutputStream.java:372)
[09:31:57 WARN]:        at java.base/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:125)
[09:31:57 WARN]:        at java.base/java.io.BufferedOutputStream.implFlush(BufferedOutputStream.java:251)
[09:31:57 WARN]:        at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:245)
[09:31:57 WARN]:        at java.base/sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:416)
[09:31:57 WARN]:        at java.base/sun.nio.cs.StreamEncoder.lockedFlush(StreamEncoder.java:218)
[09:31:57 WARN]:        at java.base/sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:205)
[09:31:57 WARN]:        at java.base/java.io.OutputStreamWriter.flush(OutputStreamWriter.java:263)
[09:31:57 WARN]:        at java.base/java.io.BufferedWriter.implFlush(BufferedWriter.java:372)
[09:31:57 WARN]:        at java.base/java.io.BufferedWriter.flush(BufferedWriter.java:359)
[09:31:57 WARN]:        at ChessCraft-0.1.0.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.sendCommand(UCIEngine.java:65)
[09:31:57 WARN]:        ... 36 more
jpenilla commented 1 year ago

The connection to stockfish is documented in the readme, if only implicitly and not explicitly. When there's a wiki setup more in-depth info could be put there.

As for the connection to the chess engine, it's done here: https://github.com/jpenilla/Stockfish-Java/blob/00fce8f4466af4e31d0692eff4d382e23e60009c/src/main/java/xyz/niflheim/stockfish/engine/UCIEngine.java#L35, it's just getting the input/output stream of the process. So if that's a network connection it's a JVM impl detail.

0.1.1-SNAPSHOT+ will also connect to bStats.

SlimeDog commented 1 year ago

After further testing, I think this has nothing to do with where I am standing. The same chess challenge command sometimes fails (with stack trace) and succeeds moments later. I will continue to attempt to refine a recipe. Any hints appreciated.

SlimeDog commented 1 year ago

I've performed scores of tests now

The pattern is fairly consistent: the first attempt at chess challenge usually fails; another a second later succeeds (I use / upArrow CR, so the delay is pretty short). It feels like a timing issue between somewhere in the transit from my client to my server to the chess server and back, resulting in a broken pipe. Average ping from my servers to stockfishchess.com is 9.5 ms, with no dropped packets. Average ping from my client to my servers is 22 ms, with no dropped packets.

jpenilla commented 1 year ago

Let me know how the log changes with the last commit to master

(can download the actions artifact here)

It's meant to give a better error output, not to fix the problem entirely. But it could do both or neither.

SlimeDog commented 1 year ago

Paper 1.19.3-407 ChessCraft 0.1.1-SNAPSHOT

Set-up commands:

/chess create_board one west
/chess set_checkerboard one

Attempt to start game, repeatedly:

/chess challenge cpu one white 800

In-game

An internal error occurred while attempting to perform this command.

Stack trace

[06:50:39 WARN]: java.lang.RuntimeException: Failed to initialize and/or connect to chess engine process
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.ChessGame.<init>(ChessGame.java:87)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.ChessBoard.startGame(ChessBoard.java:182)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.command.Commands.challengeCpu(Commands.java:239)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.execution.CommandExecutionHandler.executeFuture(CommandExecutionHandler.java:95)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.execution.CommandExecutionCoordinator$SimpleCoordinator.coordinateExecution(CommandExecutionCoordinator.java:123)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.CommandManager.executeCommand(CommandManager.java:189)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.cloud.commandframework.bukkit.BukkitCommand.execute(BukkitCommand.java:116)
[06:50:39 WARN]:        at org.bukkit.command.SimpleCommandMap.dispatch(SimpleCommandMap.java:155)
[06:50:39 WARN]:        at org.bukkit.craftbukkit.v1_19_R2.CraftServer.dispatchCommand(CraftServer.java:912)
[06:50:39 WARN]:        at org.bukkit.craftbukkit.v1_19_R2.command.BukkitCommandWrapper.run(BukkitCommandWrapper.java:64)
[06:50:39 WARN]:        at com.mojang.brigadier.CommandDispatcher.execute(CommandDispatcher.java:264)
[06:50:39 WARN]:        at net.minecraft.commands.CommandDispatcher.performCommand(CommandDispatcher.java:316)
[06:50:39 WARN]:        at net.minecraft.commands.CommandDispatcher.a(CommandDispatcher.java:300)
[06:50:39 WARN]:        at net.minecraft.server.network.PlayerConnection.a(PlayerConnection.java:2288)
[06:50:39 WARN]:        at net.minecraft.server.network.PlayerConnection.lambda$handleChatCommand$20(PlayerConnection.java:2248)
[06:50:39 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.b(IAsyncTaskHandler.java:59)
[06:50:39 WARN]:        at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
[06:50:39 WARN]:        at net.minecraft.server.TickTask.run(TickTask.java:18)
[06:50:39 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.d(IAsyncTaskHandler.java:153)
[06:50:39 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandlerReentrant.d(IAsyncTaskHandlerReentrant.java:24)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.b(MinecraftServer.java:1341)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.d(MinecraftServer.java:197)
[06:50:39 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.x(IAsyncTaskHandler.java:126)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.bh(MinecraftServer.java:1318)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.x(MinecraftServer.java:1311)
[06:50:39 WARN]:        at net.minecraft.util.thread.IAsyncTaskHandler.bq(IAsyncTaskHandler.java:114)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.a(MinecraftServer.java:1445)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.w(MinecraftServer.java:1173)
[06:50:39 WARN]:        at net.minecraft.server.MinecraftServer.lambda$spin$0(MinecraftServer.java:316)
[06:50:39 WARN]:        at java.base/java.lang.Thread.run(Thread.java:1589)
[06:50:39 WARN]: Caused by: xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.exceptions.StockfishInitException: Unable to start and bind Stockfish process.
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.<init>(UCIEngine.java:48)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.Stockfish.<init>(Stockfish.java:28)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.StockfishClient.<init>(StockfishClient.java:61)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.StockfishClient$Builder.build(StockfishClient.java:155)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.ChessGame.createStockfishClient(ChessGame.java:378)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.ChessGame.<init>(ChessGame.java:85)
[06:50:39 WARN]:        ... 29 more
[06:50:39 WARN]: Caused by: xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.exceptions.StockfishEngineException: Can not find expected line: 'readyok' in output: [/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libm.so.6: version `GLIBC_2.29' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64), /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `CXXABI_1.3.9' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64), /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `GLIBCXX_3.4.26' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64), /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `CXXABI_1.3.11' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64), /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `GLIBCXX_3.4.22' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64), /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `GLIBCXX_3.4.21' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64)]
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.readResponse(UCIEngine.java:100)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.waitForReady(UCIEngine.java:54)
[06:50:39 WARN]:        at ChessCraft-0.1.1.jar//xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.engine.UCIEngine.<init>(UCIEngine.java:43)
[06:50:39 WARN]:        ... 34 more
jpenilla commented 1 year ago

Expanding the error message:

[06:50:39 WARN]: Caused by: xyz.jpenilla.chesscraft.dependency.xyz.niflheim.stockfish.exceptions.StockfishEngineException: Can not find expected line: 'readyok' in output: [
/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libm.so.6: version `GLIBC_2.29' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64),
/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `CXXABI_1.3.9' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64),
/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `GLIBCXX_3.4.26' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64),
/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `CXXABI_1.3.11' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64),
/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `GLIBCXX_3.4.22' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64),
/home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64: /lib64/libstdc++.so.6: version `GLIBCXX_3.4.21' not found (required by /home/ram/MC/plugins/ChessCraft/engines/managed/stockfish_15.1_linux_x64)
]

Your system is either missing or has the wrong versions of libraries used by Stockfish. A couple of possible solutions:

SlimeDog commented 1 year ago

I am a simple server owner. I am running a standard CentOS system, completely up-to-date, insofar as yum reports (and server owners with no access to what is loaded on their systems do not even have that option).

stockfish_1.15.1_linux_x64 is provided by ChessCraft. It did not change, and my system libraries did not change, between ChessCraft 0.1.0 and 0.1.1, so I don't understand how the requirements have changed.

jpenilla commented 1 year ago

The requirements did not change. It simply prints the error stream where it didn't before.

Sadly I don't have a magic wand to wave that will make native programs as portable as Java ones. ChessCraft does a best-effort attempt to match your system with one of Stockfish's prebuilt binaries, if it fails for your system you'll have to step in.

SlimeDog commented 1 year ago

Of course. Any hints as to which version of stockfish I should run, or is it trial-and-error?

SlimeDog commented 1 year ago

I am not able to build anything recent with my easily-available compilers

$ gcc --version
gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44)
Copyright (C) 2015 Free Software Foundation, Inc.

On the advise of folks in the stockfish Discord, I've generated stockfish_9_linux_x64.

stockfish_9_linux_x64: ELF 64-bit LSB executable, x86-64, version 1 (SYSV),
dynamically linked (uses shared libs), for GNU/Linux 2.6.32

Will ChessCraft be able to use that? If yes, in which engines subdirectory shall I place it, and how shall I modify config.yml to recognize it?

jpenilla commented 1 year ago

In engines/custom and stockfish-engine: stockfish_9_linux_x64 in the config.

The oldest I've tested with is 12, but 9 should probably work too.

SlimeDog commented 1 year ago

OK. Works fine with SF 9. As I get time, I'll move up the release tree as far as my systems allow.

SlimeDog commented 1 year ago

I have upgraded to SF 11. That is the latest I can run on my systems, without upgrades to gcc and related software, which I prefer not to do.