Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

 All Forums
 SQL Server 2005 Forums
 SSIS and Import/Export (2005)
 OnVariableChangedValue

Author  Topic 

talleyrand
Starting Member

35 Posts

Posted - 2008-02-13 : 14:00:04
Howdy all,

Sorry to crit with a wall of text in my second post.

To set the scene, we're currently using SQL Server logging for our SSIS packages. We've been running logged for a few months now and I've developed an itch to poke around and discover what I can in our logs. It seems like it'd be nice to tie SSRS into it and so maybe I'll suggest we put up a dashboard (everything ran, nothing failed), perhaps it'll just be diagnostic element (package A failed with 'A commit failed.'), or some trending (this package is taking longer every day). Who knows at this point, I'm just trying to see what I can come up with.

We have OnInformation event logged but not OnPipelineRowsSent. I saw the fine article on slicing the message field to get items like row count out. All that text processing is fine and I can pull similar data with the OnInformation event being logged (file names, row counts, times, etc) but I'd like to get it into a more streamlined format. "Oh hey look, I can set the OnVariableValueChanged event to be logged and by unhiding the column in variable window, I can tell it to raise the event to be captured, problem solved."

Now of course those of you who have had similar thoughts have seen the same wonderful information in your log provider.
event |message
--------------------------------------------------
OnVariableValueChanged |MyExcellentVariable

That tells us what variable changed but how did it? I spent a few days taunting the devs for this boneheaded decision, seriously wtf would you not do something useful like variable name and new value? Where's the value in knowing that an item changed but not how it changed. The best theory I have is that from a most general case, while the information I want to log is primative data types, if someone had the change event on a type of Object, you wouldn't be able to accurately capture the new value of it.

Being OCD and all, I found all sorts of great System variables scoped to OnVariableValueChanged in the OnChangedEventVariable handler. Look ma, VariableValue and VariableName! Break pointed it and low and behold, that's the information I want. I whipped up Script Task and added a Dts.Log(String.Format("{0} : {1}", variableName, variableValue), 0, dataBytes) with all the success you'd expect if I was posting here. To help in searches, the other variables scoped to OnVariableValueChanged are EventHandlerStartTime, SourceDescription, SourceName, VariableValue, VariableDescription, LocaleID, Propogate, SourceID, VariableName, VariableID.

It seems that certain Tasks have custom logging events so to make that work for a Script Task, one needs to explicitly add in the logging for that component and for Script Tasks, its element is ScriptTaskLogEntry. Funny thing, the place where I want to use the script task is in the event handler. Apparently, the event handler isn't a container that the logging can reach.

I'm open to ideas but my current train of thought is that a custom component would suit my needs. I'd rather not have to copy/paste the solution into every package like I could do with Jamie's SSIS: Custom Logging Using Event Handlers post. No knock on it, mind you, just not my preferred solution. I'd love to extend the SSIS Log provider for SQL Server to make it do what I want with the event but fat chance of that not being sealed. The other thought I had was that maybe a custom event would help me out but I haven't figured out how that'd help but I think I might have caught a reference to that on a blog post.

TIA for any suggestions and hell, just for helping me organize my thoughts by putting them to text.


[edit]I suppose another option is to use Dts.Events.FireX within the EventHandler and just mask it as an OnInformation or something of that nature that is logged natively.[/edit]

Qualis
Posting Yak Master

145 Posts

Posted - 2008-02-14 : 15:24:03
Well, after a bit of research... You cannot access Variables if you roll your own Log Provider. That only leaves Events as a possibility. I created a package w/ a for loop and wired up my variable to increment from 0 to 10. I set the variable's Raise Change Event to true. I then created the event handler for the OnVariableValueChanged event and dropped a script task in. I added VariableName and VariableValue to the Read Only Variables. I went into the script and tried to use Dts.Log and Dts.Logging.Log.

As it turns out, these raise their own events for logging much like OnVariableValueChanged. To see this, drag a scrip task onto your Control Flow and then go to logging and look at the details for the Script task. You will see at the bottom that you can log ScriptTaskLogEntry. The only way the log entries from Dts.Log and Dts.Logging.Log are written out is if that is checked. Unfortunately, you cannot set logging for Event Handlers.

To get around this, I used:

Dts.Events.FireInformation(0, "Variable Value Changed Event", _
"Variable '" + Dts.Variables("VariableName").Value.ToString() + "'=" + _
Dts.Variables("VariableValue").Value.ToString(), "", 0, True)

This of course means that you have to turn on the OnInformation logging event and that can bloat your log. To avoid getting DOUBLE log entries, I set the LoggingMode on the script in the Event Handler to Dissabled.

My results:

event source message
OnInformation OnVariableValueChanged Variable 'X'=1
OnInformation OnVariableValueChanged Variable 'X'=2
OnInformation OnVariableValueChanged Variable 'X'=3
OnInformation OnVariableValueChanged Variable 'X'=4
OnInformation OnVariableValueChanged Variable 'X'=5
OnInformation OnVariableValueChanged Variable 'X'=6
OnInformation OnVariableValueChanged Variable 'X'=7
OnInformation OnVariableValueChanged Variable 'X'=8
OnInformation OnVariableValueChanged Variable 'X'=9
OnInformation OnVariableValueChanged Variable 'X'=10
Go to Top of Page

talleyrand
Starting Member

35 Posts

Posted - 2008-02-14 : 21:38:12
Much appreciated. I ended up testing out a custom component to do my repackaging of the event. This will at least let me collect my thoughts on whether we should go down this route or try something else out. I'm thinking perhaps something else as I'd hate to have to parse a multi-value column for getting some metrics. Maybe a regex CLR function would make processing the message more palatable for OnInformation, pipelinrowssent etc.

Usage note, you'll need to have a signed key to get this into your GAC, use gacutil, etc, etc


using System;
using System.Collections.Generic;
using System.Text;
using Microsoft.SqlServer.Dts;
using Microsoft.SqlServer.Dts.Runtime;

namespace billfellows.net
{
[
System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Interoperability", "CA1405:ComVisibleTypeBaseTypesShouldBeComVisible"), System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Design", "CA1001:TypesThatOwnDisposableFieldsShouldBeDisposable"),
DtsTask
(
DisplayName = "OnVariableValueChanged Component",
Description = "Repackages the OnVariableValueChanged event to the OnInformation",
TaskType = "DTS90"
)
]
public class OnVariableValueChangedComponent : Task
{
// the name of our variable
private string m_VariableName;
private string m_VariableValue;

/// <summary>
/// Intialize our component
/// </summary>
public OnVariableValueChangedComponent()
{
m_VariableName = "VariableName";
m_VariableValue = "VariableValue";
}

/// <summary>
///
/// </summary>
/// <param name="connections">The package's Connections collection.</param>
/// <param name="variableDispenser">The System variables visible to the task.</param>
/// <param name="componentEvents">Used to raise events during execution.</param>
/// <param name="log">Used to write log entries.</param>
/// <returns></returns>
public override DTSExecResult Validate(Connections connections, VariableDispenser variableDispenser, IDTSComponentEvents events, IDTSLogging log)
{
DTSExecResult _result = DTSExecResult.Success;
foreach (string _required in new string[] {m_VariableValue, m_VariableName})
{
if (!variableDispenser.Contains(_required))
{
// notify that we are invalid b/c the variable doesn't exist
// required to use this component

events.FireError(0, "", String.Format("The variable {0} is required to exist. This only works in the Event handler for OnVariableValueChanged.", _required), "", 0);
_result = DTSExecResult.Failure;
}
}
return _result;
}

/// <summary>
/// Called by the TaskHost.
/// </summary>
/// <param name="connections">The package's Connections collection.</param>
/// <param name="variableDispenser">The System variables visible to the task.</param>
/// <param name="componentEvents">Used to raise events during execution.</param>
/// <param name="log">Used to write log entries.</param>
/// <param name="transaction">Used to enlist in transactions.</param>
/// <returns>Returns a value from the DTSExecResult enumeration indicating execution success or failure.</returns>
[System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2201:DoNotRaiseReservedExceptionTypes"), System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Globalization", "CA1303:DoNotPassLiteralsAsLocalizedParameters", MessageId = "System.Exception.#ctor(System.String)")]
public override DTSExecResult Execute
(
Connections connections
, VariableDispenser variableDispenser
, IDTSComponentEvents componentEvents
, IDTSLogging log
, object transaction
)
{
string _variableName = string.Empty;
// Could have issues with this if it's anything complex
string _variableValue = string.Empty;

if (componentEvents == null)
{
throw new ArgumentNullException("componentEvents");
}

if (componentEvents.FireQueryCancel() == true)
{
return DTSExecResult.Canceled;
}

// identify the fields we will be interested in
string[] _knownVariables =
{
m_VariableName
, m_VariableValue
};

Variables _variableCollection = null;

if (! variableDispenser.Contains(m_VariableName))
{
return DTSExecResult.Failure;
}

// Lock our variables for reading
foreach(string _variable in _knownVariables)
{
// Should probably do something clever if the variable
// doesn't exist so we don't attempt to reference it
if (variableDispenser.Contains(_variable))
{
variableDispenser.LockForRead(_variable);
}
}

// lock the variables we are going to write
//variableDispenser.LockForWrite(m_VariableName);

// Grab the Variables we care about
variableDispenser.GetVariables(ref _variableCollection);

// Iterate through the variables that we were
// able to lock. Assigning values to entities as
// available.
foreach (Variable _en in _variableCollection)
{
switch (_en.Name)
{
// profile
case "VariableName":
_variableName = _en.Value.ToString();
break;
case "VariableValue":
_variableValue = _en.Value.ToString();
break;
default:
break;
}
}
bool _fireAgain = false;
componentEvents.FireInformation(0, "ValueLogComponent", string.Format("{0}:{1}", _variableName, _variableValue), string.Empty, 0, ref _fireAgain);

// unlock before we go
_variableCollection.Unlock();

return DTSExecResult.Success;
}
}
}

Go to Top of Page
   

- Advertisement -