SSIS Custom Logging Task for Event Handlers

Back in June last year, Jamie Thomson (prolific SSIS blogger) blogged a great post about custom logging using event handlers.

In the post he uses an Execute SQL Task and generates an Insert statement using Expressions, pulling lots of great logging information from system variables. The idea is you create one of these in each package's OnPostExecute event handler (and any additional events you'd like to catch) and you have some handy instrumentation.

As one of the commenters on the post noted, this requires a lot of duplicated code and clipboard inheritence. Duplicate code is one of SSIS's greatest weaknesses at present with little scope for any code reuse. The only way to achieve code reuse is to write a Custom Task.

The good news is - it's not as hard as you think! Let's look at taking Jamie's example and turning it into an SSIS task that we can share and manage across packages.

Creating a Custom Task

I'm going to skip some of the details to keep this post as short as possible, so you should read these MSDN articles for background (such as which assemblies to reference, how to install into the GAC etc):

• Creating a Custom Task
• Developing a Custom Task

The Code

Now you've got all that - here's the code for our Custom Logging Task. For brevity, I've removed some of the variables from Jamie's example but it doesn't take a rocket scientist to work out how to put them back. In fact, I'd recommend adding even more, such as the System::ExecutionInstanceGUID variable.

First we need to create a class that inherits from Task and is decorated with the DtsTask attribute. We also create two properties the event (e.g. 'OnPostExecute') and the name of the connection we should use.

[DtsTask(
    DisplayName = "Custom Logging Task",
    Description = "Writes logging info into a table",
    TaskContact = "http://www.thejoyofcode.com/")]
public class CustomLoggingTask : Task
{
    // private fields to store the values of properties
    private string _connectionName;
    private string _eventType;

    /// <summary>
    /// Gets or sets the name of the connection to be used.
    /// This should be set to the name of your ADO.NET connection
    /// </summary>
    public string ConnectionName
    {
        set
        {
            _connectionName = value;
        }
        get
        {
            return _connectionName;
        }
    }

    /// <summary>
    /// Gets or sets the name of the event being logged
    /// </summary>
    public string Event
    {
        set
        {
            _eventType = value;
        }
        get
        {
            return _eventType;
        }
    }

Next we create some member fields to store the values of the variables we're going to extract:

    // private fields to store the values of package variables
    private string _packageName;
    private string _taskName;
    private string _errorCode;
    private string _errorDescription;
    private string _machineName;
    private double _packageDuration;
    
Easy peasy so far, but now things get a bit more interesting. When creating a custom Task there are two important methods in the base class that should be overriden: Validate and Execute.

Here, we override Validate and check that everything is in order. This method is executed by the designer at design-time and used to inform the user that the task isn't correctly setup - it should be pretty self explanatory.

public override DTSExecResult Validate(Connections connections, VariableDispenser variableDispenser, IDTSComponentEvents componentEvents, IDTSLogging log)
{
    const string METHOD_NAME = "CustomLoggingTask-Validate";

    try
    {
        // Is the name of the event specified?
        if (string.IsNullOrEmpty(_eventType))
        {
            componentEvents.FireError(0, METHOD_NAME, "The event property must be specified", "", -1);
            return DTSExecResult.Failure;
        }

        // Is a connection specified...
        if (string.IsNullOrEmpty(_connectionName))
        {
            componentEvents.FireError(0, METHOD_NAME, "No connection has been specified", "", -1);
            return DTSExecResult.Failure;
        }

        // Is it valid OLEDB connection?
        SqlConnection connection = connections[_connectionName].AcquireConnection(null) as SqlConnection;

        if (connection == null)
        {
            componentEvents.FireError(0, METHOD_NAME, "The connection is not a valid ADO.NET connection", "", -1);
            return DTSExecResult.Failure;
        }

        // Do we have a SourceID variable? - this ensures we're in an event handler
        if (!variableDispenser.Contains("System::SourceID"))
        {
            componentEvents.FireError(0, METHOD_NAME, "No System::SourceID variable available. This task can only be used in an Event Handler", "", -1);
            return DTSExecResult.Failure;
        }

        return DTSExecResult.Success;
    }
    catch (Exception exc)
    {
        componentEvents.FireError(0, METHOD_NAME, "Validation Failed: " + exc.ToString(), "", -1);
        return DTSExecResult.Failure;
    }
}

Finally, we need to override the Execute method. This is called whenever the task fires and is the meat of your custom SSIS component. Here, we extract the variables from the package and write them to the database using ADO.NET. Note - because of this, the example only supports ADO.NET connections.

public override DTSExecResult Execute(Connections connections, VariableDispenser variableDispenser, IDTSComponentEvents componentEvents, IDTSLogging log, object transaction)
{
    try
    {
        string commandText = @"INSERT INTO SSISLog (EventType, PackageName, TaskName, EventCode, EventDescription, PackageDuration, Host) VALUES (@EventType, @PackageName, @TaskName, @EventCode, @EventDescription, @PackageDuration, @Host)";

        ReadVariables(variableDispenser);

        SqlConnection connection = (SqlConnection) connections[_connectionName].AcquireConnection(transaction);

        using (SqlCommand command = new SqlCommand())
        {
            command.CommandText = commandText;
            command.CommandType = CommandType.Text;
            command.Connection = connection;

            command.Parameters.Add(new SqlParameter("@EventType", _eventType));
            command.Parameters.Add(new SqlParameter("@PackageName", _packageName));
            command.Parameters.Add(new SqlParameter("@TaskName", _taskName));
            command.Parameters.Add(new SqlParameter("@EventCode", _errorCode ?? string.Empty));
            command.Parameters.Add(new SqlParameter("@EventDescription", _errorDescription ?? string.Empty));
            command.Parameters.Add(new SqlParameter("@PackageDuration", _packageDuration));
            command.Parameters.Add(new SqlParameter("@Host", _machineName));

            command.ExecuteNonQuery();
        }

        return DTSExecResult.Success;
    }
    catch (Exception exc)
    {
        componentEvents.FireError(0, "CustomLoggingTask-Execute", "Task Errored: " + exc.ToString(), "", -1);
        return DTSExecResult.Failure;
    }
}

Those of you who read the method carefully will have noted that we seemed to skip over an important part of the procedure - the reading of the variables in the package. Well, this takes a little time so we put it in its own method called ReadVariables. The basic idea here is that we have to use an object called the VariableDispenser to gain access to variables and we have to 'lock' them before we can use them, and 'unlock' them when we're finished. This is an important feature because it ensures that other activities aren't messing with the variables whilst we're using them.

Note that if there's any potential that a variable might not exist, we first check using the Contains() method to avoid an error.

private void ReadVariables(VariableDispenser variableDispenser)
{
    variableDispenser.LockForRead("System::StartTime");
    variableDispenser.LockForRead("System::PackageName");
    variableDispenser.LockForRead("System::SourceName");
    variableDispenser.LockForRead("System::MachineName");

    bool includesError = variableDispenser.Contains("System::ErrorCode");
    if (includesError)
    {
        variableDispenser.LockForRead("System::ErrorCode");
        variableDispenser.LockForRead("System::ErrorDescription");
    }

    Variables vars = null;
    variableDispenser.GetVariables(ref vars);

    DateTime startTime = (DateTime) vars["System::StartTime"].Value;
    _packageDuration = DateTime.Now.Subtract(startTime).TotalSeconds;
    _packageName = vars["System::PackageName"].Value.ToString();
    _taskName = vars["System::SourceName"].Value.ToString();
    _machineName = vars["System::MachineName"].Value.ToString();

    if (includesError)
    {
        _errorCode = vars["System::ErrorCode"].Value.ToString();
        _errorDescription = vars["System::ErrorDescription"].Value.ToString();
    }

    // release the variable locks.
    vars.Unlock();

    // reset the dispenser
    variableDispenser.Reset();
}

Tada!

And that's it. You could obviously take this simple task much further and add additional variables, including user variables. It's up to you! Also, I haven't coded this sample according to best practice, I've tried to make it as short as possible to squeeze it into a post.

I've uploaded a copy of the project for download. It's quick, dirty and comes with no warranty! Your own mileage may vary. Etc.

And finally

In a previous post I berated SSIS for its lack of compliance to Microsoft's own coding standards.

I've been spending quite a bit of time looking under the hood of SSIS now and I have found it to be one of the weirdest APIs I've worked with since my VB6 days. For example, the IDtsConnectionService interface has GetConnections() and GetConnectionsByType(string type) methods. The former returns a Connections object, which is a strongly typed collection of ConnectionManagers and the latter returns an ArrayList of ConnectionManagers. I can't even imagine how that made it in there.

To be fair though, you only have to speak to regular users of SSIS to discover that they love what the SSIS team have done since DTS. I suspect the focus for the first release was functionality and not a quality API. The only downside to this is that we'll be stuck with much of this API in vNext for backwards compatibility.

Kudos to the SSIS team for what they did achieve though.