Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SoundSwitch not refreshing devices on unplug replug #1323

Closed
BigAal opened this issue Dec 12, 2023 · 29 comments
Closed

SoundSwitch not refreshing devices on unplug replug #1323

BigAal opened this issue Dec 12, 2023 · 29 comments
Labels
Bug Issues which are bug reports released

Comments

@BigAal
Copy link

BigAal commented Dec 12, 2023

What happened?

Hello, I am using a USB hub to switch USB sound card between my personal and work laptops. whenever I switch to the personal laptop, there are no issues, but when I switch to my work laptop the device is not refreshed in SoundSwitch but refreshes normally in Windows. I have to restart SoundSwitch every time to get the device listed and be able to use my Hotkey.

I am not admin user on work laptop but admin on personal, not sure if relevant. In both cases I installed SoundSwitch for current user only. For some reason I am not getting [WINAPI] logs on my work laptop, is there a way to enable it, or is it because I am not admin? Thanks.

Step to reproduce

Using the USB Hub switch to switch soundcard between 2 computers.

Version

6.7.2.0

What version of Windows are you seeing the problem on?

Windows 10

Relevant log output

[14:25:29.079 INF]]{ State: Active, Unplugged } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[14:25:29.079 INF]]{ State: Active } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[14:25:37.148 ERR]]{ State: Active, Unplugged } Can't refresh the devices after 00:00:05(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[14:25:37.148 ERR]]{ State: Active } Can't refresh the devices after 00:00:05(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[14:25:39.086 WRN]]{ State: Active } Cancellation received.(at System.Threading.ExecutionContext.RunInternal)
[14:25:39.086 WRN]]{ State: Active, Unplugged } Cancellation received.(at System.Threading.ExecutionContext.RunInternal)
[14:25:43.084 WRN]]{ State: Active } Refresh of device interrupted(at SoundSwitch.Framework.Audio.Lister.Job.DebounceRefreshJob.OnFailure)
[14:25:43.555 WRN]]{ State: Active, Unplugged } Refresh of device interrupted(at SoundSwitch.Framework.Audio.Lister.Job.DebounceRefreshJob.OnFailure)
@BigAal BigAal added the Bug Issues which are bug reports label Dec 12, 2023
@Belphemur
Copy link
Owner

Can you try with the nightly version of SoundSwitch ? (you'll have to stop SoundSwitch and replace all its files by the one of the zip then restart it).

https://soundswitch.aaflalo.me/nightly

@BigAal
Copy link
Author

BigAal commented Dec 13, 2023

did not work, and now it happened on personal laptop. It looks like once it cannot find a device, it refuses to find it again. So the USB PnP is a small usb soundcard with Speakers and Mic. when I unplug and re-plug the usb, from the logs a refresh is happening, but only the speakers re-appears, the mic is not re-appearing unless I restart SoundSwitch and keeping it plugged.

01:10:58.857 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[01:10:59.055 INF]]{ State: Active, Unplugged } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[01:11:00.156 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[01:11:00.351 WRN]]{ State: Active, Unplugged } Can't refresh, already refreshing since 12/13/2023 06:10:59(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[01:11:04.055 WRN]]{ State: Active, Unplugged } Cancellation received.(at System.Threading.ExecutionContext.RunInternal)
[01:11:04.246 INF]]{ State: Active, Unplugged } Refreshed all devices in 00:00:05.1906258. 10/rec, 18/play(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[01:11:06.498 VRB]]{  } Foreground changed: ["C:\WINDOWS\Explorer.EXE"] "Logs" - "CabinetWClass"(at SoundSwitch.Framework.Profile.ProfileManager.<RegisterEvents>b__21_0)
[01:11:06.915 VRB]]{  } Foreground changed: ["C:\Program Files (x86)\Notepad++\notepad++.exe"] "C:\Users\A\AppData\Roaming\SoundSwitch\Logs\soundswitch20231213.log - Notepad++" - "Notepad++"(at SoundSwitch.Framework.Profile.ProfileManager.<RegisterEvents>b__21_0)
[01:11:06.918 VRB]]{  } Foreground changed: ["C:\Program Files (x86)\Notepad++\notepad++.exe"] "Reload" - "#32770"(at SoundSwitch.Framework.Profile.ProfileManager.<RegisterEvents>b__21_0)
[01:11:08.131 VRB]]{  } Foreground changed: ["C:\Program Files (x86)\Notepad++\notepad++.exe"] "C:\Users\A\AppData\Roaming\SoundSwitch\Logs\soundswitch20231213.log - Notepad++" - "Notepad++"(at SoundSwitch.Framework.Profile.ProfileManager.<RegisterEvents>b__21_0)
[01:11:35.993 DBG]]{  } Not the registered Hotkeys "Control + Shift + Oem1"(at SoundSwitch.Model.AppModel.HandleHotkeyPress)
[01:11:36.497 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Multimedia(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[01:11:36.589 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Console(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[01:11:36.697 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[01:11:36.816 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[01:11:36.818 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Icon replaced(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[01:11:37.031 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[01:11:37.033 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Icon replaced(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[01:11:37.125 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[01:11:37.193 DBG]]{  } Not the registered Hotkeys "Control + Shift + Oem7"(at SoundSwitch.Model.AppModel.HandleHotkeyPress)

@BigAal
Copy link
Author

BigAal commented Dec 13, 2023

I tried it again after restarting, and again the mic is not registering in the list.

I think what is happening is that while it is refreshing because of device change, and since the sound card has 2 devices (speaker and mic), the second device change refresh is not triggering, and the mic goes unregistered. Does that make sense?

EDIT: Confirmed my theory by forcing another refresh by disabling enabling any other audio device. Mic got picked up. So looks like a concurrent refresh issue.

@Belphemur Belphemur reopened this Dec 13, 2023
@Belphemur
Copy link
Owner

I've released a new nightly, can you try it and tell me if it's better this time ?

And yes, I think the iteration of devices get locked out when the new device get connected, so I've implemeted a better way to interrupt old refresh and let the new refresh take over.

@BigAal
Copy link
Author

BigAal commented Dec 13, 2023

Still not working:

[14:41:51.782 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[14:41:51.959 INF]]{ State: Active, Unplugged } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[14:41:52.398 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[14:41:52.588 WRN]]{ State: Active, Unplugged } Can't refresh, already refreshing since 12/13/2023 19:41:51(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[14:41:52.614 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[14:41:52.765 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic USB PnP (USB PnP Sound Device)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[14:41:53.026 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[14:41:53.157 INF]]{ Device: "[Capture]Mic USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[14:41:54.755 INF]]{ State: Active, Unplugged } Refreshed all devices in 00:00:02.7961924. 10/rec, 18/play(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)

Didn't you change the refresh logic in a previous commit and you're not relying on cancelling refresh anymore? In the code it is validating the "Refreshing" boolean and stopping the subsequent refresh. Thanks.

@Belphemur
Copy link
Owner

I was relying on rescheduling the task to cancel the current one, not working as expected.

So I've again rework the cancellation to be sure the old refresh get cancelled, and only the latest refresh can run.

Can you test again with the newest nightly (just got pushed now)

@BigAal
Copy link
Author

BigAal commented Dec 13, 2023

I think it worked, but throwing an exception. Should this be handled?

[17:47:25.716 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[17:47:25.968 INF]]{ State: Active, Unplugged } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[17:47:26.674 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Console(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:26.784 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[17:47:26.870 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Multimedia(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:26.997 WRN]]{ State: Active, Unplugged } Cancellation received.(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister+<>c__DisplayClass18_0.<Refresh>b__0)
[17:47:26.998 WRN]]{ State: Active, Unplugged, ExceptionDetail: [("HResult": -2146233088), ("Message": "Job Failed"), ("Source": null), ("InnerException": [("Type": "System.AggregateException"), ("HResult": -2146233088), ("Message": "One or more errors occurred. (Stop refreshing)"), ("Source": "System.Private.CoreLib"), ("TargetSite": "Void ExecuteCallbackHandlers(Boolean)"), ("InnerException": [("Type": "System.OperationCanceledException"), ("HResult": -2146233029), ("Message": "Stop refreshing"), ("Source": "SoundSwitch"), ("TargetSite": "Void <Refresh>b__0(System.Object)"), ("CancellationToken": "CancellationRequested: true")]), ("InnerExceptions": [[("Type": "System.OperationCanceledException"), ("HResult": -2146233029), ("Message": "Stop refreshing"), ("Source": "SoundSwitch"), ("TargetSite": "Void <Refresh>b__0(System.Object)"), ("CancellationToken": "CancellationRequested: true")]])]), ("Type": "Job.Scheduler.Job.Exception.JobException")] } Can't refresh devices(at SoundSwitch.Framework.Audio.Lister.Job.DebounceRefreshJob.OnFailure)
Job.Scheduler.Job.Exception.JobException: Job Failed
 ---> System.AggregateException: One or more errors occurred. (Stop refreshing)
 ---> System.OperationCanceledException: Stop refreshing
   at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.<>c__DisplayClass18_0.<Refresh>b__0(Object _) in D:\a\SoundSwitch\SoundSwitch\SoundSwitch\Framework\Audio\Lister\CachedAudioDeviceLister.cs:line 112
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
   --- End of inner exception stack trace ---
   at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
   at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh(CancellationToken cancellationToken) in D:\a\SoundSwitch\SoundSwitch\SoundSwitch\Framework\Audio\Lister\CachedAudioDeviceLister.cs:line 97
   at SoundSwitch.Framework.Audio.Lister.Job.DebounceRefreshJob.ExecuteAsync(CancellationToken cancellationToken) in D:\a\SoundSwitch\SoundSwitch\SoundSwitch\Framework\Audio\Lister\Job\DebounceRefreshJob.cs:line 27
   at Job.Scheduler.Job.Runner.JobRunner`1.InnerExecuteJob(IJob job, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
[17:47:26.999 INF]]{  } [WINAPI] Default device changed to "[Render]USB PnP (USB PnP Sound Device)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:27.127 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[17:47:27.129 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Icon replaced(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:27.235 WRN]]{ State: Active, Unplugged } Refresh of device interrupted(at SoundSwitch.Framework.Audio.Lister.Job.DebounceRefreshJob.OnFailure)
[17:47:27.538 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[17:47:27.540 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Icon replaced(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:27.541 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic USB PnP (USB PnP Sound Device)":Console(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:27.700 INF]]{ Device: "[Render]USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[17:47:27.969 INF]]{ Device: "[Capture]Mic USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[17:47:27.970 INF]]{ Device: "[Capture]Mic USB PnP (USB PnP Sound Device)", IconChanger: Playback } No need to change icon(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:28.102 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic USB PnP (USB PnP Sound Device)":Multimedia(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:28.235 INF]]{ Device: "[Capture]Mic USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[17:47:28.235 INF]]{ Device: "[Capture]Mic USB PnP (USB PnP Sound Device)", IconChanger: Playback } No need to change icon(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:28.244 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic USB PnP (USB PnP Sound Device)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[17:47:28.372 INF]]{ Device: "[Capture]Mic USB PnP (USB PnP Sound Device)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)

@BigAal
Copy link
Author

BigAal commented Dec 13, 2023

Also for some reason when I tried the same version on work laptop, it didn't throw an exception but the app crashed. Not sure why the difference between the 2 laptops.

@Belphemur
Copy link
Owner

Shoot so the way to cancel the stuck job isn't working if the application crashed ...
I never been able to reproduce this issue on any of my machine ... thank you for bearing with me.

Can you also send the log of the laptop ?

Also it's weird in the current log I don't see anything about actually finishing refreshing, just the previous refresh cancelled ... something is fishy.

I have another nightly coming with better logs.

https://github.com/Belphemur/SoundSwitch/actions/runs/7202375939

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

Unfortunately I cannot login to github on my work laptop.

Basically the log stops at cancellation received then Refresh of device interrupted. after that nothing, just the app crashing giving the error on the screen.

I removed the nightly now from work laptop. Trying to replicate a crash on personal laptop and I can't. It is the first time I use a nightly on work laptop so not sure if it is directly related to this or not. The only difference between both laptops is that I don't have admin access on the work laptop.

ADDIT: forgot to mention that the exception on personal laptop is between cancelation received and Refresh interrupted as you see above. On work laptop, there is nothing between those lines. Probably the crash itself.

@Belphemur
Copy link
Owner

New nightly is out: https://soundswitch.aaflalo.me/nightly

This should give better logs and fix the possible crashes.

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

ok so update on the situation. The personal laptop seems perfect:

[23:28:08.581 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[23:28:08.788 INF]]{ ThreadID: 44, TaskID: 33, State: Active, Unplugged } Cancelling Previous Context(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[23:28:08.788 INF]]{ ThreadID: 44, TaskID: 33, State: Active, Unplugged } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[23:28:09.194 INF]]{  } [WINAPI] Default device changed to "[Render]SB Play (Sound Blaster Play! 2)":Console(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:09.580 INF]]{  } [WINAPI] Default device changed to "[Render]SB Play (Sound Blaster Play! 2)":Multimedia(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:09.638 VRB]]{ State: Active, Unplugged } Device Changed received, triggering job(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.DeviceChanged)
[23:28:09.638 WRN]]{ ThreadID: 44, TaskID: 33, State: Active, Unplugged } Cancellation received.(at System.Threading.ExecutionContext.RunInternal)
[23:28:09.796 WRN]]{ State: Active, Unplugged } Refresh of device interrupted(at SoundSwitch.Framework.Audio.Lister.Job.DebounceRefreshJob.OnFailure)
[23:28:09.822 INF]]{ ThreadID: 37, TaskID: 34, State: Active, Unplugged } Cancelling Previous Context(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[23:28:09.822 INF]]{ ThreadID: 37, TaskID: 34, State: Active, Unplugged } Refreshing all devices(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)
[23:28:09.842 INF]]{  } [WINAPI] Default device changed to "[Render]SB Play (Sound Blaster Play! 2)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:10.380 INF]]{ Device: "[Render]SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[23:28:10.662 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic SB Play (Sound Blaster Play! 2)":Console(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:10.747 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic SB Play (Sound Blaster Play! 2)":Multimedia(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:10.843 INF]]{ Device: "[Render]SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[23:28:10.845 INF]]{ Device: "[Render]SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Icon replaced(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:10.861 INF]]{  } [WINAPI] Default device changed to "[Capture]Mic SB Play (Sound Blaster Play! 2)":Communications(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:11.474 INF]]{ Device: "[Render]SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[23:28:11.476 INF]]{ Device: "[Render]SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Icon replaced(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:11.579 INF]]{ Device: "[Capture]Mic SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[23:28:11.579 INF]]{ Device: "[Capture]Mic SB Play (Sound Blaster Play! 2)", IconChanger: Playback } No need to change icon(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:11.681 INF]]{ Device: "[Capture]Mic SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[23:28:11.682 INF]]{ Device: "[Capture]Mic SB Play (Sound Blaster Play! 2)", IconChanger: Playback } No need to change icon(at SoundSwitch.Model.AppModel+DefaultDeviceChangedJob.ExecuteAsync)
[23:28:11.778 INF]]{ Device: "[Capture]Mic SB Play (Sound Blaster Play! 2)", IconChanger: Playback } Changing icon(at SoundSwitch.Framework.TrayIcon.Icon.Changer.AbstractIconChanger.ChangeIcon)
[23:28:12.173 INF]]{ ThreadID: 37, TaskID: 34, State: Active, Unplugged } Refreshed all devices in 00:00:02.3508788. 10/rec, 17/play(at SoundSwitch.Framework.Audio.Lister.CachedAudioDeviceLister.Refresh)

however the work laptop is not reaching "Refreshed all devices" which is funny because now if i start the program with the USB connected, it never refreshes the list and the device stays there :) I took a pic of logs:

image

Is it possible it is timing out silently? Maybe work laptop takes much more time to recognize USB? I don't know, I don't understand why it doesn't finish the refresh

@Belphemur
Copy link
Owner

Yeah it keeps getting cancelled because it takes more than 3 seconds to enumerate the devices on the work laptop ... interesting.
I'm going to add more log to try to figure out where does it get stuck (on my machine enumerating 30 devices takes around 600ms ... so 3 secs ... felt like a looonng time).

I've increased the timeout to 10 secs and added log for every device that is found (only as verbose, so only Nightly and Debug would log that).

New nightly available: https://soundswitch.aaflalo.me/nightly

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

Ok good news. It was successful. Since it is a controlled laptop probably that is why the numbers are all over the place. I am guessing OS scans any usb that gets plugged in etc...

I did some testing to get some numbers.
when unplugging, the refreshed all is taking between 4 and 5 seconds, sometimes 2 seconds.
When plugging in, it takes anywhere between 6 seconds and 7.5 seconds.
I also tried spamming the hotkey as soon as I plugged in, it started displaying not found until it did. When spamming, it took 9.78 seconds (that was close).

It is surprising that it is taking this amount of time with only 4 speakers and 4 mics. Company controlled laptops, what are you gonna do, right?

Anyway, success!! Thank you very much Belphemur for an awesome software. And lol at the logs, so many now.

ADDIT: Just saw on my personal laptop that the time it takes to refresh increased to 5-7 seconds. Does logging affect the refresh time?

@Belphemur
Copy link
Owner

Yes logging is expected to increase the refresh time.

Seeing your test I'll increase the ttl to 20secs then.

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

just tried this morning, I missed the 10 seconds mark on multiple occasions on work laptop. 20 seconds might do the trick. I have no idea what the laptop is doing for so long ... Thanks.

@Belphemur
Copy link
Owner

Can you share the logs you got ?

I'm curious if it's a specific device or all of them take time, the latest nightly logs the time for each device to be processed.

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

I took a log from startup which didn't have the USB switched in. took 12 seconds.

Then another log when I switched in the USB, the weird thing about that, plantronics refreshed after cancelling? not sure. (redacted some foreground events)

image

Sorry couldn't get the full Log as it is hard, I am taking camera pic

@Belphemur Belphemur reopened this Dec 14, 2023
@Belphemur
Copy link
Owner

Wow just the plantronic device took 8seconds to refresh ... that's crazy.

I wonder what could be causing such issue, I'll rethink the code to see if it relates to the IconPath or something else.

@Belphemur
Copy link
Owner

Okay latest nightly should have some performance improvement. I stop loading volume info unless requested.

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

not sure I found any difference, all devices refreshed at the end at 9.7 seconds.

but can you check these logs, why would plantronics say refreshed twice with only 1 refreshing.

image

@Belphemur
Copy link
Owner

You're seeing it twice because 1 refresh was ongoing when the second event came in to trigger a new refresh.

New refresh job tell old refresh job to stop. Old refresh job had already loaded the plantronic device hence the log.
New refresh job is starting from scratch and loading it again.

The TaskID is helping to see that they are different job running concurrently.

I think I'm also going to increase the debouce ttl to wait longer like 300ms to try to avoid the double refresh issues.
New nighty with updated debounce timing.

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

ok looking good, still getting 9-12 seconds. And when I tried to stress test it by spamming the hotkeys as soon as I plugged in, I reached 19 seconds lol. A couple of questions:
1- is the Refresh opration async? because changing icons and me changing windows and all of that might affect it? .
2- Would you say all that log you are writing on the log file is affecting the total time for refreshed?

@Belphemur
Copy link
Owner

  1. Yes it is, to avoid locking the main thread (UI) I'm scheduling Task in the background. Since I listen to Windows API event, it also help decoupling the code and avoid impacting the event loop of Windows. In the past, I made Windows crash because it doesn't expect those event to take long to be processed.
  2. Yes it definitely is even if Serilog is pretty efficient, there will be an impact. I'm planning to remove some of the Verbose log for the release.

@BigAal
Copy link
Author

BigAal commented Dec 14, 2023

not sure if related to the changes you did with the volume, but now hovering over the icon shows [0%] for both speaker and mic. Not important for me but probably for others.

@Belphemur
Copy link
Owner

Since not loading the volume info at refresh time didn't seem to have a big impact and basically broke having the volume all together I put it back.

I think at this point we can consider that the issue is somewhat fixed, even if I have no idea why refreshing the device could take this long.

@BigAal
Copy link
Author

BigAal commented Dec 15, 2023

I do agree we should close this. I just want to also mention that this morning, I went above the 20 seconds, but I think I switched in the speakers while things were loading. I also realized that Refreshing is taking place twice for speaker and twice for mic so 4 times, every time I switch it in, because it is changing Default device and Communication device. So for now I have set default communication device as the always connected plantronics and got lower times. I guess that's as good as it gets with a company controlled laptop. Thanks a lot!

@Belphemur
Copy link
Owner

I've also increased the ttl to 30s to help with that and removed most logging, so I hope it will be better.

Thank you again for helping me test this!
I was never able to reproduce this or find somebody to help me test this 👍

github-actions bot pushed a commit that referenced this issue Dec 19, 2023
## [6.8.0](v6.7.2...v6.8.0) (2023-12-19)

### Enhancements

* **.NET:** Move to .NET 8.0 ([43f0d60](43f0d60))
* **device::cache:** Improve the performance and speed of caching devices ([594b49c](594b49c))
* **device::cache:** Increase the TTL for refreshing device list ([6ab8028](6ab8028))
* **device::cache:** keep only one cache alive for all devices ([9b3a126](9b3a126))
* **device::cache:** rework the logic behind refreshing devices when changes are detected in the system. ([3c12b3f](3c12b3f))

### Languages

* **Bulgarian:** Translated Settings using Weblate ([b2cf464](b2cf464))
* **Bulgarian:** Translated Tray Icon using Weblate ([fffe534](fffe534))
* **Chinese (Traditional):** Translated Settings using Weblate ([4582119](4582119))
* **French:** Translated Settings using Weblate ([4496335](4496335))
* **French:** Translated Tray Icon using Weblate ([76905a4](76905a4))
* **French:** Translated Update Download using Weblate ([67c281b](67c281b))
* **German:** Translated Settings using Weblate ([061583c](061583c))
* **German:** Translated Tray Icon using Weblate ([3da0c83](3da0c83))
* **Korean:** Translated Tray Icon using Weblate ([4ca2b15](4ca2b15))
* **Polish:** Translated Settings using Weblate ([43f8fa2](43f8fa2))
* **Polish:** Translated Tray Icon using Weblate ([3b05aeb](3b05aeb))
* **Polish:** Translated Update Download using Weblate ([6cd0022](6cd0022))
* **Serbian:** Translated Tray Icon using Weblate ([d17e650](d17e650))
* **Slovenian:** Translated Tray Icon using Weblate ([b8c4269](b8c4269))
* **Swedish:** Translated About using Weblate ([2b0a112](2b0a112))
* **Swedish:** Translated About using Weblate ([943befb](943befb))
* **Swedish:** Translated Settings using Weblate ([9a182a1](9a182a1))
* **Swedish:** Translated Settings using Weblate ([49d3fcc](49d3fcc))
* **Swedish:** Translated Settings using Weblate ([f2eb255](f2eb255))
* **Swedish:** Translated Settings using Weblate ([d9e285f](d9e285f))
* **Swedish:** Translated Settings using Weblate ([3454648](3454648))
* **Swedish:** Translated Tray Icon using Weblate ([e939073](e939073))
* **Swedish:** Translated Tray Icon using Weblate ([fe21446](fe21446))
* **Swedish:** Translated Update Download using Weblate ([c95fe6e](c95fe6e))
* **Swedish:** Translated Update Download using Weblate ([1b65fa4](1b65fa4))

### Bug Fixes

* **Device::Cache:** Devices not being refreshed ([a113175](a113175)), closes [#1323](#1323)
* **profile:** possible issue with profile where the the state couldn't be restored after the profile ended. ([a648e4e](a648e4e))

### Features

* **volume:** Add an option to keep volume level across audio devices ([ca293b5](ca293b5)), closes [#1328](#1328)
Copy link
Contributor

🎉 This issue has been resolved in version 6.8.0 🎉

The release is available on GitHub release

Your semantic-release bot 📦🚀

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug Issues which are bug reports released
Projects
None yet
Development

No branches or pull requests

2 participants