View Issue Details

IDProjectCategoryLast Update
0019668AI War 2Crash/ExceptionAug 30, 2018 11:49 am
ReporterOvalcircle Assigned Tokeith.lamothe  
Status closedResolutionno change required 
Product Version0.746 Disposing of the Invisible Man 
Summary0019668: Attempt to execute command during wrong Frame
DescriptionLook for 6/30/2018 10:33:51 PM
TagsNo tags attached.

Activities

Ovalcircle

Jun 30, 2018 10:46 pm

reporter  

AI War 2 Frame Error.jpg (238,874 bytes)   
AI War 2 Frame Error.jpg (238,874 bytes)   
ArcenDebugLog.txt (1,566,120 bytes)

BadgerBadger

Jul 1, 2018 12:28 am

manager   ~0047655

I have hit this "wrong frame" error as well

Chris_McElligottPark

Jul 2, 2018 9:30 am

administrator   ~0047679

Yeah, I've hit it some as well. I'm not sure what it is, exactly. It's something in Keith's area, and I've added it to his work list for prior to wave 4.

BadgerBadger

Jul 2, 2018 9:32 am

manager   ~0047681

If you look at the debug log, I see what looks like a bunch of threads stuck right before the error is hit. Incidentally, it would be nice if this error message also showed which command had the problem (for example, if it's a command that was just added then that would be useful for debugging)

6/28/2018 9:55:40 PM Thread 'outerThreadFor_ArcenShortTermPlanningContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:40 PM Thread 'strengthCountingContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:40 PM Thread 'movePlanningContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:40 PM Thread 'targetingContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:40 PM Thread 'collisionContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM Thread 'metalFlowContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM Thread 'ProtectionContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM Thread 'tachyonContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM Thread 'tractorContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM Thread 'gravityContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM Thread 'aiwcGravityContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now
6/28/2018 9:55:41 PM
GAAAH! We have a command we need to execute during frame 3775 but it's already frame 3776

   at System.Environment.get_StackTrace() in /Users/builduser/buildslave/mono/build/mcs/class/corlib/System/Environment.cs:line 227
   at Arcen.Universal.ArcenDebugging.ArcenDebugLog(System.String Message, DebugLogDestination Destination, Boolean IncludeStackTrace, Verbosity Verbosity) in D:\vclarge\AI_War_2_Ultra\ArcenUniversal\src\UtilityLibraries\ArcenDebugging.cs:line 155
   at Arcen.Universal.ArcenDebugging.ArcenDebugLog(System.String Message, DebugLogDestination Destination, Verbosity Verbosity) in D:\vclarge\AI_War_2_Ultra\ArcenUniversal\src\UtilityLibraries\ArcenDebugging.cs:line 116
   at Arcen.Universal.ArcenDebugging.ArcenDebugLog(System.String Message, Verbosity Verbosity) in D:\vclarge\AI_War_2_Ultra\ArcenUniversal\src\UtilityLibraries\ArcenDebugging.cs:line 95
   at Arcen.AIW2.Core.World_AIW2.OnClient_ExecuteGameCommandsReceivedFromServer(Arcen.AIW2.Core.ArcenSimContext Context) in D:\vclarge\AI_War_2_Ultra\ArcenAIW2Core\src\Logic\GameState\World_AIW2.cs:line 634

Chris_McElligottPark

Jul 2, 2018 9:48 am

administrator   ~0047683

Okay, so that sounds like either it's waiting on one thread and unable to merge them, or something else strange. I'm guessing that some command or some part of the code was super long-running. In for next version, anyhow:

* The various threads that were previously only living for 10 seconds at most now live for 30 seconds at most -- at least for now. This may cause hangs to happen in the game if something is really long-running, but ideally this will let us know a bit more about what something is doing and why, and potentially find the hangups that are taking so long.

* The error messages for commands that are trying to be executed on a different frame now say more about the command, such as what type it is. Most likely the problem isn't directly with these commands anyhow, but a thread that stalled before it or ran overlong, but it's worth having the extra info just in case.

Chris_McElligottPark

Aug 29, 2018 7:54 pm

administrator   ~0048551

Badger notes, as of 0.762:

"I am very suspicious that there's a bug in threading somewhere. I observe 0020034. In this bug, a notification is up saying "The Dark Spire wanted to launch a vengeance strike at time X. However, the current time is X + several minutes, so the notification looks really weird."

In PerSimStep for the Dark Spire there's code that says "If the current time >= X, launch the vengeance strike". And indeed, when I load the save game, the vengeance strike happens at the next sim step. This suggests that it has been several minutes since the last time PerSimStep was run for the Dark Spire for the tester. And the fact that PerSimStep happened immediately for me suggests there wasn't something in the Dark Spire code that was causing it not to run."

I think that threads may have stalled somehow, or had a background error in this case.

Chris_McElligottPark

Aug 30, 2018 11:49 am

administrator   ~0048598

Okay, this is a false alarm type of error -- we'll always need the log to see for sure, but the background threads are all working just fine. Right prior to this error, there are a lot of log entries like this:

Thread 'outerThreadFor_ArcenShortTermPlanningContext' is in state Background, WaitSleepJoin after 10 seconds, so killing it now

What is happening is the following sequence of events:

1) There are some errors on the background thread
2) These particular ones prevented the background thread from completing, or stick it into an infinite loop, either way.
3) The front-end notices, and kills the background threads (by design) and logs the messages above.
4) The prior frame didn't finish, so there was still old data in there and so this message comes up. Again as designed.

So essentially, when we see this issue we should not think "threading issue", but instead we should think "error on background thread caused it to stall." There may come a day when that's not accurate, but so far so good.

In the case of this specific report, the actual bug was:

Exception when checking for sim step: System.NullReferenceException: Object reference not set to an instance of an object
  at Arcen.AIW2.External.GameCommand_SetWormholePath+<>c__DisplayClass0_0.<Execute>b__0 (Arcen.AIW2.Core.GameEntity entity) [0x00000] in <filename unknown>:0

And that was one that Badger fixed. :)

Issue History

Date Modified Username Field Change
Jun 30, 2018 10:46 pm Ovalcircle New Issue
Jun 30, 2018 10:46 pm Ovalcircle File Added: AI War 2 Frame Error.jpg
Jun 30, 2018 10:46 pm Ovalcircle File Added: ArcenDebugLog.txt
Jul 1, 2018 12:28 am BadgerBadger Note Added: 0047655
Jul 2, 2018 9:21 am BadgerBadger Summary Not sure how this one happened => Attempt to execute command during wrong Frame
Jul 2, 2018 9:29 am Chris_McElligottPark Assigned To => keith.lamothe
Jul 2, 2018 9:29 am Chris_McElligottPark Status new => assigned
Jul 2, 2018 9:30 am Chris_McElligottPark Note Added: 0047679
Jul 2, 2018 9:32 am BadgerBadger Note Added: 0047681
Jul 2, 2018 9:48 am Chris_McElligottPark Note Added: 0047683
Aug 29, 2018 7:54 pm Chris_McElligottPark Note Added: 0048551
Aug 30, 2018 11:49 am Chris_McElligottPark Status assigned => closed
Aug 30, 2018 11:49 am Chris_McElligottPark Resolution open => no change required
Aug 30, 2018 11:49 am Chris_McElligottPark Note Added: 0048598