[RESOLVED] Stored Procedure Stepping on Itself

I have an SP in SQL Server that looks like this (cleaned for display):

Code:

---

        BEGIN TRANSACTION
        BEGIN TRY
          'Bunch o' stuff here
          COMMIT TRANSACTION
        END TRY
        BEGIN CATCH
          ROLLBACK TRANSACTION
          PRINT 'Some meaningful statement'
          SET @result = 1
        End CATCH

---

That is repeated three times. The 'Bunch o' stuff' is a series of inelegant queries that can take a bit of time to run. Since there are three of them, the SP overall takes a few minutes to run.

This SP is launched periodically as the final step of a web service. If I run it stand alone, it appears to run fine. When launched from the web service, I thought it was running fine, and it does appear to run fine at times, but I added some logging into the web service and have started seeing some unusual results creep into the log, so I thought I'd ask about them here.

One thing I am seeing is a series of messages (three, one for each part of the SP) like this:

The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION.
The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION.
The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION.

This is followed by the three statements from the PRINT statement. This is done in an odd pattern, because I would expect the first error message to be followed by the first PRINT phrase, then the next error message followed by the second PRINT statement, and so on, but that's not what's happening. I'm seeing the three error messages followed by the three PRINT phrases. I assume that this is something about how SQL Server tracks/manages messages.

The other oddity is the message itself. Since the SP usually does work, I'm wondering why it is failing. There's an obvious answer since the SP takes so long: It is possible for the web service to fire off the SP while the SP is already executing. What does SQL Server do in that instance? How does it handle concurrent calls to an SP?

There is clearly a BEGIN TRANSATION, and it appears to be working most of the time. Have I written that wrong in any way? Could one run of the SP be stepping on a second run of the SP and causing this?

I have written something similar at the work PC because I remember having issues but our server is currently down so I cannot see something.
As a quick test.
How about and IF on @result = 1 if true commit if false rollback , all these out of the try catch .
Also (and probably wrong but), I vaguely remember a difference between Tran and Transaction. I think I am wrong but it's a very fast test. Again I think I'm wrong on this one.

Quote:

---

The other oddity is the message itself. Since the SP usually does work, I'm wondering why it is failing. There's an obvious answer since the SP takes so long: It is possible for the web service to fire off the SP while the SP is already executing. What does SQL Server do in that instance? How does it handle concurrent calls to an SP?

---

I think that right there is the issue... I could be wrong about this, it's been some time since dealing with transactions like this, but the transactions are tied to the connection... and if you have a web service that's running and it tries to re-use the same connection (either because it's still open or pooling,or borh) ... it may not enact a new transaction as one is already in progress... the second one craps out for one reason or another, probably because things are locked from the first real transaction, so it tries to roll back, but the transaction wasn't started, so it throws the error you see. At least that's my theory.

One thing you may want to look at is the current transaction id and see if it is changing, or if it's the same, or what exactly you're dealing with.

-tg

That's interesting. I'll have to dig into it, but the nice thing about it is that I don't totally care...in this case. I'd like to understand it, so it's worth more digging, but the SP is pretty tolerant of failure for whatever reason.

Currently, I'm still studying the pattern to this, but it's almost secondary. My log of what is going on with the service has only been in place since mid-December of this year, though the service has been running for over a decade. A request got me looking at the log...and it has revealed a fair number of things. I think my users might be defective, or something like that. There are issues that they got which I should have been told about, but it looks like nobody bothered to tell me. I'm both baffled and amused.

I haven't even gotten to the part of this log that showed the issue I'm asking about here. What a treasure trove of interesting items have been revealed by logging.

Create a log table in your DB and write to that with an IDENTITY value key and a GETDATE() transaction date. You can log several of these in one call of the SPROC - get a GUID at the top of the SPROC - and write that GUID as well to the log table, so you can see all the "writes" associated with one SPROC call.

I'm thinking the SPROC calls are overlapping. I've had similar issues with SPROCS sending SMTP emails running in back ground IIS threads that run just too long.

Are you also writing a .LOG file in the backend code of the web service?

The ROLLBACK will remove any entries from the log table that were logged during the transaction.

You can use a logging table *variable* though as these do not take part in cuurent transaction.

JFYI, there are errors that automatically rollback current transaction so an explicit rollback is redundant and fails as expected.

I am writing a log, but not to a file, that's to the DB in the service. The service can be called several times in quick...ish, succession. Once all calls have been made to the service, the calling application notes that it is done and makes one final call to launch the SP. That SP can also be launched by a different application. Unfortunately, when I wrote the service, I didn't have the call that launches the SP take any arguments. I don't really know who is doing the calling.

Unfortunately, at roughly the same time, I screwed up my logging, which had been working. So, about the only thing I see is the messed up SP results, while having screwed up the logging such that I can't say as much as I should be able to about it. On Monday, I should be able to test that the fixes on the logging are working, and also be able to get a bit of testing on the SP behavior at the same time. All that exists in the logging is...pretty interesting, really. There may be a further bug that I have yet to even identify as being a bug.

OK.
I now show the office code and that is why I wrote the IF by memory reaction .
This is if the issue is NOT on how the web service is handling the SQL transactions.

So from what I can see on my code and MS examples, you either handle the Transaction commit INSIDE the TRY or you handle the transaction Commit outside the Catch.
So either way you are not doing that in your example.

So allegedly you are "leaving" and open transaction that will impact the second re-run.

At least that is what the examples specify. I could be wrong and the way you do it does not really matter but from my notes in the office, that was an issue for me. The notes are a couple of years old and scrambled but from what I made out and if I could help , i put it there. Also XACT_STATE seems to be useful.

Here are the 2 different ways:

https://docs.microsoft.com/en-us/sql...l-server-ver15
https://docs.microsoft.com/en-us/sql...l-server-ver15

I wandered off for a bit, as is my wont, but now I'm back....with more data, and more confusion.

When I run the SP from within SQL Server Management Studio (SSMS), it runs successfully without issue. The web service calls it from this routine:

Code:

---

Private Sub FireOffTheStoredProcedure()
        Using cn As New SqlClient.SqlConnection(mConString)
            Using cmd As SqlClient.SqlCommand = cn.CreateCommand
                Try
                    cn.Open()
                    cmd.CommandType = CommandType.StoredProcedure
                    cmd.CommandTimeout = 600
                    cmd.CommandText = "ReddSummaryMaintenance"
                    cmd.Parameters.Add("@result", SqlDbType.Int).Direction = ParameterDirection.ReturnValue

                    cmd.ExecuteNonQuery()
                    Dim retVal As Integer = CInt(cmd.Parameters("@result").Value)

                    If retVal <> 0 Then
                        SendResult(retVal, String.Empty)
                    Else
                        LogAction(Guid.Empty, Guid.Empty, "SP Success.")
                    End If
                    RecordAction()
                Catch ex As Exception
                    LogAction(Guid.Empty, Guid.Empty, "SP Exception: " & ex.Message)

                    SendResult(-99, ex.Message)
                End Try
            End Using
        End Using
    End Sub

---

A couple notes on that: SendResult creates a message based on the arguments and sends an email with that message. So, it has nothing to do with the service or the stored procedure, and so can be ignored. It isn't working, currently, but that's because of a change to our email system, which is irrelevant to this discussion.

LogAction is just writing some information to a table in the database. It is that information which is showing me that something is going wrong. What is being logged begins with "SP Exception: ", which you can see in the Catch block, and since that's the only place where that phrase appears, that means that an exception is being thrown and caught, with the exception message being what I showed in the OP.

I assumed that what was happening was that the SP was being launched more than once, and the second one was stepping on the first. However, after studying logs from the caller and the DB, that is not the case. The SP should only be launched once, and it IS only being launched once. The program that sends in data is calling the method shown here only one time. There aren't enough people running the program that multiple callers are stepping on one another. The logging in the DB confirms that. So, there is only one call to the method, and that method certainly shouldn't be firing the SP more than once, nor does it look like it is, but it is now ALWAYS failing, as far as I can see, while running the SP from within SSMS is always working.

@Sapator: As I just mentioned, I was wrong about there being a second re-run. There is not. I was wrong about that. Also, I DO handle the Transaction Commit inside the try. Having looked at the links you provided, I don't believe I am in violation of any of the rules stated there.

Also, just for grins, I fired off the SP twice within SSMS in rapid succession. Both ran to completion without issue. That's not the same thing as connecting from a web service, but it was what I could try.

So, I'm kind of baffled. I was wrong about two runs stepping on each other, because there is strong evidence that there are not two runs to do the stepping. The SP runs fine inside SSMS, but I get those errors from the web service. And just to make it a bit more confusing, it kind of looks like it may be running correctly, despite reporting that failure. I need to confirm that, though.

Here is a wild guess.

Are you running a SPROC from within this SPROC that is doing it's own BEGIN TRAN/COMMIT/ROLLBACK?

Regardless, if you are getting this error about having no transaction, try adding the XACT_STATE to that PRINT statement (are you able to see that?)

Well, not in THAT implementation, but this is getting stranger and stranger, as I have increasingly solid proof that the SP is actually running to completion in spite of reporting an error. Therefore, I'm going to move this call out of the web service, where it is hard to get at, and play around with it in a WinForms test application to see whether I can get more/better information.

Otherwise, though, that's not a bad guess at all. That SP is running a second SP, but unfortunately, that doesn't look to be related, since now that I look at it, I see that the inner SP has no transaction associated with it, and runs within its own Try...Catch block (failure of the inner SP doesn't really matter much for the outer SP, so any exception of the inner SP is ignored).

Sometimes inner errors cancel other transactions in ways we do not expect. Those two links that sapator gave go into the details - but it too general and hard to apply to your own use case, imo.

In the OP I mentioned that there were three blocks that started with BEGIN TRANSACTION, then there was a BEGIN TRY, some stuff, and a COMMIT. If there was an exception, then in the Catch block, the ROLLBACK happened followed by a PRINT statement. So, there are three transactions, one after the other. The inner SP is called after the second of these blocks and before the third of these blocks occur.

The output that I am getting is three copies of this line:

The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION.

but after those three copies come the PRINT statements from each CATCH block. Each is unique, so it's clearly three of those ROLLBACK TRANSACTION errors followed by the three printed statements. I would have expected that I would get one of the ROLLBACK TRANSACTION errors followed by the first printed statement, then the next ROLLBACK TRANSACTION error followed by the second printed statement, and so on. I'm a bit surprised to see the three errors followed by the three print statements. That seems somehow suggestive, but I'm not quite sure of what, other than that it didn't error early on, but attempted each of the blocks, failed on each of the blocks, and then failed after that.
XACT_STATE, and it returned 0, which is frankly correct, at that point, since the PRINT was right after the ROLLBACK. The ROLLBACK happened, though, and the PRINT happened. This is not like exceptions that I am used to, as the code all seems to have kind of worked.

I also just did a little playing around with the SP and confirmed that it really does run just fine in SSMS.

Better yet, I just confirmed that the SP is actually running correctly. I went into the DB, found a field that would be altered by the last of the three blocks, altered a value slightly, used my test app to run the SP, got the exception, then went to the DB to see that the SP had run. It had, and successfully.

So, to get to the three PRINT statements, the execution of the SP MUST be going into the Catch blocks. The exception states that ROLLBACK requires an open TRANSACTION, and ROLLBACK also only happens in the CATCH block, so that's two lines of evidence suggesting that an exception is being thrown and caught. However, the SP is doing what it should, which means that the COMMIT is occurring for each transaction, and that the CATCH block is NOT being entered, since COMMIT is the end of the...well, no it isn't.

I was about to say that COMMIT is the last line of the TRY block, but one line comes after it. If that one line is throwing an exception, then that would explain the error message. Let me try a test...

And that was it. The one line that came after the COMMIT was throwing an exception, but ONLY when run from the SP, not from SSMS. That one line rebuilt indexes on a table that should be a mess after running the SP.

So, I'll look further, but the permissions I have when running the SP via SSMS are much higher than the permissions of the login that the web service is using, and that's almost certainly the issue.

One bloody line....yeesh!

My OP was incorrect. I showed the COMMIT TRANSACTION immediately prior to the END TRY, but I totally overlooked the fact that there was one line between the two, and that line was critical. Then the error message, while utterly correct, misled me because I was overlooking the fact that the COMMIT was not the final act in the TRY block. So, I misled all of you, as well.