The infamous SSPI Failed error strikes again!

One of our SQL servers was generating these errors for “some” Windows logins but not all.

Error: 17806, Severity: 20, State: 2.

SSPI handshake failed with error code 0x8009030c while establishing a connection with integrated security; the connection has been closed. [CLIENT: 192.168.1.1]

Error: 18452, Severity: 14, State: 1.

Login failed for user ”. The user is not associated with a trusted SQL Server connection. [CLIENT: 192.168.1.1]

After exhausting all of the normal troubleshooting for this error (accounts locked, disabled, Sql Service accts, bad connection strings, SPN’s, etc.) I spent the next few hours learning more about the way SQL handles authentication requests than I had ever wanted to know.

The Scenario –

A couple of separate individual Windows ID’s started generating these errors while attempting connections, all other windows logins were working properly. The connections were initially happening through applications, but also occurred through sqlcmd. When logged in to the server locally with the offending ID’s the connections to SQL would succeed.

The Troubleshooting process –

Check all the regular SSPI issues, I wont bore you with the details as they are easily searchable

  • A relatively easy way of checking the “easy” authentication issues If possible/appropriate is to log into the SQL Server locally with the offending ID and fire up sqlcmd and connect to the server via sqlcmd –Sservername,port –E  (by specifying the port you force TCP/IP instead of LPC, thereby forcing the network into the equation)

Verify whether the login is trying to use NTLM or Kerberos (many ways to do this but simplest is to see if there are any other KERBEROS connections on the machine)

  • SELECT DISTINCT auth_scheme FROM sys.dm_exec_connections
  • If Kerberos is in use, there are a few additional things to verify related to SPN’s, since only NTLM was in use on this server I skipped that

Determine if the accounts were excluded from connecting to the machine through the network through a group policy or some other AD setting

After all of these checked out OK, I began to try and figure out what the error code 0x8009030c meant, turns out, its fairly obvious what the description is : sec_e_logon_denied.  This description was so helpful I thought about making this server into a boat anchor but, luckily for my employer the server room is located many miles away and has armed guards.

Since I knew we could logon locally to the SQL Server with the ID that SQL was rejecting with logon denied something else was trying to make my life miserable.

We didn’t have logon failure security auditing turned on so, I had no way of getting a better error description, As luck would have it though this would prove instrumental in finding the root cause. To get a better error message, I found this handy KB article detailing steps needed to put net logon into debug mode.

Say hello to my new best friend!  — nltest.exe

After downloading nltest & using it to enable netlogon debugging on the SQL Server, I got this slightly better message in the netlogon.log file

06/15 14:15:39 [LOGON] SamLogon: Network logon of DOMAIN\USER from Laptop Entered

06/15 14:15:39 [CRITICAL] NlPrintRpcDebug: Couldn’t get EEInfo for I_NetLogonSamLogonEx: 1761 (may be legitimate for 0xc0000064)

06/15 14:15:39 [LOGON] SamLogon: Network logon of DOMAIN\USER from Laptop Returns 0xC0000064

The error code 0XC0000064 maps to “NO_SUCH_USER”

Since I was currently logged in to the server with the ID that was returning no such user, something else was obviously wrong, and luckily at this point I knew it wasn’t SQL.

Running “set log” on the server revealed that a local DC (call it DC1) was servicing the local logon request.

After asking our AD guys about DC1 and its synchronization status, as well as whether the user actually existed there, everything still looked OK.

After looking around a bit more I discovered this gem of a command for nltest to determine which DC will handle a logon request

C:\>nltest /whowill:Domain Account

[16:32:45] Mail message 0 sent successfully (\MAILSLOT\NET\GETDC579)
[16:32:45] Response 0: DC2 D:Domain A:Account (Act found)
The command completed successfully

Even though this command returned “act found” it was returning from DC2.  (I dont exactly understand why the same account would authenticate against 2 different DC’s based on a local desktop login or a SQL login but it apparently can)

After asking the AD guys about DC2 the light bulbs apparently went off for them as that server actually exists behind a different set of firewalls, in a totally different location. While DC2 would return a ping, the console wouldn’t allow logons for some reason. After a quick reboot of DC2, and some magic AD pixie dust (I am not an AD admin, if it wasn’t totally obvious from my newfound friend nltest) the windows Id’s that were having trouble started authenticating against DC3 and our SSPI errors went away.

Interesting tidbit — During troubleshooting, I found that this particular SQL Server was authenticating accounts against at least 5 different DC’s. Some of this might be expected since there are different domains at play but, I haven’t heard a final answer from the AD guys about whether it should work that way.

The solution

Reboot the misbehaving DC, of course there may be other ways to fix this by redirecting requests to a different DC without a reboot but, since it was misbehaving anyway, and the AD experts wanted to reboot so we went with that. A reboot of SQL would have likely solved this problem too but, I hate reboot fixes of issues, they always seem to come back!