"Device Not Ready" from WdfIoTargetOpen() and Shifty ACPI

NTDEV
1

Summary

I have a UMDF2 SerCx2 peripheral driver trying to open a serial port via WdfIoTargetOpen() and getting a return value of 0x80070015, "device not ready." I'd very much like it to be ready, though, and why it's not is something I need to understand. I'm hoping someone reading this might be able to help, or point me towards something to try.

Details

The SoC I'm working with is an Intel Atom x7425E, and one of its on-chip UARTs is meant to be permanently wired to an on-board device. The system is running Windows 11 IoT Enterprise LTSC. The ACPI I added to the system is meant to declare UART0 as a serial bus to the resource hub proxy, and declare the on-board device as being connected to that serial bus. Calling the device BLIP (in keeping with my post to the vendor of the prototype board I'm using), my ACPI additions look like this:

Scope(\_SB)
{
    Device(RHPX)        // Resource Hub Proxy object
    {
        Name(_HID, "MSFT8000")
        Name(_CID, "MSFT8000")
        Name(_UID, 1)

        // Resource at index 0 is UART0
        Name(_CRS, ResourceTemplate()
        {
            // Define the UART bus
            UartSerialBus(
                115200,             // Baud
                DataBitsEight, 
                StopBitsOne, 
                0x00,               // UART handshaking lines used: none.
                LittleEndian,
                ParityTypeNone,
                FlowControlNone, 
                64,                 // Receive buffer size
                64,                 // Transmit buffer size
                "\\_SB.PC00.UA00",  // UART0 on the Intel x7425E
                ,,,
            )
        })
    }

    Device(BLIP)        // Our custom ASIC device object
    {
        Name(_HID, "BLIP0001")      // BLIP device hardware ID
        Name(_CID, "BLIP0001")      // Compatible ID
        Name(_UID, 1)               // Unique ID
        Name(_CRS, ResourceTemplate()
        {
            // Define the dependency on the resource hub
            UartSerialBus(
                115200,             // Baud
                DataBitsEight, 
                StopBitsOne, 
                0x00,               // UART handshaking lines used: none.
                LittleEndian,
                ParityTypeNone,
                FlowControlNone, 
                64,                 // Receive buffer size
                64,                 // Transmit buffer size
                "\\_SB.RHPX",       // Resource hub proxy (RSPX) object
                0,                  // Index of UART0 resource in the RHPX object
                ,,
            )
        })
    }
}

The reason I posted to the vendor's forum was mainly to find out whether \\_SB.PC00.UA00 was the right ACPI object to reference for UART0. I think it is, but it's based on dumping the ACPI and trying to understand it, and my entire knowledge of ACPI and ASL is just a couple weeks old. But if I add a _DSD to the RHPX object to expose UART0 to user-mode, I can fire up the vendor's custom build of MinComm and find it in the list of ports. It enumerates as \\?\ACPI#MSFT8000#1#{86e0d1e0-8089-11d0-9ce4-08003e301f73}\UART0, with MSFT8000 being the device name for the resource hub proxy, and the GUID being GUID_DEVINTERFACE_COMPORT. Running MinComm with that port name allows me to echo characters through the port, having wired RX and TX together for test purposes. I have a scope on the line for further verification.

The BLIP device declaration has a hardware ID of BLIP0001, which matches my driver’s INF hardware ID of ACPI\BLIP0001, so my device driver loads into the WUDFHost process. In my driver's EvtWdfDevicePrepareHardware() handler, I follow Microsoft's KMDF SerCx2 example for getting a connection ID and use the RESOURCE_HUB_CREATE_PATH_FROM_ID() macro to create a path, which is coming back as \\.\RESOURCE_HUB\0000000000000002 in a local UNICODE_STRING named deviceName.

[It's worth mentioning here that if I include the aforementioned _DSD and set the deviceName to a hardcoded path of \\?\ACPI#MSFT8000#1#{86e0d1e0-8089-11d0-9ce4-08003e301f73}\UART0, the WdfIoTargetOpen() will succeed. Since the device is permanently wired to the UART, this might be a viable workaround.]

From this I build a WDF_IO_TARGET_OPEN_PARAMS structure like so:

WDF_IO_TARGET_OPEN_PARAMS openParams = { 0 };
WDF_IO_TARGET_OPEN_PARAMS_INIT_OPEN_BY_NAME(
    &openParams,
    &deviceName,
    (GENERIC_READ | GENERIC_WRITE));
openParams.ShareAccess = 0;
openParams.CreateDisposition = FILE_OPEN;
openParams.FileAttributes = FILE_ATTRIBUTE_NORMAL;

I create a WDFIOTARGET like so:

WDFIOTARGET uartIoTarget = NULL;
status = WdfIoTargetCreate(device, WDF_NO_OBJECT_ATTRIBUTES, &uartIoTarget);

If all's still well (and it seems to be), I finally get to ruin my day by attempting to open the port:

status = WdfIoTargetOpen(uartIoTarget, &openParams);

The status is 0x80070015; I can't yet explain why. My ACPI addition seems a likely suspect due to my inexperience with it. But I'm not ruling out anything.

WDF Logs

If, rather than returning failure on EvtWdfDevicePrepareHardware() as one does in polite society, I lie to Windows and return STATUS_SUCCESS, the resource hub proxy and my driver remain in memory, making it a little easier to see what's going on. With WDF Verifier on and verbose for all the suspects (RHProxy.sys, SerCx2.sys, Intel's SerCx2 controller driver iaLPSS2_UART2_ADL.sys, and MyOwnDriver.dll), I get some WDF logs that might be more helpful to your eyes than mine.

Starting at the top, my UMDF2 SerCx2 peripheral driver log looks like this:

2: 12/16/2024-22:22:08.0456715 FxIFRStart - FxIFR logging started
5: 12/16/2024-22:22:08.0639691 FxVerifierLock::InitializeLockOrder - Object Type 0x1036 does not have a lock order defined in fx\inc\FxVerifierLock.hpp
6: 12/16/2024-22:22:08.0639691 FxVerifierLock::InitializeLockOrder - Object Type 0x1036 does not have a lock order defined in fx\inc\FxVerifierLock.hpp
7: 12/16/2024-22:22:08.0733363 FxDevice::RetrieveDeviceRegistrySettings - DirectHardwareAccess = 1
8: 12/16/2024-22:22:08.0733363 FxDevice::RetrieveDeviceRegistrySettings - RegisterAccessMode = 0
9: 12/16/2024-22:22:08.0733363 FxDevice::RetrieveDeviceRegistrySettings - FileObjectPolicy = 0
10: 12/16/2024-22:22:08.0733363 FxDevice::RetrieveDeviceRegistrySettings - FsContextUsePolicy = 4
11: 12/16/2024-22:22:08.0733363 FxPkgPnp::PnpEnterNewState - WDFDEVICE 0xFFFFFDFABBA672C8 !devobj 0x000002054459C1F0 entering PnP State WdfDevStatePnpInit from WdfDevStatePnpObjectCreated
13: 12/16/2024-22:22:08.0833734 FxPkgPnp::Dispatch - WDFDEVICE 0xFFFFFDFABBA672C8 !devobj 0x000002054459C1F0, IRP_MJ_PNP, 0x00000000(IRP_MN_START_DEVICE) IRP 0x0000020544563450
14: 12/16/2024-22:22:08.0833734 FxPkgPnp::PnpEnterNewState - WDFDEVICE 0xFFFFFDFABBA672C8 !devobj 0x000002054459C1F0 entering PnP State WdfDevStatePnpInitStarting from WdfDevStatePnpInit
15: 12/16/2024-22:22:08.0833734 FxPkgPnp::PnpEnterNewState - WDFDEVICE 0xFFFFFDFABBA672C8 !devobj 0x000002054459C1F0 entering PnP State WdfDevStatePnpHardwareAvailable from WdfDevStatePnpInitStarting
16: 12/16/2024-22:22:08.0871371 FxIoTargetRemote::OpenTargetHandle - CreateFile for WDFIOTARGET FFFFFDFABBA50AE8 returned status NTSTATUS=80070015

The log goes on after that with some power events and such, but I don't think anything my driver does after CreateFile() fails is instructive.

The RHProxy.sys log is, I think, the most likely to be useful. Here's what it caught:

49: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering Power State WdfDevStatePowerD0StartingDmaEnable from WdfDevStatePowerD0StartingConnectInterrupt
50: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering Power State WdfDevStatePowerD0StartingPostHardwareEnabled from WdfDevStatePowerD0StartingDmaEnable
51: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering Power State WdfDevStatePowerD0StartingStartSelfManagedIo from WdfDevStatePowerD0StartingPostHardwareEnabled
52: 12/16/2024-22:22:05.5221430 FxPkgIo::ResumeProcessingForPower - Power resume all queues of WDFDEVICE 0x000066F77E0D98A8
53: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - Thread FFFF990881F4A080 is processing WDFQUEUE 0x000066F77E80C4F8
54: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - WDFQUEUE 0x000066F77E80C4F8 Power Transition State 0x0000000a(FxIoQueuePowerRestarting)
55: 12/16/2024-22:22:05.5221430 FxIoQueue::ProcessPowerEvents - Power Resume: Driver has no power paused requests on WDFQUEUE 0x000066F77E80C4F8
56: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - WDFQUEUE 0x000066F77E80C4F8 Power Transition State 0x0000000b(FxIoQueuePowerRestartingNotifyingDriver)
57: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - WDFQUEUE 0x000066F77E80C4F8 Power Transition State 0x0000000c(FxIoQueuePowerRestartingDriverNotified)
58: 12/16/2024-22:22:05.5221430 FxIoQueue::ProcessPowerEvents - Power Resume: WDFQUEUE 0x000066F77E80C4F8 is now powered on and I/O has resumed
59: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - Thread FFFF990881F4A080 is processing WDFQUEUE 0x000066F77E80C4F8
60: 12/16/2024-22:22:05.5221430 FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power idle state FxIdleStartedPowerUp from FxIdleStarted
61: 12/16/2024-22:22:05.5221430 FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power idle state FxIdleDisabled from FxIdleStartedPowerUp
62: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering Power State WdfDevStatePowerDecideD0State from WdfDevStatePowerD0StartingStartSelfManagedIo
63: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering Power State WdfDevStatePowerD0 from WdfDevStatePowerDecideD0State
64: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power policy state WdfDevStatePwrPolStartingPoweredUp from WdfDevStatePwrPolStarting
65: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power policy state WdfDevStatePwrPolStartingSucceeded from WdfDevStatePwrPolStartingPoweredUp
66: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power policy state WdfDevStatePwrPolStartingDecideS0Wake from WdfDevStatePwrPolStartingSucceeded
67: 12/16/2024-22:22:05.5221430 FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power policy state WdfDevStatePwrPolStarted from WdfDevStatePwrPolStartingDecideS0Wake
68: 12/16/2024-22:22:05.5221430 FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering power idle state FxIdleDisabled from FxIdleDisabled
69: 12/16/2024-22:22:05.5221430 FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering PnP State WdfDevStatePnpEnableInterfaces from WdfDevStatePnpHardwareAvailable
70: 12/16/2024-22:22:05.5221430 FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 entering PnP State WdfDevStatePnpStarted from WdfDevStatePnpEnableInterfaces
71: 12/16/2024-22:22:05.5221430 IsLoggingEnabledAndNeeded - lastlogged 1db4f7635022e3e, current 1db503b3aac40b6, delta c505aa1278
72: 12/16/2024-22:22:05.5221430 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000009(IRP_MN_QUERY_CAPABILITIES) IRP 0xFFFF99088324F010
73: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryCapabilities - Entering QueryCapabilities handler
74: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryCapabilities - Exiting QueryCapabilities handler
75: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryCapabilitiesCompletion - Entering QueryCapabilities completion handler
76: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryCapabilitiesCompletion - Exiting QueryCapabilities completion handler
77: 12/16/2024-22:22:05.5221430 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000014(IRP_MN_QUERY_PNP_DEVICE_STATE) IRP 0xFFFF99088324F010
78: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryPnpDeviceStateCompletion - Entering QueryPnpDeviceState completion handler
79: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryPnpDeviceStateCompletion - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 returning PNP_DEVICE_STATE 0x32 IRP 0xFFFF99088324F010
80: 12/16/2024-22:22:05.5221430 FxPkgFdo::HandleQueryPnpDeviceStateCompletion - Exiting QueryPnpDeviceState completion handler
81: 12/16/2024-22:22:05.5221430 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type BusRelations IRP 0xFFFF99088324F010
82: 12/16/2024-22:22:05.5221430 FxPkgFdo::PnpQueryDeviceRelations - Entering QueryDeviceRelations handler, type BusRelations
83: 12/16/2024-22:22:05.5221430 FxChildList::ProcessBusRelations - Nothing to report on WDFCHILDLIST 000066F77CD6D5B8, returning early
84: 12/16/2024-22:22:05.5221430 FxChildList::ProcessModificationsLocked - Begin processing modifications on WDFCHILDLIST 000066F77CD6D5B8
85: 12/16/2024-22:22:05.5221430 FxChildList::ProcessModificationsLocked - end processing modifications on WDFCHILDLIST 000066F77CD6D5B8
86: 12/16/2024-22:22:05.5221430 FxChildList::ProcessModificationsLocked - Begin processing modifications on WDFCHILDLIST 000066F77CD6D5B8
87: 12/16/2024-22:22:05.5221430 FxChildList::ProcessModificationsLocked - end processing modifications on WDFCHILDLIST 000066F77CD6D5B8
88: 12/16/2024-22:22:05.5221430 FxPkgPnp::HandleQueryBusRelations - WDFDEVICE 000066F77E0D98A8, returning 0xc00000bb(STATUS_NOT_SUPPORTED) from processing bus relations
89: 12/16/2024-22:22:05.5221430 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type TargetDeviceRelation IRP 0xFFFF99088324E010
90: 12/16/2024-22:22:05.5221430 FxPkgFdo::PnpQueryDeviceRelations - Entering QueryDeviceRelations handler, type TargetDeviceRelation
91: 12/16/2024-22:22:05.5221430 FxPkgFdo::PnpQueryDeviceRelations - Exiting QueryDeviceRelations handler, status STATUS_SUCCESS
92: 12/16/2024-22:22:05.5221430 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 0x00000000(IRP_MJ_CREATE) IRP 0xFFFF99088324E010
93: 12/16/2024-22:22:05.5221430 FxIoQueue::QueueRequest - Queuing WDFREQUEST 0x000066F77CC3D1D8 on WDFQUEUE 0x000066F77E77AA58
94: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - Thread FFFF99087A52B400 is processing WDFQUEUE 0x000066F77E77AA58
95: 12/16/2024-22:22:05.5221430 FxRequest::Complete - Completing WDFREQUEST 0x000066F77CC3D1D8 for IRP 0xFFFF99088324E010 with Information 0x0, 0xc0000225(STATUS_NOT_FOUND)
96: 12/16/2024-22:22:05.5221430 FxIoQueue::DispatchEvents - Thread FFFF99087A52B400 is processing WDFQUEUE 0x000066F77E77AA58
97: 12/16/2024-22:22:05.5221430 FxPkgFdo::PnpQueryDeviceRelations - Exiting QueryDeviceRelations handler, status STATUS_SUCCESS
98: 12/16/2024-22:22:05.5378106 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type TargetDeviceRelation IRP 0xFFFF99088324F010
99: 12/16/2024-22:22:05.5378106 FxPkgFdo::PnpQueryDeviceRelations - Entering QueryDeviceRelations handler, type TargetDeviceRelation
100: 12/16/2024-22:22:05.5378106 FxPkgFdo::PnpQueryDeviceRelations - Exiting QueryDeviceRelations handler, status STATUS_SUCCESS
101: 12/16/2024-22:22:05.5378106 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 0x00000000(IRP_MJ_CREATE) IRP 0xFFFF99088324F010
102: 12/16/2024-22:22:05.5378106 FxIoQueue::QueueRequest - Queuing WDFREQUEST 0x000066F77CC3D1D8 on WDFQUEUE 0x000066F77E77AA58
103: 12/16/2024-22:22:05.5378106 FxIoQueue::DispatchEvents - Thread FFFF99087A52B400 is processing WDFQUEUE 0x000066F77E77AA58
104: 12/16/2024-22:22:05.5378106 FxRequest::Complete - Completing WDFREQUEST 0x000066F77CC3D1D8 for IRP 0xFFFF99088324F010 with Information 0x0, 0xc0000225(STATUS_NOT_FOUND)
105: 12/16/2024-22:22:05.5378106 FxIoQueue::DispatchEvents - Thread FFFF99087A52B400 is processing WDFQUEUE 0x000066F77E77AA58
106: 12/16/2024-22:22:05.8684151 FxWmiIrpHandler::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 IRP_MJ_SYSTEM_CONTROL, 0x0000000b(IRP_MN_REGINFO_EX) IRP 0xFFFF99088346E010
107: 12/16/2024-22:22:07.8125848 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type TargetDeviceRelation IRP 0xFFFF99087A533AA0
108: 12/16/2024-22:22:07.8125848 FxPkgFdo::PnpQueryDeviceRelations - Entering QueryDeviceRelations handler, type TargetDeviceRelation
109: 12/16/2024-22:22:07.8125848 FxPkgFdo::PnpQueryDeviceRelations - Exiting QueryDeviceRelations handler, status STATUS_SUCCESS
110: 12/16/2024-22:22:07.8125848 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 0x00000000(IRP_MJ_CREATE) IRP 0xFFFF99087A533AA0
111: 12/16/2024-22:22:07.8125848 FxIoQueue::QueueRequest - Queuing WDFREQUEST 0x000066F77CC3D1D8 on WDFQUEUE 0x000066F77E77AA58
112: 12/16/2024-22:22:07.8125848 FxIoQueue::DispatchEvents - Thread FFFF99088193C040 is processing WDFQUEUE 0x000066F77E77AA58
113: 12/16/2024-22:22:07.8125848 FxRequest::Complete - Completing WDFREQUEST 0x000066F77CC3D1D8 for IRP 0xFFFF99087A533AA0 with Information 0x0, 0xc0000225(STATUS_NOT_FOUND)
114: 12/16/2024-22:22:07.8125848 FxIoQueue::DispatchEvents - Thread FFFF99088193C040 is processing WDFQUEUE 0x000066F77E77AA58
115: 12/16/2024-22:22:08.0871371 FxPkgPnp::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type TargetDeviceRelation IRP 0xFFFF99087A533AA0
116: 12/16/2024-22:22:08.0871371 FxPkgFdo::PnpQueryDeviceRelations - Entering QueryDeviceRelations handler, type TargetDeviceRelation
117: 12/16/2024-22:22:08.0871371 FxPkgFdo::PnpQueryDeviceRelations - Exiting QueryDeviceRelations handler, status STATUS_SUCCESS
118: 12/16/2024-22:22:08.0871371 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E0D98A8 !devobj 0xFFFF9908833B9C30 0x00000000(IRP_MJ_CREATE) IRP 0xFFFF99087A533AA0
119: 12/16/2024-22:22:08.0871371 FxIoQueue::QueueRequest - Queuing WDFREQUEST 0x000066F77CC3D1D8 on WDFQUEUE 0x000066F77E77AA58
120: 12/16/2024-22:22:08.0871371 FxIoQueue::DispatchEvents - Thread FFFF990885A5B080 is processing WDFQUEUE 0x000066F77E77AA58
121: 12/16/2024-22:22:08.0871371 FxRequest::Complete - Completing WDFREQUEST 0x000066F77CC3D1D8 for IRP 0xFFFF99087A533AA0 with Information 0x0, 0xc0000225(STATUS_NOT_FOUND)
122: 12/16/2024-22:22:08.0871371 FxIoQueue::DispatchEvents - Thread FFFF990885A5B080 is processing WDFQUEUE 0x000066F77E77AA58

Note by the time stamps that all but the last 8 lines occur before my driver logs anything; the last 8 lines time stamp matches that of the CreateFile() failure being returned to my driver. Those STATUS_NOT_FOUND results on lines 95, 104, 113, and 121 are interesting, but earlier at line 88 there's a STATUS_NOT_SUPPORTED "from processing bus relations" might be interesting as well. I don't know much of anything about the resource hub proxy internals, though, and I'm not sure how to interpret what I'm seeing here. The timing to me suggests, again, that something is flaky before my driver ever even loads.

SerCx2.sys's log looks like this:

1: 12/16/2024-22:22:03.0937890 FxIFRStart - FxIFR logging started
2: 12/16/2024-22:22:03.0937890 FxInitialize - Initialize globals for \REGISTRY\MACHINE\SYSTEM\ControlSet001\Services\SerCx2
3: 12/16/2024-22:22:03.0937890 FxPoolInitialize - Initializing Pool 0xFFFF990881A147D0, Tracking 1
4: 12/16/2024-22:22:03.0937890 LockVerifierSection - Increment Lock counter (2) for Verifier Paged Memory from  \REGISTRY\MACHINE\SYSTEM\ControlSet001\Services\SerCx2 from driver globals FFFF990881A14760
5: 12/16/2024-22:22:03.0937890 FxPkgIo::FxPkgIo - Constructed FxPkgIo 0xFFFF99088195B3A0
6: 12/16/2024-22:22:03.0937890 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E299848 !devobj 0xFFFF9908819F52C0 0x00000000(IRP_MJ_CREATE) IRP 0xFFFF990881D48AB0
7: 12/16/2024-22:22:03.0955404 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E299848 !devobj 0xFFFF9908819F52C0 0x00000012(IRP_MJ_CLEANUP) IRP 0xFFFF990881D48AB0
8: 12/16/2024-22:22:03.0955404 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E299848 !devobj 0xFFFF9908819F52C0 0x00000002(IRP_MJ_CLOSE) IRP 0xFFFF990881D48AB0
9: 12/16/2024-22:22:03.0955404 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E299848 !devobj 0xFFFF9908819F52C0 0x00000000(IRP_MJ_CREATE) IRP 0xFFFF990881D48AB0
10: 12/16/2024-22:22:03.0955404 FxPkgGeneral::Dispatch - WDFDEVICE 0x000066F77E299848 !devobj 0xFFFF9908819F52C0 0x00000012(IRP_MJ_CLEANUP) IRP 0xFFFF990881D48AB0
11: 12/16/2024-22:22:03.0955404 imp_WdfRegistryQueryULong - WDFKEY 000066F77E3054D8, QueryULong, 0xc0000034(STATUS_OBJECT_NAME_NOT_FOUND)
12: 12/16/2024-22:22:03.0955404 imp_WdfRegistryQueryULong - WDFKEY 000066F77E3054D8, QueryULong, 0xc0000034(STATUS_OBJECT_NAME_NOT_FOUND)
13: 12/16/2024-22:22:03.0955404 imp_WdfRegistryQueryULong - WDFKEY 000066F77E3054D8, QueryULong, 0xc0000034(STATUS_OBJECT_NAME_NOT_FOUND)
14: 12/16/2024-22:22:03.1055746 imp_WdfRegistryQueryULong - WDFKEY 000066F77E306C98, QueryULong, 0xc0000034(STATUS_OBJECT_NAME_NOT_FOUND)
15: 12/16/2024-22:22:03.1055746 imp_WdfRegistryQueryULong - WDFKEY 000066F77E306C98, QueryULong, 0xc0000034(STATUS_OBJECT_NAME_NOT_FOUND)
16: 12/16/2024-22:22:03.1055746 imp_WdfRegistryQueryULong - WDFKEY 000066F77E306C98, QueryULong, 0xc0000034(STATUS_OBJECT_NAME_NOT_FOUND)
17: 12/16/2024-22:22:05.8643064 FxWmiIrpHandler::Dispatch - WDFDEVICE 0x000066F77E299848 !devobj 0xFFFF9908819F52C0 IRP_MJ_SYSTEM_CONTROL, 0x0000000b(IRP_MN_REGINFO_EX) IRP 0xFFFF99088346E010

Most of the SerCx2 entries are logged before RhProxy does anything,and it looks like there are a number of queries returning STATUS_OBJECT_NAME_NOT_FOUND. Again, I really don't know the significance of these.

Finally, what about Intel's SerCx2 controller driver? Intel's SerCx2 controller seems to be pretty noisy with power messages, and the log has apparently wrapped quite a few times by my driver has loaded. Nothing really jumps out at me in this log at all, but I can paste in the 80 or so lines of the log if anyone suspects it might be helpful.

2

DSDT manipulations delve deep into black magic and there are twisty passages I still don't grasp, but your declarations look like you are declaring a single UART twice. If BLIP is USING the UART, then it shouldn't be declares AS a UART, should it?

3

What Mr. @Tim_Roberts said.

Now, I haven't used SerCx2... but I have used the SPB controller extensions that require ASL. I think you're working too hard... The UART is already described by the vendor, you just want to describe to ACPI (and by extension the Resource Hub) your dedicated use of a given UART.

Isn't that what's described here?
Device Interface Publication for a SerCx or SerCx2 Managed Serial Port - Windows drivers | Microsoft Learn

4

I can tell you what I understand of this, but it's shaky knowledge. Thanks for your replies here, though -- the act of posting this response may have led to a less complex way forward.

ACPI

It'd be swell if there was a sample SerCx2 peripheral driver somewhere that went into more of the specifics about ACPI. Microsoft offers a good walk-through of declaring resources for the resource hub proxy here, but is a little hand-wavy about how to make use of those bus declarations in ACPI. I followed the guidance provided there to set the RHPX device up with a single UartSerialBus declared.

The first sentence on that page under the UART section says "If your UART driver used SerCx or SerCx2, you can use rhproxy to expose the driver to user mode," by the way -- I'll have more to say on this in a bit.

Note that my ACPI doesn't really declare the UART at all: that's already in the vendor's ACPI as device _SB.PC00.UA00. The _CRS in the ACPI says that this is a resource used by the device being defined.

The RHPX device uses the \\_SB.PC00.UA00 resource -- and most of its settings don't matter in this context. The BLIP device uses the \\_SB.RHPX resource at index 0, and will override the settings used in the UART resource it holds there.

The idea, I guess, is that Microsoft's rhproxy driver will hold this collection of ACPI-declared resources that can then be accessed by either kernel or user mode drivers, through a connection ID.

SerCx2 Peripheral Driver

The page on device interface publication I'd read as being designed for exposing SerCx2 UARTs to user mode applications. The second paragraph on that page says "This is as opposed to accessing the SerCx/SerCx2 controller via a connection ID -- which exclusively enables access to the UART from a dedicated peripheral driver."

Which is what I thought I wanted.

I'm writing a SerCx2 peripheral driver using UMDF2, so I read through the information about connection IDs and connecting a KMDF peripheral driver to a serial port (since UMDF2 is thankfully closer to KMDF than UMDF), and adapted the sample code there.

And that truly is a great many hoops to jump through for a chip that I already know is hardwired to a particular UART.

A New Hope?

Now, to revisit that "If your UART driver used SerCx or SerCx2, you can use rhproxy to expose the driver to user mode" statement from this page... the very next sentence reads "UART drivers that create a device interface of type GUID_DEVINTERFACE_COMPORT do not need to use rhproxy."

Having read and re-read these pages over the last week or two, I find details I previously missed. I already know how to expose the UART via GUID_DEVINTERFACE_COMPORT, and I'm using a hardcoded version of that to proceed with my work right now. I strongly suspect that since that GUID is relatively recent, Microsoft's rhproxy-based examples are simply stale.

I'll need to experiment with it, but I think I can define my device object, add \\_SB.PC00.UA00 as a resource directly, then expose it with a _DSD giving it a name that implies nothing about which UART it's connected to (BLIPPORT0, for instance). This should make connecting from the driver straightforward, while allowing some future board spin to change the underlying connection with an ACPI tweak rather than a new driver.

Which does nothing to answer the question I posed here to start with, but if it works I can't imagine why I'd care. :slight_smile: