4

We're trying to see whether a client is able to reach a database server, as it's receiving error:

[DBNETLIB][ConnectionOpen (Connect()).]SQL Server does not exist or access denied.

The error doesn't occur for some time, which is usually the result of the client being unable to reach the destination server (e.g. an incorrect database server name). The error occurs in the web application and when testing an ODBC connection using the Windows Server 2003 Web Edition OS tools.

In order to try to determine what is causing the issue, we want to see whether the connection attempt is reaching the database server. We thought we could use extended events to monitor the login attempt.

sqlserver.process_login_finish is a new event in SQL Server 2016 which "is generated when server is done processing a login (success or failure)".

We created an event session with this code:

CREATE EVENT SESSION [Test Login Audit] ON SERVER 
ADD EVENT
    sqlserver.process_login_finish
    (
        ACTION
        (
            package0.collect_system_time,
            sqlserver.client_app_name,
            sqlserver.client_hostname,
            sqlserver.nt_username
        )
    )
ADD TARGET package0.ring_buffer;
GO

ALTER EVENT SESSION [Test Login Audit] ON SERVER
  STATE = START;
GO

We then connected to the server several times, using Windows and SQL authentication, including a purposely incorrect password for the SQL user.

We then queried the extended event data as follows:

SELECT name, target_name, CAST(xet.target_data AS xml)
FROM sys.dm_xe_session_targets AS xet
JOIN sys.dm_xe_sessions AS xe
   ON (xe.address = xet.event_session_address)
WHERE xe.name = 'Test Login Audit';

However, we found no processed events:

<RingBufferTarget truncated="0" processingTime="0" totalEventsProcessed="0" eventCount="0" droppedCount="0" memoryUsed="0" />

We then created this login failure extended event session from Aaron Bertrand:

CREATE EVENT SESSION FailedLogins
ON SERVER
 ADD EVENT sqlserver.error_reported
 (
   ACTION 
   (
     sqlserver.client_app_name,
     sqlserver.client_hostname,
     sqlserver.nt_username
    )
    WHERE severity = 14

    -- added this line:
      AND error_number = 18456

      AND state > 1 -- removes redundant state 1 event
  )
  ADD TARGET package0.ring_buffer;
GO

ALTER EVENT SESSION FailedLogins ON SERVER
  STATE = START;
GO

We then used an incorrect password for a SQL user login. We then queried its data:

SELECT name, target_name, CAST(xet.target_data AS xml)
FROM sys.dm_xe_session_targets AS xet
JOIN sys.dm_xe_sessions AS xe
   ON (xe.address = xet.event_session_address)
WHERE xe.name = 'FailedLogins';

And discovered the captured event:

<RingBufferTarget truncated="0" processingTime="0" totalEventsProcessed="3" eventCount="3" droppedCount="0" memoryUsed="1323">
  <event name="error_reported" package="sqlserver" timestamp="2017-07-06T21:27:49.407Z">
    <data name="error_number">
      <type name="int32" package="package0" />
      <value>18456</value>
    </data>
    <data name="severity">
      <type name="int32" package="package0" />
      <value>14</value>
    </data>
    <data name="state">
      <type name="int32" package="package0" />
      <value>8</value>
    </data>
    <data name="user_defined">
      <type name="boolean" package="package0" />
      <value>false</value>
    </data>
    <data name="category">
      <type name="error_category" package="sqlserver" />
      <value>4</value>
      <text>LOGON</text>
    </data>
    <data name="destination">
      <type name="error_destination" package="sqlserver" />
      <value>0x0000001c</value>
      <text>BUFFER, ERRORLOG, EVENTLOG</text>
    </data>
    <data name="is_intercepted">
      <type name="boolean" package="package0" />
      <value>true</value>
    </data>
    <data name="message">
      <type name="unicode_string" package="package0" />
      <value>Login failed for user 'zzzzzzzz'. Reason: Password did not match that for the login provided. [CLIENT: 10.nnn.nnn.nnn]</value>
    </data>
    <action name="nt_username" package="sqlserver">
      <type name="unicode_string" package="package0" />
      <value />
    </action>
    <action name="client_hostname" package="sqlserver">
      <type name="unicode_string" package="package0" />
      <value>WS449</value>
    </action>
    <action name="client_app_name" package="sqlserver">
      <type name="unicode_string" package="package0" />
      <value>Microsoft SQL Server Management Studio - Query</value>
    </action>
  </event>
</RingBufferTarget>

(2 additional events removed and some information obfuscated)

Yet there was still nothing in the "Test Login Audit" event session we created on event sqlserver.process_login_finish.

So the extended events system and ring buffer are working. And logins are occurring.

So why aren't we getting any sqlserver.process_login_finish events? Do we misunderstand what a "login" is? Is this not yet a complete feature?

We get this back from @@VERSION:

Microsoft SQL Server 2016 (SP1) (KB3182545) - 13.0.4001.0 (X64) 
    Oct 28 2016 18:17:30 
    Copyright (c) Microsoft Corporation
    Developer Edition (64-bit) on Windows Server 2012 R2 Standard 6.3 <X64> (Build 9600: ) (Hypervisor)

Update 2017-07-07:

For those curious, we have solved the original connection issue. By default, named instances of SQL Server listen using dynamic ports. Our firewall only allowed port 1433.

From Microsoft's documentation on configuring ports:

If enabled, the default instance of the SQL Server Database Engine listens on TCP port 1433. Named instances of the Database Engine and SQL Server Compact are configured for dynamic ports. This means they select an available port when the SQL Server service is started. When you are connecting to a named instance through a firewall, configure the Database Engine to listen on a specific port, so that the appropriate port can be opened in the firewall.

We adjusted the SQL Server's port to 1433 and the connection issue was resolved.

(Dynamic port allocation requires at least UDP port 1434 to allow the initial port query, and then the firewall would have to sniff and auto-allow the resulting dynamically assigned port, much like many can do for FTP PASV commands. I'm not sure if any can do that for SQL port negotiation like this.)

However, as this is primarily a question about certain extended events not firing, I plan to leave the question open.

  • 1
    I could not get it fired either. Meantime I suggest you read this answer which provide few alternatives. – SqlWorldWide Jul 7 '17 at 1:38
  • For those curious, the original connection issue which prompted the creation of the event logging was caused by named instances using dynamic ports by default when firewall hole was for just 1433. I'm leaving the question open, though, because it's really about the extended event issue. – Riley Major Jul 7 '17 at 15:56

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.