6

We are using SqlDependency in a .NET web app. Intermittently in production, we receive the following error when trying to call Start:

NullReferenceException - Object reference not set to an instance of an object.
Server stack trace: 
   at System.Object.GetType()
   at log4net.Util.ReadOnlyPropertiesDictionary.GetObjectData(SerializationInfo info, StreamingContext context)
   at System.Runtime.Serialization.Formatters.Binary.WriteObjectInfo.InitSerialize(Object obj, ISurrogateSelector surrogateSelector, StreamingContext context, SerObjectInfoInit serObjectInfoInit, IFormatterConverter converter, ObjectWriter objectWriter, SerializationBinder binder)
   at System.Runtime.Serialization.Formatters.Binary.ObjectWriter.Write(WriteObjectInfo objectInfo, NameInfo memberNameInfo, NameInfo typeNameInfo)
   at System.Runtime.Serialization.Formatters.Binary.ObjectWriter.Serialize(Object graph, Header[] inHeaders, __BinaryWriter serWriter, Boolean fCheck)
   at System.Runtime.Serialization.Formatters.Binary.BinaryFormatter.Serialize(Stream serializationStream, Object graph, Header[] headers, Boolean fCheck)
   at System.Runtime.Remoting.Channels.CrossAppDomainSerializer.SerializeMessageParts(ArrayList argsToSerialize)
   at System.Runtime.Remoting.Messaging.SmuggledMethodCallMessage..ctor(IMethodCallMessage mcm)
   at System.Runtime.Remoting.Messaging.SmuggledMethodCallMessage.SmuggleIfPossible(IMessage msg)
   at System.Runtime.Remoting.Channels.CrossAppDomainSink.SyncProcessMessage(IMessage reqMsg)
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)

The code for starting the SqlDependency is simply:

SqlDependency.Start(ConnectionStringHelper.GetDatabaseConnectionString(), null);

The error first appeared after upgrading log4net from v1 to v2. We also received a similar error relating to SqlDependency not being able to find the log4net DLL, which we corrected by manually copying the DLL into C:\Windows\system32\inetsrv\

SerializationException - Unable to find assembly 'log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a'.
Server stack trace: 
   at System.Runtime.Serialization.Formatters.Binary.BinaryAssemblyInfo.GetAssembly()
   at System.Runtime.Serialization.Formatters.Binary.ObjectReader.GetType(BinaryAssemblyInfo assemblyInfo, String name)
   at System.Runtime.Serialization.Formatters.Binary.ObjectMap..ctor(String objectName, String[] memberNames, BinaryTypeEnum[] binaryTypeEnumA, Object[] typeInformationA, Int32[] memberAssemIds, ObjectReader objectReader, Int32 objectId, BinaryAssemblyInfo assemblyInfo, SizedArray assemIdToAssemblyTable)
   at System.Runtime.Serialization.Formatters.Binary.__BinaryParser.ReadObjectWithMapTyped(BinaryObjectWithMapTyped record)
   at System.Runtime.Serialization.Formatters.Binary.__BinaryParser.Run()
   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 System._AppDomain.CreateInstance(String assemblyName, String typeName)
   at System.Data.SqlClient.SqlDependency.CreateProcessDispatcher(_AppDomain masterDomain)
   at System.Data.SqlClient.SqlDependency.ObtainProcessDispatcher()
   at System.Data.SqlClient.SqlDependency.Start(String connectionString, String queue, Boolean useDefaults)

Why on earth would SqlDependency have anything to do with log4net?

cbp
  • 25,252
  • 29
  • 125
  • 205
  • What is your connection string. You can have a few errors in the connection string 1) Server Name is wrong (or no route to server) 2) Instance of Database is wrong 3) Credentials are wrong or doesn't allow access to database 4) Default database is wrong – jdweng Feb 11 '20 at 23:17
  • I'm pretty sure everything is correct in the connection string. The problem only occurs intermittently, and we use the connection string for other things and it works. – cbp Feb 11 '20 at 23:22
  • Do you have cluster (more than one server sharing one database)? – jdweng Feb 11 '20 at 23:58
  • No, it is a single machine. There are different apps using the database, but only one app uses SqlDependency – cbp Feb 12 '20 at 00:28
  • I think it is a connection issue. Do you agree? You are getting a proxy error so I think when you are sending credentials the DNS server is not responding quickly. So the access (privileged) to the log4net file is failing to open the file. How large is the log file. Could issue be due to the size of the file being huge? – jdweng Feb 12 '20 at 09:43
  • I don't think it's a connection issue. The error is not a proxy error - it's an error inside log4net. The word Proxy in the stacktrace isn't referring to the type of network proxy your thinking of. – cbp Feb 12 '20 at 09:54
  • Proxy is just going to another machine to verify credentials. The DNS server could be the proxy. – jdweng Feb 12 '20 at 10:09
  • 1
    You could wrap the `SqlDependency.Start` in a try/catch to log the exception details independently of log4net until you get logging issues figured out. We can only guess why `Start` is failing without exception details. An intermittent error could be database connectivity or something that went south during creation of the underlying Service Broker object plumbing. – Dan Guzman Feb 15 '20 at 14:59
  • Are you using the same connectionstring for you app and log4net? – Frank Nielsen Feb 16 '20 at 18:38
  • There is one logger in log4net that performs SQL access, and it has a different connection string to the one SqlDependency is using. – cbp Feb 16 '20 at 22:48
  • If understand correctly `SqlDependency` places itself in a different AppDomain, so everything that goes through `SqlDependency` is being serialized - log4net also. Is it anyway possible to "disable" or "filter out" log4net in `SqlDependency`? – Frank Nielsen Feb 17 '20 at 20:16
  • The fact that you had to copy **application** DLLs to a **system** directory should have been the first indication that something is seriously wrong with your application. Does it not strike you as possible that this issue is related? I strongly suggest that instead of trying to patch your app with multiple pieces of duct tape over where you **think** the holes are, you step back and do a full root-cause analysis with `fuslogvw` to find what's actually broken, and fix that. – Ian Kemp Feb 17 '20 at 21:20
  • As my question asks, why does SqlDependency.Start rope in the log4net assembly in the first place? SqlDependency.Start is a .NET library method entirely out of our hands. The call to is made on startup, prior to anything 'going into' SqlDependency. Why does it decide to start looking for the log4net DLL? – cbp Feb 20 '20 at 12:07

2 Answers2

2

I think there a still unresolved Type(s) that causes the NullReferenceException - Object reference not set to an instance of an object..

Last two statements in stacktrace says:

Server stack trace: 
   at System.Object.GetType()
   at log4net.Util.ReadOnlyPropertiesDictionary.GetObjectData(SerializationInfo info, StreamingContext context)

My guess is that log4net is also using an external assembly reference, so try resolve it (log4net) with Fuslogvw.exe - https://learn.microsoft.com/en-us/dotnet/framework/tools/fuslogvw-exe-assembly-binding-log-viewer

If another assembly pops up as referenced, copy that to C:\Windows\system32\inetsrv\ also.

Frank Nielsen
  • 1,546
  • 1
  • 10
  • 17
  • If the assembly is loaded dynamic, as defined in a *.config, `Fuslogvw` will not reveal it. If so go through all *.config related to `log4net` and look for any external assembly references. – Frank Nielsen Feb 18 '20 at 21:03
1

An explanation of why log4net throws an error when SqlDependency.Start is called

Because it runs Traces internally.

I guess you run into this issue which affects log4net, Version=2.0.8

Pavel Shastov
  • 2,657
  • 1
  • 18
  • 26