Identify SQL Error – Mismatched Transaction Count in SQL Server

sql-server-2008-r2sql-server-agent

On SQL Server 2008, the sproc below runs as part of a sql agent job every 4 hours. Six times in the last two months, the error below has been logged in the agent job history:

04/07/2016 20:00:00,LoginHistoryToSf,Error,0,IP-,LoginHistoryToSf,(Job
outcome),,The job failed. The Job was invoked by Schedule 108 (Every
4 Hours). The last step to run was step 1 (Sync LoginHistory for
Leads and Contacts).,00:00:18,0,0,,,,0 04/07/2016
20:00:00,LoginHistoryToSf,Error,1,IP-,LoginHistoryToSf,Sync
LoginHistory for Leads and Contacts,,Executed as user:
IP-\Administrator. — Starting SF_RefreshIAD for Contact V3.1.0
[SQLSTATE 01000] (Message 0) 20:00:00: Using Schema Error Action of
subset [SQLSTATE 01000] (Message 0) 20:00:01: Using last run time of
2016-04-07 18:45:00 [SQLSTATE 01000] (Message 0) 20:00:02: Identified
22 updated/inserted rows. [SQLSTATE 01000] (Message 0) 20:00:02:
Adding updated/inserted rows into Contact [SQLSTATE 01000] (Message 0)
Transaction count after EXECUTE indicates a mismatching number of
BEGIN and COMMIT statements. Previous count = 0 current count = 1.
[SQLSTATE 25000] (Error 266) The current transaction cannot be
committed and cannot support operations that write to the log file.
Roll back the transaction. [SQLSTATE 42000] (Error 3930). The step
failed.,00:00:18,16,3930,,,,0

I'm not sure how to reproduce or identify what might be the cause of the error. It looks like the transaction count mismatch is the cause, but since a transaction is explicitly set, I don't know how or why this is occurring or which line in the code is producing the error. Any insight is appreciated. 

GO

SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO

ALTER PROCEDURE  [dbo].[Sf_Sync_LoginHistory_Contacts]   
AS
BEGIN

BEGIN TRY
    --call sproc that refreshes local data from SF cloud linkserver
    EXEC SalesForce.dbo.SF_RefreshIAD 'SALESFORCE', 'Contact', 'Subset';
END TRY
BEGIN CATCH 
END CATCH

BEGIN TRY
    DECLARE @ID as INT, @Cursor as CURSOR, @LastRunTime datetime, @TableName varchar(50);
    Set @TableName = 'users_loginhistory';
    --Get Last Run Time varialble - the last X days of data for select
    SELECT @LastRunTime = [runtime] FROM [RemoteServer].[Blog].[dbo].[data_Service_RunTime] WHERE serviceName = @TableName;

    SET @Cursor = CURSOR FOR
    --Cursor with items  to be updated
    SELECT  bul.item_id FROM  [RemoteServer].Blog.dbo.users bu
    INNER JOIN [RemoteServer].Blog.dbo.users_loginhistory bul ON bu.uID = bul.uid 
    INNER JOIN [RemoteServer].Blog.dbo.groups bg ON bu.groupID = bg.gID
    WHERE LEFT(ISNULL(bu.salesforce_userid, ''), 3) = '003' AND bul.post_sf < 1 AND bul.date_inserted > DATEADD(day, -14, @LastRunTime)  
    AND LEFT(bu.salesforce_userid, 15) In ( 
        Select Left(Id, 15) from SALESFORCE.dbo.Contact sfc Inner Join [RemoteServer].Blog.dbo.users bu on bu.uid = Cast(IsNull(sfc.External_Id__c , 0) as bigint)
        ) 
    ORDER BY  Cast(isnull(bul.date_inserted,'') as DateTime) DESC;

    OPEN @Cursor;
    FETCH NEXT FROM @Cursor INTO @ID;

    WHILE @@FETCH_STATUS = 0
    BEGIN
        --INSERT TO SF CLOUD S
        INSERT into SALESFORCE...Login_History__c(Contact__c, Login_Date__c, Contract__c, External_ID__c) 
        SELECT distinct Cast(bu.salesforce_userid as nchar(18)), Cast(isnull(bul.date_inserted,'') as DateTime) As date_inserted, 
         Cast(isnull(bul.sf_contract_id,'')as nchar(18)) As sf_contract_id, Cast(bul.item_id as nchar(9))) 
         FROM [RemoteServer].Blog.dbo.users bu
         INNER JOIN [RemoteServer].Blog.dbo.users_loginhistory bul ON bu.uID = bul.uid 
         INNER JOIN [RemoteServer].Blog.dbo.groups bg ON bu.groupID = bg.gID
        WHERE  bul.item_id = @ID 
        ORDER BY  Cast(isnull(bul.date_inserted,'') as DateTime) DESC
        --DO UPDATE LOCAL TABLE 
        UPDATE top(1) [RemoteServer].Blog.dbo.users_loginhistory set post_sf = 1, post_sf_date = GETDATE() where item_id = @ID;
     FETCH NEXT FROM @Cursor INTO @ID;
    END

    CLOSE @Cursor;
    DEALLOCATE @Cursor;
END TRY

BEGIN CATCH
END CATCH

    --Update the Last Run Time
    Update [RemoteServer].[Blog].[dbo].[data_Service_RunTime] Set runtime = getDate() WHERE serviceName = @TableName;  

END

Best Answer

Since I don't actually see any transactions created within your SP I can only guess. But I can tell you that transactions inside a stored procedure are .. tricky.

If you have nested transactions, for example one created outside a stored procedure and one created inside the stored procedure, SQL may have a transaction count of two but it's still really only one transaction. If you perform a rollback within the stored procedure it will rollback the entire transaction (even the part outside of the SP) and then when you leave the stored procedure you'll get an error similar to what you are seeing.

In order to avoid this you have to use a SAVE TRANSACTION statement to create a savepoint in the transaction and then roll back to that point.

I've got a simple demo here. The SP part of it looks like this:

CREATE PROCEDURE usp_TransactionTest @Value int, @RollBack bit
AS
BEGIN
    BEGIN TRANSACTION
    SAVE TRANSACTION TranTest
    INSERT INTO tb_TransactionTest VALUES (@Value)
    IF @Rollback = 1 
        -- Roll back to the saved point.
        -- The transaction is not closed and  
        -- @@TRANCONT is not changed.
        ROLLBACK TRANSACTION TranTest
    -- Close the transaction created at the beginning of the SP
    COMMIT
END
GO
Related Question