Error: 18456, Severity: 14, State: 16.

[MicheleWeaver]

I am getting the error

Error: 18456, Severity: 14, State: 16.
Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]

in the log repeated every 15 seconds or so. I am logged into the server as pri\sqlservice, I have started the sql server and sql server agent with pri\sqlservice and I can access databases and tables inside the Server Management studio. I have set up the login pri\sqlservice and given it dbo owner access to all databases.

I am in the process of upgrading from 2000 to 2005. I have installed a new sql server 2005, restored backups of databases from 2000. I have also converted all packages and uploaded those to the new server (although they all point to the 2000 server). I have imported jobs and all are running fine.

I have researched and researched this issue, and none seem to apply to my specific issue.

This is an extract of my errorlog:

2006-12-20 16:23:16.95 Server Microsoft SQL Server 2005 - 9.00.1399.06 (Intel X86)
Oct 14 2005 00:33:37
Copyright (c) 1988-2005 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 1)

2006-12-20 16:23:16.98 Server (c) 2005 Microsoft Corporation.
2006-12-20 16:23:16.98 Server All rights reserved.
2006-12-20 16:23:16.98 Server Server process ID is 1780.
2006-12-20 16:23:16.98 Server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\ERRORLOG'.
2006-12-20 16:23:16.98 Server This instance of SQL Server last reported using a process ID of 4532 at 12/20/2006 4:23:52 PM (local) 12/20/2006 9:23:52 PM (UTC). This is an informational message only; no user action is required.
2006-12-20 16:23:16.98 Server Registry startup parameters:
2006-12-20 16:23:17.00 Server -d C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\master.mdf
2006-12-20 16:23:17.00 Server -e C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\ERRORLOG
2006-12-20 16:23:17.00 Server -l C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\mastlog.ldf
2006-12-20 16:23:17.23 Server SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2006-12-20 16:23:17.23 Server Detected 2 CPUs. This is an informational message; no user action is required.
2006-12-20 16:23:17.93 Server Set AWE Enabled to 1 in the configuration parameters to allow use of more memory.
2006-12-20 16:23:19.65 Server Using dynamic lock allocation. Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node. This is an informational message only. No user action is required.
2006-12-20 16:23:22.07 Server Attempting to initialize Microsoft Distributed Transaction Coordinator (MS DTC). This is an informational message only. No user action is required.
2006-12-20 16:23:23.21 Server Attempting to recover in-doubt distributed transactions involving Microsoft Distributed Transaction Coordinator (MS DTC). This is an informational message only. No user action is required.
2006-12-20 16:23:23.48 Server Database Mirroring Transport is disabled in the endpoint configuration.
2006-12-20 16:23:23.79 spid5s Starting up database 'master'.
2006-12-20 16:23:25.01 spid5s Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
2006-12-20 16:23:26.17 spid5s SQL Trace ID 1 was started by login "sa".
2006-12-20 16:23:26.37 spid5s Starting up database 'mssqlsystemresource'.
2006-12-20 16:23:27.93 spid9s Starting up database 'model'.
2006-12-20 16:23:27.95 spid5s Server name is 'KSDBT01'. This is an informational message only. No user action is required.
2006-12-20 16:23:29.06 spid9s Clearing tempdb database.
2006-12-20 16:23:29.54 Server A self-generated certificate was successfully loaded for encryption.
2006-12-20 16:23:29.62 Server Server is listening on [ 'any' <ipv4> 1433].
2006-12-20 16:23:29.62 Server Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\MSSQLSERVER ].
2006-12-20 16:23:29.62 Server Server local connection provider is ready to accept connection on [ \\.\pipe\sql\query ].
2006-12-20 16:23:29.64 Server Server is listening on [ 127.0.0.1 <ipv4> 1434].
2006-12-20 16:23:29.64 Server Dedicated admin connection support was established for listening locally on port 1434.
2006-12-20 16:23:29.68 Server SQL Server is now ready for client connections. This is an informational message; no user action is required.
2006-12-20 16:23:32.56 spid9s Starting up database 'tempdb'.
2006-12-20 16:23:32.67 spid13s Starting up database 'msdb'.
2006-12-20 16:23:32.67 spid12s Starting up database 'test'.
2006-12-20 16:23:32.67 spid14s Starting up database 'bravoAztecnology'.
2006-12-20 16:23:32.67 spid15s Starting up database 'bravoKNE'.
2006-12-20 16:23:32.67 spid16s Starting up database 'bravoKNS'.
2006-12-20 16:23:32.67 spid17s Starting up database 'bravoKNSBelgium'.
2006-12-20 16:23:32.68 spid18s Starting up database 'bravoKNSCanada'.
2006-12-20 16:23:32.68 spid19s Starting up database 'bravoKNSEngland'.
2006-12-20 16:23:34.79 spid20s The Service Broker protocol transport is disabled or not configured.
2006-12-20 16:23:34.81 spid20s The Database Mirroring protocol transport is disabled or not configured.
2006-12-20 16:23:35.01 spid12s Starting up database 'bravoKNSKennedy'.
2006-12-20 16:23:35.20 spid17s Starting up database 'bravoKNSSuperior'.
2006-12-20 16:23:35.35 spid13s Starting up database 'bravoKNSSuperiorSS'.
2006-12-20 16:23:35.48 spid19s Starting up database 'stamp'.
2006-12-20 16:23:35.83 spid20s Service Broker manager has started.
2006-12-20 16:23:38.59 spid14s Starting up database 'KNSSpecial'.
2006-12-20 16:23:39.31 spid18s Starting up database 'knsRPCS'.
2006-12-20 16:23:39.39 spid14s Analysis of database 'KNSSpecial' (16) is 100% complete (approximately 0 seconds remain). This is an informational message only. No user action is required.
2006-12-20 16:23:43.03 spid5s Recovery of any in-doubt distributed transactions involving Microsoft Distributed Transaction Coordinator (MS DTC) has completed. This is an informational message only. No user action is required.
2006-12-20 16:23:43.03 spid5s Recovery is complete. This is an informational message only. No user action is required.
2006-12-20 16:23:50.95 spid51 Using 'xpsqlbot.dll' version '2005.90.1399' to execute extended stored procedure 'xp_qv'. This is an informational message only; no user action is required.
2006-12-20 16:23:55.85 spid51 Using 'xpstar90.dll' version '2005.90.1399' to execute extended stored procedure 'xp_instance_regread'. This is an informational message only; no user action is required.
2006-12-20 16:23:57.10 spid51 Using 'xplog70.dll' version '2005.90.1399' to execute extended stored procedure 'xp_msver'. This is an informational message only; no user action is required.
2006-12-20 16:24:00.02 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:00.02 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:00.06 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:00.06 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:01.06 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:01.06 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:01.07 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:01.07 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:03.84 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:03.84 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:03.85 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:03.85 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:03.96 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:03.96 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:03.98 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:03.98 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:41.41 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:41.41 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]
2006-12-20 16:24:41.41 Logon Error: 18456, Severity: 14, State: 16.
2006-12-20 16:24:41.41 Logon Login failed for user 'PRI\sqlservice'. [CLIENT: 172.16.9.2]

 

[mrdenny]

Sounds like something is locking out the PRI\sqlservice account right after the SQL Server starts. Check the security logs on the DC to see what's going on.

Denny
MCSA (2003) / MCDBA (SQL 2000) / MCTS (SQL 2005) / MCITP Database Administrator (SQL 2005)

--Anything is possible. All it takes is a little research. (Me)

http://www.mrdenny.com

 

[Catadmin]

You say you are getting the error message in the log, yet you're able to access SQL Server just fine with that login. Does that mean, when the error messages are popping up that you're still in the system and still able to open tables? Or that after that error message comes up you've been kicked out?

You might want to also run Profiler against SQL to make sure the DBs don't have a running job or something which sets them to Single_User and kills your connection.

What permissions does the PRI\sqlservice account have in the Server? What permissions does it have in the domain? Was the SQL Server even built in the PRI domain?



Catadmin - MCDBA, MCSA
"No, no. Yes. No, I tried that. Yes, both ways. No, I don't know. No again. Are there any more questions?"
-- Xena, "Been There, Done That"

 

[MicheleWeaver]

Thanks for your response!

I never get an error message popping up. I just happened to be in the log and saw this failed login multiple times. Access to the SQL Server is fine and all the jobs are running fine. I never get kicked out.

I took your suggestion and ran a trace file. Every so often it ran

"SELECT N'Testing Connection...'"

then

"EXECUTE msdb.dbo.sp_sqlagent_get_perf_counters"

from the SQL Agent - Alert Engine. These were the only things run from the loginname pri\sqlservice. I'm not sure what the Alert Engine is. But it seems like this is where my problem is.

pri\sqlservice has admin rights on the server and domain.

 

[Catadmin]

Hmm. I wonder if "Testing Connection" thing you're seeing is what is causing your error messages. Did you check the timing of that verses when those errors show up in the Event log?



Catadmin - MCDBA, MCSA
"No, no. Yes. No, I tried that. Yes, both ways. No, I don't know. No again. Are there any more questions?"
-- Xena, "Been There, Done That"

 

[MicheleWeaver]

They don't seem to completely correspond. The failed login runs more often than the Testing Connection. There is also some replication events in the trace, but those are under a different login and I had this issue before I turned replication on.

There is a section under the sql agent properties for Alert System, which I had the database mail enabled. Disabling it did nothing though. And I am getting e-mails when a job fails.

 

[Catadmin]

Is there anything else running under that login? Any jobs or DTS/SSIS packages? Is any other person trying to log in as that account?

Oh, wait. I just realized that you don't have the latest service packs for SQL Server 2005. Run over to this link and download the post-SP1 hotfix. It should bring you up to date:

http://support.microsoft.com/kb/918222

This may or may not solve your problem.



Catadmin - MCDBA, MCSA
"No, no. Yes. No, I tried that. Yes, both ways. No, I don't know. No again. Are there any more questions?"
-- Xena, "Been There, Done That"

 

[SQLBill]

In Query Analyzer, run sp_who2. That will list all the connections being made to the instance. Find all the connections that are using that login. Compare them to what they should be doing. You may find a rogue connection that you aren't aware of or have forgotten.

One thing that can cause this is if you have a job/application/etc, that uses that login and has the password hard coded. If you changed the password but forgot to change it in a script where it's hard coded you will get that error.

-SQLBill

Posting advice: FAQ481-4875

 

[MicheleWeaver]

I ran the service packs and hot fixes. No luck. I ran the sp_who, and these are the processes:

SQLAGENT90 - Id<5908>
SQLAgent - Job invocation engine
SQLAgent - Generic Refresher
SQLAgent - Email Logger

All jobs and packages are run from the pri\sqlservice account, and all are running okay and if they fail we are notified through e-mail (database mail).

Funny thing is if I stop the sql agent, the login failure is still there.

 

[mrdenny]

Sounds like something in running on the server using the IP 172.16.9.2 and the service is running under an old password. Have you change the password for the PRI\sqlservice recently and some service wasn't updated? Check the services on the machine using that IP address and see what services are running under that account.

Denny
MCSA (2003) / MCDBA (SQL 2000) / MCTS (SQL 2005) / MCITP Database Administrator (SQL 2005)

--Anything is possible. All it takes is a little research. (Me)

http://www.mrdenny.com

 

[sqlcasey]

MicheleWeaver,

first question - why does the error log also indicate SQL Server starting up?

second question - are you currently running 2005 on a 64 bit server?

if so, please be aware that there is a serious memory bug in 2005 on 64 bit servers

this may have nothing to do with your situation at all, but figured i would mention it - as we saw similar entries in our error logs until we found the fix

 

[MicheleWeaver]

No password change.

I don't know why the startup is in the error log.

Nope, not 64 bit. Running standard version.

I stopped all sql services through the sql server configuration manager and started them back up one at a time. Its the sql server service that's generating the error. I didn't even have sql agent started yet. I do have the sql server set up to start under the pri\sqlservice account. Should this be started under a built in account?

 

[MicheleWeaver]

I killed all the processes running under pri\sqlservice. sp_who shows no pri\sqlservice. I am still getting the error in the log failed login for pri\sqlservice.

 

[Catadmin]

Could it be a linked server issue? I mean, do you have another SQL Server or a Windows job or something trying to access this box from a different box?

Or, it could be that a hacker got the name of the account and has a bot trying to break into your SQL box.



Catadmin - MCDBA, MCSA
"No, no. Yes. No, I tried that. Yes, both ways. No, I don't know. No again. Are there any more questions?"
-- Xena, "Been There, Done That"

 

[mrdenny]

Is the server KSDBT01 using the IP 172.16.9.2?

Denny
MCSA (2003) / MCDBA (SQL 2000) / MCTS (SQL 2005) / MCITP Database Administrator (SQL 2005)

--Anything is possible. All it takes is a little research. (Me)

http://www.mrdenny.com

 

[Catadmin]

Now that's a good observation, Denny.

Michele, go to the command prompt and do an IPCONFIG /ALL to verify if your server is using that IP address. If it's not, do a TRACERT on that IP and see if you can find it within your network. If it's not inside the network, see if your network / firewall admin can block that IP.

You can also check with the DHCP Admin (might be your server or your network team) to see if this IP is reserved for a specific print server, app server or another SQL Server kind of thing.



Catadmin - MCDBA, MCSA
"No, no. Yes. No, I tried that. Yes, both ways. No, I don't know. No again. Are there any more questions?"
-- Xena, "Been There, Done That"

 

[MicheleWeaver]

Thank you so much to everyone who helped. Finally found it.

We had MOM running and the database it uses (PointOne) didn't exist. We had uninstalled 2000 and installed 2005, but didn't remove MOM first.

 

[Catadmin]

Glad you found the problem. @=)



Catadmin - MCDBA, MCSA
"No, no. Yes. No, I tried that. Yes, both ways. No, I don't know. No again. Are there any more questions?"
-- Xena, "Been There, Done That"