In apps that we have in our company, we use impersonation to do a number of things. We have been doing it the same way for many years. As of a couple of weeks ago, we started seeing forced debug output when calling any version of LogonUser from advapi32.dll.
That is, when calling any version of LogonUser, we are immediately bombarded with output that gets dumped to console or our log files. We cannot prevent the dump, and we see no way of intercepting it. Here is a sample of the output we see with each request:
11/20/2019 04:42:27.072 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(2) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: Informing Windows we are a Credential Manager
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(2) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(4) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: Informing Windows we don't support the requested feature
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(4) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(6) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: Informing Windows we don't support the requested feature
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(6) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(11) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: Informing Windows we don't support the requested feature
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(11) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(9) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: Informing Windows we don't support the requested feature
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(9) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(8) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: Informing Windows we don't support the requested feature
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> NetworkProvider.Debug: NPGetCaps(8) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> CredentialManager.Debug: NPLogonNotify({****, ****}, 'MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********, 'SvcCtl', nullptr, 0x********) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackagePair.Debug: AuthPackagePair::AuthPackagePair('MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********) Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackagePair.Debug: AuthPackagePair::AuthPackagePair('MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********) Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> CredentialManager.Debug: Validated supplied credential package; delegating to appropriate handler
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: netprov::raise_logon_complete() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Activity: Received notification of Interactive account log-on
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: AccountLogonEventHandler::on_auth_complete() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Debug: Querying whether to communicate with business logic...
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::AuthPackageProperties() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: Determining whether username contains a domain name...
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::AuthPackageProperties() Exited
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_domain_account() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_local_account() Entered
11/20/2019 04:42:27.074 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: Determining whether supplied domain-name represents a domain or computer name
11/20/2019 04:42:27.075 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_local_account() Exited
11/20/2019 04:42:27.075 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_domain_account() Exited
11/20/2019 04:42:27.075 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Activity: Network provider is enabled; notifying the business logic
11/20/2019 04:42:27.075 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Debug: Transmitting information to business logic
11/20/2019 04:42:27.075 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Debug: Requesting COM interface from business logic
11/20/2019 04:42:27.084 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: AccountLogonEventHandler::on_auth_complete() Exited
11/20/2019 04:42:27.084 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: netprov::raise_logon_complete() Exited
11/20/2019 04:42:27.084 AM TestConsoleApp(26668,26672) <my_ID> CredentialManager.Debug: NPLogonNotify({****, ****}, 'MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********, 'SvcCtl', nullptr, 0x********) Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> CredentialManager.Debug: NPLogonNotify({****, ****}, 'MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********, 'SvcCtl', nullptr, 0x********) Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackagePair.Debug: AuthPackagePair::AuthPackagePair('MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********) Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> InteractiveAuthPackage.Debug: InteractiveAuthPackage::InteractiveAuthPackage() Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackagePair.Debug: AuthPackagePair::AuthPackagePair('MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********) Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> CredentialManager.Debug: Validated supplied credential package; delegating to appropriate handler
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: netprov::raise_logon_complete() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Activity: Received notification of Interactive account log-on
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: AccountLogonEventHandler::on_auth_complete() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Debug: Querying whether to communicate with business logic...
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::AuthPackageProperties() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: Determining whether username contains a domain name...
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::AuthPackageProperties() Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_domain_account() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_local_account() Entered
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: Determining whether supplied domain-name represents a domain or computer name
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_local_account() Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> AuthPackageProperties.Debug: AuthPackageProperties::is_domain_account() Exited
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Activity: Network provider is enabled; notifying the business logic
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Debug: Transmitting information to business logic
11/20/2019 04:42:27.127 AM TestConsoleApp(26668,26672) <my_ID> ServiceCommsChannel.Debug: Requesting COM interface from business logic
11/20/2019 04:42:27.128 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: AccountLogonEventHandler::on_auth_complete() Exited
11/20/2019 04:42:27.128 AM TestConsoleApp(26668,26672) <my_ID> AccountLogonEventHandler.Debug: netprov::raise_logon_complete() Exited
11/20/2019 04:42:27.128 AM TestConsoleApp(26668,26672) <my_ID> CredentialManager.Debug: NPLogonNotify({****, ****}, 'MSV1_0:Interactive', 0x********, 'MSV1_0:Interactive', 0x********, 'SvcCtl', nullptr, 0x********) Exited
We kicked it over to our IT department, but we can't find anyone that knows what changed with any recent updates. The above happens with any combination of logon type and logon provider. The output is exactly as it is presented to us, with the exception of me replacing my own ID with my_ID on each line.
This is nothing we specifically request in any way and Googling any part of each of the lines didn't seem to yield any information. Would anyone know the cause of these messages (setting in Windows, Active Directory, something else)? The CredentialManager lines stand out, but I couldn't find anything relating to Credential Manager kicking out this information.
We were thinking maybe it was a setting that could be enabled somewhere for some back-end troubleshooting and was left on or maybe it was a setting pushed out to all of our machines with the latest round of updates, but we really have no idea.
Any help would be appreciated!
These are not Windows debug entries of any form. None of these text lines match anything Windows will ever write to an internal debug trace or external log (or at least, not as of any recent Win 10 release).
As such I would expect this to be a third party security plugin. I'd take a look at what DLLs are loaded into lsass.exe or your process that aren't signed by Microsoft, or have your app's metadata.