SQL查询通知并不总是在扩展设置(SQL Server)中起作用

Question

SQL查询通知在我们的环境中并不总是有效的。它们似乎工作了一段时间，然后我们在SqlDependency.Start（…）方法调用上得到了一个ArgumentException（模拟的无效令牌-不能重复）异常，SqlMessageBus返回到使用轮询机制。之后，在SQL消息总线被释放之前，不会尝试SQL查询通知。

SqlMessageBus似乎并不总是看到SqlDependency已经启动，并尝试重新启动它。

在日志中（见下文），我看到了以下事件序列：

• 正在启动SQL通知侦听器
• SQL通知侦听器已启动
• SQL通知更改已启动
• 正在启动SQL通知侦听器
• SQL通知侦听器已在运行
• 设置SQL通知
• SQL通知更改已启动
• SQL通知超时
• 再次启动接收循环以处理更新
• 正在启动SQL通知侦听器
• 启动SQL通知侦听器时出错

环境：

• .NET 4.5.2
• Windows 7上的WinForms客户端
• Windows Server 2012 R2上IIS 8.5中托管的2个应用程序服务器（使用Windows身份验证和模拟）
• 负载平衡器
• 信号R 2.2
• SQL Server 2008 R2 SP3（使用SQL Server身份验证）

以下是捕获日志的摘录。如果需要，我可以提供完整的日志。

...
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Starting SQL notification listener
    DateTime=2015-02-06T18:47:37.3054459Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SQL notification listener started
    DateTime=2015-02-06T18:47:37.3679593Z
...
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SqlReceiver last payload ID=0, new payload ID=1
    DateTime=2015-02-06T18:47:38.1805287Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Updated receive reader initial payload ID parameter=1
    DateTime=2015-02-06T18:47:38.1805287Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Payload 1 containing 1 message(s) received
    DateTime=2015-02-06T18:47:38.1805287Z
SignalR.ScaleoutMessageBus Information: 0 : OnReceived(0, 1, 1)
    DateTime=2015-02-06T18:47:38.1805287Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : 1 records received
    DateTime=2015-02-06T18:47:38.1961135Z
...
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : No records received while setting up SQL notification
    DateTime=2015-02-06T18:47:47.1184053Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Receive loop exiting
    DateTime=2015-02-06T18:47:47.1184053Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : SqlReceiver.Receive returned
    DateTime=2015-02-06T18:47:47.1184053Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : SQL notification change fired
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SQL notification details: Type=Change, Source=Data, Info=Update
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : Starting receive loop again to process updates
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Starting SQL notification listener
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SQL notification listener was already running
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Created DbCommand: CommandType=Text, CommandText=SELECT [PayloadId], [Payload], [InsertedOn] FROM [SignalR].[Messages_0] WHERE [PayloadId] > @PayloadId, Parameters= [Name=PayloadId, Value=1]
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SqlReceiver last payload ID=1, new payload ID=2
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Updated receive reader initial payload ID parameter=2
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Payload 2 containing 1 message(s) received
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.ScaleoutMessageBus Information: 0 : OnReceived(0, 2, 1)
    DateTime=2015-02-06T18:48:13.1196355Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : 1 records received
    DateTime=2015-02-06T18:48:13.1196355Z
...
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Setting up SQL notification
    DateTime=2015-02-06T18:48:27.8859474Z
SignalR.SqlMessageBus Verbose: 0 : Created DbCommand: CommandType=Text, CommandText=SELECT [PayloadId], [Payload], [InsertedOn] FROM [SignalR].[Messages_0] WHERE [PayloadId] > @PayloadId, Parameters= [Name=PayloadId, Value=3]
    DateTime=2015-02-06T18:48:27.8859474Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : No records received while setting up SQL notification
    DateTime=2015-02-06T18:48:27.8859474Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Receive loop exiting
    DateTime=2015-02-06T18:48:27.8859474Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : SQL notification change fired
    DateTime=2015-02-06T18:49:27.9200020Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SQL notification timed out
    DateTime=2015-02-06T18:49:27.9200020Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : Starting receive loop again to process updates
    DateTime=2015-02-06T18:49:27.9200020Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Starting SQL notification listener
    DateTime=2015-02-06T18:49:27.9200020Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SQL notification listener was already running
    DateTime=2015-02-06T18:49:27.9200020Z
...
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Setting up SQL notification
    DateTime=2015-02-06T18:50:51.8614352Z
SignalR.SqlMessageBus Verbose: 0 : Created DbCommand: CommandType=Text, CommandText=SELECT [PayloadId], [Payload], [InsertedOn] FROM [SignalR].[Messages_0] WHERE [PayloadId] > @PayloadId, Parameters= [Name=PayloadId, Value=3]
    DateTime=2015-02-06T18:50:51.8614352Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : No records received while setting up SQL notification
    DateTime=2015-02-06T18:50:51.8614352Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Receive loop exiting
    DateTime=2015-02-06T18:50:51.8614352Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : SQL notification change fired
    DateTime=2015-02-06T18:51:58.0520336Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : SQL notification timed out
    DateTime=2015-02-06T18:51:58.0520336Z
SignalR.SqlMessageBus Information: 0 : Stream 0 : Starting receive loop again to process updates
    DateTime=2015-02-06T18:51:58.0520336Z
SignalR.SqlMessageBus Verbose: 0 : Stream 0 : Starting SQL notification listener
    DateTime=2015-02-06T18:51:58.0520336Z
SignalR.SqlMessageBus Error: 0 : Stream 0 : Error starting SQL notification listener: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.ArgumentException: Invalid token for impersonation - it cannot be duplicated.
   at System.Security.Principal.WindowsIdentity.CreateFromToken(IntPtr userToken)
   at System.Security.Principal.WindowsIdentity..ctor(SerializationInfo info)
   --- End of inner exception stack trace ---
Server stack trace: 
   at System.RuntimeMethodHandle.SerializationInvoke(IRuntimeMethodInfo method, Object target, SerializationInfo info, StreamingContext& context)
   at System.Runtime.Serialization.ObjectManager.CompleteISerializableObject(Object obj, SerializationInfo info, StreamingContext context)
   at System.Runtime.Serialization.ObjectManager.FixupSpecialObject(ObjectHolder holder)
   at System.Runtime.Serialization.ObjectManager.DoFixups()
   at System.Runtime.Serialization.Formatters.Binary.ObjectReader.Deserialize(HeaderHandler handler, __BinaryParser serParser, Boolean fCheck, Boolean isCrossAppDomain, IMethodCallMessage methodCallMessage)
   at System.Runtime.Serialization.Formatters.Binary.BinaryFormatter.Deserialize(Stream serializationStream, HeaderHandler handler, Boolean fCheck, Boolean isCrossAppDomain, IMethodCallMessage methodCallMessage)
   at System.Runtime.Remoting.Channels.CrossAppDomainSerializer.DeserializeObject(MemoryStream stm)
   at System.Runtime.Remoting.Messaging.SmuggledMethodCallMessage.FixupForNewAppDomain()
   at System.Runtime.Remoting.Channels.CrossAppDomainSink.DoDispatch(Byte[] reqStmBuff, SmuggledMethodCallMessage smuggledMcm, SmuggledMethodReturnMessage& smuggledMrm)
   at System.Runtime.Remoting.Channels.CrossAppDomainSink.DoTransitionDispatchCallback(Object[] args)
Exception rethrown at [0]: 
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at SqlDependencyProcessDispatcher.StartWithDefault(String connectionString, String& server, DbConnectionPoolIdentity& identity, String& user, String& database, String& service, String appDomainKey, SqlDependencyPerAppDomainDispatcher dispatcher, Boolean& errorOccurred, Boolean& appDomainStart)
   at System.Data.SqlClient.SqlDependency.Start(String connectionString, String queue, Boolean useDefaults)
   at Microsoft.AspNet.SignalR.SqlServer.ObservableDbOperation.StartSqlDependencyListener()
    DateTime=2015-02-06T18:51:58.0520336Z
...

有人看到这个问题了吗？

我还在GitHub 上的SignalR问题跟踪器中发布了这个问题

Answer 1

当当前线程中的HttpContext.Current.User.Identity为空时，通常会抛出异常"模拟令牌无效-不能重复"，也许您应该在SqlDependency.Start（）方法之前/之后检查它。

HttpContext.Current不会自然地在TPL（async/await方法）隐式创建的线程上传播，也许你应该看看这一点。如果您的服务器端应用程序是asp.net，请尝试在appSettings中将aspnet:UseTaskFriendlySynchronizationContext设置为true。