none
ndisAddDevice returns status 0xc00002f0=STATUS_OBJECTID_NOT_FOUND RRS feed

  • Question

  • Hi from Germany,

    we have an NDIS 5.1 intermediate (mux) driver running on Windows 8.1 x86.

    The driver is a combined miniport and protocol driver.
    The driver binds to two physical network adapters and then establishes a virtual adapter which represents this pair of NICs (the purpose for this architecture is redundancy).
    The driver worked as expected over several months. But sometimes after a system reboot it happens that the virtual adapter is not able to start.
    Device manager shows an exclamation mark and the error message: "Code 31. An Object ID was not found in the file."

    So far we tried to analyze this problem by capturing traces: from our driver itself and from NDIS.
    Our analysis showed that the problem seems to be caused by NDIS itself and not by our driver.
    Details are given below.
    (A) Debug traces from our intermediate mux driver:

    In the failure case we see the following sequence of actions in our driver:
    1) DriverEntry gets called and returns STATUS_SUCCESS.
    2) ProtocolBindAdapter gets called for the first NIC, opens the NIC, and returns NDIS_STATUS_SUCCESS.
    3) ProtocolBindAdapter gets called for the second NIC, opens the NIC, and calls NdisIMInitializeDeviceInstanceEx which returns NDIS_STATUS_SUCCESS. ProtocolBindAdapter returns NDIS_STATUS_SUCCESS.
    4) ProtocolPnPEventHandler gets called with NetEventBindsComplete, the driver returns NDIS_STATUS_SUCCESS.
    5) DriverUnload gets called. This is unexpected. In the working case, the driver receives a MiniportInitialize call at this point.
     
    (B) Debug traces from NDIS
    We captured NDIS traces from the error and working case according to the instructions available here: https://docs.microsoft.com/en-us/message-analyzer/built-in-trace-scenarios

    (1) Debug trace from NDIS in the failure case:
    ----------------------------------------------
    The trace shows some lines of particular interest:
    - NDIS receives an AddDevice call for PDO 8029AF10 which is our virtual adapter.
    - some components(?) start creating bindings for our miniport instance (for which the AddDevice call is not finished yet).
     "Unbinding this protocol because the underlying miniport is not ready to accept bindings [TCPIP <-> miniport 89721240]"
     "Old UnbindReasons: (0x0); new UnbindReasons: Reason_MiniportNotReady(0x20000)"
    - the ndisAddDevice call completes with status 0xc00002f0 which leads to error code 31 in device manager. From the messages prior to this point it is not clear what causes ndisAddDevice to fail.

    [1]0004.010C::04/27/2018-12:14:05.239 [mp]==>ndisAddDevice: PDO 8029AF10
    [1]0004.010C::04/27/2018-12:14:05.239 [mp]ndisQueryDeviceFlags: Device flags for nm_Iec62439_mp_{047e7a79-7427-41a7-92c1-62a37a9eafcb} = 0 (0xc0000225(STATUS_NOT_FOUND)).
    [1]0004.010C::04/27/2018-12:14:05.239 [mp]==>ndisCreateAdapterInstanceName: PDO 8029AF10
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]ndisCreateAdapterInstanceName: Iec62439 Adapter
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]ndisCreateAdapterInstanceName: couldn't get SlotNumber for Iec62439 Adapter
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisCreateAdapterInstanceName: PDO 8029AF10, Status 0x0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]ndisAddDevice: Miniport 89721240, Iec62439 Adapter
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisInitializeConfiguration: Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisReadBindPaths: Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisReadBindPaths: Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisReadOffloadRegistry: Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisOpenConfigurationEx: ConfigObject 895E7510
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisOpenConfiguration: WrapperConfigurationContext 896C2758
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisOpenConfiguration: WrapperConfigurationContext 896C2758
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisOpenConfigurationEx: ConfigObject 895E7510, Status 0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisCloseConfiguration: ConfigurationHandle 899BBD30
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisCloseConfiguration: ConfigurationHandle 00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisReadOffloadRegistry: Miniport 89721240, Status c0000001, Registry 20000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisInitializeConfiguration: Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisOpenConfigurationEx: ConfigObject 895E75F0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisOpenConfiguration: WrapperConfigurationContext 896C2758
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisOpenConfiguration: WrapperConfigurationContext 896C2758
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisOpenConfigurationEx: ConfigObject 895E75F0, Status 0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisReadConfiguration: Keyword: *NumaNodeId
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisReadConfiguration
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisCloseConfiguration: ConfigurationHandle 899BBD30
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisCloseConfiguration: ConfigurationHandle 00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisOpenConfigurationEx: ConfigObject 895E75F0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisOpenConfiguration: WrapperConfigurationContext 896C2758
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisOpenConfiguration: WrapperConfigurationContext 896C2758
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisOpenConfigurationEx: ConfigObject 895E75F0, Status 0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>NdisCloseConfiguration: ConfigurationHandle 899BBD30
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==NdisCloseConfiguration: ConfigurationHandle 00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [TCPIP <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [RASPPPOE <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [RDMANDK <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [MSLLDP <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [NDISUIO <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [LLTDIO <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old BindSources: (0x0); new BindSources: (0x1)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Creating this binding because it is statically-defined in the registry [RSPNDR <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old UnbindReasons: Reason_DriverNotReady(0x2); new UnbindReasons: (0x0)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Enabling protocol binding, because the protocol driver is now loaded and ready [TCPIP <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old UnbindReasons: Reason_DriverNotReady(0x2); new UnbindReasons: (0x0)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Enabling protocol binding, because the protocol driver is now loaded and ready [LLTDIO <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old UnbindReasons: Reason_DriverNotReady(0x2); new UnbindReasons: (0x0)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Enabling protocol binding, because the protocol driver is now loaded and ready [RSPNDR <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old UnbindReasons: (0x0); new UnbindReasons: Reason_MiniportNotReady(0x20000)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Unbinding this protocol because the underlying miniport is not ready to accept bindings [TCPIP <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old UnbindReasons: (0x0); new UnbindReasons: Reason_MiniportNotReady(0x20000)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Unbinding this protocol because the underlying miniport is not ready to accept bindings [LLTDIO <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Old UnbindReasons: (0x0); new UnbindReasons: Reason_MiniportNotReady(0x20000)
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Unbinding this protocol because the underlying miniport is not ready to accept bindings [RSPNDR <-> miniport 89721240]
    [1]0004.010C::04/27/2018-12:14:05.240 [km]Begin PNP operations on miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisIfQueryBindingMiniportIfIndex, Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisIfQueryBindingMiniportIfIndex, Miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [km]End PNP operations on miniport 89721240
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]ndisReferenceProtocol[14]: Protocol: 895E75FC, RefCount: 4, Closing: 0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==> ndisNotifyBindFailure: Miniport 89721240, Protocol 89EC6720
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisDeliverNetPnPEventSynchronously: Protocol 89EC6720, Open 00000000, NetEvent 10
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]>Begin protocol driver's NetPnPEventHandler. Protocol=89EC6720, Open=00000000, Event=16
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<End protocol driver's NetPnPEventHandler.   Protocol=89EC6720, Open=00000000, Event=16, Status=0x00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisDeliverNetPnPEventSynchronously: Protocol 89EC6720, Open 00000000, NetEvent 10, Status 0x00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<== ndisNotifyBindFailure: Miniport 89721240, Protocol 89EC6720
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisDereferenceProtocol[14]: Protocol 89EC6720,  RefCount: 3
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisDereferenceProtocol: Protocol 89EC6720
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]ndisReferenceProtocol[14]: Protocol: 895E75FC, RefCount: 4, Closing: 0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==> ndisNotifyBindFailure: Miniport 89721240, Protocol A52039D8
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisDeliverNetPnPEventSynchronously: Protocol A52039D8, Open 00000000, NetEvent 10
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]>Begin protocol driver's NetPnPEventHandler. Protocol=A52039D8, Open=00000000, Event=16
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<End protocol driver's NetPnPEventHandler.   Protocol=A52039D8, Open=00000000, Event=16, Status=0x00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisDeliverNetPnPEventSynchronously: Protocol A52039D8, Open 00000000, NetEvent 10, Status 0x00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<== ndisNotifyBindFailure: Miniport 89721240, Protocol A52039D8
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisDereferenceProtocol[14]: Protocol A52039D8,  RefCount: 3
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisDereferenceProtocol: Protocol A52039D8
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]ndisReferenceProtocol[14]: Protocol: 895E75FC, RefCount: 4, Closing: 0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==> ndisNotifyBindFailure: Miniport 89721240, Protocol A5260910
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisDeliverNetPnPEventSynchronously: Protocol A5260910, Open 00000000, NetEvent 10
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]>Begin protocol driver's NetPnPEventHandler. Protocol=A5260910, Open=00000000, Event=16
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<End protocol driver's NetPnPEventHandler.   Protocol=A5260910, Open=00000000, Event=16, Status=0x00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisDeliverNetPnPEventSynchronously: Protocol A5260910, Open 00000000, NetEvent 10, Status 0x00000000
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<== ndisNotifyBindFailure: Miniport 89721240, Protocol A5260910
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisDereferenceProtocol[14]: Protocol A5260910,  RefCount: 3
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisDereferenceProtocol: Protocol A5260910
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisAddDevice: Miniport 00000000, Status c00002f0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]<==ndisPnPAddDevice: PDO 8029AF10, Status c00002f0
    [1]0004.010C::04/27/2018-12:14:05.240 [mp]==>ndisMUnload: DriverObject 8972A5E0


    (2) Debug trace from NDIS in the working case:
    ----------------------------------------------

    Here the following line numbers are of interest:
    - NDIS receives an AddDevice call for PDO BA332600which is our virtual adapter.
    - Up to this point the messages are very similar to the error case. But in contrast to the error case at this point there are no messages talking about bindings to be created.
    - ndisAddDevice completes returning STATUS_SUCCESS.
    [0]0004.0108::04/27/2018-12:19:50.331 [mp]==>ndisAddDevice: PDO BA332600
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]ndisQueryDeviceFlags: Device flags for nm_Iec62439_mp_{047e7a79-7427-41a7-92c1-62a37a9eafcb} = 0 (0xc0000225(STATUS_NOT_FOUND)).
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisCreateAdapterInstanceName: PDO BA332600
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]ndisCreateAdapterInstanceName: Iec62439 Adapter
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]ndisCreateAdapterInstanceName: couldn't get SlotNumber for Iec62439 Adapter
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisCreateAdapterInstanceName: PDO BA332600, Status 0x0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]ndisAddDevice: Miniport 8FC5A240, Iec62439 Adapter
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisInitializeConfiguration: Miniport 8FC5A240
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisReadBindPaths: Miniport 8FC5A240
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisReadBindPaths: Miniport 8FC5A240
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisReadOffloadRegistry: Miniport 8FC5A240
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisOpenConfigurationEx: ConfigObject 895D5510
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisOpenConfiguration: WrapperConfigurationContext 896F1978
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisOpenConfiguration: WrapperConfigurationContext 896F1978
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisOpenConfigurationEx: ConfigObject 895D5510, Status 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisCloseConfiguration: ConfigurationHandle 92AAA388
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisCloseConfiguration: ConfigurationHandle 00000000
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisReadOffloadRegistry: Miniport 8FC5A240, Status c0000001, Registry 20000
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisInitializeConfiguration: Miniport 8FC5A240
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisOpenConfigurationEx: ConfigObject 895D55F0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisOpenConfiguration: WrapperConfigurationContext 896F1978
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisOpenConfiguration: WrapperConfigurationContext 896F1978
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisOpenConfigurationEx: ConfigObject 895D55F0, Status 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisReadConfiguration: Keyword: *NumaNodeId
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisReadConfiguration
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisCloseConfiguration: ConfigurationHandle 92AAA388
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisCloseConfiguration: ConfigurationHandle 00000000
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisOpenConfigurationEx: ConfigObject 895D55F0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisOpenConfiguration: WrapperConfigurationContext 896F1978
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisOpenConfiguration: WrapperConfigurationContext 896F1978
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisOpenConfigurationEx: ConfigObject 895D55F0, Status 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>NdisCloseConfiguration: ConfigurationHandle 92AAA388
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==NdisCloseConfiguration: ConfigurationHandle 00000000
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisIfUpdateInterfaceOnAddDevice IfBlock 8982DA78 Miniport 8FC5A240
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisNsiNotifyClientInterfaceChange, IfBlock 8982DA78, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisNsiClientParameterChangeHandler, CallerContext 00000000, KeyStructDesc 895D55C4, ParamDesc 895D55CC, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]ndisNsiClientParameterChangeHandler, interface change notification, interface IfType 6, NetLuid index 24, ParamDesc.   StructType 0, ParameterLength 4, ParameterOffset 10
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisNsiClientParameterChangeHandler, CallerContext 00000000, KeyStructDesc 895D55C4, ParamDesc 895D55CC, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisNsiNotifyClientInterfaceChange, IfBlock 8982DA78, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisNsiNotifyClientInterfaceChange, IfBlock 8982DA78, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]==>ndisNsiClientParameterChangeHandler, CallerContext 00000001, KeyStructDesc 895D55A4, ParamDesc 895D55AC, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]ndisNsiClientParameterChangeHandler, interface change notification, interface IfType 6, NetLuid index 24
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisNsiClientParameterChangeHandler, CallerContext 00000001, KeyStructDesc 895D55A4, ParamDesc 895D55AC, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisNsiNotifyClientInterfaceChange, IfBlock 8982DA78, NotificationType 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]<==ndisIfUpdateInterfaceOnAddDevice IfBlock 8982DA78 Miniport 8FC5A240 Status 0
    [0]0004.0108::04/27/2018-12:19:50.332 [mp]Device Added: Miniport 8FC5A240, Iec62439 Adapter


    My questions are:
     
    Why does ndisAddDevice fail in (1)?
    The bindings in (1) occur at the same time of the starting process of our protocol and miniport.
    Why does NDIS trace:
     "Unbinding this protocol because the underlying miniport is not ready to accept bindings [TCPIP <-> miniport 89721240]"
     "Old UnbindReasons: (0x0); new UnbindReasons: Reason_MiniportNotReady(0x20000)"

    The trace messages do not indicate a reason for this. Our intermediate driver should not be responsible for this failure because it's no involved in the ndisAddDevice handling.

    Unfortunately this is a serious customer problem.
    Thanks a lot for every help or hint!
    Carsten
    Monday, March 30, 2020 10:50 AM

Answers

  • Hi from the USA.

    That's an odd trace.  At a high level, miniport drivers start up in two phases:

    1. AddDevice
    2. IRP_MN_START_DEVICE / MiniportInitialize

    This state machine is driven from PNP, since PNP owns the lifetime of all device objects.  For IM drivers, however, we want to delay step 2 until after you've called NdisIMInitializeDeviceInstanceEx.

    This means that if you haven't called that routine yet, NDIS will actually fake the completion of the IRP_MN_START_DEVICE, and postpone its processing until you do call NdisIMInitializeDeviceInstanceEx.  So there is some nondeterminism in the life of an IM driver's miniport device.  NdisIMInitializeDeviceInstanceEx can be interleaved anywhere around those 2 PNP steps listed above, so you can legitimately have any of these three orderings of events:

    a: NdisIMInitializeDeviceInstanceEx, AddDevice, MiniportInitialize
    b: AddDevice, NdisIMInitializeDeviceInstanceEx, MiniportInitialize
    c: AddDevice, MiniportInitialize, NdisIMInitializeDeviceInstanceEx

    That is one of the major sources of nondeterminism in the startup of IM miniports, so it wouldn't surprise me if it explains why you're seeing nondeterministic success/failure.

    It's strange that you see a bunch of chatter about bindings, interleaved with AddDevice.  Bindings are one of the last things to be initialized - they happen late in step 2.  Notably, they happen *after* NDIS has called into your MiniportInitialize handler.  Also notably, NDIS does not fail the whole NIC just because one of the bindings above it fails to bind.  NICs can operate without any bindings.  So I wouldn't expect binding failures to cause AddDevice to fail.

    So, what to do?  My first guess -- low chance of success, but very easy to check -- is to verify your miniport's INF has an IMMiniport line in it:

    HKR,               , IMMiniport, 0x00010001, 1
    HKR, Ndi\Interfaces, UpperRange, 0,          "ndis5"
    

    Without that, NDIS won't realize that this device is for an IM driver, and won't properly wait for the NdisIMInitializeDeviceInstanceEx call.

    Since you're using NDIS 5.x, also make sure you're calling NdisIMRegisterLayeredMiniport instead of NdisMRegisterMiniport.

    Historically, the *main* reason I've seen AddDevice return STATUS_OBJECTID_NOT_FOUND is because the miniport wasn't properly installed.  When a miniport is first installed, usermode does a bit of work to assign it a name, NetLuid, guid, etc., then write all that to the registry.  If the registry doesn't have that info, NDIS will return this status code from ndisAddDevice.  However, I've always seen this as a deterministic failure: if the miniport isn't in the registry, it won't be in the registry no matter how many times you reboot.  So I'm skeptical that this is the problem here.  But let's check anyway.

    If you've got a kd, try setting a breakpoint on ndis!ndisIfFindInterfaceByNetLuid.  If that returns NULL, then we've hit this failure.  In the debugger, that's

    bp ndis!ndisIfFindInterfaceByNetLuid "gu; r eax"

    If it reports that EAX is 0, then the function failed to read the miniport from the registry.  Note that NDIS is likely going to load multiple miniports at boot, so you might have to repeat the exercise until you hit yours.

    You can also double-check that your miniport is installed by running !ndiskd.interfaces to see what network interfaces are known to NDIS, and see if your IM driver's miniport is listed, and what its NetLuid is.

    More generically, you can try playing with timings to see if this is indeed caused by some race.  For example, you might delay the call to NdisIMInitializeDeviceInstanceEx by 60 seconds (queue a timer + workitem), to see if that makes the outcome more deterministic.  If it starts deterministically failing or succeeding, then that tells us it really is something to do with the order of events.

    Monday, March 30, 2020 7:29 PM
  • Hi Jeffrey,
    whow, what a great and detailed answer. Thanks you very much!!
    Unfortunately, the customer has changed the hardware and now the error occurs once in 2 months (with daily restart of the computers).
    So we are not able to see the success of changes quickly.

    I have checked the suggestions from you:

    Yes, we are calling NdisIMRegisterLayeredMiniport (instead of NdisMRegisterMiniportNdisIMRegisterLayeredMiniport).

    No, our INF file does not contain
    HKR,               , IMMiniport, 0x00010001, 1

    What we will do is extending the INF with IMMiniport and see what happens.

    Changing the old driver (with delaying the call to NdisIMInitializeDeviceInstanceEx) is not an option for the product owner, because that would mean a new detailed product test.

    Another solution will be updating the customers product with the actual version.
    The actual version has an NDIS 6.2 intermediate driver and I guess, the chance is pretty high, that the error will not occur here.

    Once again, thanks a lot!

    Carsten
    Friday, April 3, 2020 9:41 AM

All replies

  • Hi from the USA.

    That's an odd trace.  At a high level, miniport drivers start up in two phases:

    1. AddDevice
    2. IRP_MN_START_DEVICE / MiniportInitialize

    This state machine is driven from PNP, since PNP owns the lifetime of all device objects.  For IM drivers, however, we want to delay step 2 until after you've called NdisIMInitializeDeviceInstanceEx.

    This means that if you haven't called that routine yet, NDIS will actually fake the completion of the IRP_MN_START_DEVICE, and postpone its processing until you do call NdisIMInitializeDeviceInstanceEx.  So there is some nondeterminism in the life of an IM driver's miniport device.  NdisIMInitializeDeviceInstanceEx can be interleaved anywhere around those 2 PNP steps listed above, so you can legitimately have any of these three orderings of events:

    a: NdisIMInitializeDeviceInstanceEx, AddDevice, MiniportInitialize
    b: AddDevice, NdisIMInitializeDeviceInstanceEx, MiniportInitialize
    c: AddDevice, MiniportInitialize, NdisIMInitializeDeviceInstanceEx

    That is one of the major sources of nondeterminism in the startup of IM miniports, so it wouldn't surprise me if it explains why you're seeing nondeterministic success/failure.

    It's strange that you see a bunch of chatter about bindings, interleaved with AddDevice.  Bindings are one of the last things to be initialized - they happen late in step 2.  Notably, they happen *after* NDIS has called into your MiniportInitialize handler.  Also notably, NDIS does not fail the whole NIC just because one of the bindings above it fails to bind.  NICs can operate without any bindings.  So I wouldn't expect binding failures to cause AddDevice to fail.

    So, what to do?  My first guess -- low chance of success, but very easy to check -- is to verify your miniport's INF has an IMMiniport line in it:

    HKR,               , IMMiniport, 0x00010001, 1
    HKR, Ndi\Interfaces, UpperRange, 0,          "ndis5"
    

    Without that, NDIS won't realize that this device is for an IM driver, and won't properly wait for the NdisIMInitializeDeviceInstanceEx call.

    Since you're using NDIS 5.x, also make sure you're calling NdisIMRegisterLayeredMiniport instead of NdisMRegisterMiniport.

    Historically, the *main* reason I've seen AddDevice return STATUS_OBJECTID_NOT_FOUND is because the miniport wasn't properly installed.  When a miniport is first installed, usermode does a bit of work to assign it a name, NetLuid, guid, etc., then write all that to the registry.  If the registry doesn't have that info, NDIS will return this status code from ndisAddDevice.  However, I've always seen this as a deterministic failure: if the miniport isn't in the registry, it won't be in the registry no matter how many times you reboot.  So I'm skeptical that this is the problem here.  But let's check anyway.

    If you've got a kd, try setting a breakpoint on ndis!ndisIfFindInterfaceByNetLuid.  If that returns NULL, then we've hit this failure.  In the debugger, that's

    bp ndis!ndisIfFindInterfaceByNetLuid "gu; r eax"

    If it reports that EAX is 0, then the function failed to read the miniport from the registry.  Note that NDIS is likely going to load multiple miniports at boot, so you might have to repeat the exercise until you hit yours.

    You can also double-check that your miniport is installed by running !ndiskd.interfaces to see what network interfaces are known to NDIS, and see if your IM driver's miniport is listed, and what its NetLuid is.

    More generically, you can try playing with timings to see if this is indeed caused by some race.  For example, you might delay the call to NdisIMInitializeDeviceInstanceEx by 60 seconds (queue a timer + workitem), to see if that makes the outcome more deterministic.  If it starts deterministically failing or succeeding, then that tells us it really is something to do with the order of events.

    Monday, March 30, 2020 7:29 PM
  • Hi Jeffrey,
    whow, what a great and detailed answer. Thanks you very much!!
    Unfortunately, the customer has changed the hardware and now the error occurs once in 2 months (with daily restart of the computers).
    So we are not able to see the success of changes quickly.

    I have checked the suggestions from you:

    Yes, we are calling NdisIMRegisterLayeredMiniport (instead of NdisMRegisterMiniportNdisIMRegisterLayeredMiniport).

    No, our INF file does not contain
    HKR,               , IMMiniport, 0x00010001, 1

    What we will do is extending the INF with IMMiniport and see what happens.

    Changing the old driver (with delaying the call to NdisIMInitializeDeviceInstanceEx) is not an option for the product owner, because that would mean a new detailed product test.

    Another solution will be updating the customers product with the actual version.
    The actual version has an NDIS 6.2 intermediate driver and I guess, the chance is pretty high, that the error will not occur here.

    Once again, thanks a lot!

    Carsten
    Friday, April 3, 2020 9:41 AM