G
gyroblau
Guest
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: Built-In Trace Scenarios - Message Analyzer
(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
Continue reading...
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: Built-In Trace Scenarios - Message Analyzer
(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
Continue reading...