0

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
0

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
  • Thanks. Are you saying that the insert and update statements inside the cursor are nested transactions? I'm trying to understand what is causing the transaction commit message. I'm wondering if I should rewrite the sproc and get rid of the cursor, but don't want to spend the time with the re-write and still end up with the transaction commit error. I'm wondering what I can do to be certain of eliminating this error? Thanks. – lance-p Apr 8 '16 at 18:35
  • No. Unless you have implicit_transactions set on (and that would be pretty unusual & you would know) then those commands are not creating transactions. My guess was that one of the sub procedures that you aren't displaying has transactions built into it. SalesForce.dbo.SF_RefreshIAD or [RemoteServer].[Blog].[dbo].[data_Service_RunTime]. It's also possible that since you are hitting a remote server a transaction is being created implicitly. – Kenneth Fisher Apr 8 '16 at 18:47
0

The problem is occurring with the SalesForce.dbo.SF_RefreshIAD stored procedure. You are using a Linked Server in that proc (as noted in the comment "call sproc that refreshes local data from SF cloud linkserver") and a query in that proc that is using that Linked Server is encountering an error. Errors across Linked Servers are one of the few types of errors that invalidate (i.e. cancel immediately) an existing transaction. Typically this just means that the transaction gets auto-rolled-back, but when using the TRY...CATCH construct, the operation still needs to pass control to the CATCH block, even though the transaction was already rolled-back/aborted. This can be seen in the error message you are receiving, stating:

The current transaction cannot be committed and cannot support operations that write to the log file. Roll back the transaction.

This error means that you can't do anything that would require an entry in the Transaction Log. You need to update all stored procedures that use Linked Servers (the one shown here -- dbo.Sf_Sync_LoginHistory_Contacts -- and the one it calls -- SalesForce.dbo.SF_RefreshIAD) in the following manner:

  1. Put SET XACT_ABORT ON; at the top. I personally prefer to have this set to OFF, but when using Linked Servers you need to have it ON. I remember reading in one or two places years ago that it was "required" when using Linked Serves, but I can't seem to find that documentation now.
  2. In the CATCH blocks, add:

    IF (XACT_STATE() <> 0)
    BEGIN
      ROLLBACK TRAN;
    END;
    

    This probably isn't needed in procs that do not have a BEGIN TRAN, so I would start by adding it to only the procs that have a BEGIN TRAN. If you still run into the "Transaction count after EXECUTE indicates a mismatching number of BEGIN and COMMIT statements." error then you might need to add it to procs like the one shown in the question, but I would think that it would be too late at that point to call ROLLBACK since the error should be generated upon the inner proc exiting.

The outer proc (the one shown in the question) doesn't have a BEGIN TRAN, but does have DML statements against a Linked Server -- [RemoteServer] -- so it is probably best to at least add SET XACT_ABORT ON; to the top of this one.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.