Logging to SQL Server with ODBC provider errors due to missing proc parameter?

Topics: Data Access Application Block, Logging Application Block
Jul 6, 2009 at 6:03 PM

I have an application that can successfully log to a SQL server database fine when using a System.Data.SqlClient provider.

If I use a System.Data.Odbc provider with a System DSN which test connects successfully, I get a logging error, the important line of which reads (full detail below):

Message: ERROR [42000] [Microsoft][SQL Native Client][SQL Server]Procedure or function 'WriteLog' expects parameter '@EventID', which was not supplied.

My DSN configuration is using the SQL Native Client driver connecting to a local sqlexpress instance using either (local)\SQLEXPRESS or machinename\SQLEXPRESS as the server name.   I am using Sql Server authentication.   The connection tests fine.

I did a sql trace and noted the following differences.   When connecting using the sqlclient provider, I get call to the writelog stored procedure that looks like:

EventClass=RPC:Starting
declare @p14 int
set @p14=NULL
exec WriteLog @eventID=0,@priority=0,@severity=N'Information',@title=N'Log In',@timestamp='Jul  6 2009  4:03:55:320PM',@machineName=N'RCOLLETT',@AppDomainName=N'/LM/w3svc/1/ROOT/Hsb.ExceptionLogging.Web-7-128913698338206220',@ProcessID=N'5996',@ProcessName=N'C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_wp.exe',@ThreadName=NULL,@Win32ThreadId=N'4588',@message=N'Logged in - UserName:rcollette',@formattedmessage=N'0~07/06/2009 12:03:55 PM~rcollette~Information~RCOLLETT~/LM/w3svc/1/ROOT/Hsb.ExceptionLogging.Web-7-128913698338206220~Log In~Logged in - UserName:rcollette',@LogId=@p14 output
select @p14

When I use the odbc provider I only get:

EventClass=SQL:StmtStarting
WriteLog

It doesn't appear that anything is being passed to the procedure or perhaps the sql trace for odbc connections contains less detail??

The behavior is the same if I use the "SQL Server" odbc driver rather than the SQL Native client.

We are DSN's as an interim method of managing connections to different database servers for different deployment environments (test, stage, production).   I am aware of Entlib's ability to manage connection strings on an evironment basis.  However we have homegrown solution for managing connection string that we've been using and were not quite at a point where we can migrate connection string management to Entlib's environment based method.

----------------------------------------
Logging Errors & Warnings Error: 6352 : Timestamp: 07/06/2009 3:55:33 PM
Message: Tracing to LogSource 'Security' failed. Processing for other sources will continue. See summary information below for more information. Should this problem persist, stop the service and check the configuration file(s) for possible error(s) in the configuration of the categories and sinks.


Summary for Enterprise Library Distributor Service:
======================================
-->
Message:
Timestamp: 07/06/2009 3:55:33 PM
Message: Logged in - UserName:rcollette
Category: Security
Priority: 0
EventId: 0
Severity: Information
Title:Log In
Machine: RCOLLETT
App Domain: /LM/w3svc/1/ROOT/Hsb.ExceptionLogging.Web-6-128913676803481868
ProcessId: 5996
Process Name: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_wp.exe
Thread Name:
Win32 ThreadId:4588
Extended Properties:
--> MachineName: RCOLLETT
--> TimeStamp: 07/06/2009 3:55:33 PM
--> FullName: Microsoft.Practices.EnterpriseLibrary.Logging, Version=4.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35
--> AppDomainName: /LM/w3svc/1/ROOT/Hsb.ExceptionLogging.Web-6-128913676803481868
--> WindowsIdentity: RCOLLETT\ASPNET

Exception Information Details:
======================================
Exception Type: System.Data.Odbc.OdbcException
Errors: System.Data.Odbc.OdbcErrorCollection
Source: SQLNCLI.DLL
ErrorCode: -2146232009
Message: ERROR [42000] [Microsoft][SQL Native Client][SQL Server]Procedure or function 'WriteLog' expects parameter '@EventID', which was not supplied.
Data: System.Collections.ListDictionaryInternal
TargetSite: Void HandleError(System.Data.Odbc.OdbcHandle, RetCode)
HelpLink: NULL

StackTrace Information Details:
======================================
   at System.Data.Odbc.OdbcConnection.HandleError(OdbcHandle hrHandle, RetCode retcode)
   at System.Data.Odbc.OdbcCommand.ExecuteReaderObject(CommandBehavior behavior, String method, Boolean needReader, Object[] methodArguments, SQL_API odbcApiMethod)
   at System.Data.Odbc.OdbcCommand.ExecuteReaderObject(CommandBehavior behavior, String method, Boolean needReader)
   at System.Data.Odbc.OdbcCommand.ExecuteNonQuery()
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.DoExecuteNonQuery(DbCommand command)
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteNonQuery(DbCommand command, DbTransaction transaction)
   at Microsoft.Practices.EnterpriseLibrary.Logging.Database.FormattedDatabaseTraceListener.ExecuteWriteLogStoredProcedure(LogEntry logEntry, Database db, DbTransaction transaction)
   at Microsoft.Practices.EnterpriseLibrary.Logging.Database.FormattedDatabaseTraceListener.ExecuteStoredProcedure(LogEntry logEntry)
   at Microsoft.Practices.EnterpriseLibrary.Logging.Database.FormattedDatabaseTraceListener.TraceData(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, Object data)
   at Microsoft.Practices.EnterpriseLibrary.Logging.LogSource.TraceData(TraceEventType eventType, Int32 id, LogEntry logEntry, TraceListenerFilter traceListenerFilter)
   at Microsoft.Practices.EnterpriseLibrary.Logging.LogWriter.ProcessLog(LogEntry log)
Category:
Priority: -1
EventId: 6352
Severity: Error
Title:
Machine: RCOLLETT
App Domain: /LM/w3svc/1/ROOT/Hsb.ExceptionLogging.Web-6-128913676803481868
ProcessId: 5996
Process Name: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_wp.exe
Thread Name:
Win32 ThreadId:4588
Extended Properties:
----------------------------------------

Jul 7, 2009 at 5:17 AM

I think the issue is case-sensitivity.  It is expecting @EventID but the tracelistener passed @eventID.

 

Sarah Urmeneta
Global Technology & Solutions
Avande, Inc.
entlib.support@avanade.com

Jul 7, 2009 at 2:49 PM
I modified the WriteLog stored procedure parameters (shown below) to match the paramter names as cased in the Database trace listener code and I am still getting the exact same results. I restarted the database instance to make sure the proc wasn't being cached. Any further thoughts on what could be going on here? Is it possible that Entlib is not formatting the procedure call appropriately? 
/****** Object:  StoredProcedure [dbo].[WriteLog]    Script Date: 07/07/2009 09:42:44 ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
ALTER PROCEDURE [dbo].[WriteLog]
(
	@eventID int, 
	@priority int, 
	@severity nvarchar(32), 
	@title nvarchar(256), 
	@timestamp datetime,
	@machineName nvarchar(32), 
	@AppDomainName nvarchar(512),
	@ProcessID nvarchar(256),
	@ProcessName nvarchar(512),
	@ThreadName nvarchar(512),
	@Win32ThreadId nvarchar(128),
	@message nvarchar(1500),
	@formattedmessage ntext,
	@LogId int OUTPUT
)
AS 

	INSERT INTO [Log] (
		EventID,
		Priority,
		Severity,
		Title,
		[Timestamp],
		MachineName,
		AppDomainName,
		ProcessID,
		ProcessName,
		ThreadName,
		Win32ThreadId,
		Message,
		FormattedMessage
	)
	VALUES (
		@eventID, 
		@priority, 
		@severity, 
		@title, 
		@timestamp,
		@machineName, 
		@AppDomainName,
		@ProcessID,
		@ProcessName,
		@ThreadName,
		@Win32ThreadId,
		@message,
		@formattedmessage)

	SET @LogID = @@IDENTITY
	RETURN @LogID
Jul 7, 2009 at 4:02 PM

Upon further examination, it appears that this may be an issue with the usage of Database.GetStoredProcCommand for ODBC datasources.

When executing against against sql server using the ODBC provider, the GetStoredProcCommand method sets the command's commandText property to just the name of the procedure rather than something like:

exec ProcName ?,?,?

Perhaps this is because the odbc provider does not support parameter discovery?

If I manually set the command text in the ExecuteWriteLogStoredProcedure method of the DatabaseTraceListener as shown below, the stored procedure successfully executes when using the ODBC provider.

private static int ExecuteWriteLogStoredProcedure(int eventId, int priority, TraceEventType severity, string title, DateTime timeStamp,
                                            string machineName, string appDomainName, string processId, string processName,
                                            string managedThreadName, string win32ThreadId, string message, Database db) {
            DbCommand cmd = db.GetStoredProcCommand("writelog");
            cmd.CommandText="exec writelog ?,?,?,?,?,?,?,?,?,?,?,?,?,?";
            db.AddInParameter(cmd, "eventID", DbType.Int32, eventId);
            db.AddInParameter(cmd, "priority", DbType.Int32, priority);
            db.AddParameter(cmd, "severity", DbType.String, 32, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, severity.ToString());
            db.AddParameter(cmd, "title", DbType.String, 256, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, title);
            db.AddInParameter(cmd, "timestamp", DbType.DateTime, timeStamp);
            db.AddParameter(cmd, "machineName", DbType.String, 32, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, machineName);
            db.AddParameter(cmd, "AppDomainName", DbType.String, 512, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, appDomainName);
            db.AddParameter(cmd, "ProcessID", DbType.String, 256, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, processId);
            db.AddParameter(cmd, "ProcessName", DbType.String, 512, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, processName);
            db.AddParameter(cmd, "ThreadName", DbType.String, 512, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, managedThreadName);
            db.AddParameter(cmd, "Win32ThreadId", DbType.String, 128, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, win32ThreadId);
            db.AddParameter(cmd, "message", DbType.String, 1500, ParameterDirection.Input, false, 0, 0, null, DataRowVersion.Default, message);
            db.AddInParameter(cmd, "formattedmessage", DbType.String, message);

            db.AddOutParameter(cmd, "LogId", DbType.Int32, 4);

            db.ExecuteNonQuery(cmd);
            int logId = Convert.ToInt32(cmd.Parameters[cmd.Parameters.Count - 1].Value, CultureInfo.InvariantCulture);
            return logId;
        }

 I think at this point we are going to use a Sql Native Client host alias rather than DSNs.  This should allow us to use the more conventional ADO connection method.