September 5, 2012 at 6:11 am
Hello,
While getting a handle on how to trap errors in stored procedures and how
this works when the procedure is called from within a job, I encountered
some odd behaviour which I would like to try and have someone help me
understand.
It's not that there's a problem as such, more a lack of understanding why
things work the way they do, so please bear with me as in order to try and
illustrate the mystery I need to show you what I'm doing.
OK, first I have a simple test stored procedure which forms the core of my
testing as follows:
CREATE PROC [dbo].[USP_Test]
@In_Value VARCHAR(30),
@status INT OUTPUT
AS
BEGIN
SET NOCOUNT ON;
SET @status = 0;
PRINT '* USP_Test - Starting';
PRINT '* Input Parameter = ' + @In_Value;
DECLARE @TestTable TABLE
(
TestCol1 INT NOT NULL
);
BEGIN TRY
PRINT'* Start of TRY block'
INSERT INTO @TestTable(TestCol1)
VALUES(NULL)
PRINT '* End of TRY block'
END TRY
BEGIn CATCH
PRINT '* Start of CATCH block'
SET @status = 1
RAISERROR('Forced Error',15,1)
PRINT '* End of CATCH block'
END CATCH
PRINT '* USP_Test - Ending';
END
In order to test certain behaviours I am calling this SP in two ways.
The first is within a job I've created with two steps that I've called
"TestJob". Both of this job's steps are T-SQL and are coded as follows:
Step 1 -
DECLARE @status INT;
EXEC USP_Test 'Test Job String Value',
@status OUTPUT;
PRINT 'Return Value of @status ' + CAST(@Status AS VARCHAR(6));
Step 2 -
PRINT '* Step 2 of the job is running'
The second way I call my test SP is via SSMS's query window like this:
DECLARE @status INT;
EXEC USP_Test 'Test Value',@Status OUTPUT;
PRINT 'Return Value of @status = ' + CAST(@Status AS VARCHAR(6));
I've configured the job steps to send output into a txt file for viewing the
results of job and SP execution.
When I execute the T-SQL code via SSMS, the results window shows the
following:
* USP_Test - Starting
* Input Parameter = Test Value
* Start of TRY block
* Start of CATCH block
Msg 50000, Level 15, State 1, Procedure USP_Test, Line 28
Forced Error
* End of CATCH block
* USP_Test - Ending
Return Value of @status = 1
So far, so good. I see the generated error message from RAISERROR() shown
where I expected I.e. at the point of the caught error in the CATCH block.
However, when I look at the results of the output from my test job calling
the same SP, I see the following:
Job 'Test Job' : Step 1, 'Task 1' : Began Executing 2012-09-05
10:17:56
Msg 50000, Sev 15, State 1, Line 28 : Forced Error [SQLSTATE 42000]
Msg 0, Sev 15, State 1, Line 12 : * USP_Test - Starting [SQLSTATE 01000]
Msg 0, Sev 15, State 1, Line 13 : * Input Parameter = Test Job String
Value [SQLSTATE 01000]
Msg 0, Sev 15, State 1, Line 20 : * Start of TRY block [SQLSTATE 01000]
Msg 0, Sev 15, State 1, Line 26 : * Start of CATCH block [SQLSTATE
01000]
Two things puzzle me about the above results.
The first is the fact that the forced error produced via
RAISERROR() is reported BEFORE the SP's PRINT statement steps? I don't
understand the non-linear nature of this.
The second is why each PRINT statement result is
reported as an error with an error message of zero. I would have expected to
see the results of the PRINT statements output as normal before the
RAISERROR() statement was encountered and then the forced error message and
then nothing as the SP within the job would exit at that point with the
RAISERROR() level 15.
The other odd thing is that if I replace the first PRINT command within the
TRY block with a SELECT instead, then the output of this SELECT is shown
BEFORE the forced error text.
So, it seems that using SELECT shows results in a more linear fashion than PRINT does.
I would be grateful if anyone can please enlighten me as to why the above
behaviours occur?
Regards
Steve
September 5, 2012 at 6:21 am
For what its worth, the output of PRINT will render when the batch has COMPLETED, whereas RAISERROR will render immediately. This may explain why you're seeing RAISERROR output before PRINT
:exclamation: "Be brave. Take risks. Nothing can substitute experience." :exclamation:
September 5, 2012 at 6:57 am
Robin Sasson (9/5/2012)
For what its worth, the output of PRINT will render when the batch has COMPLETED, whereas RAISERROR will render immediately. This may explain why you're seeing RAISERROR output before PRINT
I think that explains quite a bit. Thanks.
November 20, 2013 at 7:12 pm
What I found that was more interesting to me (and not mentioned in this example), was that the output of the PRINT statement was changed. Here is my example:
Before RAISERROR:
15:30:02: Checking to see if data for 11/12/2013 has already been imported into the COPS_VPS_ASSOCIATION_TABLE... [SQLSTATE 01000]
After RAISERROR:
Msg 0, Sev 16, State 1, Line 60 : 16:00:02: Checking to see if data for 11/19/2013 has already been imported into the COPS_VPS_ASSOCIATION_TABLE... [SQLSTATE 01000]
The difference between the times and dates are because the second example was run one week + one half-hour later than the first example.
What I found interesting was that the presence of the RAISERROR prefixed my PRINT statements with RAISERROR-type data, i.e., Msg, Sev, State, Line. Furthermore, if the RAISERROR is not invoked, these PRINT statements print without this prefixed information. (SQL Server 2005, if that makes a difference.) I am intrigued by the fact that RAISERROR actually changed PRINT output that had already been spooled. My results also corresponded with this post. The following was the first output:
Msg 50000, Sev 16, State 5, Line 534 : The file for date '11/19/2013' is not ready. [SQLSTATE 42000]
Viewing 4 posts - 1 through 3 (of 3 total)
You must be logged in to reply to this topic. Login to reply