triplea icon indicating copy to clipboard operation
triplea copied to clipboard

Published 20 hours ago • verified publisher icon triplea-game

AiGameTest > testAiGame sometimes hits "Not in a step, but trying to add event"

Open asvitkine opened this issue 2 years ago • 8 comments

When running on the bots, sometimes AiGameTest > testAiGame sometimes hits "Not in a step, but trying to add event".

Example: https://github.com/triplea-game/triplea/runs/6910149568?check_suite_focus=true

    java.lang.IllegalStateException: Not in a step, but trying to add event: Filler event for child: Russians roll AA dice in Moscow : 1. Current history node is: null
    	at games.strategy.engine.history.HistoryWriter.startEvent(HistoryWriter.java:119)
    	at games.strategy.engine.history.HistoryWriter.addChildToEvent(HistoryWriter.java:150)
    	at games.strategy.engine.framework.ServerGame$1.addChildToEvent(ServerGame.java:135)
    	at jdk.internal.reflect.GeneratedMethodAccessor26.invoke(Unknown Source)
    	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeSingle(EndPoint.java:136)
    	at games.strategy.engine.message.unifiedmessenger.EndPoint.lambda$invokeMultiple$0(EndPoint.java:120)
    	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
    	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
    	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
    	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
    	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
    	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
    	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeMultiple(EndPoint.java:121)
    	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeLocal(EndPoint.java:111)
    	at games.strategy.engine.message.unifiedmessenger.UnifiedMessenger.invoke(UnifiedMessenger.java:153)
    	at games.strategy.engine.message.UnifiedInvocationHandler.invoke(UnifiedInvocationHandler.java:47)
    	at com.sun.proxy.$Proxy63.addChildToEvent(Unknown Source)
    	at games.strategy.engine.history.DelegateHistoryWriter.lambda$addChildToEvent$2(DelegateHistoryWriter.java:49)
    	at java.base/java.util.Optional.ifPresent(Optional.java:183)
    	at games.strategy.engine.history.DelegateHistoryWriter.addChildToEvent(DelegateHistoryWriter.java:49)
    	at games.strategy.triplea.delegate.GameDelegateHistoryWriter.addChildToEvent(GameDelegateHistoryWriter.java:59)
    	at games.strategy.triplea.delegate.dice.RollDiceFactory.rollAaDice(RollDiceFactory.java:54)
    	at games.strategy.triplea.delegate.battle.StrategicBombingRaidBattle$FireAa$1.execute(StrategicBombingRaidBattle.java:487)
    	at games.strategy.triplea.delegate.ExecutionStack.execute(ExecutionStack.java:34)
    	at games.strategy.triplea.delegate.battle.StrategicBombingRaidBattle.fight(StrategicBombingRaidBattle.java:344)
    	at games.strategy.triplea.delegate.battle.BattleTracker.fightAirRaidsAndStrategicBombing(BattleTracker.java:1238)
    	at games.strategy.triplea.delegate.battle.BattleTracker.fightAirRaidsAndStrategicBombing(BattleTracker.java:1211)
    	at games.strategy.triplea.delegate.battle.BattleDelegate.start(BattleDelegate.java:117)
    	at games.strategy.engine.framework.ServerGame.startStep(ServerGame.java:556)
    	at games.strategy.engine.framework.ServerGame.runStep(ServerGame.java:424)
    	at games.strategy.engine.framework.ServerGame.runNextStep(ServerGame.java:326)
    	at games.strategy.engine.data.AiGameTest.testAiGame(AiGameTest.java:40)

asvitkine avatar Jun 16 '22 00:06 asvitkine

Note: This doesn't actually fail the test. (Maybe it should, but we should probably fix the issue first, or else it will make it more flaky.)

asvitkine avatar Jun 16 '22 04:06 asvitkine

The "Filler event for child:" thing comes from this logic:

  public void addChildToEvent(final EventChild node) {
    assertCorrectThread();
    if (!isCurrentEvent()) {
      log.info(
          "Not in an event, but trying to add child: "
              + node
              + ". Current history node is: "
              + current);
      startEvent("Filler event for child: " + node);
    }
    addToCurrent(node);
  }

asvitkine avatar Jun 16 '22 04:06 asvitkine

In that instance, the above log.info wrote:

    00:12:08.721 [Test worker] INFO  g.s.engine.history.HistoryWriter - Not in an event, but trying to add child: Russians roll AA dice in Moscow : 1. Current history node is: null

asvitkine avatar Jun 17 '22 20:06 asvitkine

So how can current be null?

  1. It starts of null
  2. It's not addToAndSetCurrent() which does current = newNode; because all three call sites never pass null.
  3. It shouldn't be startNextRound(), since that calls addToAndSetCurrent() immediately after (unless there's a race).
  4. It could be closeCurrent(), which does:
        final HistoryNode parent = (HistoryNode) current.getParent();
 ...
        current = parent;

asvitkine avatar Jun 17 '22 20:06 asvitkine

Making the test run 1000 in a loop repros this pretty consistently. I added some extra tracking and it seems like we're hitting case 1 for some reason. That is, there hasn't been any calls to addToCurrent() before, so current has its default value of null.

This is surprising to me since the events we get are ones that are somewhere in the middle of the game. So did we get a bunch of other ones that got lost somehow?

asvitkine avatar Jun 17 '22 23:06 asvitkine

So it's not the main history writer where that happens, but one of the ones on the cloned game data used for concurrent battle calcs by AIs. That one is cloned without history, so start at a "blank" state. So we probably need to adjust how that works.

asvitkine avatar Jun 18 '22 01:06 asvitkine

Even with the above fix, we still see this sometimes (if we modify the test to run in a loop 100 times).

Some stacks:

java.lang.IllegalStateException: Not in a step, but trying to add event: 1 cruiser moved from SZ 4 to SZ 3. Current history node is: Combat Move
	at games.strategy.engine.history.HistoryWriter.startEvent(HistoryWriter.java:119)
	at games.strategy.engine.framework.ServerGame$1.startHistoryEvent(ServerGame.java:125)
	at games.strategy.engine.framework.ServerGame$1.startHistoryEvent(ServerGame.java:116)
	at jdk.internal.reflect.GeneratedMethodAccessor51.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeSingle(EndPoint.java:136)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.lambda$invokeMultiple$0(EndPoint.java:120)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeMultiple(EndPoint.java:121)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeLocal(EndPoint.java:111)
	at games.strategy.engine.message.unifiedmessenger.UnifiedMessenger.invoke(UnifiedMessenger.java:153)
	at games.strategy.engine.message.UnifiedInvocationHandler.invoke(UnifiedInvocationHandler.java:47)
	at com.sun.proxy.$Proxy64.startHistoryEvent(Unknown Source)
	at games.strategy.engine.history.DelegateHistoryWriter.startEvent(DelegateHistoryWriter.java:55)
	at games.strategy.triplea.delegate.MoveDelegate.performMove(MoveDelegate.java:668)
	at jdk.internal.reflect.GeneratedMethodAccessor46.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at games.strategy.engine.delegate.DelegateExecutionManager$1.invoke(DelegateExecutionManager.java:120)
	at com.sun.proxy.$Proxy58.performMove(Unknown Source)
	at jdk.internal.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeSingle(EndPoint.java:136)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.lambda$invokeMultiple$0(EndPoint.java:120)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeMultiple(EndPoint.java:121)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeLocal(EndPoint.java:111)
	at games.strategy.engine.message.unifiedmessenger.UnifiedMessenger.invokeAndWait(UnifiedMessenger.java:97)
	at games.strategy.engine.message.UnifiedInvocationHandler.invoke(UnifiedInvocationHandler.java:55)
	at com.sun.proxy.$Proxy58.performMove(Unknown Source)
	at jdk.internal.reflect.GeneratedMethodAccessor46.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at games.strategy.engine.player.DefaultPlayerBridge$GameOverInvocationHandler.invoke(DefaultPlayerBridge.java:145)
	at com.sun.proxy.$Proxy58.performMove(Unknown Source)
	at games.strategy.triplea.ai.pro.util.ProMoveUtils.doMove(ProMoveUtils.java:444)
	at games.strategy.triplea.ai.pro.ProCombatMoveAi.doMove(ProCombatMoveAi.java:157)
	at games.strategy.triplea.ai.pro.AbstractProAi.move(AbstractProAi.java:144)
	at games.strategy.triplea.ai.AbstractAi.start(AbstractAi.java:515)
	at games.strategy.engine.framework.ServerGame.waitForPlayerToFinishStep(ServerGame.java:573)
	at games.strategy.engine.framework.ServerGame.runStep(ServerGame.java:430)
	at games.strategy.engine.framework.ServerGame.runNextStep(ServerGame.java:325)
	at games.strategy.engine.data.AiGameTest.testAiGame(AiGameTest.java:45)

java.lang.IllegalStateException: Not in a round, but trying to add step: germansBattle. Current history node is: Combat
	at games.strategy.engine.history.HistoryWriter.startNextStep(HistoryWriter.java:48)
	at games.strategy.engine.framework.ServerGame$1.stepChanged(ServerGame.java:157)
	at jdk.internal.reflect.GeneratedMethodAccessor47.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeSingle(EndPoint.java:136)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.lambda$invokeMultiple$0(EndPoint.java:120)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeMultiple(EndPoint.java:121)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeLocal(EndPoint.java:111)
	at games.strategy.engine.message.unifiedmessenger.UnifiedMessenger.invoke(UnifiedMessenger.java:153)
	at games.strategy.engine.message.UnifiedInvocationHandler.invoke(UnifiedInvocationHandler.java:47)
	at com.sun.proxy.$Proxy64.stepChanged(Unknown Source)
	at games.strategy.engine.framework.ServerGame.notifyGameStepChanged(ServerGame.java:593)
	at games.strategy.engine.framework.ServerGame.startStep(ServerGame.java:550)
	at games.strategy.engine.framework.ServerGame.runStep(ServerGame.java:423)
	at games.strategy.engine.framework.ServerGame.runNextStep(ServerGame.java:325)
	at games.strategy.engine.data.AiGameTest.testAiGame(AiGameTest.java:45)

asvitkine avatar Jun 23 '22 02:06 asvitkine

With a loop of 100 executions, I got 3 such failures, here's the third trace:

java.lang.IllegalStateException: Not in a round, but trying to add step: germansBattle. Current history node is: Combat
	at games.strategy.engine.history.HistoryWriter.startNextStep(HistoryWriter.java:48)
	at games.strategy.engine.framework.ServerGame$1.stepChanged(ServerGame.java:157)
	at jdk.internal.reflect.GeneratedMethodAccessor47.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeSingle(EndPoint.java:136)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.lambda$invokeMultiple$0(EndPoint.java:120)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeMultiple(EndPoint.java:121)
	at games.strategy.engine.message.unifiedmessenger.EndPoint.invokeLocal(EndPoint.java:111)
	at games.strategy.engine.message.unifiedmessenger.UnifiedMessenger.invoke(UnifiedMessenger.java:153)
	at games.strategy.engine.message.UnifiedInvocationHandler.invoke(UnifiedInvocationHandler.java:47)
	at com.sun.proxy.$Proxy64.stepChanged(Unknown Source)
	at games.strategy.engine.framework.ServerGame.notifyGameStepChanged(ServerGame.java:593)
	at games.strategy.engine.framework.ServerGame.startStep(ServerGame.java:550)
	at games.strategy.engine.framework.ServerGame.runStep(ServerGame.java:423)
	at games.strategy.engine.framework.ServerGame.runNextStep(ServerGame.java:325)
	at games.strategy.engine.data.AiGameTest.testAiGame(AiGameTest.java:45)

asvitkine avatar Jun 23 '22 02:06 asvitkine

I just ran the test 300 times and didn't see any occurrences of the above. Could this be fixed now?

asvitkine avatar Jul 08 '23 11:07 asvitkine

I just tried again with @RepeatedTest(1000) and also didn't see this. Let me close now, but we can re-open if we see this again.

asvitkine avatar Jul 08 '23 11:07 asvitkine

Re-opening since #11393 changed the map for this test quite a bit. But probably the issue is still there if we restore the original map.

asvitkine avatar Aug 01 '23 00:08 asvitkine

OK, so what happens is that while we're doing ServerGame$1.stepChanged() which does a startNextStep() via the history writer, there's a battle calculator running on another thread which clones the game:

	at games.strategy.engine.history.HistoryWriter.startNextRound(HistoryWriter.java:82)
	at games.strategy.engine.history.HistoryWriter.startNextStep(HistoryWriter.java:49)
	at games.strategy.engine.data.GameData.resetHistory(GameData.java:365)
	at games.strategy.engine.framework.GameDataManager.saveGameUncompressed(GameDataManager.java:175)
	at games.strategy.engine.framework.GameDataUtils.lambda$gameDataToBytes$0(GameDataUtils.java:32)
	at org.triplea.io.IoUtils.writeToMemory(IoUtils.java:73)
	at games.strategy.engine.framework.GameDataUtils.gameDataToBytes(GameDataUtils.java:32)
	at games.strategy.triplea.odds.calculator.ConcurrentBattleCalculator.createWorkers(ConcurrentBattleCalculator.java:125)

The cloning operation takes a write lock and clears history and then restores it.

The problem is stepChange() doesn't take a lock. So it's a race condition.

So, we can take add locking to the stepChanged() code. Or we can actually just hold a reference to the history object, since the saving operation actually creates a different history object on the game.

asvitkine avatar Aug 01 '23 03:08 asvitkine