Audio inconsistent / packet loss after player switches from one server to another.

[WuchiOnline]

My company uses Dissonance for our Unity app.

We’ve recently implemented a feature where players can jump from server to server.

The first time a player joins/hosts a server, Dissonance works great.

However, whenever a player joins/hosts a second server, we get audio loss. It randomly cuts out, and majority of the time the users can’t hear each other.

I have inspected the player logs and did not receive a packet discarded Debug.Log error message.

Can you please help me out and let me know what might be causes this?

[martindevans]

It sounds like there may be an issue with disconnection from the network not properly clearing all state, so when you switch some left-over state is disrupting the new session. Which network integration/Dissonance version/Unity version are you using?

[WuchiOnline]

Yeah, that seems likely. Is there a proper way to clear all states from a previous Dissonance server handshake so that it doesn't disrupt a new session?

Network Integration: Mirror Dissonance Version: This was at the top of the changelog, so I'm guessing it's: v8.0.0 (2021-04-22) Unity Version: 2019.4.25f1

[martindevans]

In Assets/Dissonance/Integrations/MirrorIgnorance/MirrorIgnoranceCommsNetwork.cs there is a check in the Update method which looks at the Mirror network and makes sure Dissonance is running in the same way. This should notice when the Mirror network session ends and then tells Dissonance to tear down it's own network session (see the call to Stop on line 64). If you're transitioning from one session to another instantly Dissonance may never be getting that call.

Could you drop a Debug.Log into line 65 to check if it happens when you leave a session.

[WuchiOnline]

Thanks, I'll give that a go and report back.

[WuchiOnline]

This is what happens when you successfully quit your local server and connect to another person's server as a client. I have included the log messages up until everything seems to stabilize.

MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has called Stop() and _loopbackQueue.Clear() because else if (Mode != NetworkMode.None) MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); MirrorIgnoranceClient: Disconnected MirrorIgnoranceServer: Disconnected MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); Client successfully connected to server: 172.26.23.39:30029 MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true, AND if(Mode.IsServerEnabled() != server || Mode.IsClientEnabled() != client) is true. MirrorIgnoranceCommsNetwork.Update() has called RunAsDedicatedServer() because if (client) MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); ConnectionNegotiator`1: Received handshake response from server, joined session '177117112' CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:1.034005) BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:2.061559) BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:2.008082) BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); EventQueue: Large number of received packets pending dispatch (39). Possibly due to long frame times (last frame was 2026.2403ms) MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

Note that this seems to be the "stable" Update loop series of messages when the connection stabilizes:

MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

Please keep in mind, this is what a successful handshake looks like, not what a buggy connection looks like, which I will post after this. However, I do see some fishy stuff even in the successful handshake, which I have bolded. Namely that Began Mic Capture was called 4 separate times, should it only have been one? Perhaps packets are being duplicated because of multiple mic captures, which results in a loss? New to all of this, so sorry if that doesn't make logical sense.

[WuchiOnline]

After investigating a faulty client to server handshake from the server's perspective, I noticed that there is actually a lack of handshake + began mic capture logs. This is pretty uneventful, but posting it here anyway for thoroughness. After this, I will show what a faulty connection looks like from the client's perspective:

NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 1 NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() is calling Client.NetworkReceivedPacket(_loopBackQueue[0] NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() is calling _loopbackBuffers.Put(_loopbackQueue[0].Array); NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 NETWORKINGUI: 9/23/2021 9:04:45 AM : MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

The "stable" Update loop series of messages continues from there, even though the client cannot hear the server's voice, and the server's voice cannot hear the client's voice consistently, or at all.

[WuchiOnline]

Here is the buggy flow from the client's perspective of joining a server where no one can really hear each other:

Starting from when the client is disconnecting from it's local server:

Ignorance Server Instance shutting down... Telling server thread to stop, this may take a while depending on network load

Then client connects to server:

IgnoranceClient.Start() Server Worker Thread: Finishing up. Server Worker Thread: Shutdown. Client has dispatched worker thread. Client Worker Thread: Startup Client Worker Thread: Initialized ENet. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has called Stop() and _loopbackQueue.Clear() because else if (Mode != NetworkMode.None) MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); MirrorIgnoranceClient: Disconnected MirrorIgnoranceServer: Disconnected MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

This loop continues on indefinitely.

Things I noticed when comparing to a successful client to server handshake connection (the first series of logs I posted):

"MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true." is notably absent. We can infer that networkActive isn't true in the buggy case.

Other notable absences in the buggy client flow, that were present in the successful client flow:

Client successfully connected to server: 172.26.23.39:30029 MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true, AND if(Mode.IsServerEnabled() != server || Mode.IsClientEnabled() != client) is true. BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') ConnectionNegotiator`1: Received handshake response from server, joined session '177117112'CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:1.034005)BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'') EventQueue: Large number of received packets pending dispatch (39). Possibly due to long frame times (last frame was 2026.2403ms)

What I'm seeing here is that no connection negotiator handshake was accomplished in the buggy flow, and no basic microphone captures. But the thing is, we can barely hear each other, maybe 5% of the time, so there must be some existing handshake from a previous connection before we swapped roles from client to server, and server to client.

[WuchiOnline]

Do you have any ideas given these logs? I can't determine why it is we aren't successfully making a connection handshake / microphone capture.

To be clear, what causes the buggy flow is when a user joins a server as a client, leaves that server, and then hosts their own server. That's when any incoming clients cannot reliably hear the host, and the host cannot reliably hear the clients.

At first it seems like a packet loss issue, now I'm suspecting there was no handshake at all... but how it is possible that we can occasionally hear flickers of each other's voice?

If I were to guess, the absence of this message log in the buggy flow is crucial:

"MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true."

That must mean that if (networkActive) is false. What would cause networkActive not to be set to true properly?

[martindevans]

CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:1.034005) BasicMicrophoneCapture: Began mic capture (SampleRate:48000Hz, FrameSize:960, Buffer Limit:2^13, Latency:20ms, Device:'')

You're seeing multiple restarts of the microphone systems because of the first message. That means that a single frame took a very long time, in this case 1.03 seconds! This is obviously far too long for realtime audio to work, so Dissonance decided to restart the recording system to flush out the buffers (which can't hold an entire second of audio). If you're only seeing this during level loading it's not too bad - it's fairly common for that to stall frame times quite badly.

Once the rest of this is resolved you could improve loading by having the Dissonance components disabled for the duration of the loading and then enabling them a second or two after loading has completed.

how it is possible that we can occasionally hear flickers of each other's voice?

I'm not certain about this, from these logs it looks like the Dissonance network system should be totally shut down at this point. My best guess is that packets are somehow being sent to the dead client/server objects, but I can't see any way that can happen without other warnings showing up.

Here is the buggy flow from the client's perspective...

I think you're correct about the missing logs - the network seems to be shutting down as expected (the call to Stop, the logs from showing the client/server Disconnected). However, if networkActive is false that means that Dissonance thinks Mirror is not in a session and so therefore it does not start itself up.

Could you add this in just below networkActive to debug why that's not true:

if (!networkActive)
{
    Debug.Log($"Singleton: {NetworkManager.singleton != null}");
    Debug.Log($"isNetworkActive: NetworkManager.singleton?.isNetworkActive");
    Debug.Log($"NetworkServer.active: {NetworkServer.active}");
    Debug.Log($"NetworkClient.active: {NetworkClient.active}");
    Debug.Log($"NetworkClient.connection: {NetworkClient.connection != null}");
    Debug.Log($"NetworkClient.connection.isReady: {NetworkClient.connection?.isReady}");
}```

[WuchiOnline]

From the client's perspective, when connecting into a buggy server:

// User presses button on UI to connect to server Shutting down client. Telling client thread to stop, this may take a while depending on network load Ignorance Server Instance shutting down... Telling server thread to stop, this may take a while depending on network load Server Worker Thread: Finishing up. Server Worker Thread: Shutdown. IgnoranceClient.Start() Client has dispatched worker thread. Client Worker Thread: Startup NetworkDiscovery StartAsClient already started Client Worker Thread: Initialized ENet. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update has detected that IsInitalized is true, but networkActive is false. Singleton: True isNetworkActive: NetworkManager.singleton?.isNetworkActive // I think maybe we should've changed this to: $"isNetworkActive: {NetworkManager.singleton?.isNetworkActive}"); Hopefully this is not a deal breaker NetworkServer.active: False NetworkClient.active: True NetworkClient.connection: True NetworkClient.connection.isReady: False MirrorIgnoranceCommsNetwork.Update() has called Stop() and _loopbackQueue.Clear() because else if (Mode != NetworkMode.None) MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear(); MirrorIgnoranceClient: Disconnected MirrorIgnoranceServer: Disconnected

Then this loop continues on:

MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update has detected that IsInitalized is true, but networkActive is false. Singleton: True isNetworkActive: NetworkManager.singleton?.isNetworkActive NetworkServer.active: False NetworkClient.active: True NetworkClient.connection: True NetworkClient.connection.isReady: False MirrorIgnoranceCommsNetwork.Update() has called Stop() and _loopbackQueue.Clear() because else if (Mode != NetworkMode.None) MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

[WuchiOnline]

From buggy server's perspective, when client joins the buggy server:

MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 1 MirrorIgnoranceCommsNetwork.Update() is calling Client.NetworkReceivedPacket(_loopBackQueue[0] MirrorIgnoranceCommsNetwork.Update() is calling _loopbackBuffers.Put(_loopbackQueue[0].Array); MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

Then this loop repeats: MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) is true. MirrorIgnoranceCommsNetwork.Update() has been called AND if(IsInitialized) AND if(networkActive) is true. MirrorIgnoranceCommsNetwork.Update() is looping through _loopbackQueue.Count, which is: 0 MirrorIgnoranceCommsNetwork.Update() is calling _loopbackQueue.Clear();

[WuchiOnline]

Thanks for your suggestion yesterday! As you see from my previous two comments, I implemented your debug logs, as requested. Maybe a little too literally, since I copy and pasted and did not think to reformat this one Debug.Log($"isNetworkActive: NetworkManager.singleton?.isNetworkActive"); . My apologies for not catching that. If you think that is necessary, I can retest.

Something that is super important to mention: my teammate and I were able to hear each other again very briefly/inconsistently on the buggy server, even though no handshake was established. This is really strange as you mentioned before, because theoretically we should not be able to hear each other at all.

For additional context, the client was able to hear me maybe 15 seconds after joining. And only for like 5 seconds... and then it cut out again. The same thing happened when we swapped roles. The server was able to hear the client for only 5-10 seconds after joining, and even then it would cut out intermittently.

I also think this may be highly relevant to the source issue:

NetworkServer.active: False NetworkClient.active: True NetworkClient.connection: True NetworkClient.connection.isReady: False

The first three seem correct... but the 4th one seems like it should be true?

Hopefully that helps. Please let me know if you can think of anything, or need anything else from me. This has been a real headscratcher for me and my team, and I would love to get this resolved.

[martindevans]

Sorry about that typo in the debug code, fortunately I don't think it's a deal breaker 😌

---

NetworkServer.active: False
NetworkClient.active: True
NetworkClient.connection: True
NetworkClient.connection.isReady: False

In a case like this Dissonance can see that Mirror is running in client mode, but since the connection isn't ready it's waiting for the connection to be ready before properly starting the Dissonance client. This prevents sending any packets before the connection is fully established.

isReady:false is something that usually only lasts for a few frames. If this is persisting forever I think that is the real root cause (some kind of underlying issue with how Mirror or Ignorance is handling the connection teardown or setup). You should definitely contact the Mirror devs about this (I'm in their Discord server, so feel free to tag Martin#2468 if you need my input).

---

You might be able to work around this by simply removing the isReady check in Dissonance (maybe add a short delay instead). However, this is technically not allowed by the Mirror API contract (if the connection isn't ready, it's not correct to try sending through it) so I don't recommend it!

I suspect that transitioning from one session into another instantly is confusing things in Mirror. So a better workaround may be to end one session, wait for it to end (e.g. run a coroutine until isNetworkActive == false), wait 10 more frames, and then start the next session. This gives Mirror time to do whatever it needs to do.

[WuchiOnline]

Thank you so much Martin. This all makes sense and seems plausible. I will give it a go fixing it myself, and if not I will ping the Mirror devs with my findings. I appreciate your help on this. Enjoy the rest of your week.

[WuchiOnline]

A progress update: I was able to implement your suggestion for a while (!isNetworkActive), yield frame.

Good and bad news: the guest in the "buggy" server could hear the host completely, but the host could not hear the guest at all (except for a few spurts here and there, which again is super confusing to both of us since that theoretically shouldn't be possible since a handshake was never established).

Is there a way to manually force a Dissonance handshake between a server and a client?

[martindevans]

You can call Stop() on the MirrorIgnoranceCommsNetwork component. This will force Dissonance into the "stopped" state, next frame Dissonance will see that the network is running and re-initialise itself. (Alternatively you can disable and re-enable it, if you want the stop to last longer).

Have you contacted anyone at Mirror about this issue?

[WuchiOnline]

Thanks Martin, I have not contacted Mirror yet. It's been a great learning process for me to try fixing myself, but I will reach out to them if none of my other ideas don't end up working out.

Thanks for the tip regarding Stop(), I'm going to give that a go if a handshake is never established.

[martindevans]

Since it's been a while I'll close this issue, but don't hesitate to re-open it if you still need help :)