none
System::ExecutionInstanceGUID <> Logging ExecutionId ????

    Question

  • Any help in understanding and working around this odd behavior is greatly appreciated!

     

    I have the default SQL database logging enabled (to sysdtslog90).

    I start my package with an ExecuteSQL task that writes most of the system variables to an execution log.

    Included is the value of the System::ExecutionInstanceGUID variable (which I thought should match the standard SSIS logging executionid value).

     

    I have an error handling ExecuteSQL task that updates my execution log with an end time and the task that failed.

    This is right out of the ProjectREAL audit approach.

     

    Problem with the Error ExecuteSQL update is that it is trying to match the SSIS log but cannot.

    This is the SQL being used:

    select top 1 @failureTask = source
      from dbo.sysdtslog90
      where executionid = @executionGuid
       and (upper(event) = 'ONERROR')
       and upper(source) <> @packageName
      order by endtime desc

     

    When I enable OnInformation event logging something interesting appears.

    The ExecutionGUID changes during validation of my one Data Flow Task in the package YET the system variable does not get updated with the new value!!!!

     

    Log Excerpt:

    1 OnInformation DFT Load Customer Test B94FDA4C-46D9-4193-BD87-12CFCB31EA1A Validation phase is beginning.
    2 OnInformation DFT Load Customer Test 282F7D2E-329A-49DB-90B6-838053114940 Validation phase is beginning.
    3 PackageStart AuditSample 282F7D2E-329A-49DB-90B6-838053114940 Beginning of package execution.
    4 OnPreExecute AuditSample 282F7D2E-329A-49DB-90B6-838053114940 
    5 OnPreExecute SCR Set Correct Execution GUID 282F7D2E-329A-49DB-90B6-838053114940 
    6 OnVariableValueChanged AuditSample 282F7D2E-329A-49DB-90B6-838053114940 ExecutionGUID
    7 OnInformation SCR Set Correct Execution GUID 282F7D2E-329A-49DB-90B6-838053114940 System Variable - Package Name AuditSample Start Time 11/14/2007 8:56:26 PM ExecutionGuid b94fda4c-46d9-4193-bd87-12cfcb31ea1a

     

    Please also reference http://forums.microsoft.com/MSDN/ShowPost.aspx?PostID=420279&SiteID=1

     

    Thursday, November 15, 2007 2:31 AM

Answers

  • The connect bug where the execution ID reported by IS Service is different than the execution ID recorded by package is fixed in SQL Server 2008. Personally, I am not aware of any plan to port the fix to Sql Server 2005 because the fix itself is quite involved and require some changes in the object interfaces.

     

    Monday, November 19, 2007 11:16 PM

All replies

  • Thursday, November 15, 2007 2:43 AM
  •  Joe Salvatore wrote:

    Any help in understanding and working around this odd behavior is greatly appreciated!

     

    I have the default SQL database logging enabled (to sysdtslog90).

    I start my package with an ExecuteSQL task that writes most of the system variables to an execution log.

    Included is the value of the System::ExecutionInstanceGUID variable (which I thought should match the standard SSIS logging executionid value).

     

    I have an error handling ExecuteSQL task that updates my execution log with an end time and the task that failed.

    This is right out of the ProjectREAL audit approach.

     

    Problem with the Error ExecuteSQL update is that it is trying to match the SSIS log but cannot.

    This is the SQL being used:

    select top 1 @failureTask = source
      from dbo.sysdtslog90
      where executionid = @executionGuid
       and (upper(event) = 'ONERROR')
       and upper(source) <> @packageName
      order by endtime desc


     



    What datatype are you using in the mapping page of the Execute sql task for @executionGuid variable?

    Notice that System::ExecutionInstanceGUID is a string variable and must be passed as string to any parameter in the execute sql task.

    I have used a a similar method for custom log and I know that the values match.
    Thursday, November 15, 2007 3:55 AM
  • Thanks for the efforts Matthew and Rafael.

    I think I have something more unusual that datatype issues.

     

    I have tried mapping my stored procs uniqueidentifier paramater to the System::ExecutionInstanceGUID variable using SSIS datatypes GUID, NVARCHAR and VARCHAR with the same result (a mismatch with te GUID being logged).

     

    The other observation I'll add is that running in VS I get a GUID switch and it appears as though I get double validation wth a different GUID for the second validation which is subsequently the GUID used for the remainder of the package and the log. Very ODD!

     

    sysdts90 log:

    id | event          | source       | executionid
    001 | OnPreValidate  | AuditSample  | 920806F9-609B-47BB-930E-4F61998B6E1E
    137 | OnPostValidate | AuditSample  | 920806F9-609B-47BB-930E-4F61998B6E1E
    138 | OnPreValidate  | AuditSample  | 728B2D62-3AEA-4917-927F-5E0834D0D55C

     

    My table value using the System::ExecutionInstanceGUID variable = 3439427B-4446-3441-432D-343644392D34

     

    This GUID switch does not occur with execution outside of VS but the GUIDs still do not match what the log is using.

     

    ALSO... noted that on subsequent package executions using VS the same GUID is somehow being cached and being reported by the System::ExecutionInstanceGUID variable as well as the first validation GUID.

     

    Second VS execution results (note similar GUIDS in log at start and in the variable):

     

    sysdts90 log:

     id | event          | source       | executionid
    001 | OnPreValidate  | AuditSample  | 920806F9-609B-47BB-930E-4F61998B6E1E
    137 | OnPostValidate | AuditSample  | 920806F9-609B-47BB-930E-4F61998B6E1E
    138 | OnPreValidate  | AuditSample  | FEA78A40-2DD6-4E58-BCF1-D5C5CD230C36

     

    My table value using the System::ExecutionInstanceGUID variable = 3439427B-4446-3441-432D-343644392D34

     

    Third execution outside of VS results (note similar GUID in just the variable):

     

    sysdts90 log:

     id | event          | source       | executionid
    001 | OnPreValidate  | AuditSample  | F3714D2A-8B3C-4D2C-BF5C-F8E795715A1C
    137 | OnPostValidate | AuditSample  | F3714D2A-8B3C-4D2C-BF5C-F8E795715A1C

    138 | OnPreValidate  | AuditSample  | F3714D2A-8B3C-4D2C-BF5C-F8E795715A1C

     

    My table value using the System::ExecutionInstanceGUID variable = 3439427B-4446-3441-432D-343644392D34

     

    Still I am lost over this behavior and how to get things operational.

    Any thoughts?

     

    Thursday, November 15, 2007 4:57 PM
  • Did you see the Connect submission on this?  It was listed in the thread you linked. https://connect.microsoft.com/SQLServer/feedback/ViewFeedback.aspx?FeedbackID=233836

    Also, have you made any copies of packages and not changed their GUID?

    What version of SSIS are you using?  RTM?  SP1?  SP2?
    Thursday, November 15, 2007 5:41 PM
  • Thanks Phil!

    I did see the submission. I wanted to add additional context by detailing the VS execution oddities and note that this was all happening within SSIS designer and not outside using code. Your point is well taken.

     

    I did verify that even though I copied my package from another that I did reGUID (is that a word?).

     

    Version of SSIS is 9.0.3054 which is post SP2 (Applied GDR2 from http://support.microsoft.com/?kbid=934458 via MS Update notification after application of SP2).

     

    I'm cosidering a SQL workaround that would set my own User::ExecutionGUID SSIS variable by getting the same value as that used by logging. Ugly short term fix but do feel that System::ExecutionInstanceGUID is broke.

     

    Any other ideas someone could share would be welcome.

    THANKS!

     

    Thursday, November 15, 2007 7:15 PM
  • [Microsoft follow-up]

    Microsoft, please reference the Connect submission I linked to above.  Any way we can get that in a hotfix, instead of waiting for SQL Server 2008?
    Thursday, November 15, 2007 7:21 PM
  • Thanks Phil!

     

    For those interested, I've a workaround that will ensure I am able to get the correct ExecutionGUID being used by logging.

    In my ExecuteSQL task that I use at the start of each package to perform some custom execution logging, I've added the following to get the GUID from sysdtslog90 rather than using the unmatched GUID from the System:ExecutionInstanceGUID variable:

    SET @ExecutionGuid = (SELECT TOP 1

    [executionid]

    FROM

    [SSIS_ETL_Audit].[dbo].[sysdtslog90]

    WHERE

    [event] = 'PackageStart'

    AND [source] = @PackageName

    AND [starttime] >= @StartTime)

     

    This simply requires mapping the System:Tongue TiedtartTime variable via parameters on the ExecuteSQL task.

     

    Hope consideration is seriously taken for fixing the population of the System:ExecutionInstanceGUID variable.

     

     

    Friday, November 16, 2007 3:11 PM
  • The connect bug where the execution ID reported by IS Service is different than the execution ID recorded by package is fixed in SQL Server 2008. Personally, I am not aware of any plan to port the fix to Sql Server 2005 because the fix itself is quite involved and require some changes in the object interfaces.

     

    Monday, November 19, 2007 11:16 PM
  • Thanks Cho.
    Monday, November 19, 2007 11:40 PM