Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
asvitkine opened this issue Jun 16, 2022 · 12 comments · Fixed by #10689 or #11844
Closed

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

asvitkine opened this issue Jun 16, 2022 · 12 comments · Fixed by #10689 or #11844
Assignees
@asvitkine
Labels
2.6 Problem A problem, bug, defect - something to fix

Comments

@asvitkine
Copy link
Contributor

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 asvitkine added the Problem A problem, bug, defect - something to fix label Jun 16, 2022
@asvitkine
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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 asvitkine mentioned this issue Jun 18, 2022
Merged
@asvitkine asvitkine reopened this Jun 23, 2022
@asvitkine
Copy link
Contributor Author

asvitkine commented Jun 23, 2022 •
edited
Loading

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
Copy link
Contributor Author

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 asvitkine added the 2.6 label Jul 8, 2023
@asvitkine
Copy link
Contributor Author

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

@asvitkine
Copy link
Contributor Author

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
Copy link
Contributor Author

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 asvitkine reopened this Aug 1, 2023
@asvitkine asvitkine self-assigned this Aug 1, 2023
@asvitkine
Copy link
Contributor Author

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 asvitkine mentioned this issue Aug 1, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@asvitkine asvitkine

Labels
2.6 Problem A problem, bug, defect - something to fix
Projects
None yet
Milestone
No milestone
1 participant
@asvitkine