View Issue Details

IDProjectCategoryLast Update
0026372AI War 2Gameplay IssueFeb 14, 2022 5:20 pm
ReporterBadgerBadger Assigned ToChris_McElligottPark  
Status resolvedResolutionfixed 
Product VersionBeta 3.802 New Challengers Approach 
Fixed in VersionBeta 3.803 Encyclopedia Madness 
Summary0026372: MP Bugs 3.802
DescriptionI ran a quick (10 minute) game with human empire/necro sidekick. Saw some errors. Here on the host:

2/14/2022 10:40:33 AM 3.802 HOST DELAYED32 TID7 Generate FULL Map Complete 515ms Seed: 214900591
2/14/2022 10:41:14 AM 3.802 HOST Inner Error in AIWar2NetworkSync.Server_SendBatchOfSyncsBasedOnCurrentSyncStage, debugStage 1000: System.NullReferenceException: Object reference not set to an instance of an object
  at AIWar2NetworkSync.Server_SendBatchOfSquadsToSyncCheck (System.Int32 clientsOfRelevance) [0x00234] in <ceffa06672c44c6ba338280b5f234487>:0
  at AIWar2NetworkSync.Server_SendBatchOfSyncsBasedOnCurrentSyncStage () [0x000dd] in <ceffa06672c44c6ba338280b5f234487>:0
  at System.Environment.get_StackTrace () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at Arcen.Universal.ArcenDebugging.ArcenLog_InnerOnMainThreadOnly (System.String Message, Arcen.Universal.DebugLogDestination Destination, System.Boolean IncludeStackTrace, Arcen.Universal.Verbosity Verbosity, System.DateTime Timestamp) [0x00000] in <f5981153be3e4befbda749321f211800>:0
  at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.Verbosity Verbosity) [0x00000] in <f5981153be3e4befbda749321f211800>:0
  at AIWar2NetworkSync.Server_SendBatchOfSyncsBasedOnCurrentSyncStage () [0x00000] in <ceffa06672c44c6ba338280b5f234487>:0
  at Arcen.AIW2.Core.AIWar2Networking.OnServer_CheckForSendingServerBatchMessageToClients () [0x00000] in <ceffa06672c44c6ba338280b5f234487>:0
  at Arcen.AIW2.Core.World_AIW2.OnHost_SendHostCommandsAndSuchToClients () [0x00000] in <ceffa06672c44c6ba338280b5f234487>:0
  at Arcen.AIW2.Core.Engine_AIW2.ProcessArbitraryFrameOnMainThread (System.Boolean& stalledWaitingOnConnections, System.String& reasonForNoVisualUpdates) [0x00000] in <ceffa06672c44c6ba338280b5f234487>:0
  at Arcen.Universal.Engine_Universal.OnUpdateEngineUniversalFromMainThread () [0x00000] in <f5981153be3e4befbda749321f211800>:0
  at Arcen.AIW2.Core.ArcenGameControllerBase.BaseUpdate () [0x00000] in <ceffa06672c44c6ba338280b5f234487>:0
  at ArcenGameController.Update () [0x00000] in <37480ea94fbe44d48f5ee03d59378c32>:0

That error did not show on the client. A few minutes later I did see some client errors though:

2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED26 TID7 Canary code mismatch at EntityCanaryPostSys ('' instead of 'P'). Code above it is the real problem.
2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED27 TID7 Canary code mismatch at EntityCanaryGP ('' instead of 'GP'). Code above it is the real problem.
2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED28 TID7 GameEntity_Squad deserialization error at stage 17000 from serialized version 3.802 loading into new version 3.802, error: System.Exception: AIReinforcementPointContent Error: DeserializeFrom_Inner DoByIndex=true nameIndex of 2943 larger than IndexSerializationInfo.SerializedNamesList.Count of 1981 on table: GameEntityTypeDataTable FieldNameForErrors: AIReinforcementPointContent From Version: 3.802
  at Arcen.Universal.ArcenDynamicTable`1[T].DeserializeFrom_Inner (Arcen.Universal.SerMetaData MetaData, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.String& NameFound, System.Boolean DoByIndex, Arcen.Universal.LookupSwapAllowed SwapAllowed, System.String FieldNameForErrors) [0x0020e] in <f5981153be3e4befbda749321f211800>:0
  at Arcen.Universal.ArcenDynamicTable`1[T].DeserializeByIndex (Arcen.Universal.SerMetaData MetaData, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.String FieldNameForErrors) [0x00001] in <f5981153be3e4befbda749321f211800>:0
  at Arcen.AIW2.Core.GameEntity_Squad.DeserializeSquadIntoSelf (Arcen.Universal.SerMetaData MetaData, System.Int32 primaryKeyID, Arcen.AIW2.Core.GameEntityTypeData typeData, Arcen.AIW2.Core.Planet NewPlanet, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.Boolean HideErrors, System.Boolean IsLoadingTemplate, Arcen.Universal.SerializationCommandType SerializationCmdType, Arcen.AIW2.Core.PlanetFaction NewPlanetFaction) [0x01347] in <ceffa06672c44c6ba338280b5f234487>:0
2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED29 TID7 Canary code mismatch at CanaryCode ('' instead of 'ThSeus'). Code above it is the real problem.
2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED30 TID18 Canary code mismatch at hash ('' instead of '#'). Code above it is the real problem.
2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED31 TID18 Canary code mismatch at hash ('' instead of '#'). Code above it is the real problem.
2/14/2022 10:45:12 AM 3.802 CLIENT DELAYED32 TID18 Canary code mismatch at hash ('' instead of '#'). Code above it is the real problem.
...
2/14/2022 10:45:40 AM 3.802 CLIENT DELAYED105 TID35 Canary code mismatch at hash ('' instead of '#'). Code above it is the real problem. <==== I saw a bunch of these
TagsNo tags attached.

Activities

Chris_McElligottPark

Feb 14, 2022 4:35 pm

administrator   ~0064447

If you're in the middle of seeing a lot of canary code issues, can you turn on (on the host) the heavy network metadata option? That will cause the game to become really jerky and laggy, so only do it while it is having troubles. But if there are other data mismatches, then it should find those. I don't know what is happening, but something is not making it across properly, and that should give us the real exception.

From the above, I can fix the host error, but all of the client errors are... just more for the pile of kind of invisible stuff, unfortunately.

Chris_McElligottPark

Feb 14, 2022 4:36 pm

administrator   ~0064448

The canaries that you see, the way those are behaving, that's why I was suspecting that the host was erroring in not sending some. It's a really strange situation.

Chris_McElligottPark

Feb 14, 2022 4:48 pm

administrator   ~0064449

* Paid closer attention to my canaries that were in Badger's most recent MP report, and did a code review of the system serialization for the dozenth time... and found what looks to have been the problem with serialization that was coming up intermittently in multiplayer.
** Specifically, there was some data that was being serialized only in the event that the pursuit target was alive. However, the data that it was basing this on was based on two sequential calls, and it was possible -- however, "unlikely" in some respects, for the pursuit target to die in that interval. In those cases, the host would say "here's the FRD that is alive" and then would go "whoops it's dead, don't send the rest of the data actually" and the client would see "here's the FRD that's alive, good" and then try to read the follow-on data, not knowing the host didn't send that. The host is now consistent about not sending that by using a local variable to ensure consistency between those two calls.
** This is something that Bummeri and his group have been sending me logs for for a month or two, and hopefully this is finally the solution to that one. It's been really confusing! Thanks to everyone who has been making reports on this, and fingers crossed that there were not two of this sort of issue in that part of the code. At least I have a better idea what to look for if I need to, and I can always seed more canaries if I find I need to.

Chris_McElligottPark

Feb 14, 2022 5:07 pm

administrator   ~0064450

* Added one more canary into MP, to make sure that if there's an issue with external deserialization, we'll know about it. I think there might be.

* Just in case the "theseus error" is not fixed by my prior fix in this build, I've built out the data collection for the theseus error a lot more, and it now gives us more information.
** Even if I have fixed things at the moment, there's always the possibility that a theseus error could happen again (because of mods, actually, is one big reason), and so having that extra error information should let us point to which faction or which mod, or know that it is in fact base game info (there's now and "error 6" that will happen before the theseus error if it's internal data).

Chris_McElligottPark

Feb 14, 2022 5:14 pm

administrator   ~0064451

* Added better instrumentation to Server_SendBatchOfSquadsToSyncCheck, since it was able to have errors on the host in rare cases, apparently.
** Discovered one place where an error could have happened if a squad died right before being sent to the client (this had to do with the planetfaction being null, and was not possible until last week because of other semi-related changes I made, so this might not be so rare now, actually). Anyhow, it's fixed.

Chris_McElligottPark

Feb 14, 2022 5:20 pm

administrator   ~0064453

Thanks! Last one for now:

* Added in some more canaries for network code around planet faction communication, because I suspect that the hash code canary is telling the truth and there's a second issue in there. I didn't see it on a code review, however, so this one is probably still in the wind. It's something else temporal, I have a feeling.

Issue History

Date Modified Username Field Change
Feb 14, 2022 12:49 pm BadgerBadger New Issue
Feb 14, 2022 12:49 pm BadgerBadger Status new => assigned
Feb 14, 2022 12:49 pm BadgerBadger Assigned To => Chris_McElligottPark
Feb 14, 2022 4:35 pm Chris_McElligottPark Note Added: 0064447
Feb 14, 2022 4:36 pm Chris_McElligottPark Note Added: 0064448
Feb 14, 2022 4:48 pm Chris_McElligottPark Note Added: 0064449
Feb 14, 2022 5:07 pm Chris_McElligottPark Note Added: 0064450
Feb 14, 2022 5:14 pm Chris_McElligottPark Note Added: 0064451
Feb 14, 2022 5:20 pm Chris_McElligottPark Status assigned => resolved
Feb 14, 2022 5:20 pm Chris_McElligottPark Resolution open => fixed
Feb 14, 2022 5:20 pm Chris_McElligottPark Fixed in Version => Beta 3.803 Encyclopedia Madness
Feb 14, 2022 5:20 pm Chris_McElligottPark Note Added: 0064453