Unit Testing Databases with tSQLt Part 5 – testing that a procedure calls another procedure

by Greg M Lucas on 18 November 2011

In Part 4, we implemented some tests for a simple INSERT procedure with output parameters and wrote the code to pass those tests – ExceptionHandler. In Part 5 we are going to extend ExceptionHandler to collect even more information by calling another stored procedure and use our tests to make sure that ExceptionHandler calls that procedure in the expected way

To recap on where we’d got to in previous sessions, we have an Exception table that will store details of SQL Server exceptions and a stored procedure called ExceptionHandler (below) which is called within a TRY…CATCH.. block and stores details about the error in the Exception table.

CREATE TABLE [log4].[Exception]
(
  [ExceptionId]     int              NOT NULL IDENTITY(1,1)
, [UtcDate]         datetime         NOT NULL
, [SystemDate]      datetime         NOT NULL
, [ErrorContext]    nvarchar ( 512 ) NULL
, [ErrorNumber]     int              NULL
, [Severity]        int              NULL
, [State]           int              NULL
, [ErrorProcedure]  nvarchar ( 128 ) NULL
, [ErrorLine]       int              NULL
, [ErrorMessage]    nvarchar ( max ) NULL
)
CREATE PROCEDURE [log4].[ExceptionHandler]
(
  @ErrorContext    nvarchar  (  512 )
, @ErrorProcedure  nvarchar  (  128 )  = NULL    OUT
, @ErrorNumber     int                 = NULL    OUT
, @Severity        int                 = NULL    OUT
, @State           int                 = NULL    OUT
, @ErrorLine       int                 = NULL    OUT
, @ErrorMessage    nvarchar  ( 4000 )  = NULL    OUT
, @ReturnMessage   nvarchar  ( 1000 )  = NULL    OUT
, @ExceptionId     int                 = NULL    OUT
)
AS
BEGIN
    SET NOCOUNT ON;

    SET @ErrorContext    = COALESCE(@ErrorContext, '');
    SET @ErrorProcedure  = COALESCE(NULLIF(@ErrorProcedure, ''), ERROR_PROCEDURE(), '');
    SET @ErrorNumber     = COALESCE(@ErrorNumber, ERROR_NUMBER(), 0);
    SET @Severity        = COALESCE(@Severity, ERROR_SEVERITY(), 0);
    SET @State           = COALESCE(@State, ERROR_STATE(), 0);
    SET @ErrorLine       = COALESCE(@ErrorLine, ERROR_LINE(), 0);
    SET @ErrorMessage    = COALESCE(@ErrorMessage, ERROR_MESSAGE()
                                , 'ERROR_MESSAGE() Not Found for @@ERROR: ' + CAST(@ErrorNumber AS varchar));

    --!============================================================================
    --!
    --! TODO: New Code for SessionInfoOutput will go here
    --!
    --!============================================================================

    --! Generate a detailed, nicely formatted error message to return to the caller
    SET @ReturnMessage  = CASE WHEN LEN(@ErrorContext) > 0 THEN @ErrorContext + ' due to ' ELSE 'ERROR! ' END
                        + CASE
                            WHEN LEN(ERROR_MESSAGE()) > 400 THEN '"' + SUBSTRING(@ErrorMessage, 1, 400) + '..."'
                            ELSE '"' + @ErrorMessage + '"'
                          END;

    --! Record what we have
    INSERT [log4].[Exception]
    (
      [ErrorContext]
    , [ErrorNumber]

    , [Severity]
    , [State]
    , [ErrorProcedure]
    , [ErrorLine]
    , [ErrorMessage]
    )
    VALUES
    (
      @ErrorContext
    , @ErrorNumber
    , @Severity
    , @State
    , @ErrorProcedure
    , @ErrorLine
    , @ErrorMessage
    );

    SET @ExceptionId = SCOPE_IDENTITY();

    SET NOCOUNT OFF;

    RETURN;
END

The user story we are working on in this session is “As a support analyst I want more information about the user session when an exception occurs – such as: calling application, login name, SPID etc“. In SQL2005/8 we can get this from master.sys.dm_exec_sessions using the @@SPID value as the lookup key. The simplest way to implement this within ExceptionHandler (above) would be to add a JOIN to this DMV but I already know (based on other user stories) that this functionality will be required elsewhere. To be properly agile, I should probably do this the simple way then refactor it later when I need this feature elsewhere but I have taken an executive decision to implement it the way I am about to describe. I have already written the following procedure and associated test to output the information I’m interested in from the dm_exec_sessions DMV and my SessionInfoOutput procedure currently looks like this:

CREATE PROCEDURE [log4].[SessionInfoOutput]
    (
      @SessionId          int
    , @HostName           nvarchar  ( 128 ) = NULL    OUT
    , @ProgramName        nvarchar  ( 128 ) = NULL    OUT
    , @NTDomain           nvarchar  ( 128 ) = NULL    OUT
    , @NTUsername         nvarchar  ( 128 ) = NULL    OUT
    , @LoginName          nvarchar  ( 128 ) = NULL    OUT
    , @OriginalLoginName  nvarchar  ( 128 ) = NULL    OUT
    , @SessionLoginTime   datetime          = NULL    OUT
    )
AS
BEGIN
    SET NOCOUNT ON

    SELECT
          @HostName           = s.[host_name]
        , @ProgramName        = s.[program_name]
        , @NTDomain           = s.nt_domain
        , @NTUsername         = s.nt_user_name
        , @LoginName          = s.login_name
        , @OriginalLoginName  = s.original_login_name
        , @SessionLoginTime   = s.login_time
    FROM
        master.sys.dm_exec_sessions AS [s] WITH (NOLOCK)
    WHERE
        s.session_id = @SessionId

    SET NOCOUNT OFF
END

This is a rather simplistic example for testing that one procedure calls another but nonetheless serves to demonstrate the approach. Only the first parameter @SessionId is mandatory, the rest are defined as OUTPUT so (in this case) will be NULL.

In this test [test_ExceptionHandler_calls_SessionInfoOutput] (shown below), I create an [expected] table which has one column for each SessionInfoOutput parameter which I then populate with the expected values – in this case, @@SPID followed by seven NULLs.

This next bit of code tells the tSQLt testing framework to replace log4.SessionInfoOutput with a procedure that just collects the input values passed to SessionInfoOutput into a table called log4.SessionInfoOutput_SpyProcedureLog.

EXEC tSQLt.SpyProcedure 'log4.SessionInfoOutput';

This is the essence of mocking an object – I have already written tests for SessionInfoOutput and in this test I just want to confirm that (a) ExceptionHandler does actually call SessionInfoOutput and (b) that the correct parameters are passed.

This scenario is a┬ábit limited since all parameters bar one will be NULL but I did say this was a simplistic example. But imagine if the called procedure was a lot more complex with numerous tests, logical branches and lots of data setup required. The key point here is that I have already written the necessary tests including all the required data set up etc. to confirm that SessionInfoOutput behaves in the required way for a given combination of inputs. Without the ability to mock SessionInfoOutput with tSQLt.SpyProcedure, the only way I can confirm that that ExceptionHandler passed in the correct values would be to retest the outcome of SessionInfoOutput including all that setup. By doing things this way, I already know that SessionInfoOutput works and all I have to do is validate what ExceptionHandler passes to SessionInfoOutput – a much simpler and quicker test to write.

Once I’ve mocked SessionInfoOutput, I can call ExceptionHandler with the minimum inputs (remember I don’t care what or even if it writes to Exception for this test). Then I collect the supplied input values from log4.SessionInfoOutput_SpyProcedureLog into an [actual] table so that I can use log4.assertEqualsTable to compare the expected and actual values. By the way, I can’t just compare [expected] with [SessionInfoOutput_SpyProcedureLog] as the SpyProcedureLog has extra an extra ID column so we can’t just do a simple comparison on the tables.

CREATE PROCEDURE [ExceptionHandlerTests].[test_ExceptionHandler_calls_SessionInfoOutput]
AS
BEGIN
    IF OBJECT_ID('[ExceptionHandlerTests].[actual]') IS NOT NULL DROP TABLE [ExceptionHandlerTests].[actual];
    IF OBJECT_ID('[ExceptionHandlerTests].[expected]') IS NOT NULL DROP TABLE [ExceptionHandlerTests].[expected];

    CREATE TABLE [ExceptionHandlerTests].[expected]
    (
      SessionId          int               NULL
    , HostName           nvarchar  ( 128 ) NULL
    , ProgramName        nvarchar  ( 128 ) NULL
    , NTDomain           nvarchar  ( 128 ) NULL
    , NTUsername         nvarchar  ( 128 ) NULL
    , LoginName          nvarchar  ( 128 ) NULL
    , OriginalLoginName  nvarchar  ( 128 ) NULL
    , SessionLoginTime   datetime          NULL
    );

    EXEC tSQLt.SpyProcedure 'log4.SessionInfoOutput';

    DECLARE @SessionId int = @@SPID;

    --! Store the expected values for subsequent comparison
    INSERT [ExceptionHandlerTests].[expected]
    VALUES (@SessionId, NULL, NULL, NULL, NULL, NULL, NULL, NULL)

    -- Exercise
    EXEC log4.ExceptionHandler 'Oops!';

    --! Collect the values of the parameters that were actually passed to usp_WorkingSetFill
    SELECT
          SessionId
        , HostName
        , ProgramName
        , NTDomain
        , NTUsername
        , LoginName
        , OriginalLoginName
        , SessionLoginTime
    INTO [ExceptionHandlerTests].[actual]
    FROM log4.SessionInfoOutput_SpyProcedureLog;

    --! Assert
    EXEC tSQLt.assertEqualsTable '[ExceptionHandlerTests].[expected]', '[ExceptionHandlerTests].[actual]';
END

So we run this test and not unexpectedly it fails like this:

[ExceptionHandlerTests].[test_ExceptionHandler_calls_SessionInfoOutput] failed: unexpected/missing resultset rows!
|_m_|SessionId|HostName|ProgramName|NTDomain|NTUsername|LoginName|OriginalLoginName|SessionLoginTime|
+---+---------+--------+-----------+--------+----------+---------+-----------------+----------------+
|<  |53       |!NULL!  |!NULL!     |!NULL!  |!NULL!    |!NULL!   |!NULL!           |!NULL!          |

The block of code below needs to be placed in ExceptionHandler (above) where indicated by TODO: New Code for SessionInfoOutput will go here.

    --!
    --! Session variables (keep it SQL2005 compatible)
    --!
    DECLARE @SessionId     int              ; SET @SessionId     = @@SPID;
    DECLARE @ServerName    nvarchar ( 128 ) ; SET @ServerName    = @@SERVERNAME;
    DECLARE @DatabaseName  nvarchar ( 128 ) ; SET @DatabaseName  = DB_NAME();

    --!
    --! log4.SessionInfoOutput variables
    --!
    DECLARE   @HostName           nvarchar  ( 128 )
            , @ProgramName        nvarchar  ( 128 )
            , @NTDomain           nvarchar  ( 128 )
            , @NTUsername         nvarchar  ( 128 )
            , @LoginName          nvarchar  ( 128 )
            , @OriginalLoginName  nvarchar  ( 128 )
            , @SessionLoginTime   datetime

    --!
    --! Get the details for the current session
    --!
    EXEC log4.SessionInfoOutput
              @SessionId          = @SessionId          OUT
            , @HostName           = @HostName           OUT
            , @ProgramName        = @ProgramName        OUT
            , @NTDomain           = @NTDomain           OUT
            , @NTUsername         = @NTUsername         OUT
            , @LoginName          = @LoginName          OUT
            , @OriginalLoginName  = @OriginalLoginName  OUT
            , @SessionLoginTime   = @SessionLoginTime   OUT

    --!
    --! For demo purposes, prove that the spy procedure replaces log4.SessionInfoOutput
    --!
    RAISERROR('Host Name should be missing if SessionInfoOutput was properly mocked: Value: %s', 0, 1, @HostName) WITH NOWAIT;

For the the purposes of this blog I have also added an extra line RAISERROR... to demonstrate that when we use tSQLt.SpyProcedure, the real stored procedure is not called at all and in this case all the outputs will be NULL. To ensure that you see the required output, I suggest running just this single test (as demonstrated below) to see the output before removing the RAISERROR(... line and re-running all tests.

tSQLt.Run'[ExceptionHandlerTests].[test_ExceptionHandler_calls_SessionInfoOutput]'
Host Name should be missing if SessionInfoOutput was properly mocked: Value: (null)
Test Case Summary: 1 test case(s) executed, 1 succeeded, 0 failed, 0 errored.

So that is the first part of the story, we now need to refactor some of our earlier tests to reflect the new columns we need to add to the Exception table. [ExceptionTableTests].[test_Exception_metadata] (created in Part 2) is the only test we have that validates columns at the table level and this will need to be updated to test for the new columns, and [ExceptionHandlerTests].[test_ExceptionHandler_inserts_columns_in_correct_order] (created in Part 4) will also need to be updated to ensure that the new columns are inserted in the correct order. The new version of our Exception table now looks like this and the refactored version of [test_ExceptionHandler_inserts_columns_in_correct_order] is below that. In order to pass this test, the [ExceptionHandler] procedure needed to have the new columns added to the INSERT step (shown below).

CREATE TABLE [log4].[Exception]
(
  [ExceptionId]        int                  NOT NULL    IDENTITY( 1,1 )
, [UtcDate]            datetime             NOT NULL
, [SystemDate]         datetime             NOT NULL
-----------------------------------------------------------------------
, [ErrorContext]       nvarchar    ( 512 )  NULL
, [ErrorNumber]        int                  NULL
, [Severity]           int                  NULL
, [State]              int                  NULL
, [ErrorProcedure]     nvarchar    ( 128 )  NULL
, [ErrorLine]          int                  NULL
, [ErrorMessage]       nvarchar    ( max )  NULL
-----------------------------------------------------------------------
, [SessionId]          int                  NOT NULL
, [ServerName]         nvarchar    ( 128 )  NOT NULL
, [DatabaseName]       nvarchar    ( 128 )  NOT NULL
, [HostName]           nvarchar    ( 128 )  NULL
, [ProgramName]        nvarchar    ( 128 )  NULL
, [NTDomain]           nvarchar    ( 128 )  NULL
, [NTUsername]         nvarchar    ( 128 )  NULL
, [LoginName]          nvarchar    ( 128 )  NULL
, [OriginalLoginName]  nvarchar    ( 128 )  NULL
, [SessionLoginTime]   datetime             NULL
)
ON [DEFAULT]
CREATE PROCEDURE [ExceptionHandlerTests].[test_ExceptionHandler_inserts_columns_in_correct_order]
AS
BEGIN
    IF OBJECT_ID('[ExceptionHandlerTests].[expected]') IS NOT NULL DROP TABLE [ExceptionHandlerTests].[expected];
    IF OBJECT_ID('[ExceptionHandlerTests].[actual]') IS NOT NULL DROP TABLE [ExceptionHandlerTests].[actual];

    --! Create a table to store what we expect to see
    CREATE TABLE [ExceptionHandlerTests].[expected]
    (
      [ErrorContext]       nvarchar  ( 512 )  NULL
    , [ErrorNumber]        int                NULL
    , [ErrorSeverity]      int                NULL
    , [ErrorState]         int                NULL
    , [ErrorProcedure]     nvarchar  ( 128 )  NULL
    , [ErrorLine]          int                NULL
    , [ErrorMessage]       nvarchar  ( max )  NULL
    , [SessionId]          int                NULL
    , [HostName]           nvarchar  ( 128 )  NULL
    , [ProgramName]        nvarchar  ( 128 )  NULL
    , [NTDomain]           nvarchar  ( 128 )  NULL
    , [NTUsername]         nvarchar  ( 128 )  NULL
    , [LoginName]          nvarchar  ( 128 )  NULL
    , [OriginalLoginName]  nvarchar  ( 128 )  NULL
    , [SessionLoginTime]   datetime           NULL
    )
    ;

    DECLARE @ErrorContext        nvarchar  (  512 )  = 'Oops!';
    DECLARE @NEW_LINE            char      (    1 )  = CHAR(10);
    DECLARE @CreateProcedureCmd  nvarchar  ( 2000 );

    --!
    --! Session values
    --!
    DECLARE @SessionId     int               = @@SPID;
    DECLARE @ServerName    nvarchar  ( 128 ) = @@SERVERNAME;
    DECLARE @DatabaseName  nvarchar  ( 128 ) = DB_NAME();

    DECLARE   @HostName           nvarchar  ( 128 )
            , @ProgramName        nvarchar  ( 128 )
            , @NTDomain           nvarchar  ( 128 )
            , @NTUsername         nvarchar  ( 128 )
            , @LoginName          nvarchar  ( 128 )
            , @OriginalLoginName  nvarchar  ( 128 )
            , @SessionLoginTime   datetime

    SELECT
          @HostName           = s.[host_name]
        , @ProgramName        = s.[program_name]
        , @NTDomain           = s.nt_domain
        , @NTUsername         = s.nt_user_name
        , @LoginName          = s.login_name
        , @OriginalLoginName  = s.original_login_name
        , @SessionLoginTime   = s.login_time
    FROM
        master.sys.dm_exec_sessions AS [s]
    WHERE
        s.session_id = @SessionId

    --! Store the expected values for subsequent comparison
    INSERT [ExceptionHandlerTests].[expected]
    VALUES
    (
      @ErrorContext
    , 8134
    , 16
    , 1
    , 'ExceptionGenerator'
    , 9
    , 'Divide by zero error encountered.'
    , @SessionId
    , @HostName
    , @ProgramName
    , @NTDomain
    , @NTUsername
    , @LoginName
    , @OriginalLoginName
    , @SessionLoginTime
    )

    SET @CreateProcedureCmd = 'CREATE PROCEDURE [ExceptionHandlerTests].[ExceptionGenerator]'
                            + @NEW_LINE + 'AS'
                            + @NEW_LINE + 'BEGIN'
                            + @NEW_LINE + '    SET ANSI_WARNINGS ON;'
                            + @NEW_LINE + '    SET ARITHABORT ON;'
                            + @NEW_LINE + ''
                            + @NEW_LINE + '    BEGIN TRY'
                            + @NEW_LINE + '        --! Force an exception that we can catch'
                            + @NEW_LINE + '        DECLARE @result float = (SELECT 1.1 / 0);'
                            + @NEW_LINE + '    END TRY'
                            + @NEW_LINE + '    BEGIN CATCH'
                            + @NEW_LINE + ''
                            + @NEW_LINE + '        EXEC log4.ExceptionHandler ' + COALESCE('''' + @ErrorContext + '''', 'NULL') + ';'
                            + @NEW_LINE + ''
                            + @NEW_LINE + '    END CATCH'
                            + @NEW_LINE + 'END'

    IF OBJECT_ID(N'[ExceptionHandlerTests].[ExceptionGenerator]', 'P') > 0
        DROP PROCEDURE [ExceptionHandlerTests].[ExceptionGenerator];

    --! Create the procedure
    EXEC (@CreateProcedureCmd);

    --! Now run the sproc
    EXEC (N'EXEC [ExceptionHandlerTests].[ExceptionGenerator];');

    --! Collect the row that was just added
    SELECT TOP 1
          [ErrorContext]
        , [ErrorNumber]
        , [ErrorSeverity]
        , [ErrorState]
        , [ErrorProcedure]
        , [ErrorLine]
        , [ErrorMessage]
        , [SessionId]
        , [HostName]
        , [ProgramName]
        , [NTDomain]
        , [NTUsername]
        , [LoginName]
        , [OriginalLoginName]
        , [SessionLoginTime]
    INTO [ExceptionHandlerTests].[actual]
    FROM [log4].[Exception]
    ORDER BY ExceptionId DESC;

    --! Assert
    EXEC tSQLt.assertEqualsTable '[ExceptionHandlerTests].[expected]', '[ExceptionHandlerTests].[actual]';
END

The Learning Curve

You may have noted that on the new definition for the Exception table, SessionId, ServerName and DatabaseName are specified as NOT NULL – this is because in my initial design I could not envisage a circumstance when these values are not available – given that they will hold values from SQL Server functions @@SPID, @@SERVERNAME or DB_NAME() respectively. Also in my original design, these three values were also output by SessionInfoOutput.

However, implementing these changes caused unexpected breaks in other tests. Some such as in [test_Exception_ExceptionId_is_unique] (Part 3) were easily addressed within the test itself by specifying values for the three new NOT NULL columns added to Exception. The second failure in [test_ExceptionHandler_calls_SessionInfoOutput] was more interesting and caused me to re-think my design somewhat. The reason that this test failed was because (as we learnt above) the call to SessionInfoOutput is mocked, meaning that no actual values are output so when ExceptionHandler went on to do the INSERT, the test failed with this error:


[ExceptionHandlerTests].[test_ExceptionHandler_calls_SessionInfoOutput] failed: Cannot insert the value NULL into column 'SessionId', table 'Log4TSqlDB.log4.Exception'; column does not allow nulls. INSERT fails.{ExceptionHandler,70}

My first thought was to use COALESCE on the INSERT within ExceptionHandler – but hang on a second, isn’t that just a dodgy workaround to get an unrelated test to pass? That is not a valid reason for changing the actual code. As a rule I prefer to avoid nullable columns but the reason the rest of the columns in this table are nullable is that I don’t want some NOT NULL restriction in my logging block breaking an application that uses it because I’ve failed to foresee a situation where something could somehow end up as NULL. So although, I can’t imagine a situation where @@SPID, @@SERVERNAME or DB_NAME() would not return a value, there could be a situation where SessionInfoOutput fails resulting in those output parameters not being populated. And if SessionInfoOutput does fail – we end up with a an unhandled exception. Not good.

So after thinking this through, the solution was to define and populate those three values within ExceptionHandler itself (so removing them from SessionInfoOutput). I used a TRY...CATCH... block within the scaled down SessionInfoOutput procedure to handle any errors. As a third party library, the Log4TSql framework should never be the reason for a consuming application breaking.

This is one of the huge advantages of following test-driven development properly – as a developer I get to encounter and deal with problems in the design/development phase before such issues ever get the chance to become bugs in production. For reference, the finished version of ExceptionHandler is below.

In the final version of ExceptionHandler all the parameters now get defaulted to some value which means that I can actually make more of the the columns NOT NULL. This will mean refactoring a few more tests but satisfies the traditionalist DBA in me that just doesn’t like nullable columns. I won’t cover the additional refactoring here but if you continue to read the posts in this series you will see the evidence of that rework.

CREATE PROCEDURE [log4].[ExceptionHandler]
(
  @ErrorContext    nvarchar  (  512 )
, @DatabaseName    nvarchar  (  128 )  = NULL    OUT
, @ErrorProcedure  nvarchar  (  128 )  = NULL    OUT
, @ErrorNumber     int                 = NULL    OUT
, @Severity        int                 = NULL    OUT
, @State           int                 = NULL    OUT
, @ErrorLine       int                 = NULL    OUT
, @ErrorMessage    nvarchar  ( 4000 )  = NULL    OUT
, @ReturnMessage   nvarchar  ( 1000 )  = NULL    OUT
, @ExceptionId     int                 = NULL    OUT
)
AS
BEGIN
    SET NOCOUNT ON;

    SET @ErrorContext    = COALESCE(@ErrorContext, '');
    SET @ErrorProcedure  = COALESCE(NULLIF(@ErrorProcedure, ''), ERROR_PROCEDURE(), '');
    SET @ErrorNumber     = COALESCE(ERROR_NUMBER(), 0);
    SET @Severity        = COALESCE(ERROR_SEVERITY(), 0);
    SET @State           = COALESCE(ERROR_STATE(), 0);
    SET @ErrorLine       = COALESCE(ERROR_LINE(), 0);
    SET @ErrorMessage    = COALESCE(ERROR_MESSAGE()
                                , 'ERROR_MESSAGE() Not Found for @@ERROR: ' + CAST(@ErrorNumber AS varchar));
    SET @DatabaseName    = COALESCE(@DatabaseName, DB_NAME());

    --!
    --! Generate a detailed, nicely formatted error message to return to the caller
    --!
    SET @ReturnMessage  = CASE WHEN LEN(@ErrorContext) > 0 THEN @ErrorContext + ' due to ' ELSE 'ERROR! ' END
                        + CASE
                            WHEN LEN(ERROR_MESSAGE()) > 400 THEN '"' + SUBSTRING(@ErrorMessage, 1, 400) + '..."'
                            ELSE '"' + @ErrorMessage + '"'
                          END;
    --!
    --! log4.SessionInfoOutput variables
    --!
    DECLARE   @SessionId          int
            , @ServerName         nvarchar    ( 128 )
            , @HostName           nvarchar    ( 128 )
            , @ProgramName        nvarchar    ( 128 )
            , @NTDomain           nvarchar    ( 128 )
            , @NTUsername         nvarchar    ( 128 )
            , @LoginName          nvarchar    ( 128 )
            , @OriginalLoginName  nvarchar    ( 128 )
            , @SessionLoginTime   datetime

    --! Populate these here rather than as part of the DECLARE to keep it SQL2005 compatible
    SET @SessionId     = @@SPID;
    SET @ServerName    = @@SERVERNAME;

    --! Get the details for the current session
    EXEC log4.SessionInfoOutput
          @SessionId          = @SessionId
        , @HostName           = @HostName           OUT
        , @ProgramName        = @ProgramName        OUT
        , @NTDomain           = @NTDomain           OUT
        , @NTUsername         = @NTUsername         OUT
        , @LoginName          = @LoginName          OUT
        , @OriginalLoginName  = @OriginalLoginName  OUT
        , @SessionLoginTime   = @SessionLoginTime   OUT

    --! Record what we have
    INSERT [log4].[Exception]
    (
      [ErrorContext]
    , [ErrorNumber]
    , [Severity]
    , [State]
    , [ErrorProcedure]
    , [ErrorLine]
    , [ErrorMessage]
    -- New Session Info columns
    , [SessionId]
    , [ServerName]
    , [DatabaseName]
    , [HostName]
    , [ProgramName]
    , [NTDomain]
    , [NTUsername]
    , [LoginName]
    , [OriginalLoginName]
    , [SessionLoginTime]
    )
    OUTPUT inserted.ExceptionId INTO @tblExceptionId
    VALUES
    (
      @ErrorContext
    , @ErrorNumber
    , @Severity
    , @State
    , @ErrorProcedure
    , @ErrorLine
    , @ErrorMessage
    -- New Session Info values
    , @SessionId
    , @ServerName
    , @DatabaseName
    , @HostName
    , @ProgramName
    , @NTDomain
    , @NTUsername
    , @LoginName
    , @OriginalLoginName
    , @SessionLoginTime
    );

    SELECT @ExceptionId = ExceptionId FROM @tblExceptionId;

    SET NOCOUNT OFF;

    RETURN;
END

The more observant reader may have also noticed that in [ExceptionHandler] above, that the line SET @ExceptionId = SCOPE_IDENTITY(); immediately after the INSERT has been replaced. I recently came across this post by Sebastian Meine talking about an issue with SCOPE_IDENTITY() and @@IDENTITY on SQL 2008. This bug, also acknowledged by Microsoft (KB2019779) only seems to affect tables with large rowcounts (i.e. 1m+) and where parallel execution plans are involved. As I have no control over how Log4TSql will be used in the real world, I decided to change my code so that this doesn’t cause a problem in the future. Although I haven’t written a test to support the code variation, all my existing tests serve to prove that my change hasn’t broken any of the required functionality.

In this section we looked at testing that one stored procedure calls another without the need to test the called procedure logic more than necessary. We also explored a little about how following test-driven development practices are helpful when we need to refactor code and also helps us make better informed design decisions earlier in the SDLC. In Part 6, I will be looking at testing a SELECT procedure.

Log4TSql is an open source logging framework for SQL Server 2005+ written by Greg M Lucas on behalf of data-centric solutions ltd and licensed for public use under the GNU Lesser General Public License. You can download the latest version of this library along with all the source code and unit tests from sourceforge. Please feel free to use and modify the library as you wish under the terms of the license. I am always interested in hearing how other people or organisations have put this framework to use.

Comments on this entry are closed.

Previous post:

Next post: