Sign in
 
Home20122008 R2200820052000LibraryForums
SQL Server >
> 
> 
What happens at midnight ?

Proposed Answer What happens at midnight ?

  • Tuesday, October 17, 2006 1:21 PM
     
     
    Sign In to Vote
    0

    Everyday at just gone midnight, my MSSQL server won't accept connections. About 25 minutes later, it seems to be OK. There's no third party backup software running on this machine which is MSSQL server aware. Has anyone any suggestions as to why this might be happening ?

    The client app trying to use the db reports

    17/10/2006 00:02:04 Email2DBServer Cannot open database "Email2DB" requested by the login. The login failed. From OpenLocalDatabase

     and there's an entry in the event log

    Event Type: Failure Audit
    Event Source: MSSQL$EMAIL2DB
    Event Category: (4)
    Event ID: 18456
    Date:  17/10/2006
    Time:  00:02:04
    User:  NAVIGATOR-BATH\navigator-service
    Computer: NAVIGAT2A
    Description:
    Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    Data:
    0000: 18 48 00 00 0e 00 00 00   .H......
    0008: 13 00 00 00 4e 00 41 00   ....N.A.
    0010: 56 00 49 00 47 00 41 00   V.I.G.A.
    0018: 54 00 32 00 41 00 5c 00   T.2.A.\.
    0020: 45 00 4d 00 41 00 49 00   E.M.A.I.
    0028: 4c 00 32 00 44 00 42 00   L.2.D.B.
    0030: 00 00 07 00 00 00 6d 00   ......m.
    0038: 61 00 73 00 74 00 65 00   a.s.t.e.
    0040: 72 00 00 00               r...   

     

All Replies

  • Tuesday, October 17, 2006 4:42 PM
    Moderator
     
     Proposed Answer
    Sign In to Vote
    1
    Hi,

    make sure that your database is not detached during the backup operation. Some backup scenarios do these tasks to make a cold backup. After the backup, they will attached the database again to the server.

    HTH, Jens K. Suessmeyer.

    ---
    http://www.sqlserver2005.de
    ---
     
  • Tuesday, October 17, 2006 5:00 PM
     
     
    Sign In to Vote
    0

    I'm currently just using drivesnapshot (http://www.drivesnapshot.de/) to backup this machine and it's not aware of any running software, it just takes an image of the disk. It also starts running a good hour before this error message occurs.

    Is there anything else on this W2KAS which may tell the db to detach ?

     
  • Tuesday, October 17, 2006 11:34 PM
    Moderator
     
     
    Sign In to Vote
    0

    It would be useful to see more of the error log.

    By default, databases in SQL Express are closed when there are no more connections open. (Closed is different than detached) Errors such as your describing can happen if some other process on the computer has a lock on the file when SQL tries to re-open the database. The log could help provide more information, but from your description, it could be that your file backup process has the database file locked for copying at the same time you are trying to open the database.

    About the only way to confirm this would be if drivesnapshot keeps a time log of when each file being copied. You might consider excluding the .mdf file from your drivesnapshot backup for a few days to see if that changes the behavior you are seeing.

    Mike

     
  • Wednesday, October 18, 2006 8:46 AM
     
     Proposed Answer
    Sign In to Vote
    1

    There's always four entries in the Application Event Log which I've appended to the end of this message. I don't know if SQL Express keeps it's own error log too, but a quick look hasn't revealed one (maybe someone can let me know if there should be one).

    The backup process doesn't lock any files, it backs up the disk on a sector by sector basis and thus isn't aware of what files it's backing up. But to be 100% certain it's not the cause, I'm just running the backup now.
    I'll also make sure that the backup doesn't run tonight.

    Here's the four event log entries

    Event Type: Failure Audit
    Event Source: MSSQL$EMAIL2DB
    Event Category: (4)
    Event ID: 18456
    Date:  18/10/2006
    Time:  00:03:30
    User:  NAVIGATOR-BATH\navigator-service
    Computer: NAVIGAT2A
    Description:
    Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    Data:
    0000: 18 48 00 00 0e 00 00 00   .H......
    0008: 13 00 00 00 4e 00 41 00   ....N.A.
    0010: 56 00 49 00 47 00 41 00   V.I.G.A.
    0018: 54 00 32 00 41 00 5c 00   T.2.A.\.
    0020: 45 00 4d 00 41 00 49 00   E.M.A.I.
    0028: 4c 00 32 00 44 00 42 00   L.2.D.B.
    0030: 00 00 07 00 00 00 6d 00   ......m.
    0038: 61 00 73 00 74 00 65 00   a.s.t.e.
    0040: 72 00 00 00               r...   

    Event Type: Information
    Event Source: HHCTRL
    Event Category: None
    Event ID: 1903
    Date:  18/10/2006
    Time:  00:09:12
    User:  N/A
    Computer: NAVIGAT2A
    Description:
    The description for Event ID ( 1903 ) in Source ( HHCTRL ) cannot be found. The local computer may not have the necessary registry information or message DLL files to display messages from a remote computer. The following information is part of the event: http://go.microsoft.com/fwlink?LinkID=45839.

    Event Type: Information
    Event Source: MSSQL$EMAIL2DB
    Event Category: (2)
    Event ID: 17401
    Date:  18/10/2006
    Time:  00:32:10
    User:  N/A
    Computer: NAVIGAT2A
    Description:
    Server resumed execution after being idle 813 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    Data:
    0000: f9 43 00 00 0a 00 00 00   ùC......
    0008: 13 00 00 00 4e 00 41 00   ....N.A.
    0010: 56 00 49 00 47 00 41 00   V.I.G.A.
    0018: 54 00 32 00 41 00 5c 00   T.2.A.\.
    0020: 45 00 4d 00 41 00 49 00   E.M.A.I.
    0028: 4c 00 32 00 44 00 42 00   L.2.D.B.
    0030: 00 00 00 00 00 00         ...... 

    Event Type: Information
    Event Source: MSSQL$EMAIL2DB
    Event Category: (2)
    Event ID: 17137
    Date:  18/10/2006
    Time:  00:32:12
    User:  NAVIGATOR-BATH\navigator-service
    Computer: NAVIGAT2A
    Description:
    Starting up database 'Email2DB'.
    Data:
    0000: f1 42 00 00 0a 00 00 00   ñB......
    0008: 13 00 00 00 4e 00 41 00   ....N.A.
    0010: 56 00 49 00 47 00 41 00   V.I.G.A.
    0018: 54 00 32 00 41 00 5c 00   T.2.A.\.
    0020: 45 00 4d 00 41 00 49 00   E.M.A.I.
    0028: 4c 00 32 00 44 00 42 00   L.2.D.B.
    0030: 00 00 07 00 00 00 6d 00   ......m.
    0038: 61 00 73 00 74 00 65 00   a.s.t.e.
    0040: 72 00 00 00               r...   

     

     

     
  • Wednesday, October 18, 2006 1:46 PM
     
     
    Sign In to Vote
    0
    Backup's finished and no new entries in the event log, so I don't think that's the cause.
     
  • Thursday, October 19, 2006 2:16 AM
    Moderator
     
     
    Sign In to Vote
    0

    SQL Server keeps it's error log at C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\LOG, there will be much more information there than we put into the Event log.

    Of the Event Log messages you posted, the second one doesn't seem to have anything to do with SQL. The first one is a login failure, which is a bit concerning. The third and fourth are normal Events that get log when the server "wakes up" from being idel and when it opens a database that has been closed.

    I don't have any familiarity with the backup program you're using and I'm not sure what impact a sector copy would have on the database file. The log for the time period of the problem should give us more detail on what is happening in SQL server, take a look at the pertinent log and feel free to post the whole thing in the forum if you're fine with the disclosure. (If you're not, you can e-mail it to me. My contact info in in my profile, just remove the "online" from the address.)

    Mike

     
  • Thursday, October 19, 2006 8:42 AM
     
     
    Sign In to Vote
    0

    Many thanks. Here's the log, the error occurs at approx 3mins part midnight everyday

    2006-10-13 13:52:51.79 Server      Microsoft SQL Server 2005 - 9.00.2047.00 (Intel X86)
     Apr 14 2006 01:12:25
     Copyright (c) 1988-2005 Microsoft Corporation
     Express Edition on Windows NT 5.0 (Build 2195: Service Pack 4)

    2006-10-13 13:52:51.99 Server      (c) 2005 Microsoft Corporation.
    2006-10-13 13:52:51.99 Server      All rights reserved.
    2006-10-13 13:52:51.99 Server      Server process ID is 1056.
    2006-10-13 13:52:51.99 Server      Logging SQL Server messages in file 'c:\MSSQL_data\MSSQL.2\MSSQL\LOG\ERRORLOG'.
    2006-10-13 13:52:52.03 Server      This instance of SQL Server last reported using a process ID of 1016 at 13/10/2006 13:47:51 (local) 13/10/2006 12:47:51 (UTC). This is an informational message only; no user action is required.
    2006-10-13 13:52:52.03 Server      Registry startup parameters:
    2006-10-13 13:52:52.09 Server        -d c:\MSSQL_data\MSSQL.2\MSSQL\DATA\master.mdf
    2006-10-13 13:52:52.09 Server        -e c:\MSSQL_data\MSSQL.2\MSSQL\LOG\ERRORLOG
    2006-10-13 13:52:52.09 Server        -l c:\MSSQL_data\MSSQL.2\MSSQL\DATA\mastlog.ldf
    2006-10-13 13:52:52.15 Server      SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
    2006-10-13 13:52:52.15 Server      Detected 2 CPUs. This is an informational message; no user action is required.
    2006-10-13 13:52:55.85 Server      Error: 8313, Severity: 16, State: 1.
    2006-10-13 13:52:55.85 Server      Error in mapping SQL Server performance object/counter indexes to object/counter names. SQL Server performance counters are disabled.
    2006-10-13 13:52:55.90 Server      Error: 3409, Severity: 16, State: 1.
    2006-10-13 13:52:55.90 Server      Performance counter shared memory setup failed with error -1. Reinstall sqlctr.ini for this instance, and ensure that the instance login account has correct registry permissions.
    2006-10-13 13:52:58.07 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-10-13 13:53:03.51 Server      Could not query the FIPS compliance mode flag from registry. Error 2(error not found).
    2006-10-13 13:53:04.54 Server      Database mirroring has been enabled on this instance of SQL Server.
    2006-10-13 13:53:05.95 spid4s      Starting up database 'master'.
    2006-10-13 13:53:07.92 spid4s      1 transactions rolled forward in database 'master' (1). This is an informational message only. No user action is required.
    2006-10-13 13:53:08.60 spid4s      0 transactions rolled back in database 'master' (1). This is an informational message only. No user action is required.
    2006-10-13 13:53:08.60 spid4s      Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
    2006-10-13 13:53:11.87 spid4s      SQL Trace ID 1 was started by login "sa".
    2006-10-13 13:53:12.56 spid4s      Starting up database 'mssqlsystemresource'.
    2006-10-13 13:53:13.73 spid4s      The resource database build version is 9.00.2047. This is an informational message only. No user action is required.
    2006-10-13 13:53:18.89 spid7s      Starting up database 'model'.
    2006-10-13 13:53:19.04 spid4s      Server name is 'NAVIGAT2A\EMAIL2DB'. This is an informational message only. No user action is required.
    2006-10-13 13:53:19.10 spid4s      Starting up database 'msdb'.
    2006-10-13 13:53:19.64 Server      A self-generated certificate was successfully loaded for encryption.
    2006-10-13 13:53:19.70 Server      Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\EMAIL2DB ].
    2006-10-13 13:53:19.70 Server      Server local connection provider is ready to accept connection on [ \\.\pipe\MSSQL$EMAIL2DB\sql\query ].
    2006-10-13 13:53:19.70 Server      Dedicated administrator connection support was not started because it is not available on this edition of SQL Server. This is an informational message only. No user action is required.
    2006-10-13 13:53:19.76 Server      SQL Server is now ready for client connections. This is an informational message; no user action is required.
    2006-10-13 13:53:21.21 spid7s      Clearing tempdb database.
    2006-10-13 13:53:29.85 spid7s      Starting up database 'tempdb'.
    2006-10-13 13:53:32.18 spid4s      Recovery is complete. This is an informational message only. No user action is required.
    2006-10-13 13:53:32.45 spid10s     The Service Broker protocol transport is disabled or not configured.
    2006-10-13 13:53:32.46 spid10s     The Database Mirroring protocol transport is disabled or not configured.
    2006-10-13 13:53:33.85 spid10s     Service Broker manager has started.
    2006-10-13 23:27:02.96 Server      Server resumed execution after being idle 34324 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-13 23:27:06.27 spid51      Starting up database 'Email2DB'.
    2006-10-14 00:03:16.31 Logon       Error: 18456, Severity: 14, State: 16.
    2006-10-14 00:03:16.31 Logon       Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    2006-10-14 00:27:13.24 Server      Server resumed execution after being idle 524 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-14 00:27:14.09 spid51      Starting up database 'Email2DB'.
    2006-10-15 00:03:05.63 Logon       Error: 18456, Severity: 14, State: 16.
    2006-10-15 00:03:05.63 Logon       Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    2006-10-15 00:27:06.88 Server      Server resumed execution after being idle 537 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-15 00:27:06.92 spid51      Starting up database 'Email2DB'.
    2006-10-16 00:03:03.43 Logon       Error: 18456, Severity: 14, State: 16.
    2006-10-16 00:03:03.43 Logon       Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    2006-10-16 00:27:08.26 Server      Server resumed execution after being idle 539 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-16 00:27:08.26 spid51      Starting up database 'Email2DB'.
    2006-10-16 10:48:00.96 spid51      Starting up database 'Email2DB'.
    2006-10-16 21:54:38.70 Server      Server resumed execution after being idle 423 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-16 21:54:38.72 spid51      Starting up database 'Email2DB'.
    2006-10-16 21:58:26.39 spid51      Starting up database 'Email2DB'.
    2006-10-16 22:18:34.38 spid51      Starting up database 'Email2DB'.
    2006-10-17 00:02:04.06 Logon       Error: 18456, Severity: 14, State: 16.
    2006-10-17 00:02:04.06 Logon       Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    2006-10-17 00:18:19.90 Server      Server resumed execution after being idle 70 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-17 00:18:20.02 spid51      Starting up database 'Email2DB'.
    2006-10-17 11:11:58.88 spid52      Using 'xpstar90.dll' version '2005.90.2047' to execute extended stored procedure 'xp_instance_regread'. This is an informational message only; no user action is required.
    2006-10-17 12:32:41.93 spid51      Starting up database 'Email2DB'.
    2006-10-17 14:07:55.85 spid53      Using 'xplog70.dll' version '2005.90.2047' to execute extended stored procedure 'xp_msver'. This is an informational message only; no user action is required.
    2006-10-18 00:03:30.26 Logon       Error: 18456, Severity: 14, State: 16.
    2006-10-18 00:03:30.26 Logon       Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    2006-10-18 00:32:10.22 Server      Server resumed execution after being idle 813 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-18 00:32:12.00 spid51      Starting up database 'Email2DB'.
    2006-10-18 15:31:52.35 Server      Server resumed execution after being idle 21265 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-18 15:31:53.68 spid51      Starting up database 'Email2DB'.
    2006-10-19 00:02:17.43 Logon       Error: 18456, Severity: 14, State: 16.
    2006-10-19 00:02:17.43 Logon       Login failed for user 'NAVIGATOR-BATH\navigator-service'. [CLIENT: <local machine>]
    2006-10-19 00:31:18.03 Server      Server resumed execution after being idle 834 seconds: user activity awakened the server. This is an informational message only. No user action is required.
    2006-10-19 00:31:18.65 spid51      Starting up database 'Email2DB'.

     

     
  • Friday, October 20, 2006 12:07 AM
    Moderator
     
     
    Sign In to Vote
    0

    Thanks for the log. I found some good coverage on this particular error on the SQL Protocol blog in this post. They don't mention State 16 in the post, but it is discussed in the comments. According to the post, there are two reason this might happen:

    1. The user making the call does not have permission to log into the target database. Since this process is running at midnight, I'll assume this is an automated task running on a schedule. You should double-check what user context the automation tool is using when it runs at midnight. Is it possible that the tool is running in the context of some machine account rather than a user account? The blog offers and idea on how to verify if this is the problem.
    2. The second possible cause of this problem is that the database is offline when the script is run. I still think it is possible that your backup process is locking the file or at least causing it to be slow to be opened, which could trick SQL into thinking it's offline. One way to troubleshoot this would be to set the database to AutoClose=False and see if this impacts anything. You could also try changing the timeout for the script your running to give the database a bit more time to open, or just execute the script at 12:30 AM, by which time the database seems fine.

    If the problem really is related to file locking and the Close/Open status of the database, I'm worried that AutoClose=False may actually prevent your backup program from working on this file. You should be sure to verify that your backup process still works before changing the AutoClose property as a perminent solution.

    Mike

     
  • Friday, October 20, 2006 11:44 AM
     
     
    Sign In to Vote
    0

    Thanks for that.

    I'm going to stop the backup running this weekend to see if that stops the error messages.

    I have just one program which access the DB. It runs 24 x 7 as a service. The service is logged on with a user account which is part of the Admin group.
    Once per hour, the program gets email from a pop3 box, parses it and then writes some data to the db.

    The program works fine all the time, except for during the period of approx 00:02 and 00:30 where it reports the error
    "19/10/2006 00:02:18 Email2DBServer Cannot open database "Email2DB" requested by the login. The login failed. From OpenLocalDatabase"

    How do I set the AutoClose=False, I can't find the setting and Googling didn't help :(

     
  • Friday, October 20, 2006 4:50 PM
    Moderator
     
     
    Sign In to Vote
    0
     David_navigator wrote:

    How do I set the AutoClose=False, I can't find the setting and Googling didn't help :(

    USE [master];
GO
ALTER DATABASE [yourDB] SET AUTO_CLOSE ON/OFF WITH NO_WAIT;
GO

    http://msdn2.microsoft.com/en-us/library/ms174269.aspx

    regards

     
  • Tuesday, October 24, 2006 9:07 AM
     
     
    Sign In to Vote
    0

    Very strange :(

    I stopped the backup running over the weekend and the error message was still written to the Event log, so I think we can exclude the backup software, however last night (for the first time) the error didn't occur.

    Nothing out of the ordinary was running and non of the regular services had stopped, so now it's even more of a mystery, I'll report back tomorrow whether the error occurs again or not.

    I haven't yet changed the AutoClose setting.