Failure/foul-magics
1
0
Fork 0
forked from External/mage
Code Pull requests Releases Packages Activity Actions

server, tests: improved game error and AI logs, added docs, added error stats in load test's result table (related to #11572);

Browse source
This commit is contained in:
Oleg Agafonov 2024-01-08 23:21:44 +04:00
parent 19e829a959
commit eedb9e6054
5 changed files with 80 additions and 53 deletions
Download patch file Download diff file Expand all files Collapse all files

9
Mage.Common/src/main/java/mage/view/GameView.java
View file

@ -37,6 +37,7 @@ public class GameView implements Serializable {
private static final long serialVersionUID = 1L; private static final long serialVersionUID = 1L;
private static final Logger LOGGER = Logger.getLogger(GameView.class); private static final Logger LOGGER = Logger.getLogger(GameView.class);
private final int priorityTime; private final int priorityTime;
private final int bufferTime; private final int bufferTime;
private final List<PlayerView> players = new ArrayList<>(); private final List<PlayerView> players = new ArrayList<>();
@ -59,6 +60,7 @@ public class GameView implements Serializable {
private final int turn; private final int turn;
private boolean special = false; private boolean special = false;
private final boolean rollbackTurnsAllowed; private final boolean rollbackTurnsAllowed;
private int totalErrorsCount;
public GameView(GameState state, Game game, UUID createdForPlayerId, UUID watcherUserId) { public GameView(GameState state, Game game, UUID createdForPlayerId, UUID watcherUserId) {
Player createdForPlayer = null; Player createdForPlayer = null;
@ -198,7 +200,8 @@ public class GameView implements Serializable {
} else { } else {
this.special = false; this.special = false;
} }
rollbackTurnsAllowed = game.getOptions().rollbackTurnsAllowed; this.rollbackTurnsAllowed = game.getOptions().rollbackTurnsAllowed;
this.totalErrorsCount = game.getTotalErrorsCount();
} }
private void checkPaid(UUID uuid, StackAbility stackAbility) { private void checkPaid(UUID uuid, StackAbility stackAbility) {
@ -331,4 +334,8 @@ public class GameView implements Serializable {
Gson gson = new GsonBuilder().create(); Gson gson = new GsonBuilder().create();
return gson.toJson(this); return gson.toJson(this);
} }
public int getTotalErrorsCount() {
return this.totalErrorsCount;
}
} }

21
Mage.Server.Plugins/Mage.Player.AI.MA/src/mage/player/ai/ComputerPlayer6.java
View file

@ -450,23 +450,22 @@ public class ComputerPlayer6 extends ComputerPlayer /*implements Player*/ {
if (res != null) { if (res != null) {
return res; return res;
} }
} catch (TimeoutException e) { } catch (TimeoutException | InterruptedException e) {
logger.info("simulating - timed out"); // AI thinks too long
logger.info("ai simulating - timed out");
task.cancel(true); task.cancel(true);
} catch (ExecutionException e) { } catch (ExecutionException e) {
// exception error in simulated game // game error
logger.error("AI simulation catch game error: " + e, e);
task.cancel(true); task.cancel(true);
// real games: must catch and log // real games: must catch and log
// unit tests: must raise again for test fail // unit tests: must raise again for fast fail
logger.error("AI simulation game catch error: " + e.getCause(), e);
if (this.isTestsMode()) { 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) { } catch (Throwable e) {
e.printStackTrace(); // ?
task.cancel(true); logger.error("AI simulation catch unknown error: " + e, e);
} catch (Exception e) {
e.printStackTrace();
task.cancel(true); task.cancel(true);
} }
//TODO: timeout handling //TODO: timeout handling

15
Mage.Tests/src/test/java/org/mage/test/load/LoadTest.java
View file

@ -778,12 +778,16 @@ public class LoadTest {
public int getDurationMs() { public int getDurationMs() {
return (int) ((this.timeEnded.getTime() - this.timeStarted.getTime())); return (int) ((this.timeEnded.getTime() - this.timeStarted.getTime()));
} }
public int getTotalErrorsCount() {
return this.finalGameView.getTotalErrorsCount();
}
} }
private static class LoadTestGameResultsList extends HashMap<Integer, LoadTestGameResult> { private static class LoadTestGameResultsList extends HashMap<Integer, LoadTestGameResult> {
private static final String tableFormatHeader = "|%-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|%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) { public LoadTestGameResult createGame(int index, String name, long randomSeed) {
if (this.containsKey(index)) { if (this.containsKey(index)) {
@ -799,6 +803,7 @@ public class LoadTest {
"index", "index",
"name", "name",
"random sid", "random sid",
"errors",
"turn", "turn",
"player 1", "player 1",
"player 2", "player 2",
@ -817,6 +822,7 @@ public class LoadTest {
String.valueOf(gameResult.index), //"index", String.valueOf(gameResult.index), //"index",
gameResult.name, //"name", gameResult.name, //"name",
String.valueOf(gameResult.randomSeed), // "random sid", String.valueOf(gameResult.randomSeed), // "random sid",
String.valueOf(gameResult.getTotalErrorsCount()), // "errors",
String.valueOf(gameResult.getTurn()), //"turn", String.valueOf(gameResult.getTurn()), //"turn",
String.valueOf(gameResult.getLife1()), //"player 1", String.valueOf(gameResult.getLife1()), //"player 1",
String.valueOf(gameResult.getLife2()), //"player 2", String.valueOf(gameResult.getLife2()), //"player 2",
@ -831,6 +837,7 @@ public class LoadTest {
"TOTAL/AVG", //"index", "TOTAL/AVG", //"index",
String.valueOf(this.size()), //"name", String.valueOf(this.size()), //"name",
"total, secs: " + String.format("%.3f", (float) this.getTotalDurationMs() / 1000), // "random sid", "total, secs: " + String.format("%.3f", (float) this.getTotalDurationMs() / 1000), // "random sid",
String.valueOf(this.getTotalErrorsCount()), // errors
String.valueOf(this.getAvgTurn()), // turn String.valueOf(this.getAvgTurn()), // turn
String.valueOf(this.getAvgLife1()), // player 1 String.valueOf(this.getAvgLife1()), // player 1
String.valueOf(this.getAvgLife2()), // player 2 String.valueOf(this.getAvgLife2()), // player 2
@ -840,6 +847,10 @@ public class LoadTest {
System.out.printf(tableFormatData, data.toArray()); System.out.printf(tableFormatData, data.toArray());
} }
private int getTotalErrorsCount() {
return this.values().stream().mapToInt(LoadTestGameResult::getTotalErrorsCount).sum();
}
private int getAvgTurn() { private int getAvgTurn() {
return this.values().stream().mapToInt(LoadTestGameResult::getTurn).sum() / this.size(); return this.values().stream().mapToInt(LoadTestGameResult::getTurn).sum() / this.size();
} }

2
Mage/src/main/java/mage/game/Game.java
View file

@ -293,6 +293,8 @@ public interface Game extends MageItem, Serializable, Copyable<Game> {
Player getLosingPlayer(); Player getLosingPlayer();
int getTotalErrorsCount();
//client event methods //client event methods
void addTableEventListener(Listener<TableEvent> listener); void addTableEventListener(Listener<TableEvent> listener);

86
Mage/src/main/java/mage/game/GameImpl.java
View file

@ -77,6 +77,7 @@ import java.io.IOException;
import java.io.Serializable; import java.io.Serializable;
import java.util.*; import java.util.*;
import java.util.Map.Entry; import java.util.Map.Entry;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.stream.Collectors; import java.util.stream.Collectors;
/** /**
@ -99,6 +100,8 @@ public abstract class GameImpl implements Game {
protected boolean simulation = false; protected boolean simulation = false;
protected boolean checkPlayableState = false; protected boolean checkPlayableState = false;
protected AtomicInteger totalErrorsCount = new AtomicInteger(); // for debug only: error stats
protected final UUID id; protected final UUID id;
protected boolean ready; protected boolean ready;
@ -180,6 +183,7 @@ public abstract class GameImpl implements Game {
this.checkPlayableState = game.checkPlayableState; this.checkPlayableState = game.checkPlayableState;
this.id = game.id; this.id = game.id;
this.totalErrorsCount.set(game.totalErrorsCount.get());
this.ready = game.ready; this.ready = game.ready;
//this.tableEventSource = game.tableEventSource; // client-server part, not need on copy/simulations //this.tableEventSource = game.tableEventSource; // client-server part, not need on copy/simulations
@ -1588,7 +1592,7 @@ public abstract class GameImpl implements Game {
@Override @Override
public void playPriority(UUID activePlayerId, boolean resuming) { public void playPriority(UUID activePlayerId, boolean resuming) {
int errorContinueCounter = 0; int priorityErrorsCount = 0;
infiniteLoopCounter = 0; infiniteLoopCounter = 0;
int rollbackBookmark = 0; int rollbackBookmark = 0;
clearAllBookmarks(); clearAllBookmarks();
@ -1605,8 +1609,8 @@ public abstract class GameImpl implements Game {
Player player; Player player;
while (!isPaused() && !checkIfGameIsOver()) { while (!isPaused() && !checkIfGameIsOver()) {
try { try {
if (rollbackBookmark == 0) { if (rollbackBookmarkOnPriorityStart == 0) {
rollbackBookmark = bookmarkState(); rollbackBookmarkOnPriorityStart = bookmarkState();
} }
player = getPlayer(state.getPlayerList().get()); player = getPlayer(state.getPlayerList().get());
state.setPriorityPlayerId(player.getId()); state.setPriorityPlayerId(player.getId());
@ -1656,39 +1660,44 @@ public abstract class GameImpl implements Game {
return; return;
} }
} }
} catch (Exception ex) { } catch (Exception e) {
logger.fatal("Game exception gameId: " + getId(), ex); // INNER error - can continue to execute
if ((ex instanceof NullPointerException) this.totalErrorsCount.incrementAndGet();
&& errorContinueCounter == 0 && ex.getStackTrace() != null) { logger.fatal("Game error: " + getId() + " - " + this, e);
logger.fatal(ex.getStackTrace()); this.fireErrorEvent("Game error occurred: ", e);
}
this.fireErrorEvent("Game exception occurred: ", ex);
// stack info // additional info
String info = this.getStack().stream().map(MageObject::toString).collect(Collectors.joining("\n")); logger.info("---");
logger.info(String.format("\nStack before error %d: \n%s\n", this.getStack().size(), 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 // too many errors - end game
if (errorContinueCounter > 15) { if (priorityErrorsCount > 15) {
throw new MageException("Iterated player priority after game exception too often, game ends! Last error:\n " throw new MageException("Too many errors, game will be end. Last error: " + e);
+ ex.getMessage());
} }
// rollback game to prev state // rollback to prev state
GameState restoredState = restoreState(rollbackBookmark, "Game exception: " + ex.getMessage()); GameState restoredState = restoreState(rollbackBookmarkOnPriorityStart, "Game error: " + e);
rollbackBookmark = 0; rollbackBookmarkOnPriorityStart = 0;
if (restoredState != null) { 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 { } 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()); Player activePlayer = this.getPlayer(getActivePlayerId());
if (activePlayer != null && !activePlayer.isTestsMode()) { if (activePlayer != null && !activePlayer.isTestsMode()) {
errorContinueCounter++; // real game - try to continue
priorityErrorsCount++;
continue; continue;
} else { } else {
// tests - try to fail fast
throw new MageException(UNIT_TESTS_ERROR_TEXT); throw new MageException(UNIT_TESTS_ERROR_TEXT);
} }
} finally { } finally {
@ -1697,14 +1706,15 @@ public abstract class GameImpl implements Game {
state.getPlayerList().getNext(); state.getPlayerList().getNext();
} }
} }
} catch (Exception ex) { } catch (Exception e) {
logger.fatal("Game exception " + ex.getMessage(), ex); // OUTER error - game must end (too many errors also come here)
this.fireErrorEvent("Game exception occurred: ", ex); this.totalErrorsCount.incrementAndGet();
logger.fatal("Game end on critical error: " + e, e);
this.fireErrorEvent("Game end on critical error: " + e, e);
this.end(); this.end();
// don't catch game errors in unit tests, so test framework can process it (example: errors in AI simulations) // re-raise error in unit tests, so framework can catch it (example: errors in AI simulations)
if (ex.getMessage() != null && ex.getMessage().equals(UNIT_TESTS_ERROR_TEXT)) { if (UNIT_TESTS_ERROR_TEXT.equals(e.getMessage())) {
//this.getContinuousEffects().traceContinuousEffects(this);
throw new IllegalStateException(UNIT_TESTS_ERROR_TEXT); throw new IllegalStateException(UNIT_TESTS_ERROR_TEXT);
} }
} finally { } finally {
@ -1714,7 +1724,6 @@ public abstract class GameImpl implements Game {
} }
} }
//resolve top StackObject
protected void resolve() { protected void resolve() {
StackObject top = null; StackObject top = null;
try { try {
@ -3498,6 +3507,11 @@ public abstract class GameImpl implements Game {
lkiShortLiving.clear(); lkiShortLiving.clear();
} }
@Override
public int getTotalErrorsCount() {
return this.totalErrorsCount.get();
}
@Override @Override
public void cheat(UUID ownerId, Map<Zone, String> commands) { public void cheat(UUID ownerId, Map<Zone, String> commands) {
if (commands != null) { if (commands != null) {
@ -3519,15 +3533,9 @@ public abstract class GameImpl implements Game {
if (command.getValue().contains("life:")) { if (command.getValue().contains("life:")) {
String[] s = command.getValue().split(":"); String[] s = command.getValue().split(":");
if (s.length == 2) { if (s.length == 2) {
try { int amount = Integer.parseInt(s[1]);
int amount = Integer.parseInt(s[1]); player.setLife(amount, this, null);
player.setLife(amount, this, null);
logger.debug("Setting player's life: ");
} catch (NumberFormatException e) {
logger.fatal("error setting life", e);
}
} }
} }
break; break;
} }
@ -3973,7 +3981,7 @@ public abstract class GameImpl implements Game {
Player activePayer = this.getPlayer(this.getActivePlayerId()); Player activePayer = this.getPlayer(this.getActivePlayerId());
StringBuilder sb = new StringBuilder() StringBuilder sb = new StringBuilder()
.append(this.isSimulation() ? "!!!SIMULATION!!! " : "") .append(this.isSimulation() ? "!!!SIMULATION!!! " : "")
.append("; ").append(this.getGameType().toString()) .append(this.getGameType().toString())
.append("; ").append(CardUtil.getTurnInfo(this)) .append("; ").append(CardUtil.getTurnInfo(this))
.append("; active: ").append((activePayer == null ? "none" : activePayer.getName())) .append("; active: ").append((activePayer == null ? "none" : activePayer.getName()))
.append("; stack: ").append(this.getStack().toString()) .append("; stack: ").append(this.getStack().toString())