Is SQL Agent manipulating the errors raised by SQL Server, before dumping them to the output file?
One customer reported that when he was executing the following batch
use master
exec sp_updatestats
from SQL Server Management Studio (SSMS) he was getting different results than when the same stored procedure was ran from a SQL Server Agent's Job. Specifically from a step of the T-SQL subsystem.
SSMS was showing the following output:
Updating [dbo].[spt_fallback_db]
0 index(es)/statistic(s) have been updated, 0 did not require update.
Updating [dbo].[spt_fallback_dev]
0 index(es)/statistic(s) have been updated, 0 did not require update.
Updating [dbo].[spt_fallback_usg]
0 index(es)/statistic(s) have been updated, 0 did not require update.
Updating [sys].[queue_messages_1003150619]
[queue_clustered_index], update is not necessary...
[queue_secondary_index], update is not necessary...
0 index(es)/statistic(s) have been updated, 2 did not require update.
Updating [sys].[queue_messages_1035150733]
[queue_clustered_index], update is not necessary...
[queue_secondary_index], update is not necessary...
0 index(es)/statistic(s) have been updated, 2 did not require update.
.
.
.
Statistics for all tables have been updated.
While if the batch is run by SQL Server Agent, through a T-SQL subsystem job's step:
Job 'TestJob' : Step 1, 'TestStep' : Began Executing 2007-11-29 17:30:49
Updating [dbo].[spt_fallback_db] [SQLSTATE 01000]
0 index(es)/statistic(s) have been updated, 0 did not require update. [SQLSTATE 01000]
Updating [dbo].[spt_fallback_dev] [SQLSTATE 01000]
0 index(es)/statistic(s) have been updated, 0 did not require update. [SQLSTATE 01000]
Updating [dbo].[spt_fallback_usg] [SQLSTATE 01000]
0 index(es)/statistic(s) have been updated, 0 did not require update. [SQLSTATE 01000]
Updating [sys].[queue_messages_1003150619] [SQLSTATE 01000]
, update is not necessary... [SQLSTATE 01000]
, update is not necessary... [SQLSTATE 01000]
0 index(es)/statistic(s) have been updated, 2 did not require update. [SQLSTATE 01000]
Updating [sys].[queue_messages_1035150733] [SQLSTATE 01000]
, update is not necessary... [SQLSTATE 01000]
, update is not necessary... [SQLSTATE 01000]
0 index(es)/statistic(s) have been updated, 2 did not require update. [SQLSTATE 01000]
.
.
.
Statistics for all tables have been updated. [SQLSTATE 01000]
As you can notice there are several differences between both sets of results:
- All rows in the Agent's log have [SQLSTATE 01000] appended to the end.
- Also in Agent's log, in all those rows referencing the name of an index, it has been removed from the message and has been left as ", update is not necessary...".
The reason for behind the first point is that SQL Server Agent, as part of its T-SQL subsystem, it implements an error handler which purposely manipulates the error received from the server and, among other things, it appends to the error message as received from the server, its corresponding ODBC SQLSTATE. In this case, it is always showing 01000, which indicates a "General warning". But why is the error handler involved here in the first place. Is SQL Server raising any errors while running this batch?
The answer is: Yes. All those messages you see when you execute sp_updatestats, are reported to you (the client actually) by raising errors (raiserror). As can be seen in the table below, the severity of all the errors we are getting is 10, and as Database Engine Error Severities describes, severities lower or equal to 10 are informational errors.
So, by running this stored procedure,
exec sp_helptext 'sp_updatestats'
I can obtain the definition of the stored procedure sp_udpatestats, and then search through it for any occurrences of raiserror. Up to 9 different errors can be raised by sp_updatestats. The following query reveals the severity level and the message text used for each of them for the locale 1033 (US English).
select * from master.sys.messages where language_id = 1033 and message_id in (15247, 15635, 14138, 15654, 15650, 15651, 15652, 15653, 15005) order by message_id
| message_id | language_id | severity | is_event_logged | text |
| 14138 | 1033 | 16 | 0 | Invalid option name '%s'. |
| 15005 | 1033 | 10 | 0 | Statistics for all tables have been updated. |
| 15247 | 1033 | 16 | 0 | User does not have permission to perform this action. |
| 15635 | 1033 | 16 | 0 | Cannot execute '%ls' because the database is in read-only access mode. |
| 15650 | 1033 | 10 | 0 | Updating %s |
| 15651 | 1033 | 10 | 0 | %d index(es)/statistic(s) have been updated, %d did not require update. |
| 15652 | 1033 | 10 | 0 | %s has been updated... |
| 15653 | 1033 | 10 | 0 | %s, update is not necessary... |
| 15654 | 1033 | 10 | 0 | Table %s: cannot perform the operation on the table because its clustered index is disabled. |
For all the errors raised by sp_updatestats with a severity of 10, the error handler implemented by SQL Server Agent will capture them and will modify the original message to append the most appropriate ODBC SQLSTATE, given the severity set by the server. So, for a severity of up to 10 (Informational), the SQLSTATE is set to 01000 (General warning).
Up to here, we have explained the reason for the first change we noticed in the output. Still you could ask yourself, but why would somebody need to know what's the value for that SQLSTATE? I cannot answer that question, to be honest. It has been like that since, SQL Server 7.0 RTM, and I'm afraid whoever wrote the specs or code for it back in 1994, will hardly remember today, what were those good reasons which moved them to put that additional information on each and every error. :-)
But, how would we explain the second difference? Why was the index name removed from the text for error whose message_id was 15653?
Well, it is the undesired effect of a workaround implemented also at that time (SQL 7 RTM), which has lived in the code until nowadays because nobody had ever reported it to us. It is actually still there in SQL Server 2008 CTP 5 code, and will most probably be also in RTM bits. Simply, because the risk for potential regressions if we remove it now is considerably high.
The workaround I'm referring to, which produces this second variation in the error message, consists of trimming (removing trailing and leading spaces) the original message, and then checking if the first character is an opening square bracket ([). If it is an opening square bracket and there is a closing square bracket, all the text in between them is removed. And that's exactly what is happening here.
When sp_updatestats raises errors 15652 or 15653 it does it this way
raiserror(15652, -1, -1, @ind_name_quoted)
or
raiserror(15653, -1, -1, @ind_name_quoted)
@ind_name_quoted is the name of the index as stored in the name column of sys.indexes, and enclosed between square brackets by using the quotename(<IndexNameAsInNameFromSysIndexes>, '[') function.
This explains the reason for the second change in the output.
So, to summarize, you should expect SQL Server Agent's T-SQL subsystem to modify any errors received by SQL Server in the following ways:
- Any leading or trailing spaces in the original message will be removed.
- If after completing the spaces trimming operation, the resulting string begins with an opening square bracket, everything between that first character and the first closing bracket will be removed.
- Any carriage-return or line-feed characters in the original error message are replaced with a blank space.
So, if you have any application which parses the output of a given T-SQL job, make sure it doesn't rely in the original format of the error messages because SQL Server Agent will modify them, one way or another.
One possible workaround would be, to use the CmdExec subsystem and run an external SQL Server client (like sqlcmd) to run the given batch and redirect its output to the step's output log.
The following examples will help illustrate the different possible problems:
raiserror('My first error message will remain intact, except that the SQLSTATE will be appended to the end.', -1, -1)
raiserror(' My second error message will loose the five trailing and five leading spaces. ', -1, -1)
raiserror('My third error message will loose the carriage-return an line-feed
and will include two spaces instead.', -1, -1)
raiserror(' [My fourth error message will loose its two leading spaces and everything up to here] and only [this] part will remain.', -1, -1)
Output from SSMS:
My first error message will remain intact, except that the SQLSTATE will be appended to the end.
My second error message will loose the five trailing and five leading spaces.
My third error message will loose the carriage-return an line-feed
and will include two spaces instead.
[My fourth error message will loose its two leading spaces and everything up to here] and only [this] part will remain.
Output when the same batch is run from SQL Server Agent:
Job 'TestJob' : Step 1, 'TestStep' : Began Executing 2007-11-29 19:29:26
My first error message will remain intact, except that the SQLSTATE will be appended to the end. [SQLSTATE 01000]
My second error message will loose the five trailing and five leading spaces. [SQLSTATE 01000]
My third error message will loose the carriage-return an line-feed and will include two spaces instead. [SQLSTATE 01000]
and only [this] part will remain. [SQLSTATE 01000]
I don't know if this post will ever be useful for anyone, but I only hope somebody is brave enough to read it all through. :-)
Comments
- Anonymous
March 05, 2008
The comment has been removed - Anonymous
March 06, 2008
The comment has been removed - Anonymous
July 21, 2008
Thanks!!! I did read it all, tested the code and you are correct. I was wondering why!!! And that million dollar question is solved. Thanks again.