Sql-server – Duplicate login details per user in error log

sql serversql-server-2008-r2

Being able to view details of who successfully logs into a database and which user's login failed via the error logs is a good thing. However I have a scenario that I need help with:

For some reason the success and failure details are logged multiple times and as such if I login to a SQL Server 2008 R2 instance this very minute, I see multiple "Login successful for user …" messages.

Can anyone help to resolve this (without turning off the option to save login success/failure) as it is filling up the logs and pushing down relevant information.
Example of a successful login for a user recorded multiple times in the same min, second

Best Answer

I realize this doesn't answer the question "why does the log file have multiple entries for 'Login succeeded...'", however since you also seem to be concerned about the other log entries being "drowned-out" by these low-importance login messages, I thought I'd add the following as an answer.

Instead of using SQL Server Management Studio's built-in interface for looking at log files, you can use the following code that will allow you to ignore log messages you are not interested in. This allows you to concentrate on messages that may be more immediately relevant.

IF NOT EXISTS(
    SELECT s.name + '.' + t.name 
    FROM tempdb.sys.tables t 
        INNER JOIN tempdb.sys.schemas s ON t.schema_id = s.schema_id 
    WHERE s.name + '.' + t.name = 'dbo.ErrorLogAnalysis'
    )
BEGIN
    CREATE TABLE tempdb.dbo.ErrorLogAnalysis
    (
        LogDate DATETIME,
        ProcessInfo NVARCHAR(255),
        [Text] NVARCHAR(MAX)
    );
END

TRUNCATE TABLE tempdb.dbo.ErrorLogAnalysis;
EXEC sp_ReadErrorLog 0,1;
INSERT INTO tempdb.dbo.ErrorLogAnalysis
SELECT ela.*
FROM tempdb.dbo.ErrorLogAnalysis ela
WHERE ela.Text NOT LIKE 'Login succeeded%'
ORDER BY LogDate DESC;

It may be helpful to point out that client-side code is quite likely to use more than a single connection to SQL Server. This may in fact be the precise reason why more than a single entry is recorded in the SQL Server Error Log.

To prove this, I've written a very simple VB.Net command-line app that creates 5 connections to my local SQL Server instance. Once all five connections have been opened, the app executes a simple query against the server showing 5 session_id values that the app has open. It then closes all 5 connections, and exits.

This is the code:

Module Module1

    Sub Main()

        Dim sConnString As String =
            "SERVER=localhost;" & _
            "DATABASE=master;" & _
            "TRUSTED_CONNECTION=True;" & _
            "Application Name=MultiConnTest"
        Dim sqlC1 As New SqlClient.SqlConnection(sConnString)
        Dim sqlC2 As New SqlClient.SqlConnection(sConnString)
        Dim sqlC3 As New SqlClient.SqlConnection(sConnString)
        Dim sqlC4 As New SqlClient.SqlConnection(sConnString)
        Dim sqlC5 As New SqlClient.SqlConnection(sConnString)
        sqlC1.Open()
        sqlC2.Open()
        sqlC3.Open()
        sqlC4.Open()
        sqlC5.Open()
        Dim sqlCMD As New SqlClient.SqlCommand( _
            "SELECT session_id, login_name " & _
            "FROM sys.dm_exec_sessions des " & _
            "WHERE des.host_name = HOST_NAME " & _
            "   AND des.program_name = 'MultiConnTest';", sqlC1)
        Console.WriteLine("Testing multiple connections to SQL Server.")
        Console.WriteLine()
        Console.WriteLine("Sessions currently open on the server, with username")
        Dim sqlReader As SqlClient.SqlDataReader = sqlCMD.ExecuteReader
        Dim iSessionID As Int32
        Dim sUserName As String
        While sqlReader.Read
            iSessionID = sqlReader.GetValue(0)
            sUserName = sqlReader.GetValue(1)
            Console.WriteLine(iSessionID & vbTab & sUserName)
        End While
        sqlReader.Close()
        sqlCMD = Nothing
        sqlC1.Close()
        sqlC2.Close()
        sqlC3.Close()
        sqlC4.Close()
        sqlC5.Close()
        Console.WriteLine("Press any key to exit")
        Console.ReadKey()

    End Sub

End Module

The console output from running this against my machine is:

Testing multiple connections to SQL Server.

Sessions currently open on the server, with username
52      Max
53      Max
54      Max
55      Max
56      Max
Press any key to exit

The SQL Server Error Log, after enabling auditing of both successful and unsuccessful logins, shows:

LogDate                 ProcessInfo Text
2014-09-16 10:31:54.290 Logon       Login succeeded for user 'Max'. Connection made using Windows authentication. [CLIENT: <local machine>]
2014-09-16 10:31:54.290 Logon       Login succeeded for user 'Max'. Connection made using Windows authentication. [CLIENT: <local machine>]
2014-09-16 10:31:54.290 Logon       Login succeeded for user 'Max'. Connection made using Windows authentication. [CLIENT: <local machine>]
2014-09-16 10:31:54.290 Logon       Login succeeded for user 'Max'. Connection made using Windows authentication. [CLIENT: <local machine>]
2014-09-16 10:31:54.290 Logon       Login succeeded for user 'Max'. Connection made using Windows authentication. [CLIENT: <local machine>]

I think you can see from this a possible source of your error log entries is not some errant SQL Server behavior that can be "disabled", but is far more likely to be the desired result arising from the combination of auditing successful logins, and client applications that use multiple connections.

I would check the source code of whatever applications are running against your SQL Server to determine if they are in-fact using multiple connections.

If they are, I would use sp_readerrorlog to look at the error log. I might even go so far as to create a stored procedure to encapsulate the functionality of sp_readerrorlog to produce output in whatever format you desire.

Related Question