none
Login timeout expiration

    Question

  • We are getting the following error message sporadically:

     

    Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration. Time spent during login: total 6108 ms, enqueued 1 ms, network writes 1 ms, network reads 6108 ms, establishing SSL 6107 ms, negotiating SSPI 0 ms, validating login 0 ms. [CLIENT: #.#.#.#]

     

    We are seeing this message because we enabled some DBCC trace flags to try and figure out why our clients are having their connections terminated to the SQL 2005 (x64) server we have in production. It appears that the establishment of SSL is taking a very long time according to the log entry. What is using SSL? I'm assuming it is trying to communicate with one of my domain controllers and I'd like to know what perfmon counters i should watch to see what's going on. Is it making an LDAPS connection or kerberos? Or native ntlm?

     

    We've already updated the NIC drivers/firmware and disabled the TcpChimney setting mentioned in the KB articles, but nothing so far has had an effect. I'm now trying to figure out if my DC is overloaded but don't know what counters to look at.

     

    Thanks

    Steve

    Tuesday, October 30, 2007 6:34 PM

All replies

  • Hi, Steve

     

         Can you attach the full ERRORLOG content when the problem repro? You can also try to use SQL Profile to trace the client request see which one got rejected by the server. The workaround here in your connection string, you can enlarge the query timeout see whether that make the problem gone.

     

    Good Luck!

    Ming.

     

    Wednesday, October 31, 2007 6:46 PM
  • Hi Ming,

     

    I had to scrub the errorlog a little bit for privacy-sake. The relevant info is below. The problem is very intermittent, so we have not left a trace running for days. If you can suggest some counters to trace, I can arrange to leave profiler running for a while to see if we get lucky. Also, we've seen this problem with both our own application and the SQL2005 query analyzer. Any idea on how to decipher the error message? I'm guessing the problem is the length of time for the SSL connection setup, but I don't know how to trace that, since I don't know how or why SSL is being used.

    Thanks

     

    Code Block

    2007-10-25 21:36:11.65 Server      Microsoft SQL Server 2005 - 9.00.3042.00 (X64)
     Feb 10 2007 00:59:02
     Copyright (c) 1988-2005 Microsoft Corporation
     Standard Edition (64-bit) on Windows NT 5.2 (Build 3790: Service Pack 2)

    2007-10-25 21:36:11.67 Server      (c) 2005 Microsoft Corporation.
    2007-10-25 21:36:11.67 Server      All rights reserved.
    2007-10-25 21:36:11.67 Server      Server process ID is 1336.
    2007-10-25 21:36:11.67 Server      Authentication mode is MIXED.
    2007-10-25 21:36:11.68 Server      Logging SQL Server messages in file 'D:\Programs\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\ERRORLOG'.
    2007-10-25 21:36:11.68 Server      This instance of SQL Server last reported using a process ID of 1240 at 10/25/2007 9:08:24 PM (local) 10/26/2007 1:08:24 AM (UTC). This is an informational message only; no user action is required.
    2007-10-25 21:36:11.68 Server      Registry startup parameters:
    2007-10-25 21:36:11.68 Server        -l D:\Programs\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\mastlog.ldf
    2007-10-25 21:36:11.70 Server        -e D:\Programs\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\ERRORLOG
    2007-10-25 21:36:11.70 Server        -d D:\Programs\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\master.mdf
    2007-10-25 21:36:11.76 Server      SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
    2007-10-25 21:36:11.76 Server      Detected 2 CPUs. This is an informational message; no user action is required.
    2007-10-25 21:36:13.75 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.
    2007-10-25 21:36:14.90 Server      Attempting to initialize Microsoft Distributed Transaction Coordinator (MS DTC). This is an informational message only. No user action is required.
    2007-10-25 21:36:14.96 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.
    2007-10-25 21:36:15.04 Server      Database mirroring has been enabled on this instance of SQL Server.
    2007-10-25 21:36:15.31 spid5s      Starting up database 'master'.
    2007-10-25 21:36:18.10 spid5s      Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
    2007-10-25 21:36:18.59 spid5s      SQL Trace ID 1 was started by login "sa".
    2007-10-25 21:36:18.68 spid5s      Starting up database 'mssqlsystemresource'.
    2007-10-25 21:36:18.73 spid5s      The resource database build version is 9.00.3042. This is an informational message only. No user action is required.
    2007-10-25 21:36:19.13 spid9s      Starting up database 'model'.
    2007-10-25 21:36:19.13 spid5s      Server name is 'PRDREF01'. This is an informational message only. No user action is required.
    2007-10-25 21:36:19.34 spid9s      Clearing tempdb database.
    2007-10-25 21:36:19.62 Server      A self-generated certificate was successfully loaded for encryption.
    2007-10-25 21:36:19.63 Server      Server is listening on [ 'any' <ipv4> 1433].
    2007-10-25 21:36:19.65 Server      Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\MSSQLSERVER ].
    2007-10-25 21:36:19.65 Server      Server named pipe provider is ready to accept connection on [ \\.\pipe\sql\query ].
    2007-10-25 21:36:19.65 Server      Server is listening on [ 'any' <ipv4> 1434].
    2007-10-25 21:36:19.65 Server      Dedicated admin connection support was established for listening remotely on port 1434.
    2007-10-25 21:36:19.92 spid9s      Starting up database 'tempdb'.
    2007-10-25 21:36:19.93 Server      SQL Server is now ready for client connections. This is an informational message; no user action is required.
    2007-10-25 21:36:20.34 spid12s     The Service Broker protocol transport is disabled or not configured.
    2007-10-25 21:36:20.34 spid12s     The Database Mirroring protocol transport is disabled or not configured.
    2007-10-25 21:36:21.15 spid12s     Service Broker manager has started.
    2007-10-25 21:36:23.29 spid16s     Starting up database 'msdb'.
    2007-10-25 21:36:26.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.
    2007-10-25 21:36:26.92 spid5s      Recovery is complete. This is an informational message only. No user action is required.
    2007-10-25 21:36:27.01 spid5s      Launched startup procedure 'sp_MSrepl_startup'.
    2007-10-25 21:36:28.18 spid52      Configuration option 'show advanced options' changed from 0 to 1. Run the RECONFIGURE statement to install.
    2007-10-25 21:36:28.37 spid52      Configuration option 'Agent XPs' changed from 0 to 1. Run the RECONFIGURE statement to install.
    2007-10-25 21:36:28.62 spid52      Configuration option 'show advanced options' changed from 1 to 0. Run the RECONFIGURE statement to install.
    2007-10-25 21:36:29.60 spid52      Using 'xpsqlbot.dll' version '2005.90.3042' to execute extended stored procedure 'xp_qv'. This is an informational message only; no user action is required.
    2007-10-25 21:36:30.18 spid52      Using 'xpstar90.dll' version '2005.90.3042' to execute extended stored procedure 'xp_instance_regread'. This is an informational message only; no user action is required.
    2007-10-25 21:36:30.82 spid52      Using 'xplog70.dll' version '2005.90.3042' to execute extended stored procedure 'xp_msver'. This is an informational message only; no user action is required.
    2007-10-26 11:04:52.71 spid63      DBCC TRACEON 4029, server process ID (SPID) 63. This is an informational message only; no user action is required.
    2007-10-26 11:04:52.71 spid63      DBCC TRACEON 3689, server process ID (SPID) 63. This is an informational message only; no user action is required.
    2007-10-30 13:07:49.15 Logon       Login succeeded for user 'MYDOMAIN\user2'. Connection: trusted. [CLIENT: 10.0.10.138]
    2007-10-30 13:08:15.48 Logon       Error: 17830, Severity: 20, State: 2.
    2007-10-30 13:08:15.48 Logon       Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration. Time spent during login: total 1006 ms, enqueued 1 ms, network writes 1 ms, network reads 1006 ms, establishing SSL 1006 ms, negotiating SSPI 0 ms, validating login 0 ms. [CLIENT: 10.0.10.139]
    2007-10-30 13:08:17.38 Logon       Error: 17830, Severity: 20, State: 2.
    2007-10-30 13:08:17.38 Logon       Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration. Time spent during login: total 6108 ms, enqueued 1 ms, network writes 1 ms, network reads 6108 ms, establishing SSL 6107 ms, negotiating SSPI 0 ms, validating login 0 ms. [CLIENT: 10.0.10.138]
    2007-10-30 13:08:32.16 Logon       Login succeeded for user 'MYDOMAIN\user1'. Connection: trusted. [CLIENT: 10.0.10.139]
    2007-10-30 13:09:27.73 Logon       Login succeeded for user 'MYDOMAIN\user2'. Connection: trusted. [CLIENT: 10.0.10.138]

     

     

    Thursday, November 1, 2007 11:59 AM
  • I'm also having this problem.  Tried the SynAttackProtect and TCP Chimney registry edits too, to no avail.  Would love to get to the bottom of this if anyone can help?

     

    Tuesday, November 6, 2007 12:45 PM
  • I would recommend turning on the following trace flags:

    DBCC TRACEON 4029

    DBCC TRACEON 3689

    and see what you get in the SQl error log when the problem occurs. In our case we can see that there is a long delay in performing the SSL authentication. Unfortunately, no one on this board has been able to tell me what this is or where I should look. At present, we suspect a bad module in our HP switch, as many of the ports are being flooded with non-broadcast traffic that shouldn't be reaching them. This *may* be the cause of the network delays that result in a timeout.

     

    -Steve

    Tuesday, November 6, 2007 2:28 PM
  • I already have these on but they haven't really helped too much.  The message in the error log is:

     

    Message
    Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration. Time spent during login: total 4 ms, enqueued 1 ms, network writes 1 ms, network reads 3 ms, establishing SSL 3 ms, negotiating SSPI 0 ms, validating login 0 ms. [CLIENT: 192.168.147.106]

     

    Tuesday, November 6, 2007 2:57 PM
  • Did anybody ever come to a resolution on this, we are having the same issue on Server 2008 R2.

    Michael

    Friday, October 22, 2010 12:59 PM
  • I'm seeing this issue as well on SQL 2008R2/Windows2008R2. I have 10 different apps connecting to the sql server. The only one I'm seeing the issue with is a WEB/ISS application. I get around 1000 of these errors every 5 mins, a waste of bandwidth...
    • Proposed as answer by BlueIzzzz Monday, October 17, 2011 1:50 PM
    • Unproposed as answer by BlueIzzzz Monday, October 17, 2011 1:50 PM
    Thursday, October 13, 2011 12:27 PM
  • What I figured out was that some applications automatically assume  the local system account of the machine the application is running on, so we really see this when the service is running under "Local System Account" - meaning that it is try to log into SQL as <domain name>\computer name$. I added this to the SQL server login and granted permissions to the database used by the application running on that machine. This resolved the "Failed Login" errors along with the following error message:

     

    Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration. Time spent during login: total 1006 ms, enqueued 1 ms, network writes 1 ms, network reads 1006 ms, establishing SSL 1006 ms, negotiating SSPI 0 ms, validating login 0 ms. [CLIENT: 10.0.10.139]

     

     

    • Proposed as answer by BlueIzzzz Monday, October 17, 2011 1:54 PM
    Monday, October 17, 2011 1:54 PM