View Issue Details
ID | Project | Category | Date Submitted | Last Update | |
---|---|---|---|---|---|
0019668 | AI War 2 | Crash/Exception | Jun 30, 2018 10:46 pm | Aug 30, 2018 11:49 am | |
Reporter | Ovalcircle | Assigned To | keith.lamothe | ||
Status | closed | Resolution | no change required | ||
Product Version | 0.746 Disposing of the Invisible Man | ||||
Summary | 0019668: Attempt to execute command during wrong Frame | ||||
Description | Look for 6/30/2018 10:33:51 PM | ||||
Tags | No tags attached. | ||||
|
|
|
I have hit this "wrong frame" error as well |
|
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. |
|
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 |
|
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. |
|
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. |
|
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. :) |
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 |