SQL Query Notifications do not always work in scal

问题:

SQL Query Notifications do not always work in our environment. They seem to work for a little while, and then we get an ArgumentException (Invalid token for impersonation - it cannot be duplicated) exception on SqlDependency.Start(...) method call, and SqlMessageBus falls back to using polling mechanism. After that, SQL Query Notifications are not attempted until the SQL message bus has been disposed.

It seems that, SqlMessageBus doesn't always see that SqlDependency has already been started and tries to start it again.

In the log (see below), I see the following sequence of events:

• Starting SQL notification listener
• SQL notification listener started
• SQL notification change fired
• Starting SQL notification listener
• SQL notification listener was already running
• Setting up SQL notification
• SQL notification change fired
• SQL notification timed out
• Starting receive loop again to process updates
• Starting SQL notification listener
• Error starting SQL notification listener

Environment:

• .NET 4.5.2
• WinForms Clients on Windows 7
• 2 Application Servers hosted in IIS 8.5 on Windows Server 2012 R2 (using Windows Authentication & Impersonation)
• Load Balancer
• SignalR 2.2
• SQL Server 2008 R2 SP3 (using SQL Server Authentication)

The following is an excerpt from a captured log. I can supply the full log if needed.

...
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
...

Has anyone seen this problem?

I also posted this question in SignalR issue tracker on GitHub

回答1:

The exception "Invalid token for impersonation - it cannot be duplicated" is usually thrown when HttpContext.Current.User.Identity is empty in the current thread, maybe you should check it before / after the SqlDependency.Start() method.

HttpContext.Current don't naturally propagate over implicitly created threads by TPL (async / await methods), maybe you should have a look on this side. If your server-side app is asp.net, try to set aspnet:UseTaskFriendlySynchronizationContext to true in your appSettings.