c# - 使用正确的凭据获取 SQL Server 超时错误，立即拒绝(故意)不正确的凭据

Question

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

System.Data.SqlClient.SqlException:超时已过。操作完成前超时时间已过或服务器未响应

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

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

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

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

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   Starttime       Event               Query82     4:37:50 PM      Login               -- network protocol: LPC  set 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 off82     4:37:50 PM      SP:StmtStarting     EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0, @NodeStatus = @p1, @PoolWeighting = @p282     4:37:50 PM      SP:Starting         EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0, @NodeStatus = @p1, @PoolWeighting = @p282     4:37:50 PM      SP:StmtStarting     UPDATE    ModelingNodeState   SET    NodeStatus = @NodeStatus,    PoolWeighting = ISNULL(@PoolWeighting, PoolWeighting)   WHERE    NodeIdentifier = @NodeIdentifier     83     4:38:07 PM      Login               -- network protocol: LPC  set 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 off82     4:37:50 PM      SP:Completed        EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0, @NodeStatus = @p1, @PoolWeighting = @p280     4:40:10 PM      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(   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')           is not null then 1      else 0  end                         AS bit) 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.object_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')           is not null then 1      else 0  end                         AS bit)=@_msparam_0) ORDER BY [Schema] ASC,[Name] ASC80     4:40:10 PM      SQL:BatchStarting   use [master]62     4:20:10 PM      Logout              NULL55     4:20:02 PM      Logout              NULL74     4:13:37 PM      Logout              NULL59     4:20:10 PM      Logout              NULL55     4:40:29 PM      Login               -- network protocol: TCP/IP  set 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   set transaction isolation level  read committed  set implicit_transactions off 82     4:37:50 PM      Logout              NULL

This is definitely a deeper level of SQL debugging than I'm accustomed to, so please let me know if I'm misreading this, but it certainly appears like this statement was running without incident, just incredibly slowly. And again, it was running fine beforehand, started timing out, then resumed normal operation.

The only thing I can think of now that I've ruminated in public is that if there were some long-running locks jamming up the tables called by the sproc, that might explain it. Because LINQ-to-SQL somewhat hides the login/logout process, it's possible that the login was always working fine, and it's just this one sproc call that timed out due to a block. Whether those tables were locked, and if so, why, is impossible to say at this point. Does that sound like the most likely explanation for what I saw, or does anyone have another theory?

For completeness, here's the body of the 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 表上尚未诊断的源锁定导致语句超时，而不是连接超时。 LINQ-to-SQL 通常方便的连接管理混淆了这种区别。

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

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

经验教训:

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

感谢社区反馈引导我找到(希望)正确答案!