[POGO] rare? crash in PAL, different error than #45

[musliner]

logs avail on request; machine was 56% idle.

musliner@openmind0:~/openmind/code/test/results/pal-tournament-v2-shared-6-3-1-E-2022-01-07-103701-openmind0/openmind-in-polycraft-v2-domains-tournament-2022-01-07-103838-a0a51282ce0e

2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] [16:40:15] [TOURNAMENT MANAGER API THREAD/INFO]: [CLIENT TO TOUR MANAGER]{"goal":{"goalType":"ITEM","goalAchieved":true},"command_result":{"command":"RESET","argument":"domain /openmind/code/test/pal-game-configs/from-v2-shared-6-3-1-E/POGO_L06_T03_S01_X0100_E_U0015_V0_G00015_I0028_N1.json","result":"SUCCESS","message":"Attempting Reset","stepCost":0.0}}^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] [16:40:15] [Server thread/INFO]: Running Command on SERVER side: edu.utd.minecraft.mod.polycraft.aitools.commands.APICommandReset^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] [16:40:15] [Server thread/INFO]: [edu.utd.minecraft.mod.polycraft.privateproperty.network.AbstractBaseMessage::46]: Test^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] [16:40:15] [Server thread/INFO]: [edu.utd.minecraft.mod.polycraft.experiment.old.ExperimentManager:sendExperimentUpdates:322]: Sending Update...^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] [16:40:15] [Server thread/FATAL]: Error executing task^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] java.util.concurrent.ExecutionException: java.util.ConcurrentModificationException^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_162]^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_162]^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] at net.minecraft.util.Util.runTask(SourceFile:45) [Util.class:?]^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:660) [MinecraftServer.class:?]^M
^M
2022-01-07_16:40:17: PAL: [2022-01-07 10:40:15] at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:605) [MinecraftServer.class:?]^M

[musliner]

this may be related to agent sending action command racing against game reset.. not sure. I added a couple seconds delay after we/PAL realize we've made the POGO to give PAL some time to converge, and at least on two tests this didnt appear.

[musliner]

(there was already a similar delay in our agent after PAL announces game-over, but this issue occurred before that happened afaict)

[StephenGss]

I found the cause of this error. There was a line referencing our old experiment system that was causing the issue.
I'll push an update with the fix.

[StephenGss]

This is fixed by commit 480052c

[musliner]

this is now happening with regularity when we try to run 100 game tournaments, and the fix above doesnt fix it... the exception is caught but apparently that's not enough, b/c the game then hangs on the next sense-all:

2022-03-31_17:02:21: DEBUG: Reset Triggered... ^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] [17:02:20] [Client thread/INFO]: [edu.utd.minecraft.mod.polycraft.aitools.TournamentManager:onClientTick:124]: RESET domain /openmind/code/polycraft-v2/pogo_100_PN/POGO_L00_T01_S01_X0100_U9999_V0_G00008_I0055_N0.json^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] [17:02:20] [Client thread/INFO]: Sending Command to SERVER side: edu.utd.minecraft.mod.polycraft.aitools.commands.APICommandReset^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] [17:02:20] [TOURNAMENT MANAGER API THREAD/INFO]: [CLIENT TO TOUR MANAGER]{"goal":{"goalType":"ITEM","goalAchieved":true},"command_result":{"command":"RESET","argument":"domain /openmind/code/polycraft-v2/pogo_100_PN/POGO_L00_T01_S01_X0100_U9999_V0_G00008_I0055_N0.json","result":"SUCCESS","message":"Attempting Reset","stepCost":0.0}}^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] [17:02:20] [Server thread/INFO]: Running Command on SERVER side: edu.utd.minecraft.mod.polycraft.aitools.commands.APICommandReset^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] [17:02:20] [Server thread/FATAL]: Error executing task^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] java.util.concurrent.ExecutionException: java.util.ConcurrentModificationException^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at net.minecraft.util.Util.runTask(SourceFile:45) [Util.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:660) [MinecraftServer.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:605) [MinecraftServer.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at net.minecraft.server.integrated.IntegratedServer.tick(IntegratedServer.java:152) [IntegratedServer.class:?]^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:481) [MinecraftServer.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] Caused by: java.util.ConcurrentModificationException^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:909) ~[?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.util.ArrayList$Itr.next(ArrayList.java:859) ~[?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at edu.utd.minecraft.mod.polycraft.aitools.commands.APICommandReset.serverExecute(APICommandReset.java:87) ~[APICommandReset.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at edu.utd.minecraft.mod.polycraft.privateproperty.network.APICommandMessageHandler$1.run(APICommandMessageHandler.java:25) ~[APICommandMessageHandler$1.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_162]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] at net.minecraft.util.Util.runTask(SourceFile:44) ~[Util.class:?]^M
^M
2022-03-31_17:02:21: PAL: [2022-03-31 12:02:20] ... 5 more^M
^M
2022-03-31_17:02:21: DEBUG: AzureBlobConnectionError: Check Azure Storage Key!^M
2022-03-31_17:02:22: PAL: [2022-03-31 12:02:22] [17:02:22] [BOT API THREAD/INFO]: [edu.utd.minecraft.mod.polycraft.aitools.BotAPI$1:run:728]: SENSE_ALL NONAV^M
^M

(hang)