Unreported error in an order entry application designed in SQL

Tags:
SQL Server stored procedures
SQL Server tables
I have developed an order entry application in SQL Server for a client. One of its functions is to insert invoices into the relevant tables. The procedure only does the job 997 times out of 1000 on average. In a single day, that means that hundreds of invoices are incomplete. No errors are reported, no exceptions are raised, no additional entries are in the logs - it is just that the stored procedure doesn't run every now and then. I have stooped to submitting the stored procedure in a loop to force a retry based on the results of the last attempt. Otherwise, I have no idea. Can you offer any advice?

Answer Wiki

Thanks. We'll let you know when a new response is added.

There has to be some reason that the stored procedure isn’t running. Stored procedures do not simply not run when executed.

There may be an error which is being trapped within your T/SQL code so it’s not making it’s way back up to the calling code. I would recommend adding some logging to the procedures so that we have a better chance of seeing why the procedures are failing.

Discuss This Question: 13  Replies

 
There was an error processing your information. Please try again later.
Thanks. We'll let you know when a new response is added.
Send me notifications when members answer or reply to this question.

REGISTER or login:

Forgot Password?
By submitting you agree to receive email from TechTarget and its partners. If you reside outside of the United States, you consent to having your personal data transferred to and processed in the United States. Privacy
  • carlosdl
    When this happens, does the stored procedure run but without doing all of the operations it is supposed to do, or it does not run at all ? Is there any pattern on the data of the non-inserted invoices ?
    68,430 pointsBadges:
    report
  • Fred10538
    I'm the person who started this thread. Sorry, I have not been monitoring your answers, but I can tell you I have been monitoring the problem. The stored procedure does not run and the return value is 0. The stored proc performs many update statements, but one of those is to set one column equal to another: update _btblInvoiceLines set fQtyLastProcessLineTotExcl = fQuantityLineTotExcl where idInvoiceLines = @LineID After the stored proc has returned back to the calling Delphi program, I submit the following query select count(*) as count from _btblinvoiceLines where fQtyLastProcessLineTotExcl = 0 and idInvoiceLines = :i_iLineID If the count = 0, then I know the stored proc ran, and I exit a loop. If it didn't run, I insert a record into a log that shows me how many retries have been attempted on the lineid and exec the stored proc again. Now here's the thing. Since I put the stored proc in a loop 10 days ago, with a max of 9 retries, this stored proc has been called 1000's of times sucessfully doing it's job without any error. However, also in those 10 days, there were 111 of 1x retries, that is the stored proc was called twice before it succeeded, there were 16 of 2x retires, 3 of 3x retires, 2 of 4x retries, 3 of 5x retires, 2 of 6x retires, 3 of 7x retires, 2 x 8 retires and 2 of 9x retries. All the retires < 9 were ultimately successful, but since I had limited the retry count to 9, 9 retires of the same stored procedure on the same invoice line was coded by me to throw an error the user! I set up a trace on the server, and noted that during the period when the 9x retires were attempted, the server was doing 500 sql operations a second! I do not know how to decide what would prevent the server from running the stored proc first time, every time! I am at the stage where I'm willing to pay someone to figure this out as my reputation as a developer is at stake. (you're only as good as your last performace)
    60 pointsBadges:
    report
  • Fred10538
    Further to this: if you're confused, then so am I. Understand that in the case where the stored proc is retried once, what it means is that 20 millinseconds after the first attempt failed, the second attempt succeeded. The stored proc did not run the first time. None of the updates or inserts within the stored proc occured. Nothing else changed in the database in those 20 milliseconds, but nevertheless, the second attempt performed all it's updates and inserted all it's inserts. I shake my head in disbelief.
    60 pointsBadges:
    report
  • Denny Cherry
    Are you using explicit transactions which would be causing deadlocking, or timeouts to the client which aren't being captured correctly by the client application?
    66,005 pointsBadges:
    report
  • carlosdl
    The original recommendation to add some logging to the procedure is still valid, and that is what I would do.
    68,430 pointsBadges:
    report
  • Fred10538
    Thanks for all your input, it has helped. I have littered the stored proc with xp_logevent messages, and upon examining my own log table to determine when a retry happened, I was able to see that my stored procedure gave up in the middle, after doing some of it's select and update statements, but just before a crucial insert statement it unceremoniously exited. As I reported when I started the thread, no error was raised, and no error code was returned when this happened. So, at least I know that the Stored Proc was started and ran part-way. But that doesn't tell me why it exited, does it? To answer previous questions: 1. The transaction is started (and commited) in the Delphi app. 2. The select statements use "with (updlock)" where applicable and the update statements use "with (rowlock)" 3. There is no pattern to the data here. Do remember, that the SP often is called to process the same invoice line that it just failed-on, a split second ago, only to succeed the second time around running against the exact same unchanged data the second time. It's hard to believe, but it's true. I want the server to tell me why it couldn't do what I asked it to do, not just not do it. Is that too much to ask for, I wonder?
    60 pointsBadges:
    report
  • Denny Cherry
    Fred, Can you post the block of code that's failing and the few statements directly above it, specifically including anything with a locking hint on it. Denny
    66,005 pointsBadges:
    report
  • Fred10538
    Denny. It's not that simple. I will gladly mail you the source code files, SQL Server Logs and my own logs if you tell me where to send them.
    60 pointsBadges:
    report
  • Fred10538
    Thanks for the replies so far. I have had a chance to look back at this problem. Fortunately for me, my retry loop in the calling program has taken care of the times when the stored procedure did not run to the end the first time it was called, so no data corruption has resulted. I have littered the stored procedure with xp_logevent calls. After each select, update or insert statement I collect the last error eg. set
    @LastError = @@Error 
    if @LastError <> 0 
    begin
    set @message = "error at step 2"
    raiserror(@message,1,16) with log 
    goto myend. 
    end
    
    As the "End Updateinvoicedetail" line does not show in the log, this is an indication that an exception was raised, but it was not reported in a log nor raised to the application and the @@Error was not set. The last 4 lines of the stored procedure are thus:
    set @message = 'End   UpdateInvoicedetail - ' +  cast(@LineID as varchar)
    exec xp_logevent 55000, @message, INFORMATIONAL
    myend:
    return @LastError
    
    Here is the relevant snippet from the server log the first time the stored proc ran (but only partially) 2009-01-08 11:28:52.33 spid85 Begin UpdateInvoicedetail - 1985586 2009-01-08 11:28:52.33 spid85 selecting invoice line1985586 2009-01-08 11:28:52.33 spid85 selecting stkitem 1985586 2009-01-08 11:28:52.33 spid85 selecting invnum 1985586 2009-01-08 11:28:52.33 spid85 selecting lottracking 1985586 2009-01-08 11:28:52.33 spid85 inserting to PostST 1985586 2009-01-08 11:28:52.34 spid85 inserting to lottx 1985586 2009-01-08 11:28:52.34 spid85 selecting stkitem (2) 1985586 2009-01-08 11:28:52.34 spid85 updating stkitem 1985586 2009-01-08 11:28:52.34 spid85 select whsestk 1985586 2009-01-08 11:28:52.34 spid85 updating whsestk 1985586 2009-01-08 11:28:52.34 spid85 select LotQty 1985586 2009-01-08 11:28:52.45 spid85 update LotQty 1985586 Then as it failed to produce the results expected by the calling application, it first wrote a "retry entry" into the log. This entry shows the lineid of the line in question, with the retry count of 1 (the 1st one) and a return value from the stored procedure of 0 with a timestamp that is consistent with the other log. 92527 2009-01-08 11:29:08.093 9 11 111682 1985586-1-0 and then it called the stored procedure again (3 seconds later). This time the procedure succeeded. As can be seen by the SQL server log entries. 2009-01-08 11:29:08.12 spid85 Begin UpdateInvoicedetail - 1985586 2009-01-08 11:29:08.12 spid85 selecting invoice line1985586 2009-01-08 11:29:08.12 spid85 selecting stkitem 1985586 2009-01-08 11:29:08.12 spid85 selecting invnum 1985586 2009-01-08 11:29:08.12 spid85 selecting lottracking 1985586 2009-01-08 11:29:08.12 spid85 inserting to PostST 1985586 2009-01-08 11:29:08.12 spid85 inserting to lottx 1985586 2009-01-08 11:29:08.12 spid85 selecting stkitem (2) 1985586 2009-01-08 11:29:08.12 spid85 updating stkitem 1985586 2009-01-08 11:29:08.12 spid85 select whsestk 1985586 2009-01-08 11:29:08.12 spid85 updating whsestk 1985586 2009-01-08 11:29:08.12 spid85 select LotQty 1985586 2009-01-08 11:29:08.23 spid85 update LotQty 1985586 2009-01-08 11:29:08.26 spid85 update invoiceline 1985586 2009-01-08 11:29:08.26 spid85 End UpdateInvoicedetail - 1985586 Now the next question is what statements were executing (this is not the whole stored proc)
    set @message = '      select LotQty ' +  cast(@LineID as varchar)
    exec xp_logevent 55000, @message, INFORMATIONAL
    
    select @fQtyOnHand = isNull(fQtyOnhand,0),
    	@fQtyReserved = isNull(fQtyReserved,0)
    from _etbllottrackingQty with (UPDLOCK)
    where iLotTrackingID = @iLotID
    and iWarehouseID = @WareHouseID
    
    set @message = '      update LotQty ' +  cast(@LineID as varchar)
    exec xp_logevent 55000, @message, INFORMATIONAL
    
    update _etblLottrackingQty
    set fQtyOnHand = isNull(fQtyOnhand,0) - dbo.lower(@Qty, @fQtyOnHand),
        fQtyReserved = isNull(fQtyReserved,0) - dbo.lower(@Qty, @fQtyReserved)
    where iLotTrackingID = @iLotID
    and iWarehouseID = @WareHouseID
    
    SET @MyError = @@Error
    
    if (@MyError <> 0)
    begin
    	set @Message = 'Unable to update lottrackingqty for lineid = ' + cast(@LineID as varchar)
    	raiserror(@Message, 16,1) WITH LOG
    	goto myend
    end
    
    And here is the code for the function dbo.lower
    ALTER function [dbo].[Lower](@val1 float, @val2 float)
    returns float
    as
    begin
      if @val1 < @val2
        return @val1
      return @val2
    end
    
    Well, you did ask, MrDenny. :-)
    60 pointsBadges:
    report
  • Denny Cherry
    It appears that no one (including myself) asked what version of SQL you are using. If 2005 or higher have you tried putting TRY / CATCH logic into the stored procedure to see if that catches it? I'm curious why this select statement takes 10 seconds.
    select @fQtyOnHand = isNull(fQtyOnhand,0),
    @fQtyReserved = isNull(fQtyReserved,0)
    from _etbllottrackingQty with (UPDLOCK)
    where iLotTrackingID = @iLotID
    and iWarehouseID = @WareHouseID
    I'm wondering if the calling application is set to timeout after 30 seconds (the .NET default) and that is what is causing your problem. If the statement isn't failing, but just running to long and the calling code is stopping the database but the error isn't being reported to the calling code because it's being caught by the try/catch or something. That would explain it only happening sometimes.
    66,005 pointsBadges:
    report
  • Fred10538
    So many questions, so few milliseconds. (I've developed a sense of humour about this) Anyway, I have at last discovered the cause of the problem. Does 1025 ring a bell It is a deadlock. The deadlock always occurs on the select ... _etbllottrackingqty with (updlock) and the although the error was being reported to my application, the users on the shop-floor were just clicking "ok" - telling each other "it does that sometimes, just click ok. dumbass" Turns out that SQL server 2005, was detecting a deadlock, my application was constantly the deadlock victim, SQL server was rolling back the transaction thus far on my behalf (without me having to call a rollback) The "other application" that uses the database is a "professional application" that escalates page locks... and my retry logic was doing the job correctly! So, even though I know about the deadlock, I have left the application as it is, to retry in the face of an apparently unprocssed transaction. No harm done. Nothing ventured nothing gained. At least I can sleep at night now. :-)
    60 pointsBadges:
    report
  • carlosdl
    I think that select is taking 10 (or so) milliseconds, not seconds. I also think the timeout is one possible reason. It could be a good idea to put some logging to the calling application as well, so we can see how long the procedure is taking to end. If there is nothing more between the end of the code you pasted and the line where you log "update invoiceline", and no error is raised, I can only think of a timeout in the update to etblLottrackingQty.
    68,430 pointsBadges:
    report
  • carlosdl
    Ignore my last post, I had not read your last comments when I wrote it. Good work Fred. Now you know how users behave. Keep that in mind.
    68,430 pointsBadges:
    report

Forgot Password

No problem! Submit your e-mail address below. We'll send you an e-mail containing your password.

Your password has been sent to:

To follow this tag...

There was an error processing your information. Please try again later.

REGISTER or login:

Forgot Password?
By submitting you agree to receive email from TechTarget and its partners. If you reside outside of the United States, you consent to having your personal data transferred to and processed in the United States. Privacy

Thanks! We'll email you when relevant content is added and updated.

Following