Unable to attach because of a problem in RegistryWatcher

[gigamegawatts]

I was having a problem attaching any device, and based on my debugging the problem seems to occur in RegistryWatcher when it tries to find the usbipd-win RootPath. I'm not familiar with the RegistryWatcher API, so I might be barking up the wrong tree, but let me explain...

I installed the 1.1.1 release of usbipd-win.

I made the specified changes to my WSL2 Ubuntu 20.04 distribution to enable usbip.

From an Administrative command prompt, usbipd wsl list works as expected, but usbipd wsl attach --busid=3-4 (or any other busid) fails with:

usbip: error: Attach Request for 3-4 failed - Request Completed Successfully
usbipd: error: Failed to attach device with ID '3-4'.

I tried stopping the service then running "usbipd server Logging:LogLevel:Default=Trace" from a command prompt. The request still fails, and the output from usbipd didn't specify the problem:

new connection from 172.22.53.25
dbug: UsbIpServer.Server[0]
connection closed

So, I downloaded the master branch of the project's code, and ran it in Visual Studio 2019. When I ran the attach request, an exception occurred in RegistryWatcher:

 System.Management.ManagementException: Not found
       at System.Management.ManagementException.ThrowWithExtendedInfo(ManagementStatus errorCode)
       at System.Management.ManagementEventWatcher.Start()
       at UsbIpServer.RegistryWatcher..ctor() in C:\Users\gigam\source\repos\dotnet\usbipd-win\UsbIpServer\RegistryWatcher.cs:line 29
       at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
       at System.Reflection.RuntimeConstructorInfo.Invoke(BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitScopeCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.Resolve(ServiceCallSite callSite, ServiceProviderEngineScope scope)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.DynamicServiceProviderEngine.<>c__DisplayClass1_0.<RealizeService>b__0(ServiceProviderEngineScope scope)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope)
       at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope.GetService(Type serviceType)
       at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
       at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
       at UsbIpServer.Server.<>c__DisplayClass7_1.<<ExecuteAsync>b__1>d.MoveNext() in C:\Users\gigam\source\repos\dotnet\usbipd-win\UsbIpServer\Server.cs:line 91

So, I put a breakpoint at line 29 of RegistryWatcher. The query it is running looks correct to me:

"SELECT * FROM RegistryTreeChangeEvent WHERE Hive='HKEY_LOCAL_MACHINE' AND RootPath='SOFTWARE\\\\usbipd-win'"

I checked the registry, and that key exists. But, when watcher.Start() runs, the "Not found" exception is thrown.

To see if the problem was specifically with the usbipd-win key, I changed the RootPath to a "known good" one:

"SELECT * FROM RegistryTreeChangeEvent WHERE Hive='HKEY_LOCAL_MACHINE' AND RootPath='SOFTWARE\\\\Microsoft'"

To my surprise, this not only prevented the "Not found" exception, but it actually allowed the program to continue successfully. It went into ConnectedClient.HandleRequestImportAsync() as expected, detached the device from Windows and attached it to Linux. The device showed up in Linux's lsusb output.

Although the code is using APIs that I've never worked with before, I assume that changing the RootPath will prevent detach requests from working, so this isn't a fix.

Do you have any ideas on why that RegistryWatcher query might fail on my PC, or what changes I might make to the query syntax to allow it to find the usbipd-win RootPath?

BTW, my PC isn't anything special: Win 11 Home upgraded from Win 10 Home. It's a relatively recent install of Win 10, from January of this year, and I've never messed around with the registry.

I exported the usbipd-win part of the registry. I can provide the full contents if you like, but the key names are:

Key Name:          HKEY_LOCAL_MACHINE\SOFTWARE\usbipd-win
. . .
Key Name:          HKEY_LOCAL_MACHINE\SOFTWARE\usbipd-win\Devices
. . .
Key Name:          HKEY_LOCAL_MACHINE\SOFTWARE\usbipd-win\Devices\{b0b1d849-c49e-4af5-9fc3-1a231181d714}
. . .
Key Name:          HKEY_LOCAL_MACHINE\SOFTWARE\usbipd-win\Devices\{b0b1d849-c49e-4af5-9fc3-1a231181d714}\Filter

Thanks,

Dan.

[dorssel]

When you run 'usbipd server', either from the command line or from a debugger, you must do so as administrator. My guess is you ran directly from visual studio, which would require you to run VS itself as root.

[gigamegawatts]

Yes, when debugging I run Visual Studio as administrator.

The same Exception in RegistryWatcher also occurs if I run usbipd.exe from the command line, but I'm running my recompiled version that logs any Exception within the try/finally clause of Server.ExecuteAsync().

When I run the release 1.1.1 version of usbipd from the command line, it fails silently, as shown below:

PS C:\Users\gigam> usbipd server Logging:LogLevel:Default=Trace
dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
      Hosting starting
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Users\gigam
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
      Hosting started
dbug: UsbIpServer.Server[0]
      new connection from 172.26.60.73
dbug: UsbIpServer.Server[0]
      connection closed

Does this output show that no Exception occurred? I'm not familiar with now anonymous methods handle an Exception without an Exception handler.

If there's definitely no Exception occurring, then I'm clearly barking up the wrong tree with the RegistryWatcher issue - it must be a problem introduced when I recompiled the code -- so I'd need to debug with the release version instead.

The "new connection from" and "connection closed" messages are from Server.ExecuteAsync(), but I guess other code gets invoked between those 2 logged messages, not just the RegistryWatcher code. I don't know if the "dbug: UsbIpServer.Server[0]" is a clue -- I can't figure out where that output comes from in the code.

Nothing at all is written to the Event Viewer, so it would seem that no Warnings or Errors are being logged.

Any suggestions on how I might better debug the problem?

Thanks,

Dan.

[dorssel]

@gigamegawatts
I've just created PR #86 that may (or may not) solve your issue.

My best guess is: 1.1.1 uses so called "trimmed assemblies" in order to reduce the installation size. Converting to .NET 6 gave me a warning that System.Management (the component that actually does the registry watching) is in fact not compatible with trimming.

Could you give the build artifact a try? It is at https://github.com/dorssel/usbipd-win/actions/runs/1453006711
Note that the installer is not signed (but the drivers are).

[gigamegawatts]

Thanks for trying, but unfortunately that didn't fix the problem.

Output from the attach command is the same as before:

C:\Users\gigam>usbipd wsl attach --busid=5-5
[sudo] password for dwatts:
usbip: error: Attach Request for 5-5 failed - Unknown Op Common Status

usbipd: error: Failed to attach device with ID '5-5'.

If I run usbipd from the command line, output is almost the same as before:

C:\Users\gigam>usbipd server Logging:LogLevel:Default=Trace
dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
      Hosting starting
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Users\gigam
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
      Hosting started
dbug: UsbIpServer.Server[1000]
      new connection from 172.30.157.150
dbug: UsbIpServer.Server[1000]
      connection closed

There is no indication from Windows (in Device Manager) that it attempted to detach the USB device. No messages related to the program appear in the Event Viewer.

The only difference from the 1.1.1 release is that "dbug: UsbIpServer.Server[0]" has changed to "dbug: UsbIpServer.Server[1000]". I don't know if that's significant. Do you know where that log statement comes from? I still can't find it.

I tried running usbip list from the Linux side, and that fails with the same output from usbipd so whatever's going wrong isn't related to the process of detaching the USB device. Oddly, if I run uspibd in the debugger, the "usbip list" command still results in the same "Not Found" Exception in RegistryWatcher, though I don't think there's anything to watch for when handling a list command.

Here's the output from the usbip (the "..." is just the rest of a very long list of device names from names.c):

$ sudo usbip --debug list --remote=172.30.144.1
. . .
usbip: debug: names.c:356:[parse] line 20362 class ff Vendor Specific Class
usbip: debug: names.c:409:[parse] line 20363 subclass ff:ff Vendor Specific Subclass
usbip: debug: names.c:442:[parse] line 20364 protocol ff:ff:ff Vendor Specific Protocol
usbip: debug: usbip_list.c:138:[list_exported_devices] connected to 172.30.144.1:3240
usbip: debug: usbip_network.c:171:[usbip_net_recv_op_common] usbip_net_recv failed: -1
usbip: error: Exported Device List Request failed - Request Completed Successfully

usbip: error: failed to get device list from 172.30.144.1

Unless it would break other behavior in the program, would it be possible to add an Exception handler that logs any exception in the anonymous method in Server.ExecuteAsync(), such as:

                _ = Task.Run(async () =>
                {
                    Logger.LogDebug($"new connection from {clientAddress}");
                    try
                    {
                        using var cancellationTokenRegistration = stoppingToken.Register(() => tcpClient.Close());
                        using var serviceScope = ServiceScopeFactory.CreateScope();
                        var clientContext = serviceScope.ServiceProvider.GetRequiredService<ClientContext>();
                        clientContext.TcpClient = tcpClient;
                        clientContext.ClientAddress = clientAddress;
                        var connectedClient = serviceScope.ServiceProvider.GetRequiredService<ConnectedClient>();
                        await connectedClient.RunAsync(stoppingToken);
                    } catch (Exception ex)
                    {
                        Logger.LogError(ex, "Error connecting to usbipd client");
                        throw;
                    }
                    finally
                    {
                        Logger.LogDebug("connection closed");
                    }
                }, stoppingToken);

I'm still not sure if an Exception occurs when I run your build - it might be something caused by my build.

Thanks,

Dan.

[dorssel]

Just so you know, the dbug: UsbIpServer.Server[1000] is perfectly fine. The latest build indeed changed the EventId from 0 to 1000. The output from the server looks all normal.

What puzzles me most is that you are able to do a listing on the host with usbipd list but not on the client with usbip list --remote. The enumeration code that generates the list should be the same on both. There must be something with the actual communication of that list going wrong. But the connect and disconnect seem to be going alright.

It's best to first get usbip list --remote working and only then move on to attaching. But for now, I am out of ideas. Let me think about it a little; maybe I will indeed try to add some more logging. Feel free to experiment there now that you have a build environment...

EDIT: The registry watcher is not involved for listing devices.

[gigamegawatts]

OK, I found the root cause of the problem. It's nothing to do with the usbipd-win code, so I'll close this issue.

For reasons that I haven't figured out, on my PC the ManagementEventWatcher is looking in the 32-bit part of the Windows registry, not the 64-bit part. If I add the usbipd-win key to the 32-bit registry, the code works, but of course no registry change is ever detected so the detach command has no effect. That's actually not a showstopper for me, since I'll rarely need to switch the USB device back to Windows (I'm just working with embedded device development).

I wrote a small program to just do the ManagementEventWatcher call, and can't find any workaround that can be implemented in code. The fix would presumably be somewhere in the WMI stack, but I couldn't find anything via Google. Perhaps I have the only PC in the world with this problem.

I'll try reporting it to Microsoft, but I'm not optimistic. The only fix might be to do a clean install of Windows. If I run into similar issues with other software, I'll do just that.

So, thanks for your help, and apologies for wasting your time with this bizarre problem.

[gigamegawatts]

Problem was with user PC, not usbipd-win software.

[dorssel]

That's actually very interesting!
See: https://docs.microsoft.com/en-us/windows/win32/wmisdk/requesting-wmi-data-on-a-64-bit-platform

usbipd-win is 64-bit only. This means that WMI should default to the 64-bit provider. However, it is also possible to use the 32-bit provider and still request 64-bit data. What I think is wrong here is that somehow on your computer the 64-bit provider is broken and therefore WMI requests fall back to being served by the 32-bit provider, which defaults to using 32-bit data (syswow64).

I made 2 changes in PR #89:

• ask for 64-bit data, no matter if the provider is 64-bit or 32-bit
• log an error if the RegistryWatcher fails to initialize (always a good idea)

This means it should now work for you, although there is still something wrong with your 64-bit WMI provider. Maybe you should do some dism repair on Windows.

Could you test the build artifact at https://github.com/dorssel/usbipd-win/actions/runs/1455823723?

[gigamegawatts]

Thanks, you found the root cause of the problem.

The new code gave the same result, and still located the usbipd-win key if it was in the 32-bit part of the registry. But, your comment about the 64-bit WMI provider being the cause was absolutely correct.

I finally thought to check the Task Manager to see what architecture WmiPrvSE.exe was running under, and there were actually 2 of them, one x86 and one x64. I killed the x86 one, and now usbipd-win works as expected, both attach and detach. (I'm still running the new build artifact - I can uninstall it and test with the 1.1.1 release if you don't intend to release the new code.)

I haven't figured out what's starting the x86 one yet -- hopefully nothing malevolent.

Thanks again for your help.

[dorssel]

And yet I again I learned something new (thanks!)

It is perfectly normal that multiple such WmiPrvSE processes are running (I didn't know that, but just found out). They can run as different users (depending on the information queried: LOCAL SYSTEM, NETWORK SERVICE, etc.). And also at different bitness, depending on the bitness of the process querying. I also found a new flag: __RequiredArchitecture.

It seems it works as follows: when a process requests information, the WMI service spawns a process to deal with it, unless such a process is already running. So, when usbipd-win asked for the information, WMI decided it could be handled by the process already running as SYSTEM (because that is the user required to deliver the information). That happened to be a 32-bit process, probably because some other 32-bit process was already using it. That should work fine, as either bitness provider should be able to handle either bitness queries (I think). By specifying __ProviderArchitecture you can change the preferred provider bitness, but only if no provider is already running. So if you ask for 64, and no provider is currently running, it will spawn a 64-bit provider. But if you ask for 64-bit and a 32-bit provider is already running, you'll get that one anyway. And that is where __RequiredArchitecture comes in. If you specify that too, you'll definitely get the bitness provider you asked for.

I've updated #89 to now force 64-bit providers. It cannot hurt (usbipd-win is available only for 64-bit anyway) and it just may help. In any case, the added logging is an improvement as well.

Thanks for staying in for the long haul on this one. Now I am ready to really close this one (unless you got some more...)

[gigamegawatts]

The x86 copy of WmiPrvSE.exe that was running on my PC was under Username SYSTEM, so there were two different WmiPrvSE processes running under SYSTEM, one x86 and one x64. I'm not certain if this is a valid situation -- if so, then the WMI stack didn't handle it properly on my PC. The x86 version of WmiPrvSE.exe seems legit, not malware: it's located in a Windows\WinSxS subfolder.

My suspicion was some MSI motherboard software service was launching it - it's a known troublemaker that caused unrelated problems when I did the Windows 11 upgrade. I uninstalled it and rebooted, and the x86 WmiPrvSE hasn't reappeared yet.

Yes, you can consider the issue closed. The usbipd-win program is working great on my PC now.

Thanks.