使用正确的凭据获取 SQL Server 超时错误，使用（故意）不正确的凭据立即拒绝

Question

这是一个令人费解的问题。我运行良好的 ASP.NET 3.5 应用程序突然开始出现超时错误...

System.Data.SqlClient.SqlException：超时已过期。在操作完成之前超时时间已过或服务器没有响应

...但仅适用于连接字符串中具有正确用户名/密码的请求。如果我们故意弄乱了配置中的连接字符串，SQL Server 会正确拒绝请求，但会立即拒绝，而不是在等待 15 秒后（配置超时），这清楚地表明它与服务器通信没有问题。

我们反弹了 SQL Server 框（SQL Server 2005，已完全修补）和 IIS 框，触摸了 web.config 以强制重新启动应用程序等，但没有运气。所有请求都会挂起 15 秒，然后报告该错误。在任何时候，我们都能够直接访问数据库服务器（管理工作室、监控工具），并且我能够在 Visual Studio 中配置我的本地站点副本，以毫无意外地访问同一个数据库服务器。这个问题本身突然出现并持续了一天的大部分时间（错误在早上 6:17 开始记录）在下午 4:30 左右突然自行解决。

似乎在这台 Web 服务器和这台数据库服务器之间存在网络路由问题，但仅使用一组特定的 SQL 凭据。我知道这没有任何意义，但我们可以想象的任何其他情况都没有。我是一位非常有经验的开发人员，无论是我还是我们非常有经验的 DBA 或系统管理员都无法在事件日志、监控异常情况等中找到任何可以对这组奇怪且自我解决的症状给出合理解释的内容。

这发生在我们客户的测试环境中，这并不理想，但因为我们不明白到底发生了什么，我们担心这可能会突然出现在生产环境中，我们将集体头疼，所以非常欢迎任何想法或疯狂的理论。

LINQ-to-SQL 生成的正在爆炸的代码行是 ExecuteMethodCall：

[Function(Name="dbo.spSetModelingNodeState")]
public int spSetModelingNodeState([Parameter(Name="NodeIdentifier", DbType="VarChar(60)")] string nodeIdentifier, [Parameter(Name="NodeStatus", DbType="Int")] System.Nullable<int> nodeStatus, [Parameter(Name="PoolWeighting", DbType="Float")] System.Nullable<double> poolWeighting)
{
    IExecuteResult result = this.ExecuteMethodCall(this, ((MethodInfo)(MethodInfo.GetCurrentMethod())), nodeIdentifier, nodeStatus, poolWeighting);
    return ((int)(result.ReturnValue));
}

我调用该代码的代码是（缩写）：

using (MyDataContext myDataContext = new MyDataContext(_connectionString))
{
    myDataContext.spSetModelingNodeState(
        Adapter.Identifier, // string
        (int)newHealthValue, // enum, cast to int
        PoolWeighting); // float
}

编辑：花了几天时间来追踪，但我在下面添加了日志/Profiler 信息，根据评论者的请求，以及相关存储过程的主体

SQL Server 日志仅显示登录和注销，没有任何问题的迹象。 Profiler 跟踪也没有确凿证据，但以下 似乎 显示了一个耗时 18 秒的语句。跟随 spid 82。它从 4:37:50 开始，做一些事情，然后 spid 83 在 4:38:07 记录登录。 Spid 82 记录下一个完成，开始时间是相同的 4:38:07，但是因为这些是按顺序记录的，所以它实际上必须发生在 4:38:07（上一个跟踪语句）和 4:40:10（随后声明）。

Spid 开始时间事件查询 82 下午 4:37:50 登录——网络协议：LPC 设置quoted_identifier on set arithabort off set numeric_roundabort off set ansi_warnings on set ansi_padding on set ansi_nulls on set concat_null_yields_null on set cursor_close_on_commit off set implicit_transactions off 82 下午 4:37:50 SP:StmtStarting EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0，@NodeStatus = @p1，@PoolWeighting = @p2 82 下午 4:37:50 SP：开始执行 @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0，@NodeStatus = @p1，@PoolWeighting = @p2 82 下午 4:37:50 SP:StmtStarting 更新 ModelingNodeState SET NodeStatus = @NodeStatus, PoolWeighting = ISNULL(@PoolWeighting, PoolWeighting) 其中 NodeIdentifier = @NodeIdentifier 83 下午 4:38:07 登录 - 网络协议：LPC 设置quoted_identifier on set arithabort off set numeric_roundabort off set ansi_warnings on set ansi_padding on set ansi_nulls on set concat_null_yields_null on set cursor_close_on_commit off set implicit_transactions off 82 下午 4:37:50 SP：已完成执行 @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0，@NodeStatus = @p1，@PoolWeighting = @p2 80 下午 4:40:10 SP:StmtStarting SELECT 'Server[@Name=' + quotename(CAST(serverproperty(N'Servername') AS sysname),'''') + ']' + '/Database[@Name =' + quotename(db_name(),'''') + ']' + '/Table[@Name=' + quotename(tbl.name,'''') + ' and @Schema=' + quotename(SCHEMA_NAME (tbl.schema_id),'''') + ']' AS [Urn], tbl.name AS [Name], SCHEMA_NAME(tbl.schema_id) AS [Schema], CAST( tbl.is_ms_shipped = 1 然后 1 的情况当（从 sys.extended_properties 中选择major_id，其中major_id = tbl.object_id 和minor_id = 0 和class= 1 和name = N'microsoft_database_tools_support'）不为空，则1 else 0 结束AS 位）AS [IsSystemObject]，tbl.create_date AS [CreateDate], stbl.name AS [Owner] FROM sys.tables AS tbl INNER JOIN sys.database_principals AS stbl ON stbl.principal_id = ISNULL(tbl.principal_id, (OBJECTPROPERTY(tbl.ob ject_id, 'OwnerId'))) WHERE (CAST( case when tbl.is_ms_shipped = 1 then 1 when ( select major_id from sys.extended_properties where major_id = tbl.object_id and minor_id = 0 and class= 1 and name = N'microsoft_database_tools_support' ) 不为空然后 1 否则 0 结束 AS 位)=@_msparam_0) ORDER BY [Schema] ASC,[Name] ASC 80 4:40:10 PM SQL:BatchStarting 使用 [master] 62 下午 4:20:10 注销 NULL 55 下午 4:20:02 注销 NULL 74 下午 4:13:37 注销 NULL 59 下午 4:20:10 注销 NULL 55 下午 4:40:29 登录 -- 网络协议：TCP/IP 设置quoted_identifier on set arithabort off set numeric_roundabort off set ansi_warnings on set ansi_padding on set ansi_nulls on set concat_null_yields_null on set cursor_close_on_commit off set implicit_transactions 55 4:40:29 PM SQL:BatchStarting 设置事务隔离级别读取已提交设置隐式_事务关闭 82 下午 4:37:50 注销 NULL

这绝对是比我习惯的更深层次的 SQL 调试，所以如果我看错了，请告诉我，但看起来这条语句运行时毫无意外，只是非常缓慢。再次，它之前运行良好，开始超时，然后恢复正常运行。

我现在唯一能想到的，我在公共场合反省的是，如果有一些长期运行的锁堵塞了存储过程调用的表，那可能会解释它。因为 LINQ-to-SQL 在某种程度上隐藏了登录/注销过程，所以登录可能一直工作正常，只是这个 sproc 调用由于阻塞而超时。这些表是否被锁定，如果是，为什么，目前还不能说。这听起来像是对我所看到的最有可能的解释，还是有人有其他理论？

为了完整起见，这里是存储过程的主体：

/****** Object:  StoredProcedure [dbo].[spSetModelingNodeState]    Script Date: 10/29/2010 14:37:46 ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
ALTER PROCEDURE [dbo].[spSetModelingNodeState]
(
@NodeIdentifier varchar(60),
@NodeStatus int,
@PoolWeighting float = NULL
)
AS
/*try to update existing row to new state*/
UPDATE
    ModelingNodeState
SET
    NodeStatus = @NodeStatus,
    PoolWeighting = ISNULL(@PoolWeighting, PoolWeighting)
WHERE
    NodeIdentifier = @NodeIdentifier

IF @@ROWCOUNT = 0
    /*not found, so insert new one*/
    INSERT
        ModelingNodeState(
            NodeIdentifier,
            PoolWeighting,
            NodeStatus,
            LastModelingResult)
    VALUES(
        @NodeIdentifier,
        ISNULL(@PoolWeighting, 1),
        0,
        NULL)

DECLARE @timestamp datetime
SET @timestamp = CURRENT_TIMESTAMP

/*fill endtime of previous node state*/
UPDATE 
    ModelingNodeStateLog
SET
    EndTime = @timestamp
WHERE
    EndTime IS NULL AND
    NodeIdentifier = @NodeIdentifier AND
    NodeStatus <> @NodeStatus

/*start a new entry in the log (yes, I saw I should remove the IF check and always insert, but that's how it currently is in the db)*/
IF @@ROWCOUNT <> 0
    INSERT
        ModelingNodeStateLog
        (
        NodeIdentifier,
        NodeStatus,
        StartTime
        )
    VALUES
        (
        @NodeIdentifier,
        @NodeStatus,
        @timestamp
        )

RETURN

Answer 1

由于没有其他人插话，我将假设我对发生的事情的进化理论是正确的。具体来说，这是由于 ModelingNodeState 或 ModelingNodeStateLog 表上尚未诊断的源锁定导致 statement 超时，而不是 connection 超时。这种区别被 LINQ-to-SQL 通常方便的连接管理混淆了。

这与所有观察到的症状一致：

1. 在连接字符串中故意使用错误凭据的 Sproc 调用在连接级别被立即拒绝
2. 允许在连接字符串中使用正确凭据的 Sproc 调用登录（SQL Server 日志显示正常登录/注销），但再次执行锁定表的语句时超时
3. LINQ 隐藏了底层 SQL 连接管理意味着捕获的堆栈跟踪无法用于区分连接和语句超时，我错误地认为这是连接超时。
4. 我们不知道这些表中的一个或两个表是如何/为什么/如果全天锁定的，但是某处的未提交语句可能会完成它，因为这是在涉及 DBA 工作、迁移的一夜部署之后开始的脚本等。这将解释事情突然开始（在脚本开始后），持续一整天，然后在有问题的脚本提交或回滚时突然解决，也许是当运行它的应用程序在工作日结束时关闭.

经验教训：

1. 不要仅仅因为您在异常或堆栈跟踪中看到“超时”一词就认为您知道超时是什么种类
2. 在我思考的过程中，我意识到可以允许应用程序的整个方面完全失败，而不会影响关键的应用程序功能。我将重写它，这样这个问题的再次出现就不会像今天那样导致整个应用程序崩溃。

感谢社区反馈引导我找到（让我们希望）正确答案！

Answer 2

我在从另一台计算机恢复数据库备份后看到了这种行为。

这可以通过 Management Studio 中的 SQL 命令修复。见How to fix orphaned SQL Server users