From eedb9e60547551380f19b993e73d1ac5dc570418 Mon Sep 17 00:00:00 2001 From: Oleg Agafonov Date: Mon, 8 Jan 2024 23:21:44 +0400 Subject: [PATCH] server, tests: improved game error and AI logs, added docs, added error stats in load test's result table (related to #11572); --- .../src/main/java/mage/view/GameView.java | 9 +- .../src/mage/player/ai/ComputerPlayer6.java | 21 +++-- .../java/org/mage/test/load/LoadTest.java | 15 +++- Mage/src/main/java/mage/game/Game.java | 2 + Mage/src/main/java/mage/game/GameImpl.java | 86 ++++++++++--------- 5 files changed, 80 insertions(+), 53 deletions(-) diff --git a/Mage.Common/src/main/java/mage/view/GameView.java b/Mage.Common/src/main/java/mage/view/GameView.java index e3c6ad4ab5b..f7d5b82dc58 100644 --- a/Mage.Common/src/main/java/mage/view/GameView.java +++ b/Mage.Common/src/main/java/mage/view/GameView.java @@ -37,6 +37,7 @@ public class GameView implements Serializable { private static final long serialVersionUID = 1L; private static final Logger LOGGER = Logger.getLogger(GameView.class); + private final int priorityTime; private final int bufferTime; private final List players = new ArrayList<>(); @@ -59,6 +60,7 @@ public class GameView implements Serializable { private final int turn; private boolean special = false; private final boolean rollbackTurnsAllowed; + private int totalErrorsCount; public GameView(GameState state, Game game, UUID createdForPlayerId, UUID watcherUserId) { Player createdForPlayer = null; @@ -198,7 +200,8 @@ public class GameView implements Serializable { } else { this.special = false; } - rollbackTurnsAllowed = game.getOptions().rollbackTurnsAllowed; + this.rollbackTurnsAllowed = game.getOptions().rollbackTurnsAllowed; + this.totalErrorsCount = game.getTotalErrorsCount(); } private void checkPaid(UUID uuid, StackAbility stackAbility) { @@ -331,4 +334,8 @@ public class GameView implements Serializable { Gson gson = new GsonBuilder().create(); return gson.toJson(this); } + + public int getTotalErrorsCount() { + return this.totalErrorsCount; + } } diff --git a/Mage.Server.Plugins/Mage.Player.AI.MA/src/mage/player/ai/ComputerPlayer6.java b/Mage.Server.Plugins/Mage.Player.AI.MA/src/mage/player/ai/ComputerPlayer6.java index e34d996a2f9..639eb52b134 100644 --- a/Mage.Server.Plugins/Mage.Player.AI.MA/src/mage/player/ai/ComputerPlayer6.java +++ b/Mage.Server.Plugins/Mage.Player.AI.MA/src/mage/player/ai/ComputerPlayer6.java @@ -450,23 +450,22 @@ public class ComputerPlayer6 extends ComputerPlayer /*implements Player*/ { if (res != null) { return res; } - } catch (TimeoutException e) { - logger.info("simulating - timed out"); + } catch (TimeoutException | InterruptedException e) { + // AI thinks too long + logger.info("ai simulating - timed out"); task.cancel(true); } catch (ExecutionException e) { - // exception error in simulated game + // game error + logger.error("AI simulation catch game error: " + e, e); task.cancel(true); // real games: must catch and log - // unit tests: must raise again for test fail - logger.error("AI simulation game catch error: " + e.getCause(), e); + // unit tests: must raise again for fast fail if (this.isTestsMode()) { - throw new IllegalStateException("One of the simulated games raise the error: " + e.getCause()); + throw new IllegalStateException("One of the simulated games raise the error: " + e, e); } - } catch (InterruptedException e) { - e.printStackTrace(); - task.cancel(true); - } catch (Exception e) { - e.printStackTrace(); + } catch (Throwable e) { + // ? + logger.error("AI simulation catch unknown error: " + e, e); task.cancel(true); } //TODO: timeout handling diff --git a/Mage.Tests/src/test/java/org/mage/test/load/LoadTest.java b/Mage.Tests/src/test/java/org/mage/test/load/LoadTest.java index e2d966f8d14..af553e4dcc0 100644 --- a/Mage.Tests/src/test/java/org/mage/test/load/LoadTest.java +++ b/Mage.Tests/src/test/java/org/mage/test/load/LoadTest.java @@ -778,12 +778,16 @@ public class LoadTest { public int getDurationMs() { return (int) ((this.timeEnded.getTime() - this.timeStarted.getTime())); } + + public int getTotalErrorsCount() { + return this.finalGameView.getTotalErrorsCount(); + } } private static class LoadTestGameResultsList extends HashMap { - private static final String tableFormatHeader = "|%-10s|%-15s|%-20s|%-10s|%-15s|%-15s|%-10s|%-20s|%n"; - private static final String tableFormatData = "|%-10s|%15s|%20s|%10s|%15s|%15s|%10s|%20s|%n"; + private static final String tableFormatHeader = "|%-10s|%-15s|%-20s|%-10s|%-10s|%-15s|%-15s|%-10s|%-20s|%n"; + private static final String tableFormatData = "|%-10s|%15s|%20s|%10s|%10s|%15s|%15s|%10s|%20s|%n"; public LoadTestGameResult createGame(int index, String name, long randomSeed) { if (this.containsKey(index)) { @@ -799,6 +803,7 @@ public class LoadTest { "index", "name", "random sid", + "errors", "turn", "player 1", "player 2", @@ -817,6 +822,7 @@ public class LoadTest { String.valueOf(gameResult.index), //"index", gameResult.name, //"name", String.valueOf(gameResult.randomSeed), // "random sid", + String.valueOf(gameResult.getTotalErrorsCount()), // "errors", String.valueOf(gameResult.getTurn()), //"turn", String.valueOf(gameResult.getLife1()), //"player 1", String.valueOf(gameResult.getLife2()), //"player 2", @@ -831,6 +837,7 @@ public class LoadTest { "TOTAL/AVG", //"index", String.valueOf(this.size()), //"name", "total, secs: " + String.format("%.3f", (float) this.getTotalDurationMs() / 1000), // "random sid", + String.valueOf(this.getTotalErrorsCount()), // errors String.valueOf(this.getAvgTurn()), // turn String.valueOf(this.getAvgLife1()), // player 1 String.valueOf(this.getAvgLife2()), // player 2 @@ -840,6 +847,10 @@ public class LoadTest { System.out.printf(tableFormatData, data.toArray()); } + private int getTotalErrorsCount() { + return this.values().stream().mapToInt(LoadTestGameResult::getTotalErrorsCount).sum(); + } + private int getAvgTurn() { return this.values().stream().mapToInt(LoadTestGameResult::getTurn).sum() / this.size(); } diff --git a/Mage/src/main/java/mage/game/Game.java b/Mage/src/main/java/mage/game/Game.java index dcbdf7cd973..b929018b73b 100644 --- a/Mage/src/main/java/mage/game/Game.java +++ b/Mage/src/main/java/mage/game/Game.java @@ -293,6 +293,8 @@ public interface Game extends MageItem, Serializable, Copyable { Player getLosingPlayer(); + int getTotalErrorsCount(); + //client event methods void addTableEventListener(Listener listener); diff --git a/Mage/src/main/java/mage/game/GameImpl.java b/Mage/src/main/java/mage/game/GameImpl.java index 28616f354ae..99de9ee1369 100644 --- a/Mage/src/main/java/mage/game/GameImpl.java +++ b/Mage/src/main/java/mage/game/GameImpl.java @@ -77,6 +77,7 @@ import java.io.IOException; import java.io.Serializable; import java.util.*; import java.util.Map.Entry; +import java.util.concurrent.atomic.AtomicInteger; import java.util.stream.Collectors; /** @@ -99,6 +100,8 @@ public abstract class GameImpl implements Game { protected boolean simulation = false; protected boolean checkPlayableState = false; + protected AtomicInteger totalErrorsCount = new AtomicInteger(); // for debug only: error stats + protected final UUID id; protected boolean ready; @@ -180,6 +183,7 @@ public abstract class GameImpl implements Game { this.checkPlayableState = game.checkPlayableState; this.id = game.id; + this.totalErrorsCount.set(game.totalErrorsCount.get()); this.ready = game.ready; //this.tableEventSource = game.tableEventSource; // client-server part, not need on copy/simulations @@ -1588,7 +1592,7 @@ public abstract class GameImpl implements Game { @Override public void playPriority(UUID activePlayerId, boolean resuming) { - int errorContinueCounter = 0; + int priorityErrorsCount = 0; infiniteLoopCounter = 0; int rollbackBookmark = 0; clearAllBookmarks(); @@ -1605,8 +1609,8 @@ public abstract class GameImpl implements Game { Player player; while (!isPaused() && !checkIfGameIsOver()) { try { - if (rollbackBookmark == 0) { - rollbackBookmark = bookmarkState(); + if (rollbackBookmarkOnPriorityStart == 0) { + rollbackBookmarkOnPriorityStart = bookmarkState(); } player = getPlayer(state.getPlayerList().get()); state.setPriorityPlayerId(player.getId()); @@ -1656,39 +1660,44 @@ public abstract class GameImpl implements Game { return; } } - } catch (Exception ex) { - logger.fatal("Game exception gameId: " + getId(), ex); - if ((ex instanceof NullPointerException) - && errorContinueCounter == 0 && ex.getStackTrace() != null) { - logger.fatal(ex.getStackTrace()); - } - this.fireErrorEvent("Game exception occurred: ", ex); + } catch (Exception e) { + // INNER error - can continue to execute + this.totalErrorsCount.incrementAndGet(); + logger.fatal("Game error: " + getId() + " - " + this, e); + this.fireErrorEvent("Game error occurred: ", e); - // stack info - String info = this.getStack().stream().map(MageObject::toString).collect(Collectors.joining("\n")); - logger.info(String.format("\nStack before error %d: \n%s\n", this.getStack().size(), info)); + // additional info + logger.info("---"); + logger.info("Game state on error: " + this); + String info = this.getStack() + .stream() + .map(o -> "* " + o.toString()) + .collect(Collectors.joining("\n")); + logger.info(String.format("Stack on error %d: \n%s\n", this.getStack().size(), info)); + logger.info("---"); // too many errors - end game - if (errorContinueCounter > 15) { - throw new MageException("Iterated player priority after game exception too often, game ends! Last error:\n " - + ex.getMessage()); + if (priorityErrorsCount > 15) { + throw new MageException("Too many errors, game will be end. Last error: " + e); } - // rollback game to prev state - GameState restoredState = restoreState(rollbackBookmark, "Game exception: " + ex.getMessage()); - rollbackBookmark = 0; - + // rollback to prev state + GameState restoredState = restoreState(rollbackBookmarkOnPriorityStart, "Game error: " + e); + rollbackBookmarkOnPriorityStart = 0; if (restoredState != null) { - this.informPlayers(String.format("Auto-restored to %s due game error: %s", restoredState, ex.getMessage())); + this.informPlayers(String.format("Auto-restored to %s due game error: %s", restoredState, e)); } else { - logger.error("Can't auto-restore to prev state."); + logger.error("Can't auto-restore to prev state"); } + // count total errors Player activePlayer = this.getPlayer(getActivePlayerId()); if (activePlayer != null && !activePlayer.isTestsMode()) { - errorContinueCounter++; + // real game - try to continue + priorityErrorsCount++; continue; } else { + // tests - try to fail fast throw new MageException(UNIT_TESTS_ERROR_TEXT); } } finally { @@ -1697,14 +1706,15 @@ public abstract class GameImpl implements Game { state.getPlayerList().getNext(); } } - } catch (Exception ex) { - logger.fatal("Game exception " + ex.getMessage(), ex); - this.fireErrorEvent("Game exception occurred: ", ex); + } catch (Exception e) { + // OUTER error - game must end (too many errors also come here) + this.totalErrorsCount.incrementAndGet(); + logger.fatal("Game end on critical error: " + e, e); + this.fireErrorEvent("Game end on critical error: " + e, e); this.end(); - // don't catch game errors in unit tests, so test framework can process it (example: errors in AI simulations) - if (ex.getMessage() != null && ex.getMessage().equals(UNIT_TESTS_ERROR_TEXT)) { - //this.getContinuousEffects().traceContinuousEffects(this); + // re-raise error in unit tests, so framework can catch it (example: errors in AI simulations) + if (UNIT_TESTS_ERROR_TEXT.equals(e.getMessage())) { throw new IllegalStateException(UNIT_TESTS_ERROR_TEXT); } } finally { @@ -1714,7 +1724,6 @@ public abstract class GameImpl implements Game { } } - //resolve top StackObject protected void resolve() { StackObject top = null; try { @@ -3498,6 +3507,11 @@ public abstract class GameImpl implements Game { lkiShortLiving.clear(); } + @Override + public int getTotalErrorsCount() { + return this.totalErrorsCount.get(); + } + @Override public void cheat(UUID ownerId, Map commands) { if (commands != null) { @@ -3519,15 +3533,9 @@ public abstract class GameImpl implements Game { if (command.getValue().contains("life:")) { String[] s = command.getValue().split(":"); if (s.length == 2) { - try { - int amount = Integer.parseInt(s[1]); - player.setLife(amount, this, null); - logger.debug("Setting player's life: "); - } catch (NumberFormatException e) { - logger.fatal("error setting life", e); - } + int amount = Integer.parseInt(s[1]); + player.setLife(amount, this, null); } - } break; } @@ -3973,7 +3981,7 @@ public abstract class GameImpl implements Game { Player activePayer = this.getPlayer(this.getActivePlayerId()); StringBuilder sb = new StringBuilder() .append(this.isSimulation() ? "!!!SIMULATION!!! " : "") - .append("; ").append(this.getGameType().toString()) + .append(this.getGameType().toString()) .append("; ").append(CardUtil.getTurnInfo(this)) .append("; active: ").append((activePayer == null ? "none" : activePayer.getName())) .append("; stack: ").append(this.getStack().toString())