Custom Target does not work when defined in config file

Question

I have created a custom target that pulls values out of the LogInfoEvent properties dictionary for sending into a stored procedure.

[Target("DatabaseModelEventLogger")]
public class SqlStoredProcedureTarget : TargetWithLayout
{
    private const string CommandTextKey = "commandText";
    private const string ConnectionStringKey = "connectionString";
    private const string HostKey = "dbHost";
    private const string DatabaseNameKey = "dbDatabase";
    private const string UsernameKey = "dbUserName";
    private const string PasswordKey = "dbPassword";

    [RequiredParameter]
    public string StoredProcedureName { get; set; } = string.Empty;

    public string SqlConnectionString { get; set; } = string.Empty;

    protected override void Write(AsyncLogEventInfo[] logEvents)
    {
        foreach (AsyncLogEventInfo eventInfo in logEvents)
        {
            this.Write(eventInfo);
        }
    }

    protected override void Write(AsyncLogEventInfo logEvent)
    {
        this.Write(logEvent.LogEvent);
    }

    protected override void Write(LogEventInfo logEvent)
    {
        this.SaveToDatabase(logEvent);
    }

    private void SaveToDatabase(LogEventInfo logInfo)
    {
        if (logInfo == null || logInfo.Parameters == null || logInfo.Parameters.Length == 0)
        {
            return;
        }

        SqlConnectionStringBuilder connectionBuilder = this.CreateConnectionStringBuilder(logInfo);

        using (var connection = new SqlConnection(connectionBuilder.ToString()))
        {
            using (var sqlCommand = new SqlCommand(this.StoredProcedureName, connection))
            {
                sqlCommand.CommandType = System.Data.CommandType.StoredProcedure;

                foreach (LogParameter parameter in logInfo.Parameters)
                {
                    // Add the parameter info using the rendered value of the layout.
                    sqlCommand.Parameters.AddWithValue(parameter.Name, parameter.Value.ToString());
                }

                sqlCommand.Connection.Open();
                sqlCommand.ExecuteNonQuery();
            }
        }
    }

    private SqlConnectionStringBuilder CreateConnectionStringBuilder(LogEventInfo logInfo)
    {
        var connectionBuilder = new SqlConnectionStringBuilder();

        if (string.IsNullOrEmpty(this.StoredProcedureName))
        {
            throw new InvalidOperationException("You can not save the provided LogEventInfo to the database without a valid CommandText property.");
        }

        // Setup the connection builder
        if (!string.IsNullOrEmpty(this.SqlConnectionString))
        {
            connectionBuilder.ConnectionString = this.SqlConnectionString;
        }

        object hostName = null;
        if (logInfo.Properties.TryGetValue(HostKey, out hostName) && hostName != null)
        {
            connectionBuilder.DataSource = hostName.ToString();
        }

        object database = null;
        if (logInfo.Properties.TryGetValue(DatabaseNameKey, out database) && database != null)
        {
            connectionBuilder.InitialCatalog = database.ToString();
        }

        object userName = null;
        object password = null;
        if ((logInfo.Properties.TryGetValue(UsernameKey, out userName) && userName != null) &&
            (logInfo.Properties.TryGetValue(PasswordKey, out password) && password != null))
        {
            connectionBuilder.IntegratedSecurity = false;
            connectionBuilder.UserID = userName.ToString();
            connectionBuilder.Password = password.ToString();
        }
        else
        {
            connectionBuilder.IntegratedSecurity = true;
        }

        return connectionBuilder;
    }
}

The first line of code that executes in my app is the registration for that target definition.

ConfigurationItemFactory.Default.Targets
        .RegisterDefinition("DatabaseModelEventLogger", typeof(SqlStoredProcedureTarget));

I then add it to my configuration file

Now when ever I want to log something, I just invoke my log methods and assign extra stuff to the event.

public void Error(string message, Exception exception, [CallerMemberName] string methodName = "")
{
    this.Log(LogLevel.Error, message, exception, methodName);
}

    public void Log(LogLevel level, string message, Exception exception = null, [CallerMemberName] string methodName = "")
    {
        var targetRuleConfig = new TargetRuleConfiguration();
        var eventInfo = new LogEventInfo(targetRuleConfig.MapLogLevelToNLog(level), this.logger.Name, message);
        eventInfo.Properties.Add(nameof(exception), exception.GetType().FullName);
        eventInfo.Properties.Add(nameof(exception.StackTrace), exception.StackTrace);
        eventInfo.Properties.Add(nameof(methodName), methodName);
        this.logger.Log(eventInfo);
    }

Nothing is ever written to the database. During runtime, I don't see any targets within LogManager.Configuration.AllTargets.

If I programmatically instance the target and set it up:

public class SqlLogConfiguration
{
    private SqlStoredProcedureTarget databaseTarget;

    public SqlLogConfiguration(string connectionString, string storedProcedure)
    {
        this.LoggingLevels = new LogLevel[] { LogLevel.Info };
        this.StoredProcedureName = storedProcedure;
        this.ConnectionString = connectionString;

        this.databaseTarget = new SqlStoredProcedureTarget();
    }

    public SqlLogConfiguration(string connectionString, string storedProcedure, LogLevelType logLevelType, params LogLevel[] levels) : this(connectionString, storedProcedure)
    {
        this.LoggingLevels = levels;
        this.LogLevelType = logLevelType;
    }

    public LogLevel[] LoggingLevels { get; private set; }

    public LogLevelType? LogLevelType { get; private set; }

    public string ConnectionString { get; set; }

    public string StoredProcedureName { get; set; }

    public void Configure()
    {
        if (!this.LogLevelType.HasValue)
        {
            throw new InvalidOperationException("The configuration has not been assigned a valid LogLevelType.");
        }

        this.databaseTarget.StoredProcedureName = StoredProcedureName;
        this.databaseTarget.SqlConnectionString = ConnectionString;

        LogManager.Configuration.AddTarget("Sql", this.databaseTarget);

        var targetRules = new TargetRuleConfiguration();
        targetRules.ConfigureTargetRules(this.databaseTarget, this.LoggingLevels, this.LogLevelType.Value);
    }
}

It writes out to the database without any issues. Why is my config file not working?

I do see a NullReferenceException being thrown when I turn on NLog internal logging. The exception happens after it finds my target though. You can see in the log file here, that it assigns my target the correct property values. I'm not sure why the exception is thrown.

2015-11-10 10:20:21.7119 Trace FindReachableObject:
2015-11-10 10:20:21.7119 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}'
2015-11-10 10:20:21.7249 Debug Setting 'UppercaseLayoutRendererWrapper.uppercase' to 'true'
2015-11-10 10:20:21.7249 Trace Wrapping LevelLayoutRenderer with UppercaseLayoutRendererWrapper
2015-11-10 10:20:21.7249 Trace FindReachableObject:
2015-11-10 10:20:21.7249 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}'
2015-11-10 10:20:21.7249 Trace FindReachableObject:
2015-11-10 10:20:21.7379 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}'
2015-11-10 10:20:21.7379 Trace  Scanning SimpleLayout ''''
2015-11-10 10:20:21.7379 Trace   Scanning LevelLayoutRenderer 'Layout Renderer: ${level}'
2015-11-10 10:20:21.7379 Trace FindReachableObject:
2015-11-10 10:20:21.7379 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2015-11-10 10:20:21.7379 Trace FindReachableObject:
2015-11-10 10:20:21.7539 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}'
2015-11-10 10:20:21.7539 Debug Setting 'SqlStoredProcedureTarget.name' to 'database'
2015-11-10 10:20:21.7539 Debug Setting 'SqlStoredProcedureTarget.storedProcedureName' to 'SaveAppLog'
2015-11-10 10:20:21.7539 Debug Setting 'SqlStoredProcedureTarget.sqlConnectionString' to 'foo'
2015-11-10 10:20:21.7539 Error Error in Parsing Configuration File. Exception : NLog.NLogConfigurationException: Exception occurred when loading configuration from C:\Users\b5130\Source\Workspaces\Core\Main\Source\Samples\ CompanyFoo.Logging\04.StoredProcedureWithEncryptedConnectionString\bin\Debug\NLog.config ---> System.NullReferenceException: Object reference not set to an instance of an object.
   at NLog.Config.XmlLoggingConfiguration.ExpandSimpleVariables(String input)
   at NLog.Config.XmlLoggingConfiguration.SetPropertyFromElement(Object o, NLogXmlElement element)
   at NLog.Config.XmlLoggingConfiguration.ParseTargetElement(Target target, NLogXmlElement targetElement)
   at NLog.Config.XmlLoggingConfiguration.ParseTargetsElement(NLogXmlElement targetsElement)
   at NLog.Config.XmlLoggingConfiguration.ParseNLogElement(NLogXmlElement nlogElement, String baseDirectory)
   at NLog.Config.XmlLoggingConfiguration.ParseTopLevel(NLogXmlElement content, String baseDirectory)
   at NLog.Config.XmlLoggingConfiguration.Initialize(XmlReader reader, String fileName, Boolean ignoreErrors)
   --- End of inner exception stack trace ---
2015-11-10 10:20:21.7699 Debug --- NLog configuration dump ---
2015-11-10 10:20:21.7699 Debug Targets:
2015-11-10 10:20:21.7699 Debug Rules:
2015-11-10 10:20:21.7699 Debug --- End of NLog configuration dump ---
2015-11-10 10:20:21.7699 Info Watching path 'C:\Users\b5130\Source\Workspaces\Core\Main\Source\Samples\ CompanyFoo.Logging\04.StoredProcedureWithEncryptedConnectionString\bin\Debug' filter 'NLog.config' for changes.
2015-11-10 10:20:21.8069 Trace FindReachableObject:
2015-11-10 10:20:21.8069 Info Found 0 configuration items
2015-11-10 10:20:21.8069 Info Configuration initialized.
2015-11-10 10:20:21.8169 Info NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 4.3.0. Product version: 4.3.0-alpha1.
2015-11-10 10:20:21.8169 Trace FindReachableObject:
2015-11-10 10:20:21.8169 Info Found 0 configuration items
2015-11-10 10:20:21.8389 Trace FindReachableObject:
2015-11-10 10:20:21.8389 Info Found 0 configuration items
2015-11-10 10:20:21.8389 Trace FindReachableObject:
2015-11-10 10:20:21.8479 Info Found 0 configuration items
2015-11-10 10:20:21.8479 Trace FindReachableObject:
2015-11-10 10:20:21.8479 Info Found 0 configuration items
2015-11-10 10:20:21.8479 Debug Targets for _04.StoredProcedureWithEncryptedConnectionString.Program by level:
2015-11-10 10:20:21.8479 Debug Trace =>
2015-11-10 10:20:21.8639 Debug Debug =>
2015-11-10 10:20:21.8639 Debug Info =>
2015-11-10 10:20:21.8639 Debug Warn =>
2015-11-10 10:20:21.8639 Debug Error =>
2015-11-10 10:20:21.8639 Debug Fatal =>
2015-11-10 10:20:21.8639 Debug Targets for  CompanyFoo.Core.Logging.LogService by level:
2015-11-10 10:20:21.8819 Debug Trace =>
2015-11-10 10:20:21.8819 Debug Debug =>
2015-11-10 10:20:21.8819 Debug Info =>
2015-11-10 10:20:21.8819 Debug Warn =>
2015-11-10 10:20:21.8819 Debug Error =>
2015-11-10 10:20:21.8939 Debug Fatal =>
2015-11-10 10:20:21.8939 Trace LogFactory.Flush(00:00:15)
2015-11-10 10:20:21.8939 Trace Flushing all targets...
2015-11-10 10:20:21.8939 Trace ForEachItemInParallel() 0 items
2015-11-10 10:20:22.4297 Info Shutting down logging...
2015-11-10 10:20:22.4297 Info Stopping file watching for path 'C:\Users\b5130\Source\Workspaces\Core\Main\Source\Samples\ CompanyFoo.Logging\04.StoredProcedureWithEncryptedConnectionString\bin\Debug' filter 'NLog.config'
2015-11-10 10:20:22.4297 Info Closing old configuration.
2015-11-10 10:20:22.4297 Trace LogFactory.Flush(00:00:15)
2015-11-10 10:20:22.4407 Trace Flushing all targets...
2015-11-10 10:20:22.4407 Trace ForEachItemInParallel() 0 items
2015-11-10 10:20:22.4407 Debug Closing logging configuration...
2015-11-10 10:20:22.4407 Debug Finished closing logging configuration.
2015-11-10 10:20:22.4407 Debug Targets for _04.StoredProcedureWithEncryptedConnectionString.Program by level:
2015-11-10 10:20:22.4407 Debug Trace =>
2015-11-10 10:20:22.4407 Debug Debug =>
2015-11-10 10:20:22.4587 Debug Info =>
2015-11-10 10:20:22.4587 Debug Warn =>
2015-11-10 10:20:22.4587 Debug Error =>
2015-11-10 10:20:22.4587 Debug Fatal =>
2015-11-10 10:20:22.4587 Debug Targets for  CompanyFoo.Core.Logging.LogService by level:
2015-11-10 10:20:22.4587 Debug Trace =>
2015-11-10 10:20:22.4737 Debug Debug =>
2015-11-10 10:20:22.4737 Debug Info =>
2015-11-10 10:20:22.4737 Debug Warn =>
2015-11-10 10:20:22.4737 Debug Error =>
2015-11-10 10:20:22.4737 Debug Fatal =>
2015-11-10 10:20:22.4737 Info Logger has been shut down.

Update

If I set a break point on the three Write methods that my Target overrides, the debugger never hits them. This seems to confirm that somethings is going wrong while NLog is trying to setup my Target from config and it never gets added to the log manager configuration.

I've also determined that the null reference is coming because the LogManager.Configuration property is null. Why would that not be set? I'm not manually replacing it anywhere, so this should be an instance loaded from the config file right?

Joe · Accepted Answer

I found that commenting out the parameter elements in your target would allow the logger to load without exception.

If you add the following, the config file is parsed without exception.

[Target("DatabaseModelEventLogger")]
public class SqlStoredProcedureTarget : TargetWithLayout
{
    //removed for brevity...

    public SqlStoredProcedureTarget()
    {
        this.Parameters = new List();
    }

    /// 
    /// Gets the collection of parameters. Each parameter contains a mapping
    /// between NLog layout and a database named or positional parameter.
    /// 
    /// 
    [ArrayParameter(typeof (DatabaseParameterInfo), "parameter")]
    public IList Parameters { get; private set; }

    //removed for brevity...
}

Custom Target does not work when defined in config file

Answers (1)

Related Questions