Voice playback seems to be disconnected when scene change

adhicl commented 6 years ago

Hi and sorry if this is a repeat,

I tried to spawn the broadcast trigger prefab after I change scene and it seems like it makes it disconnect the voice chat. If I spawn on the first scene then there is no problem. I am using Unity Unet HLAPI

Expected Behavior

Should actually also connected even if spawn in the next scene

Actual Behavior

Voice chat does not comes out when spawn in the next scene

Steps to Reproduce

Follow tutorial, but turn off auto create player in network manager
When unet client is connected call change scene
in the the next scene. At the start function, call SceneClient.addPlayer(0)
Voice playback would not come out

Your Environment

Dissonance version 3.0.2 Unity 2017.1.0p4 Windows 10 Pro Build Settings Windows

martindevans commented 6 years ago

Hi adhicl

Just to check I've understood the problem:

You're in a scene with a DissonanceComms component somewhere
You change to another scene when the network connects
You spawn a player - now you hear no voice

If so, are you sure that you have a DissonanceComms component in the second scene? If that component is destroyed on scene change you will have no voice comms.

adhicl commented 6 years ago

Hi, yes that is how. and I make sure to add a script with don't destroy on load so that the dissonancecomms setup prefab stay on the second scene.

Okay additional info, when I trying things in my scene inside the editor during running the game, interestingly if I clicked on the prefab with broadcast trigger, then I get a message in the log: began mic capture for the second time. and only after that I can hear my voice: before: bug-0 after: bug

So maybe, when the scene changes, the mic recording is turned off?

martindevans commented 6 years ago

It could be related to the scene changing, I'll have to investigate that a little more.

Is it possible this is related to the error you have in the console about the HMD not being found - if the HMD isn't connected then it might not be possible to properly initialise it's microphone. Do you have a second microphone connected to your PC? If so try setting Dissonance to use that one all the time and see if voice works.

adhicl commented 6 years ago

I don't think it is because of the device, since when I spawn it without changing scene, there is no problem with voice chat.

martindevans commented 6 years ago

Hi adhicl, I just wanted to give you an update on this. I've been unwell this week so the 3.0.3 release was delayed a couple of days - I've only just pushed it out to the store when the initial plan was for Tuesday! Since that's out of the way I'm hoping to properly start investigating this issue tomorrow :)

martindevans commented 6 years ago

I've just tried to reproduce this using the Dissonance HLAPI demo scene, unfortunately I can't reproduce it. Here was my test setup:

Attach DissonanceComms and HLAPI Comms Network components to the NetworkManager object in the HLAPI Demo scene. This means Dissonance is created before the network is active, and is long lived.
Removed DissonanceSetup object from HLAPI Game World scene.
Start a session (host in editor)
Join session (standalone client)

I can hear my voice right away.

Could you give me the stacktrace of the the two events you have highlighted when you click on the prefab (Disposed pipeline and Began mic capture). I'm not sure how simply selecting an item in the hierarchy can trigger an event!

adhicl commented 6 years ago

Hi, I tried it a few more times. And it seems that sometimes it could run to capture the voice, only I need to wait around more than 5 minutes? Other time it just won't.

These are the stack trace in the log for the two events:

[Dissonance:Recording] BasePreprocessingPipeline: Disposed pipeline UnityEngine.Debug:Log(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:100) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:Info(String) (at Assets/Plugins/Dissonance/Core/Log.cs:316) Dissonance.Audio.Capture.BasePreprocessingPipeline:Dispose() (at Assets/Plugins/Dissonance/Core/Audio/Capture/BasePreprocessingPipeline.cs:115) Dissonance.Audio.Capture.WebRtcPreprocessingPipeline:Dispose() (at Assets/Plugins/Dissonance/Core/Audio/Capture/WebRtcPreprocessingPipeline.cs:50) Dissonance.Audio.Capture.MicrophoneCapture:Dispose() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:306) Dissonance.Audio.Capture.CapturePipelineManager:StopTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:115) Dissonance.Audio.Capture.CapturePipelineManager:RestartTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:129) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:86) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

[Dissonance:Recording] MicrophoneCapture: Began mic capture (SampleRate:48000 FrameSize:960, Buffer Limit:2^13) UnityEngine.Debug:Log(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:100) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:WriteLogFormat(LogLevel, String, Object[]) (at Assets/Plugins/Dissonance/Core/Log.cs:221) Dissonance.Log:Info(String, Object[]) (at Assets/Plugins/Dissonance/Core/Log.cs:322) Dissonance.Audio.Capture.MicrophoneCapture:.ctor(String, AudioClip) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:70) Dissonance.Audio.Capture.MicrophoneCapture:Start(String) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:106) Dissonance.Audio.Capture.CapturePipelineManager:RestartTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:136) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:86) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

martindevans commented 6 years ago

I've chased down these stacktraces a bit and it's a reset in the CapturePipelineManager:Update method. The code for this is here (CapturePipelineManager Line 85):

if (MicCapture != null && MicCapture.Update() || DetectFrameSkip(deltaTime))
    RestartTransmissionPipeline();

We know it's not a frame skip because that would print a warning, so MicCapture.Update() must be returning true. That returns true if the mic itself requires a reset, the only time it does that is determiend by this code (MicrophoneCapture.cs Line 162):

//Cause a mic reset if:
// - The sample count is zero that's an error
// - The device is changed we really have no idea what state we're in any more
if (_clip.samples == 0 || _audioDeviceChanged)
     return true;

So this is either:

An error case. The microphone buffer has zero samples which probably indicates some kind of microphone problem (mic isn't plugged in etc)
An unusual case. An audio device reset occurs in a number of edge cases such as changing audio output hardware, plugging in a new microphone, changing output sample rate etc.

Could you replace that bit of code in MicrophoneCapture.cs with this:

if (_clip.samples == 0)
{
     Log.Warn("Debugging Case 1 - Microphone clip has zero samples!");
     return true;
}

if (_audioDeviceChanged)
{
     Log.Warn("Debugging Case 2 - Audio device was changed");
     return true;
}

With that I'll be able to determine which of those two case it is.

adhicl commented 6 years ago

Hi, I do what you requested and I found out something I do on my bad. I am sorry, I forgot I actually turn off all warning message and collapse on before. So this is the stack I found out after I turn on warning.

The above log does not show up unfortunately. But I got these warnings

[Dissonance:Recording] MicrophoneCapture: Insufficient buffer space, requested 53082, clamped to 16383 (dropping samples) UnityEngine.Debug:LogWarning(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:103) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:Warn(String) (at Assets/Plugins/Dissonance/Core/Log.cs:342) Dissonance.Audio.Capture.MicrophoneCapture:DrainMicSamples() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:217) Dissonance.Audio.Capture.MicrophoneCapture:Update() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:181) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:85) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

[Dissonance:Recording] BasePreprocessingPipeline: Failed to write microphone samples into input queue UnityEngine.Debug:LogWarning(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:103) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:Warn(String) (at Assets/Plugins/Dissonance/Core/Log.cs:342) Dissonance.Audio.Capture.BasePreprocessingPipeline:Send(Single[]) (at Assets/Plugins/Dissonance/Core/Audio/Capture/BasePreprocessingPipeline.cs:147) Dissonance.Audio.Capture.MicrophoneCapture:SendFrame() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:307) Dissonance.Audio.Capture.MicrophoneCapture:ConsumeSamples(ArraySegment`1) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:267) Dissonance.Audio.Capture.MicrophoneCapture:DrainMicSamples() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:245) Dissonance.Audio.Capture.MicrophoneCapture:Update() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:181) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:85) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

Which happen from the host side log and happen repetitively till the mic runs with the following messages (these part is same as client)

--when started recording

[Dissonance:Recording] CapturePipelineManager: Detected a frame skip of 149.2747ms, forcing reset of Microphone capture pipeline UnityEngine.Debug:LogWarning(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:103) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:WriteLogFormat(LogLevel, String, Single) (at Assets/Plugins/Dissonance/Core/Log.cs:230) Dissonance.Log:Warn(String, Single) (at Assets/Plugins/Dissonance/Core/Log.cs:354) Dissonance.Audio.Capture.CapturePipelineManager:DetectFrameSkip(Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:102) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:85) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

[Dissonance:Recording] BasePreprocessingPipeline: Disposed pipeline UnityEngine.Debug:Log(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:100) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:Info(String) (at Assets/Plugins/Dissonance/Core/Log.cs:316) Dissonance.Audio.Capture.BasePreprocessingPipeline:Dispose() (at Assets/Plugins/Dissonance/Core/Audio/Capture/BasePreprocessingPipeline.cs:115) Dissonance.Audio.Capture.WebRtcPreprocessingPipeline:Dispose() (at Assets/Plugins/Dissonance/Core/Audio/Capture/WebRtcPreprocessingPipeline.cs:50) Dissonance.Audio.Capture.MicrophoneCapture:Dispose() (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:319) Dissonance.Audio.Capture.CapturePipelineManager:StopTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:115) Dissonance.Audio.Capture.CapturePipelineManager:RestartTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:129) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:86) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

[Dissonance:Recording] WebRtcPreprocessingPipeline: Associated preprocessor with playback filter - but filter is not running UnityEngine.Debug:LogWarning(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:103) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:Warn(String) (at Assets/Plugins/Dissonance/Core/Log.cs:342) Dissonance.Audio.Capture.WebRtcPreprocessor:SetFilterPreprocessor(IntPtr) (at Assets/Plugins/Dissonance/Core/Audio/Capture/WebRtcPreprocessingPipeline.cs:248) Dissonance.Audio.Capture.WebRtcPreprocessor:.ctor() (at Assets/Plugins/Dissonance/Core/Audio/Capture/WebRtcPreprocessingPipeline.cs:190) Dissonance.Audio.Capture.WebRtcPreprocessingPipeline:.ctor(WaveFormat) (at Assets/Plugins/Dissonance/Core/Audio/Capture/WebRtcPreprocessingPipeline.cs:38) Dissonance.Audio.Capture.MicrophoneCapture:.ctor(String, AudioClip) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:63) Dissonance.Audio.Capture.MicrophoneCapture:Start(String) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:106) Dissonance.Audio.Capture.CapturePipelineManager:RestartTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:136) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:86) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

[Dissonance:Recording] MicrophoneCapture: Began mic capture (SampleRate:48000 FrameSize:960, Buffer Limit:2^13) UnityEngine.Debug:Log(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:100) Dissonance.Logs:SendLogMessage(String, LogLevel) (at Assets/Plugins/Dissonance/Core/Log.cs:135) Dissonance.Log:WriteLog(LogLevel, String) (at Assets/Plugins/Dissonance/Core/Log.cs:207) Dissonance.Log:WriteLogFormat(LogLevel, String, Object[]) (at Assets/Plugins/Dissonance/Core/Log.cs:221) Dissonance.Log:Info(String, Object[]) (at Assets/Plugins/Dissonance/Core/Log.cs:322) Dissonance.Audio.Capture.MicrophoneCapture:.ctor(String, AudioClip) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:70) Dissonance.Audio.Capture.MicrophoneCapture:Start(String) (at Assets/Plugins/Dissonance/Core/Audio/Capture/MicrophoneCapture.cs:106) Dissonance.Audio.Capture.CapturePipelineManager:RestartTransmissionPipeline() (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:136) Dissonance.Audio.Capture.CapturePipelineManager:Update(Boolean, Single) (at Assets/Plugins/Dissonance/Core/Audio/Capture/CapturePipelineManager.cs:86) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:439)

[Dissonance:Recording] WebRtcPreprocessingPipeline: Associated preprocessor with playback filter - but filter is not running UnityEngine.Debug:LogWarning(Object) Dissonance.LogMessage:Log() (at Assets/Plugins/Dissonance/Core/Log.cs:103) Dissonance.Logs:WriteMultithreadedLogs() (at Assets/Plugins/Dissonance/Core/Log.cs:124) Dissonance.DissonanceComms:Update() (at Assets/Plugins/Dissonance/DissonanceComms.cs:435) :

martindevans commented 6 years ago

Aha! There was a known issue #58 with the frame skip detector in 3.0.2. Can I get you to upgrade to 3.0.3 (just released a few days ago) to see if that fixes the issue?

adhicl commented 6 years ago

Hi, I try update to 3.0.3 but it still same. But I try to make a simple workaround. I call RestartTransmissionPipeline function in CapturePipeline from DissonanceComms _capture after I change scene and the avatar spawned. So far it works for me. But I hope there is not any bad implication from this?

martindevans commented 6 years ago

Calling RestartTransmissionPipeline is totally fine - it will cause a brief hitch in audio capture but that's all. Ultimately the bug in Dissonance is really that it's not calling it itself at the appropriate time.

Now that you're on 3.0.3 could you give me another log sample. Most importantly I want to see when Dissonance first starts up the microphone (when the [Dissonance:Recording] MicrophoneCapture: Began mic capture is shown) and then what happens after that.

adhicl commented 6 years ago

Hi, ok, good then. And these are the logs: from the hosting side and client side.

trace log.zip

martindevans commented 6 years ago

Hi adhicl,

I've had a read through those logs, unfortunately it all looks ok. The microphone starts up when the client connects, and doesn't seem to be suffering from any errors.

A few thoughts:

Are the client and server logs captured from different runs? The server says hosting session 86130370 but the client joins session 1008798525. There have been some other bugs to do with session numbers being incorrect, so I just wanted to check.
You've added in the ForceResumeCapture method to restart the capture system (which is a good idea). You may be able to achieve the same by having the DissonanceSetup prefab in the scene (but disabled), and then simply enabling the gameObject when you would normally call ForceResumeCapture() - if that works then you don't need to make any changes to the Dissonance source.
There's one possible error case in microphone capture which isn't logged, could you try changing the code in MicrophoneCapture:Update to:

if (!_started)
{
    _readHead = Microphone.GetPosition(_micName);
    _started = _readHead > 0;

    // vvv The line below is new! vvv
    if (_started) Log.Error("Microphone capture has begun receiving samples");

    if (!_started)
        return false;
}

Once you've put this is don't call your force restart and see if the message ever gets logged. If it does not then this confirms my suspicion that the microphone hardware is not initialising properly.

adhicl commented 6 years ago

Hi,

Yes it is different run, since I capture the log from the editor, so I do it twice.
I do what you proposed (enable and disable) it works :). I actually tried dissonance setup on the other scene before but got and error, disabling it actually is how it supposed to be :)
I add the log and it shows up. Here are the logs before I move use number 2 above. trace log.zip

martindevans commented 6 years ago

I've had a look through your log and there's something incredibly wrong here! These two things happen as soon as the mic starts:

[Dissonance:Recording] MicrophoneCapture: Microphone capture has begun receiving samples
[Dissonance:Recording] MicrophoneCapture: Insufficient buffer space, requested 301920, clamped to 16383 (dropping samples)

That second message indicates that 301,920 samples are provided within a single frame - that's 6.29 seconds of data! Technically the mic system is meant to gracefully handle errors like this, but this way too big (150x more data than is meant to arrive in a single frame). Notably the next time you restart the microphone this does not happen, so I guess that first time was when it didn't work, and then the second time was your restart which fixes the problem?

I think this has got to be related to your HMD hardware somehow - for some reason the mic isn't initializing the first time properly and that's breaking Dissonance until you restart the mic and the second time it's already initialised so it's ok. Have you tried this with any other HMDs and encountered the same problem?

martindevans commented 6 years ago

Dissonance 4.0.0 just went live on the asset store. I never managed to completely track down this issue but since it's been dead for a while I'll close it now. Please feel free to comment here if the issue persists :)

adhicl commented 6 years ago

Hi, yeah it is okay to close it down. your disable/ enable solution is actually fit more with my case

Placeholder-Software / Dissonance