March 8, 2010 at 4:40 am
Running SQL 2005 SP3 and have a SQL job that 'fires' whenever "SQL Server Agent Starts". Normally this job has no problems, but after a recent server reboot (post Windows Update updates), the job failed with 'unable to connect to SQL server...'.
In the SQL error logfile I see:-
March 8, 2010 at 4:46 am
My apologies - the post got away from me....
The SQL logfile shows:-
Login failed for user.....
Error: 18456, Severity: 14, State: 16
I'm assuming that the SQL job couldn't connect due to the engine still coming up (recovering....). Would welcome any advice on how to overcome this problem in the future.
Seems SQL Agent is firing the job too early and the database engine is not yet ready to accept requests. So can i 'delay' SQLAgent from issuing this request until the engine has finished recovering. Or does anyone know of any other solution? Thanks.
Andy
March 8, 2010 at 5:38 am
What is the default database of the login running the job?
Try to change that to Tempdb or Master.
HTH,
Robbert
March 8, 2010 at 6:21 am
Hi Robbert,
Thanks for your comment. Unfortunately the owner of the job already has 'master' set as its default database...
Andy
March 8, 2010 at 7:36 am
ajarman (3/8/2010)
the job failed with 'unable to connect to SQL server...'.In the SQL error logfile I see:-
Are other jobs running fine ?
can u using the same (this job's)account for others jobs also ?
and can u post details of error captured in log ?
-------Bhuvnesh----------
I work only to learn Sql Server...though my company pays me for getting their stuff done;-)
March 8, 2010 at 7:42 am
Andy,
does the database has the auto_close attribute set to ON?
If so turn it OFF.
If you look at the database owner, from database properties and then Files, is it blank?
If so fill in the appropiate owner.
HTH,
Robbert Hof
March 8, 2010 at 8:36 am
Hello Robbert & Bhuvnesh,
Thanks again for your responses.
Bhuvnesh: Other SQL jobs owned by the same job owner (which failed) - work fine. In fact the only failure I'm seeing is this one specific job, which is scheduled to start, when the SQL
Agent service starts up (its the only job I have scheduled this way). The majority of times this job runs without any problems, its just on the odd occassions it doesn't.
The only error message I'm seeing is the 'cannot connect to SQL Server' in the job history. Followed by the 'login failed...' message in the SQL logfile...
Robbert: The database that this SQL job runs against is owned by a SQL login account (presuambly no problems with that). The 'options' on the database are:
AUTO_CLOSE: False
AUTO_CREATE_STATISTICS: True
AUTO_SHRINK: False
AUTO_UPDATE_STATISTICS: True
AUTO_UPDATE_STATISTICS_ASYNCHRONOUSLY: False
Andy
March 9, 2010 at 10:52 pm
You should need to review the error log file...if any database in recovery mode then you might get this error. if you can post the error log file where you can see the error...or
use following query to retrieve error log.
sp_readerrorlog 0
-------Bhuvnesh----------
I work only to learn Sql Server...though my company pays me for getting their stuff done;-)
March 10, 2010 at 3:22 am
Hi Bhuvnesh,
Not sure theres anything more in the logfile, that I haven't shared before... But as I'm looking for some help:-D
I highlighted in bold where I believe the SQLAGENT job attempts to connect to the database... If the server is still in 'recovery mode', then I'm unsure if its a bug that the SQLAGENT job is firing too early?
Alternatively, I'd be interested in a way in delaying the firing of this job by an extra 30/60/... seconds based on this event.
Thanks for your interest.
Andy
2010-03-07 01:09:36.62 Server Microsoft SQL Server 2005 - 9.00.4262.00 (Intel X86)
Aug 13 2009 17:08:37
Copyright (c) 1988-2005 Microsoft Corporation
Standard Edition on Windows NT 5.2 (Build 3790: Service Pack 2)
2010-03-07 01:09:36.62 Server (c) 2005 Microsoft Corporation.
2010-03-07 01:09:36.62 Server All rights reserved.
2010-03-07 01:09:36.62 Server Server process ID is 1512.
2010-03-07 01:09:36.62 Server Authentication mode is MIXED.
2010-03-07 01:09:36.62 Server Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\ERRORLOG'.
2010-03-07 01:09:36.62 Server This instance of SQL Server last reported using a process ID of 1500 at 07/03/2010 01:05:10 (local) 07/03/2010 01:05:10 (UTC). This is an informational message only; no user action is required.
2010-03-07 01:09:36.62 Server Registry startup parameters:
2010-03-07 01:09:36.62 Server -d C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\master.mdf
2010-03-07 01:09:36.62 Server -e C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\ERRORLOG
2010-03-07 01:09:36.62 Server -l C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\mastlog.ldf
2010-03-07 01:09:36.64 Server SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2010-03-07 01:09:36.64 Server Detected 4 CPUs. This is an informational message; no user action is required.
2010-03-07 01:09:36.73 Server Address Windowing Extensions is enabled. This is an informational message only; no user action is required.
2010-03-07 01:09:36.81 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.
2010-03-07 01:09:36.88 Server Attempting to initialize Microsoft Distributed Transaction Coordinator (MS DTC). This is an informational message only. No user action is required.
2010-03-07 01:09:38.93 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.
2010-03-07 01:09:38.93 Server Database mirroring has been enabled on this instance of SQL Server.
2010-03-07 01:09:38.94 spid5s Starting up database 'master'.
2010-03-07 01:09:39.04 spid5s Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
2010-03-07 01:09:39.12 spid5s CHECKDB for database 'master' finished without errors on 2010-02-28 23:30:01.900 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:39.12 spid5s SQL Trace ID 1 was started by login "sa".
2010-03-07 01:09:39.13 spid5s Starting up database 'mssqlsystemresource'.
2010-03-07 01:09:39.18 spid5s The resource database build version is 9.00.4262. This is an informational message only. No user action is required.
2010-03-07 01:09:39.32 spid5s Server name is 'ARES\MSSQL'. This is an informational message only. No user action is required.
2010-03-07 01:09:39.32 spid9s Starting up database 'model'.
2010-03-07 01:09:39.63 spid9s CHECKDB for database 'model' finished without errors on 2010-02-28 23:30:06.060 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:39.63 spid9s Clearing tempdb database.
2010-03-07 01:09:39.74 spid9s Starting up database 'tempdb'.
2010-03-07 01:09:39.76 spid9s Analysis of database 'tempdb' (2) is 100% complete (approximately 0 seconds remain). This is an informational message only. No user action is required.
2010-03-07 01:09:39.78 spid9s CHECKDB for database 'tempdb' finished without errors on 2010-02-28 23:30:06.060 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:39.79 spid12s Server is listening on [ 'any' <ipv4> 4022].
2010-03-07 01:09:39.79 spid12s The Service Broker protocol transport is now listening for connections.
2010-03-07 01:09:39.79 spid12s The Database Mirroring protocol transport is disabled or not configured.
2010-03-07 01:09:39.79 spid12s Service Broker manager has started.
2010-03-07 01:09:39.82 Server A self-generated certificate was successfully loaded for encryption.
2010-03-07 01:09:39.82 Server Server is listening on [ 'any' <ipv4> 1733].
2010-03-07 01:09:39.82 Server Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\MSSQL ].
2010-03-07 01:09:39.82 Server Server local connection provider is ready to accept connection on [ \\.\pipe\MSSQL$MSSQL\sql\query ].
2010-03-07 01:09:39.83 Server Server is listening on [ 127.0.0.1 <ipv4> 1734].
2010-03-07 01:09:39.83 Server Dedicated admin connection support was established for listening locally on port 1734.
2010-03-07 01:09:39.86 Server SQL Server is now ready for client connections. This is an informational message; no user action is required.
2010-03-07 01:09:39.90 spid18s Starting up database 'msdb'.
2010-03-07 01:09:39.90 spid19s Starting up database 'SCCiDBA'.
2010-03-07 01:09:39.90 spid27s Starting up database 'SQLsafeRepository'.
2010-03-07 01:09:39.90 spid28s Starting up database 'MasterCard'.
2010-03-07 01:09:39.90 spid29s Starting up database 'Guidestar'.
2010-03-07 01:09:39.90 spid21s Starting up database 'MatchingEngine'.
2010-03-07 01:09:39.90 spid20s Starting up database 'distribution'.
2010-03-07 01:09:39.90 spid22s Starting up database 'Observatory_Staging'.
2010-03-07 01:09:39.90 spid24s Starting up database 'PROBE'.
2010-03-07 01:09:39.91 spid25s Starting up database 'IderaRepository'.
2010-03-07 01:09:39.91 spid23s Starting up database 'Postcode_Directory'.
2010-03-07 01:09:39.91 spid26s Starting up database 'PROBE_ARC'.
2010-03-07 01:09:40.15 spid27s CHECKDB for database 'SQLsafeRepository' finished without errors on 2010-03-06 04:35:48.907 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:40.35 spid19s CHECKDB for database 'SCCiDBA' finished without errors on 2010-03-06 04:35:48.573 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:40.46 spid18s CHECKDB for database 'msdb' finished without errors on 2010-02-28 23:30:06.457 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:40.57 spid20s CHECKDB for database 'distribution' finished without errors on 2008-06-18 20:01:36.150 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:41.40 spid52 Using 'xpsqlbot.dll' version '2005.90.4035' to execute extended stored procedure 'xp_qv'. This is an informational message only; no user action is required.
2010-03-07 01:09:41.75 spid52 Using 'xpstar90.dll' version '2005.90.4262' to execute extended stored procedure 'xp_instance_regread'. This is an informational message only; no user action is required.
2010-03-07 01:09:41.84 spid52 Using 'xplog70.dll' version '2005.90.4035' to execute extended stored procedure 'xp_msver'. This is an informational message only; no user action is required.
2010-03-07 01:09:42.03 spid25s Analysis of database 'IderaRepository' (11) is 100% complete (approximately 0 seconds remain). This is an informational message only. No user action is required.
2010-03-07 01:09:42.06 spid25s CHECKDB for database 'IderaRepository' finished without errors on 2010-03-06 02:52:03.123 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:42.48 spid28s CHECKDB for database 'MasterCard' finished without errors on 2010-03-06 02:53:23.607 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:42.83 spid29s CHECKDB for database 'Guidestar' finished without errors on 2010-03-06 02:51:41.143 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:42.86 spid26s Analysis of database 'PROBE_ARC' (12) is 100% complete (approximately 0 seconds remain). This is an informational message only. No user action is required.
2010-03-07 01:09:43.03 spid22s CHECKDB for database 'Observatory_Staging' finished without errors on 2010-03-06 02:57:55.187 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:43.08 spid26s CHECKDB for database 'PROBE_ARC' finished without errors on 2008-10-27 21:03:43.913 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:43.19 spid23s CHECKDB for database 'Postcode_Directory' finished without errors on 2008-10-27 20:13:27.897 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:43.25 spid24s Analysis of database 'PROBE' (10) is 100% complete (approximately 0 seconds remain). This is an informational message only. No user action is required.
2010-03-07 01:09:43.85 spid24s CHECKDB for database 'PROBE' finished without errors on 2010-03-06 03:11:07.700 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:45.76 spid21s Analysis of database 'MatchingEngine' (7) is 100% complete (approximately 0 seconds remain). This is an informational message only. No user action is required.
2010-03-07 01:09:45.77 Logon Error: 18456, Severity: 14, State: 16.
2010-03-07 01:09:45.77 Logon Login failed for user 'MYSPIKES\sql.server'. [CLIENT: <local machine>]
2010-03-07 01:09:45.86 spid21s CHECKDB for database 'MatchingEngine' finished without errors on 2010-03-06 02:53:31.260 (local time). This is an informational message only; no user action is required.
2010-03-07 01:09:45.92 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.
2010-03-07 01:09:45.92 spid5s Recovery is complete. This is an informational message only. No user action is required.
2010-03-07 01:09:45.95 spid5s Launched startup procedure 'sp_MSrepl_startup'.
2010-03-07 01:10:00.17 spid79 Using 'odsole70.dll' version '2005.90.4035' to execute extended stored procedure 'sp_OACreate'. This is an informational message only; no user action is required.
2010-03-07 01:10:02.86 spid79 SQL Trace ID 2 was started by login "Idera_DiagnosticManager".
2010-03-07 02:15:03.43 spid69 Replication-Replication Distribution Subsystem: agent ARES\MSSQL-PROBE-Customer Tables-HERA\MSSQL-75 scheduled for retry. TCP Provider: An existing connection was forcibly closed by the remote host.
Viewing 9 posts - 1 through 8 (of 8 total)
You must be logged in to reply to this topic. Login to reply