View Issue Details
| ID | Project | Category | Date Submitted | Last Update | |
|---|---|---|---|---|---|
| 0024707 | AI War 2 | Gameplay Issue | Apr 18, 2021 1:07 am | Apr 20, 2021 1:41 pm | |
| Reporter | BadgerBadger | Assigned To | Chris_McElligottPark | ||
| Status | resolved | Resolution | fixed | ||
| Product Version | 2.803 Multiplayer Option Overload | ||||
| Fixed in Version | 2.805 Relentless On Several Levels | ||||
| Summary | 0024707: MP problems 4/17 | ||||
| Description | Report from tonight's session steam multi-socket direct: 10 second countdown for clients, followed by failure, no error messages. Confirmed behaviour for multiple hosts and multiple clients. 100% failure rate. multi-socket relay -> We had problems with one host (steadily worsening into unusable) , but success with a different host. We had our best results playing with this on the second host. steam tubes direct -> significant problems connection, could not play on samesteam tubes relayed -> one person could correctly connect, another person took 30+ seconds into failure. We could not use this steam p2p direct: connected but lousy performance. We gave up on using this after a while steam p2p relay: noone could connect at all As a client, with the game paused, on the galaxy map I sometimes see a bunch of planets flash to "unowned by anyone", then rapidly back to the "correct" owner. Also a lot of times I saw only one faction's units appear at a time (like "our scourge allies appear. Once I started having a lot of problems on this front I would need to quit/reconnect. I never saw anything to connect this problem to anything in the ArcenDebugLog And now errors from the ArcenDebugLog 4/17/2021 8:58:12 PM 2.803 SINGLEP STEAM P2P NETWORKING: P2P connection from <redacted> connected. 4/17/2021 8:58:12 PM 2.803 SINGLEP MP Error: Socket was off! ... at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.Verbosity Verbosity) [0x00000] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenNetworkClientConnection.RespondToNewConnectionAcceptedByTransportLayer () [0x00000] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.AIW2.Core.SteamP2PSocketBase.ConnectionRequest_OnHost (Steamworks.SteamId IncomingClient) [0x00000] in <1f50711f1c004d99af815a25f7649175>:0 at Steamworks.SteamNetworking+<>c.<InstallEvents>b__3_0 (Steamworks.Data.P2PSessionRequest_t x) [0x00000] in <1a4d0b9e0e9644d59545a7f1c42821c8>:0 at Steamworks.Dispatch+<>c__DisplayClass29_0`1[T].<Install>b__0 (System.IntPtr x) [0x00000] in <1a4d0b9e0e9644d59545a7f1c42821c8>:0 at Steamworks.Dispatch.ProcessCallback (Steamworks.Dispatch+CallbackMsg_t msg, System.Boolean isServer) [0x00000] in <1a4d0b9e0e9644d59545a7f1c42821c8>:0 at Steamworks.Dispatch.Frame (Steamworks.Data.HSteamPipe pipe) [0x00000] in <1a4d0b9e0e9644d59545a7f1c42821c8>:0 at Steamworks.SteamClient.RunCallbacks () [0x00000] in <1a4d0b9e0e9644d59545a7f1c42821c8>:0 4/17/2021 9:52:54 PM 2.803 CLIENT Error in thread for execution context 'executionContext' NullReferenceException Object reference not set to an instance of an object ===STACK FRAMES (with file info)=== FILE METHOD IL_OFFSET NATIVE_OFFSET LINE_NUMBER COLUMN_NUMBER DeployDroneContents_ONLYCallFromSimBGThread 89 260 0 0 DeployDroneContents_ONLYCallFromSimBGThread 85 191 0 0 <CheckForInternalShipDeployment_DroneProducers_FromSimBGThread>b__0 203 607 0 0 DoForEntities 104 286 0 0 DoForEntities 31 159 0 0 CheckForInternalShipDeployment_DroneProducers_FromSimBGThread 14 219 0 0 DoCombatSecond_FromSimBGThread 92 259 0 0 ... 4/17/2021 10:24:56 PM 2.803 CLIENT Error, received 1001 items in external pattern ExternalData_FactionCommon when that pattern is only supposed to contain 1; the e\ xtra items will be ignored (parsing the non-ignored items may cause errors if the pattern implementation is not expecting the right types, etc) ExternalDataHeader: EXTE\ RNAL DATA - Squad ... at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.Verbosity Verbosity) [0x00000] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenExternalData.DeserializedIntoSelf (System.Object ParentObject, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.Boolean IsForPartialS\ yncDuringMultiplayer, System.String ExternalDataHeader) [0x00000] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenExternalData.DeserializeExternalDataFrom (Arcen.Universal.ArcenExternalDataPattern externalPattern, System.String namespaceName, System.Object\ ParentObject, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.String ExternalDataHeader, System.Boolean IsForPartialSyncDuringMultiplayer) [0x00000] in <00af\ 5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenExternalDataLookup.DeserializeExternalDataFrom (Arcen.Universal.ArcenDeserializationBuffer Buffer, System.String ExternalDataHeader, System.Bo\ olean IsForPartialSyncDuringMultiplayer) [0x00000] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.AIW2.Core.GameEntity_Squad.DeserializedIntoSelf (System.Int32 primaryKeyID, Arcen.AIW2.Core.GameEntityTypeData typeData, Arcen.AIW2.Core.Planet Planet, Arcen\ .Universal.ArcenDeserializationBuffer Buffer, System.Boolean HideErrors, System.Boolean IsLoadingTemplate, Arcen.Universal.SerializationCommandType SerializationCmdType\ ) [0x00000] in <1f50711f1c004d99af815a25f7649175>:0 at AIWar2NetworkSync.Client_AcceptDivergenceDataFromHost (Arcen.Universal.ArcenDeserializationBuffer buffer) [0x00000] in <1f50711f1c004d99af815a25f7649175>:0 at Arcen.AIW2.Core.AIWar2Networking.HandleMessage (System.Int64 UniqueMessageIDFromSender, System.Boolean IsFromSelfWithoutNetwork, System.UInt32 senderNetworkID, Arc\ en.Universal.ArcenNetworkMessageType CoreNetworkMessageType, Arcen.Universal.ArcenDeserializationBuffer buffer) [0x00000] in <1f50711f1c004d99af815a25f7649175>:0 <this is interesting, because we didn't have the DZ enabled in this game> 4/17/2021 10:25:08 PM 2.803 CLIENT ERROR: DeserializeExternalDataFrom for EXTERNAL DATA - Squad debugStage: 8100 Error: System.Exception: Could not read string, bu\ t did get this partial one: ',”uAr-8_5Pip'T_2D^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@\ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@\ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@\ <lots more ^@s, ending here:> ^@^@^@^@^@^@'. Was for field with name:' InternalName' Exception: System.Exception: Tried to read condensed string format index 108 which is >= the lengt\ h of 106 supported characters. Some bad data just happened prior to this! at Arcen.Universal.ArcenDeserializationBufferModern.GetBits_InnerHelperChar (System.Boolean ReadFullUnicode) [0x000c1] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenDeserializationBufferModern.ReadString_Condensed (System.String FieldNameForErrors) [0x00105] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenDeserializationBufferModern.ReadString_Condensed (System.String FieldNameForErrors) [0x0022b] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.AIW2.External.DZResourceConversion.DeserializedIntoSelf (Arcen.Universal.ArcenDeserializationBuffer Buffer) [0x00181] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 .... at Arcen.AIW2.External.DZResourceConversion.DeserializeNewFrom (Arcen.Universal.ArcenDeserializationBuffer Buffer) [0x00007] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 at Arcen.AIW2.External.DarkZenithPerUnitData.DeserializeIntoSelf (Arcen.Universal.ArcenDeserializationBuffer Buffer, System.Boolean IsForPartialSyncDuringMultiplayer) [0x00116] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 .... 4/17/2021 10:25:08 PM 2.803 CLIENT Not fatal - just a warning: Client_AcceptDivergenceDataFromHost: Error in faction index sent: -1. Abandoning rest of sync fix d\ ata from this cycle. 4/17/2021 10:25:09 PM 2.803 CLIENT DoEntitySecondLogic for NecromancerFlagship debug code 80 exception System.NullReferenceException: Object reference not set to a\ n instance of an object at Arcen.AIW2.Core.GameEntity_Squad.DoEntitySecondLogic_FromSimBGThread (Arcen.AIW2.Core.ArcenSimContext Context) [0x00cda] in <1f50711f1c004d99af815a25f7649175>:0 4/17/2021 10:26:00 PM 2.803 CLIENT Not fatal - just a warning: Client_AcceptDivergenceDataFromHost: Error in faction index sent: -1. Abandoning rest of sync fix d\ ata from this cycle. 4/17/2021 10:34:51 PM 2.803 CLIENT Checking if fully connected 4/17/2021 10:36:50 PM 2.803 CLIENT Not fatal - just a warning: Client_AcceptDivergenceDataFromHost: Error in faction index sent: -1. Abandoning rest of sync fix d\ ata from this cycle. 4/17/2021 10:36:51 PM 2.803 CLIENT DoEntitySecondLogic for ArkOne debug code 80 exception System.NullReferenceException: Object reference not set to an instance of\ an object at Arcen.AIW2.Core.GameEntity_Squad.DoEntitySecondLogic_FromSimBGThread (Arcen.AIW2.Core.ArcenSimContext Context) [0x00cda] in <1f50711f1c004d99af815a25f7649175>:0 4/17/2021 10:37:30 PM 2.803 CLIENT ERROR: DeserializeExternalDataFrom for EXTERNAL DATA - Faction debugStage: 9000 Error: System.Exception: Could not read string, but did g\ et this partial one: '´1G??ß_^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@....^@^@^@'. Was \ for field with name:' RequiredTag' Exception: System.Exception: Tried to read condensed string format index 122 which is\ >= the length of 106 supported characters. Some bad data just happened prior to this! at Arcen.Universal.ArcenDeserializationBufferModern.GetBits_InnerHelperChar (System.Boolean ReadFullUnicode) [0x000c1] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenDeserializationBufferModern.ReadString_Condensed (System.String FieldNameForErrors) [0x00105] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenDeserializationBufferModern.ReadString_Condensed (System.String FieldNameForErrors) [0x0022b] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.AIW2.Core.FireteamRequiredTarget.DeserializedIntoSelf (Arcen.Universal.ArcenDeserializationBuffer Buffer) [0x0005c] in <1f50711f1c004d99af815a25f7649175>:0 at Arcen.AIW2.Core.FireteamRequiredTarget.DeserializeNewFrom (Arcen.Universal.ArcenDeserializationBuffer Buffer) [0x00007] in <1f50711f1c004d99af815a25f7649175>:0 at Arcen.AIW2.External.ExternalData_AIFactionCommon.DeserializeExternalData (Arcen.AIW2.Core.Faction ParentFaction, System.Object[] Target, System.Int32 ItemsToExpect, Arcen.U\ niversal.ArcenDeserializationBuffer Buffer, System.Boolean IsForPartialSyncDuringMultiplayer) [0x00883] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 at Arcen.AIW2.Core.ArcenExternalDataPatternImplementationBase_Faction.DeserializeExternalDataOuter (System.Object ParentObject, System.Object[] Target, System.Int32 ItemsToExp\ ect, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.Boolean IsForPartialSyncDuringMultiplayer) [0x000a4] in <1f50711f1c004d99af815a25f7649175>:0 at Arcen.Universal.ArcenExternalData.DeserializedIntoSelf (System.Object ParentObject, Arcen.Universal.ArcenDeserializationBuffer Buffer, System.Boolean IsForPartialSyncDuring\ Multiplayer, System.String ExternalDataHeader) [0x000ed] in <00af5fac95e44bc3bd78957a3c3d30da>:0 at Arcen.Universal.ArcenExternalDataLookup.DeserializeExternalDataFrom (Arcen.Universal.ArcenDeserializationBuffer Buffer, System.String ExternalDataHeader, System.Boolean IsF\ orPartialSyncDuringMultiplayer) [0x00341] in <00af5fac95e44bc3bd78957a3c3d30da>:0 <and then immediately below this> 4/17/2021 10:37:30 PM 2.803 CLIENT Exception in AIWar2Networking.HandleMessage: messageType: FromServerToClient_PeriodicFactionExternalSyncDataThatJustOverrides Is\ FromSelfWithoutNetwork: False senderNetworkID: 0 CoreNetworkMessageType: GameSpecific buffer.GetLengthOfCurrentChunk(): 25995 Exception: System.Exception: Canary code e\ xception at CanaryCode (fac3). Code above it is the real problem. at Arcen.Universal.ArcenDeserializationBufferModern.ValidateNetworkCanary (System.String ExpectedCanaryString, System.String CanaryFieldName) [0x00086] in <00af5fac95\ e44bc3bd78957a3c3d30da>:0 at AIWar2NetworkSync.Client_AcceptPeriodicFactionExternalSyncDataThatJustOverrides (Arcen.Universal.ArcenDeserializationBuffer buffer) [0x00141] in <1f50711f1c004d99a\ f815a25f7649175>:0 at Arcen.AIW2.Core.AIWar2Networking.HandleMessage (System.Int64 UniqueMessageIDFromSender, System.Boolean IsFromSelfWithoutNetwork, System.UInt32 senderNetworkID, Arcen.Universal.ArcenNetworkMessageType CoreNetworkMessageType, Arcen.Universal.ArcenDeserializationBuffer buffer) [0x00258] in <1f50711f1c004d99af815a25f7649175>:0 4/17/2021 10:38:33 PM 2.803 CLIENT ActuallyFireSalvoAtTargetPriorityList error at debugStage 4200, error: System.NullReferenceException: Object reference not set to an instance of an object at Arcen.AIW2.External.EntitySimLogicImplementation.ActuallyFireSalvoAtTargetPriorityList (Arcen.AIW2.Core.ArcenSimContext Context, Arcen.AIW2.Core.EntitySystem Syste\ m, System.Boolean trace, Arcen.Universal.ArcenCharacterBuffer tracingBuffer, System.Boolean DoShotsAllInstaHit) [0x0024f] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 4/17/2021 10:40:00 PM 2.803 CLIENT Exception in entity tooltip text generation at stage 5000:System.NullReferenceException: Object reference not set to an instance\ of an object at Arcen.AIW2.External.SpecialFaction_FallenSpire.WriteCityTooltipDetails (Arcen.Universal.ArcenDoubleCharacterBuffer tooltipBuffer, Arcen.AIW2.Core.GameEntity_Squad city) [0x000ab] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 at Arcen.AIW2.External.SpireHubDescriptionAppender.AddToDescriptionBuffer (Arcen.AIW2.Core.GameEntity_Squad RelatedEntityOrNull, Arcen.AIW2.Core.GameEntityTypeData RelatedEntityTypeData, Arcen.Universal.ArcenDoubleCharacterBuffer Buffer) [0x0006b] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 at Arcen.AIW2.External.Window_InGameHoverEntityInfo.GetTextForEntity (Arcen.Universal.ArcenDoubleCharacterBuffer buffer, Arcen.AIW2.Core.GameEntity_Base EntityBase, Arcen.AIW2.Core.Fleet+Membership MembershipBase, Arcen.AIW2.Core.GameEntityTypeData TypeDataOrNull, System.Int32 OptionalCountToShow, Arcen.AIW2.Core.Faction ForFactionOrNull, System.Byte OptionalForMarkLevel, Arcen.AIW2.Core.FromSidebarType IsFromSidebarType, Arcen.AIW2.External.ShipExtraDetailFlags DetailFlags) [0x0d63e] in <23f9e2b9ae5b46d18c6817613d7f9f97>:0 Here is a client trying to connect and failing. Unfortunately it doesn't tell me what the connection type was (we tried all of them), but including for potentially useful notes 4/17/2021 8:59:38 PM 2.803 SINGLEP Multiplayer Connection Time Taken: Establishing_Connection - 10.0s^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempting connection to: <redacted>.^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Main with SteamId 0^M <=== id 0? that seem unlikely 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Frequent with SteamId 0^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Bulky1 with SteamId 0^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Bulky2 with SteamId 0^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed ProblemDetectedLocally^M <=== 4x problem text, but no indication of the problem? 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M <===== 4x of this message? 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 9:00:14 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 9:00:14 PM 2.803 SINGLEP Multiplayer Connection Time Taken: Establishing_Connection - 10.0s^M <Note again the 4x repetition of this message 4/17/2021 9:33:31 PM 2.803 HOST STEAM RELAY SOCKET NETWORK: Connection from <redacted> to be accepted.^M 4/17/2021 9:33:31 PM 2.803 HOST STEAM RELAY SOCKET NETWORK: Connection from <redacted> to be accepted.^M 4/17/2021 9:33:31 PM 2.803 HOST STEAM RELAY SOCKET NETWORK: Connection from <redacted> to be accepted.^M 4/17/2021 9:33:31 PM 2.803 HOST STEAM RELAY SOCKET NETWORK: Connection from <redacted> to be accepted.^M | ||||
| Tags | No tags attached. | ||||
|
|
Observed on a client: If as a client I hit "X" to select all the units for a fleet, sometimes it fails to select a bunch of them. If I hover those units they say "I am part of fleet XYZ, whose hotkey is X", but hitting the fleet hotkey won't select them |
|
|
Vassal entries like Scourge -> Highseem to be wildly repeated for MP clients Necromacer: structures don't seem to rebuild after being killed.Necromancer: make it easier to sacrifice things. How about Sacrifice enough for X hacking points, and show 20, 40, 80 or "All selected units" |
|
|
First batch: * Fixed some exceptions that could happen in DeployDroneContents_ONLYCallFromSimBGThread() on MP clients. This should not have been running on clients in general. * Put in some more canary code in Client_AcceptDivergenceDataFromHost, which seems to have been having some errors in MP at times. ** Errors in this could cause various strange afflictions like units disappearing, so finding the root of this is important and this should be a good step on that path. * Fixed an exception that could happen during hacks on MP clients. In general this code is again now not run on MP clients. Ships involved are being immediately synced from the host to the clients anyhow. ** In general, just to be on the safe side, but in extra instrumentation for this even on the host, and split it into its own method, however. |
|
|
* Fixed a number of potential cross-threading issues in ActuallyFireSalvoAtTargetPriorityList(), most of which were mainly able to happen on MP clients, but technically which could likely happen under rare circumstances in SP as well. |
|
|
* Fixed some cross threading exceptions that could happen in WriteCityTooltipDetails, mainly in MP. |
|
|
@BadgerBadger: Any chance you happen to be able to find out which faction was faction index 3 in this one? |
|
|
* Canary was hit for some faction's external data in MP, but not sure which one. We have improved the canary code to give us more information about what faction name and type is present. |
|
|
@BadgerBadger: In that log where ProblemDetectedLocally is present, can you look further back above it and see if it says something about welcoming the Steam user in question? This error should be one that is hit if SteamClient.Init() failed for some reason. If there's any insight you can give me on that, that would be useful. Usually it says something along the lines of this: Hello Steam user 'x-4000 (Chris McElligott Park)' If it's not saying that at any point prior to the ProblemDetectedLocally error, in that log, then we have narrowed this down a lot. If there's another error showing there, then that's a different problem. If it DOES say hello, but then still has the ProblemDetectedLocally, that's a whole other can of worms, I guess. Which OS is this one on? |
|
|
"Here is a client trying to connect and failing. Unfortunately it doesn't tell me what the connection type was (we tried all of them), but including for potentially useful notes 4/17/2021 8:59:38 PM 2.803 SINGLEP Multiplayer Connection Time Taken: Establishing_Connection - 10.0s^M 4/17/2021 9:00:04 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempting connection to: <redacted>.^M" Note that the connection type is actually baked into every error message, so I can tell that this was direct multi-sockets in this particular case. It's all good on that, though why it's failing is not clear. It looks very strongly like the Steam client is not properly initialized in this particular case, but why I am not sure. It is possible that this is also just an issue with the wrapper not properly talking to the steamworks API, or me having a wrong version of the API library. |
|
|
Here are some more logs of that client trying to connect and failing. In these cases there was no feedback as to what was going on, just a 10 second timer followed by a failure. This was on windows laptop, not sure which version. Late Axionic Computations (0.3s) Eject And Reinsert Warp Cores (7.3s) Final Checks (0.5s)^M 4/17/2021 7:42:38 PM 2.803 SINGLEP Hello Steam user '<redacted>'^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Attempting connection to <redacted>.^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Attempt connection Main with <redacted>^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Attempt connection Frequent with <redacted>^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Attempt connection Bulky1 with <redacted>^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Attempt connection Bulky2 with <redacted>^M 4/17/2021 7:43:39 PM 2.803 CLIENT STEAM RELAY SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed None^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed None^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed None^M 4/17/2021 7:43:49 PM 2.803 SINGLEP STEAM RELAY SOCKET NETWORK: Connection changed None^M 4/17/2021 7:43:49 PM 2.803 SINGLEP Multiplayer Connection Time Taken: Establishing_Connection - 10.0s^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempting connection to: <redacted IP>.^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Main with SteamId 0^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Frequent with SteamId 0^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Bulky1 with SteamId 0^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Attempt connection Bulky2 with SteamId 0^M 4/17/2021 7:44:29 PM 2.803 CLIENT STEAM DIRECT SOCKET NETWORK: Connection changed Connecting^M 4/17/2021 7:44:39 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed ProblemDetectedLocally^M 4/17/2021 7:44:39 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 7:44:39 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 7:44:39 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 7:44:39 PM 2.803 SINGLEP STEAM DIRECT SOCKET NETWORK: Connection changed None^M 4/17/2021 7:44:39 PM 2.803 SINGLEP Multiplayer Connection Time Taken: Establishing_Connection - 10.0s^M |
|
|
Faction index 3 in this game is a Hunter Fleet |
|
|
* Whenever you quit the game to the main menu or the OS from an active game (or get booted in multiplayer from a lost connection -- this should work, anyhow) it now logs a little "Memory Profile Debug Data On Game Exit" table.\ ** This currently covers how many fleets, fleet memberships, orders, planetfactions, faction, other gameentities, shots, ships, speed groups, and planets have been created, garbage collected, and are still active since last reloading the game. ** There seems to be a memory leak in multiplayer on the clients, and comparing these numbers between client and host should give us some ideas on where that is. It's possible that these are in "external data" somewhere, in which case we will have to greatly expand our footprint reporting. ** If you're curious, essentially if the number of active ones is super duper high on the client, that's the point of concern for a memory leak. That said, if the number of total ones created is very much higher on the client compared to the host, then that could be indicative of a performance problem (rather than a memory leak). ** These numbers mean almost nothing in isolation (unless numbers are in the hundreds of thousands or up), so if you report your version of these, please pair the client(s) and the host versions of the report together. ** If your game is getting laggy near the end of a long session, or clients are seeing strange behaviors, or whatever else, then please do send us these plus whatever other information you feel like is relevant! ** Fleets or fleet memberships in particular are suspicious right now, as Badger had noted that sometimes on clients not all of the ships would be selected if you press the hotkey associated with that fleet. That could be a different form of code bug, but malformed/duplicate fleets or memberships is the highest likelihood. Paired with general command delays and slowdowns on clients in long sessions that reset when disconnecting and reconnecting, we know there is SOME sort of client memory leak in general. ** In the absolute worst case, we can brute force fixing some of this (that may be needed in the event that mods are what contain a memory leak, for example, since we can't fix those sorts of things) by doing a complete rebuild on the client periodically, but this would lose some UI state and might be annoying. If we did do it, for the most part it would likely just feel like a "save interruption" in a game like Factorio. And if we did it, it would be an optional thing. For now we'd rather go hunting for the leak. |
|
|
Okay, so the ProblemDetectedLocally actually just happens on timeout, too: "If the application does not respond to the connection attempt in a timely manner, and we stop receiving communication from the client, the connection attempt will be timed out locally, transitioning the connection to the k_ESteamNetworkingConnectionState_ProblemDetectedLocally state. The client may also close the connection before it is accepted, and a transition to the k_ESteamNetworkingConnectionState_ClosedByPeer is also possible depending the exact sequence of events." So that's not super helpful! |
|
|
Interesting extra data about P2P in general: k_EP2PSessionErrorTimeout The connection timed out because the target user didn't respond, perhaps they aren't calling AcceptP2PSessionWithUser. Corporate firewalls can also block this (NAT traversal is not firewall traversal), make sure that UDP ports 3478, 4379, and 4380 are open in an outbound direction. |
|
|
@BadgerBadger: I think I will need some help or at least clarification on these two parts of your report: You wrote: "Vassal entries like Scourge -> Highseem to be wildly repeated for MP clients" My question: where is it reporting these from in the code? I'm not sure what is triggering this. It is quite possible that this should only be running on the host in the first place, but I'm not sure where this data is from. You wrote: "Necromacer: structures don't seem to rebuild after being killed.Necromancer: make it easier to sacrifice things. How about Sacrifice enough for X hacking points, and show 20, 40, 80 or "All selected units"" My question: what triggers the rebuild of a necromancer structure? If it's "do this for the local faction" but is set to only run on the host, then that might be it. In general, I would strongly suggest that this become "do this on the host only, period, and do it for whatever faction." The end result of this will have to go through the host anyhow, and that would do it in a more timely manner. |
|
|
Thanks for the info that faction index 3 was hunter. That is... discouraging. It's one of those factions with almost no information on it. I am starting to suspect that I'm going to need to stop syncing the vast majority of external data to clients, and let that stuff stay on the host only. That will involve breaking all mods, and having some special logic for "show extra info of this sort" in tooltips for factions and ships for clients, introducing a small lag for each of those pieces of data to show up. On the plus side, if I do that, then the risk of memory leaks in a long term sense just falls through the floor (yay!), and the total amount of data transferred from hosts to clients will drop to something like 1/5 of what it is now (is my best guess, but it's hard to be sure). So there's a good chance that could be great for performance all around, as well as long-term reliability. |
|
|
The vassal and necromancer stuff is more notes for me than anything else. You can ignore those for the moment |
|
|
Not syncing external data to clients can cause UI problems; anything that is used for UI purposes will need to get pushed to clients, which is a lot. |
|
|
The UI stuff would have to be recreated in a different way for the UI on clients. It is a fair bit of stuff, but potentially less work than chasing infinite memory issues. I stayed away from doing that sort of thing for the very reason you mentioned, but the reality is that most of our problems come from that stuff in terms of just random errors that pop out of nowhere, and this would be a major way to stem the tide of that. Essentially I'd need to set up an easy pipeline for something that affects the UI to say "request this info from the host if we're a client" versus the current way of just directly looking at external data. There are a few dozen places where that's relevant, but it's a lot less than it could be. The severity of the other problem (the memory stuff mainly) is rather telling if that means this is an attractive concept. ;) |
|
|
Okay, in that case, everything that can be solved is solved for now. More work will be needed in some fashion for a few things, but either that will be an architecture update on my part, or a response to new canaries. Or both. In terms of general connection stuff, that will probably be a library change, fun fun. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| Apr 18, 2021 1:07 am | BadgerBadger | New Issue | |
| Apr 18, 2021 1:07 am | BadgerBadger | Status | new => assigned |
| Apr 18, 2021 1:07 am | BadgerBadger | Assigned To | => Chris_McElligottPark |
| Apr 18, 2021 1:09 am | BadgerBadger | Note Added: 0061140 | |
| Apr 18, 2021 1:10 am | BadgerBadger | Note Added: 0061141 | |
| Apr 20, 2021 10:53 am | Chris_McElligottPark | Note Added: 0061155 | |
| Apr 20, 2021 11:04 am | Chris_McElligottPark | Note Added: 0061156 | |
| Apr 20, 2021 11:09 am | Chris_McElligottPark | Note Added: 0061157 | |
| Apr 20, 2021 11:18 am | Chris_McElligottPark | Note Added: 0061158 | |
| Apr 20, 2021 11:20 am | Chris_McElligottPark | Note Added: 0061159 | |
| Apr 20, 2021 11:26 am | Chris_McElligottPark | Note Added: 0061160 | |
| Apr 20, 2021 11:28 am | Chris_McElligottPark | Note Added: 0061161 | |
| Apr 20, 2021 11:47 am | BadgerBadger | Note Added: 0061162 | |
| Apr 20, 2021 12:02 pm | BadgerBadger | Note Added: 0061163 | |
| Apr 20, 2021 12:20 pm | Chris_McElligottPark | Note Added: 0061164 | |
| Apr 20, 2021 12:23 pm | Chris_McElligottPark | Note Added: 0061165 | |
| Apr 20, 2021 12:26 pm | Chris_McElligottPark | Note Added: 0061166 | |
| Apr 20, 2021 12:30 pm | Chris_McElligottPark | Note Added: 0061167 | |
| Apr 20, 2021 12:38 pm | Chris_McElligottPark | Note Added: 0061168 | |
| Apr 20, 2021 1:24 pm | BadgerBadger | Note Added: 0061169 | |
| Apr 20, 2021 1:25 pm | BadgerBadger | Note Added: 0061170 | |
| Apr 20, 2021 1:34 pm | Chris_McElligottPark | Note Added: 0061171 | |
| Apr 20, 2021 1:41 pm | Chris_McElligottPark | Status | assigned => resolved |
| Apr 20, 2021 1:41 pm | Chris_McElligottPark | Resolution | open => fixed |
| Apr 20, 2021 1:41 pm | Chris_McElligottPark | Fixed in Version | => 2.805 Relentless On Several Levels |
| Apr 20, 2021 1:41 pm | Chris_McElligottPark | Note Added: 0061172 |
