search

Placeholder-Software / Dissonance

Unity Voice Chat Asset
71 stars 5 forks source link

[bug] Race Condition between Editor Mode Threads and Game Update Threads #162

Closed maasaimosh closed 5 years ago

maasaimosh commented 5 years ago

Context

I was getting lots of exceptions when using Dissonance in the editor. The errors were suspicious of multi-threading problems ( simple loops running out of elements )

e.g.

Message: Argument is out of range.
Parameter name: index
  at System.Collections.Generic.List`1[System.UInt16].get_Item (Int32 index) [0x0000c] in /Users/builduser/buildslave/mono/build/mcs/class/corlib/System.Collections.Generic/List.cs:633 
  at Dissonance.Networking.Server.ServerRelay`1[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer].ProcessPacketRelay (Dissonance.Networking.PacketReader& reader, Boolean reliable) [0x00082] in C:\PROJECT\Assets\Plugins\Dissonance\Core\Networking\Server\ServerRelay.cs:60

which is a fairly simple for loop like:

for (var i = 0; i < _tmpIdBuffer.Count; i++)
{    ....
   if (!_peers.TryGetClientInfoById(_tmpIdBuffer[i], out clientInfo))

So I whacked in some thread logging and see two threads clashing on important codepaths

Sorting this out will help all your users

Expected Behavior

No exceptions in logs. Single thread accessing important collections at one time.

Actual Behavior

Worrying exceptions in logs. When thread checks put in, evidence of multiple threads accessing important codepaths at the same time

Workaround

None, needs code fix

Fix

a) synchronise important sections b) make sure only one thread ever calls important sections c) threadlocal structures... though this may still have a race on the data freshness level instead

Steps to Reproduce

Provide a detailed set of steps to reproduce the problem

  1. Change ServerRelay.cs.ProcessPacketRelay() to log incoming thread ids

    private HashSet<int> seen_thread_ids = new HashSet<int>();

private int last_thread_id = int.MinValue ;

public void ProcessPacketRelay(ref PacketReader reader, bool reliable)
{
    // Check how many threads are accessing this

    lock( seen_thread_ids )
    {
        int thread_id = System.Threading.Thread.CurrentThread.ManagedThreadId ;

        bool fresh = seen_thread_ids.Add( thread_id );

        if( fresh )
        {
            Log.Error( "ServerRelay.ProcessPacketRelay(): New thread id encountered: "  + thread_id );
        }

        if( thread_id != last_thread_id )
        {
            Log.Error( "ServerRelay.ProcessPacketRelay(): Switch thread id [ "+last_thread_id+" ] to [ "  + thread_id +" ]");
        }

        last_thread_id = thread_id ;
    }

  2. Run the code in a Unity Editor

  3. Notice the logging ( error level ) shows two threads accessing this important call. Often at the same time :(

e.g. (abbreviated)

[Dissonance:Network] (12:26:33.647) ServerRelay`1: ServerRelay.ProcessPacketRelay(): Switch thread id [ 1 ] to [ 9 ]
0x0000000043375AAA (Mono JIT Code) [Startup.cs:33] Dissonance.Editor.Windows.Startup:Update () 
0x000000004336F693 (Mono JIT Code) [EditorApplication.cs:127] UnityEditor.EditorApplication:Internal_CallUpdateFunctions () 
0x00000000008011DE (Mono JIT Code) (wrapper runtime-invoke) object:runtime_invoke_void (object,intptr,intptr,intptr)
0x00000001414210AC (Unity) MainMessageLoop
0x000000014142296C (Unity) WinMain
0x0000000141E7B1F8 (Unity) __tmainCRTStartup
0x00007FF8DB657974 (KERNEL32) BaseThreadInitThunk
0x00007FF8DD17A271 (ntdll) RtlUserThreadStart

and then another thread:

[Dissonance:Network] (12:26:33.588) ServerRelay`1: ServerRelay.ProcessPacketRelay(): Switch thread id [ 9 ] to [ 1 ]
0x00000000432BBF07 (Mono JIT Code) [ServerRelay.cs:53] Dissonance.Networking.Server.ServerRelay`1<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:ProcessPacketRelay (Dissonance.Networking.PacketReader&,bool) 
0x000000003F4A0928 (Mono JIT Code) [BaseServer.cs:244] Dissonance.Networking.BaseServer`3<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:NetworkReceivedPacket (Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer,System.ArraySegment`1<byte>) 
0x000000003F49FD4B (Mono JIT Code) [ForgeRemasteredCommsNetwork.cs:160] Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredCommsNetwork:PreprocessPacketToServer (System.ArraySegment`1<byte>) 
0x000000003F49F380 (Mono JIT Code) [ForgeRemasteredClient.cs:59] Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient:Send (System.ArraySegment`1<byte>,int,bool) 
0x00000000434835B9 (Mono JIT Code) [ForgeRemasteredClient.cs:101] Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient:SendUnreliable (System.ArraySegment`1<byte>) 
0x0000000043483470 (Mono JIT Code) [BaseClient.cs:517] Dissonance.Networking.BaseClient`3<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:Dissonance.Networking.Client.IClient<TPeer>.SendUnreliable (System.ArraySegment`1<byte>) 
0x0000000043482A70 (Mono JIT Code) [BaseClient.cs:437] Dissonance.Networking.BaseClient`3<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:SendUnreliableP2P (System.Collections.Generic.List`1<Dissonance.Networking.ClientInfo`1<System.Nullable`1<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>>>,System.ArraySegment`1<byte>) 
0x00000000434825A8 (Mono JIT Code) [BaseClient.cs:527] Dissonance.Networking.BaseClient`3<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:Dissonance.Networking.Client.IClient<TPeer>.SendUnreliableP2P (System.Collections.Generic.List`1<Dissonance.Networking.ClientInfo`1<System.Nullable`1<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>>>,System.ArraySegment`1<byte>) 
0x000000003F49EA37 (Mono JIT Code) [SendQueue.cs:88] Dissonance.Networking.Client.SendQueue`1<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:Update () 
0x000000003F49709D (Mono JIT Code) [BaseClient.cs:199] Dissonance.Networking.BaseClient`3<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:RunUpdate (System.DateTime) 
0x000000003F496D80 (Mono JIT Code) [BaseClient.cs:174] Dissonance.Networking.BaseClient`3<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer>:Update () 
0x000000003F49627D (Mono JIT Code) [BaseCommsNetwork.cs:159] Dissonance.Networking.BaseCommsNetwork`5/Session<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Dissonance.Unit, Dissonance.Unit>:Update () 
0x000000003F484CF0 (Mono JIT Code) [BaseCommsNetwork.cs:330] Dissonance.Networking.BaseCommsNetwork`5<Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Dissonance.Unit, Dissonance.Unit>:Update () 
0x000000003F4838FD (Mono JIT Code) [ForgeRemasteredCommsNetwork.cs:117] Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredCommsNetwork:Update () 
0x0000000140509116 (Unity) BaseBehaviourManager::CommonUpdate<BehaviourManager>
0x0000000140509798 (Unity) BehaviourManager::Update
0x0000000140725F33 (Unity) `InitPlayerLoopCallbacks'::`38'::UpdateScriptRunBehaviourUpdateRegistrator::Forward
0x0000000140723028 (Unity) PlayerLoop
0x00000001411ED4D5 (Unity) PlayerLoopController::UpdateScene
0x00000001411EEA58 (Unity) PlayerLoopController::UpdateSceneIfNeeded
0x00000001411F905D (Unity) Application::TickTimer
0x00000001414210AC (Unity) MainMessageLoop
0x000000014142296C (Unity) WinMain
0x0000000141E7B1F8 (Unity) __tmainCRTStartup
0x00007FF8DB657974 (KERNEL32) BaseThreadInitThunk
0x00007FF8DD17A271 (ntdll) RtlUserThreadStart

Your Environment

DISSONANCE: 6.4.2 NETWORKING: ForgeRemastered UNITY: 2017.4.28 OS: Windows 10

Runtime: EDITOR MODE

martindevans commented 5 years ago

Thanks for the very detailed issue report! I will try to reproduce this tomorrow.

The parts of code you've modified to monitor for multiple threads are not meant to be multithreaded. The issue appears to be that the editor calling into this code for some reason on a background thread, thread 9 in your tests.

maasaimosh commented 5 years ago

Okay... I've looked in more detail about what is calling what. The Editor stuff may be a red herring. However, this means that deployed games without the Editor may still exhibit the bad behaviour. There are still two threads running at the same time and clashing at important parts like ProcessPacketRelay() and SendUnsequenced()

Using a stacktrace at the point where I detect a thread change in ServerRelay.ProcessPacketRelay()

The 'Editor' thread... originates straight out of ForgeRemastered threading. Perhaps merely logged within the Editor thread.

[Dissonance:Network] (16:31:13.229) ServerRelay`1: ServerRelay.ProcessPacketRelay(): Switch thread id [ 1 ] to [ 4 ]
Stack Trace:
   at Dissonance.Networking.Server.ServerRelay`1[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].ProcessPacketRelay(PacketReader ByRef reader, Boolean reliable)
   at Dissonance.Networking.BaseServer`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].NetworkReceivedPacket(ForgeRemasteredPeer source, ArraySegment`1 data)

   at Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer.ForgeNetworkMessageReceived(BeardedManStudios.Forge.Networking.NetworkingPlayer player, BeardedManStudios.Forge.Networking.Frame.FrameStream frame, BeardedManStudios.Forge.Networking.NetWorker networker)
   at BeardedManStudios.Forge.Networking.NetWorker.OnMessageReceived(BeardedManStudios.Forge.Networking.NetworkingPlayer player, BeardedManStudios.Forge.Networking.Frame.FrameStream frame)
   at BeardedManStudios.Forge.Networking.UDPServer.FireRead(BeardedManStudios.Forge.Networking.Frame.FrameStream frame, BeardedManStudios.Forge.Networking.NetworkingPlayer currentPlayer)
   at BeardedManStudios.Forge.Networking.UDPServer.PacketSequenceComplete(BeardedManStudios.BMSByte data, Int32 groupId, Byte receivers, Boolean isReliable)
   at BeardedManStudios.Forge.Networking.UDPPacketGroup.CompleteSequence(UInt64 id, BeardedManStudios.Forge.Networking.UDPPacketSequence sequence, BeardedManStudios.Forge.Networking.PacketComplete packetCompleteHandle, BeardedManStudios.Forge.Networking.NetWorker networker)
   at BeardedManStudios.Forge.Networking.UDPPacketGroup.AddPacket(UDPPacket packet, BeardedManStudios.Forge.Networking.PacketComplete packetCompleteHandle, BeardedManStudios.Forge.Networking.NetWorker networker)
   at BeardedManStudios.Forge.Networking.UDPPacketManager.AddPacket(UDPPacket packet, BeardedManStudios.Forge.Networking.PacketComplete packetCompleteHandle, BeardedManStudios.Forge.Networking.NetWorker networker)
   at BeardedManStudios.Forge.Networking.UDPServer.ReadPacket(BeardedManStudios.BMSByte packet)
   at BeardedManStudios.Forge.Networking.UDPServer.ReadClients()
   at BeardedManStudios.Threading.Task+<>c__DisplayClass1_0.<Queue>b__0(System.Object state)

The normal update thread ( this will be expected codepath I presume ). This originates from Dissonance:

[Dissonance:Network] (16:31:13.262) ServerRelay`1: ServerRelay.ProcessPacketRelay(): Switch thread id [ 4 ] to [ 1 ]
Stack Trace:
   at Dissonance.Networking.Server.ServerRelay`1[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].ProcessPacketRelay(PacketReader ByRef reader, Boolean reliable)
   at Dissonance.Networking.BaseServer`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].NetworkReceivedPacket(ForgeRemasteredPeer source, ArraySegment`1 data)
   at Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredCommsNetwork.PreprocessPacketToServer(ArraySegment`1 packet)
   at Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient.Send(ArraySegment`1 packet, Int32 channel, Boolean reliable)
   at Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient.SendUnreliable(ArraySegment`1 packet)
   at Dissonance.Networking.BaseClient`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].Dissonance.Networking.Client.IClient<TPeer>.SendUnreliable(ArraySegment`1 packet)
   at Dissonance.Networking.BaseClient`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].SendUnreliableP2P(System.Collections.Generic.List`1 destinations, ArraySegment`1 packet)
   at Dissonance.Networking.BaseClient`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].Dissonance.Networking.Client.IClient<TPeer>.SendUnreliableP2P(System.Collections.Generic.List`1 destinations, ArraySegment`1 packet)
   at Dissonance.Networking.Client.SendQueue`1[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].Update()
   at Dissonance.Networking.BaseClient`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].RunUpdate(DateTime utcNow)
   at Dissonance.Networking.BaseClient`3[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].Update()
   at Dissonance.Networking.BaseCommsNetwork`5+Session[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Unit, Assembly-CSharp-firstpass, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Unit, Assembly-CSharp-firstpass, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].Update()
   at Dissonance.Networking.BaseCommsNetwork`5[[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredServer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredClient, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredPeer, Assembly-CSharp, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Unit, Assembly-CSharp-firstpass, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null],[Dissonance.Unit, Assembly-CSharp-firstpass, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]].Update()
   at Dissonance.Integrations.ForgeNetworkingRemastered.ForgeRemasteredCommsNetwork.Update()
maasaimosh commented 5 years ago

I guess one important thing to mention is that in my configuration, I am running both the Server and a Client.

This is because I don't want to have a separate dissonance server process to maintain.

Is that a configuration you have planned ?

martindevans commented 5 years ago

The 'Editor' thread... originates straight out of ForgeRemastered threading

Aha, that certainly makes more sense that the editor itself calling things. It's possible the Dissonnce Forge Remastered integration doesn't properly handle any multithreading that's built into FNR itself - it looks like FNR is delivering packets (in OnMessageReceived) on a background thread so perhaps we're not properly handling that (i.e. marshalling the event back onto the main thread before passing it to Dissonance).

in my configuration, I am running both the Server and a Client.

This configuration is built into Dissonance, we call it Host mode where one single peer runs as both a Dissonance client and server. Have you made a modification to Dissonance ro run both, or are you just using the built in Host mode?

martindevans commented 5 years ago

I asked on the FNR Discord support channel and apparently rhe various events raised by FNR (e.g. playerDisconnected and binaryMessageReceived) will not be invoked on the main thread. I'm pretty sure that the Dissonance FNR integration does not handle this properly, I'll fix it first thing tomorrow!

martindevans commented 5 years ago

I've fixed this and submitted an update to the asset store, that will probably take around a week to be approved and released. If anyone using FNR has this issue in the meantime please email me (martin@placeholder-software.co.uk) your invoice number and I can send you the updated package :)

martindevans commented 5 years ago

This fix is now available on the asset store as v6.4.2 (they rushed it through for us since it was a critical bug).