Using the SQL Error log to help log meaningful errors for your Automated Restore jobs.

road-sign-663368_1280

 

In one of my previous posts I went over a scenario where an Auto restore job was logging Restore errors to a table and the error that was being inserted was ‘3013 – RESTORE LOG is terminating abnormally’ and this was due to SQL Server only providing the Last most error produced which is stored within ERROR_NUMBER() and ERROR_MESSAGE() at point of error.

2017-07-17 21_27_50-TS3 - Remote Desktop Connection Manager v2.7

I found this error less than useful so I set out to try and log something more meaningful , which I ended up doing for the specific error (4305) which was being encountered at the time, but I wanted to make this better and less specific to the 4305 error.

I took the original code I wrote and built upon it to provide a solution for our auto restoration woes, but first I needed to try and find some of the most common Restore error codes from SQL server that we may encounter,  here is a list (Please add a comment for any you feel I may have missed 🙂 )

 

927 — Database cannot be opened. It is in the middle of a restore.
1834 — File in use
3013 – Restore Terminated abnormally
3044 — Zero length device name
3119 –Problems were identified while planning for the RESTORE statement. Previous messages provide details.
3154 — The backup set holds a backup of a database other than the existing database.
3156 — Cannot be restored to location, issue Replace or Move
3159 – The tail of the log for the database has not been backed up. Use BACKUP LOG WITH NORECOVERY to backup the log if it contains work you do not want to lose. Use the WITH REPLACE or WITH STOPAT clause of the RESTORE statement to just overwrite the contents of the log.
3169 — Incompatible version
3201 — Cannot open backup device , file not found or access is denied
3241 – The media family on device is incorrectly formed. SQL Server cannot process this media family.
3257 –There is insufficient free space on disk volume to create the database. The database requires 1425744527360 additional free bytes, while only 655797846016 bytes are available.
4305 — The log in this backup set begins at LSN 377000000100800001, which is too recent to apply to the database. An earlier log backup that includes LSN 377000000084800001 can be restored.
4326 — The log in this backup set terminates at LSN 377000000077600001, which is too early to apply to the database. A more recent log backup that includes LSN 377000000084800001 can be restored.

 

Now that I had a nice little list of error codes –  I could enable them to log to the SQL server error log:

 


EXEC master..sp_altermessage 927, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 1834, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3013, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3044, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3119, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3154, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3156, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3159, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3169, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3201, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3241, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 3257, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 4305, 'WITH_LOG', TRUE
GO
EXEC master..sp_altermessage 4326, 'WITH_LOG', TRUE
GO

 

Now that I have switched on logging for the error codes listed above, any new occurrences of these errors will now populate the SQL server error log.

 

My next step was to adapt the code I already had from the 4305 issue to do the following:

 

  • Check the error log using xp_ReadErrorLog specifically searching for the error code 3013 for a start time of GETDATE() less 50ms and an EndTime of GETDATE().

 


DECLARE @ErrorDatetime DATETIME
DECLARE @ErrorDatetimePlusSecond DATETIME
SELECT @ErrorDatetime = DATEADD(MS,-50,GETDATE())
SET @ErrorDatetimePlusSecond = DATEADD(MS,50,@ErrorDatetime)

DECLARE @3013ErrorOccurred DATETIME
DECLARE @AllErrorMessages NVARCHAR(4000)

IF OBJECT_ID('TempDB..#Errors') IS NOT NULL
DROP TABLE #Errors

CREATE TABLE #Errors
(
LogDate DATETIME,
ProcessInfo NVARCHAR(10),
TextDetails NVARCHAR(4000)
)
INSERT INTO #Errors (LogDate,ProcessInfo,TextDetails)
EXEC xp_ReadErrorLog 0, 1, N'3013', NULL,@ErrorDatetime,@ErrorDatetimePlusSecond,N'DESC'

SELECT @3013ErrorOccurred = LogDate FROM #Errors

DELETE FROM #Errors

 

  • If the 3013 error is found for the exact time of dropping into the Catch block then search using xp_ReadErrorLog  once again but this time for the DATETIME of the 3013 error only (All Subsequent errors that would have been returned in the SSMS window will share the same DATETIME as the 3013 error)

 


IF @3013ErrorOccurred IS NOT NULL
BEGIN

--Get all Subsequent errors that occured in addition to the 3013 error (they will share the same DATETIME Stamp.

INSERT INTO #Errors
EXEC xp_ReadErrorLog 0, 1, NULL, NULL,@3013ErrorOccurred,@3013ErrorOccurred,N'DESC'

 

Now if we were to select from our temp table at this moment in time we may see something like this:

 

2017-07-17 22_32_50-SQLQuery1.sql - LAPTOP-ADRIANB_SQLDEV2.master (ADASTRA_buckmana (59))_ - Microso

 

In this example we had an occurrence of the 3013 error and also a 3241 error, but how can we make this usable to log out to a table as a single row?

 

Lets explore the rest of the code…

 


SET @AllErrorMessages =
(
SELECT TextDetails + LaggedErrorMessage + ' | '
FROM
(SELECT TextDetails,LAG(TextDetails,1,0) OVER (ORDER BY (SELECT 1)) AS LaggedErrorMessage
FROM #Errors
) AS ErrorLogInfo
WHERE TextDetails LIKE 'Error:%'
FOR XML PATH('')
)

 

  • Lets explain that one so we can really understand whats going on, First we take our temp table and apply a LAG() to it, Lag by 1 and return 0 for the default row. We want to be able to see the error code with its associated error message on the same row but keeping the natural order from the temp table so we use a little trick from David Fowler’s Post by using an ORDER BY (SELECT 1) in the OVER Clause.

 

If we were to query the temp table at this stage, this is what we would see:

 

2017-07-17 22_45_36-SQLQuery1.sql - LAPTOP-ADRIANB_SQLDEV2.master (ADASTRA_buckmana (59))_ - Microso

 

  • We want only the highlighted rows for the purpose of our error logging, Notice how we now have the correct message that corresponds to the Error number on the left, so we pop the LAG() query into a derived table so that we can filter its results using WHERE TextDetails LIKE ‘Error:%’ , which gives us the following result:

 

 

2017-07-17 22_50_40-SQLQuery1.sql - LAPTOP-ADRIANB_SQLDEV2.master (ADASTRA_buckmana (59))_ - Microso

 

 

  • Concatenate the results using TextDetails + LaggedErrorMessage:

 

 

2017-07-17 22_50_56-SQLQuery1.sql - LAPTOP-ADRIANB_SQLDEV2.master (ADASTRA_buckmana (59))_ - Microso

 

 

  • Roll it all up into one row using FOR XML PATH(”) :

 

 

2017-07-17 22_54_42-SQLQuery1.sql - LAPTOP-ADRIANB_SQLDEV2.master (ADASTRA_buckmana (59))_ - Microso

 

 

  • Assign the value to the variable @AllErrorMessages

 

  • Then finally for logging the value of @AllErrorMessages Use STUFF to clean up the trailing ‘ | ‘ which is not required for the end of the error message as this is used for separating the messages only.

 

 

So that’s the breakdown of the code, but how do we use it?

 

Put all of this inside of a the CATCH block and wrap the RESTORE statement/s in a TRY block, see below example:


BEGIN TRY

RESTORE DATABASE [SQLUnderCover]
FROM DISK = 'D:\Backups\SQLUndercover_FULL_20170717_200100.bak'

END TRY
BEGIN CATCH

DECLARE @ErrorDatetime DATETIME
DECLARE @ErrorDatetimePlusSecond DATETIME
SELECT @ErrorDatetime = DATEADD(MS,-50,GETDATE())
SET @ErrorDatetimePlusSecond = DATEADD(MS,50,@ErrorDatetime)

DECLARE @3013ErrorOccurred DATETIME
DECLARE @AllErrorMessages NVARCHAR(4000)

IF OBJECT_ID('TempDB..#Errors') IS NOT NULL
DROP TABLE #Errors

CREATE TABLE #Errors
(
LogDate DATETIME,
ProcessInfo NVARCHAR(10),
TextDetails NVARCHAR(4000)
)
INSERT INTO #Errors (LogDate,ProcessInfo,TextDetails)
EXEC xp_ReadErrorLog 0, 1, N'3013', NULL,@ErrorDatetime,@ErrorDatetimePlusSecond,N'DESC'

SELECT @3013ErrorOccurred = LogDate FROM #Errors

DELETE FROM #Errors

IF @3013ErrorOccurred IS NOT NULL
BEGIN

--Get all Subsequent errors that occured in addition to the 3013 error (they will share the same DATETIME Stamp.

INSERT INTO #Errors
EXEC xp_ReadErrorLog 0, 1, NULL, NULL,@3013ErrorOccurred,@3013ErrorOccurred,N'DESC'

SET @AllErrorMessages =
(
SELECT TextDetails + LaggedErrorMessage + ' | '
FROM
(SELECT TextDetails,LAG(TextDetails,1,0) OVER (ORDER BY (SELECT 1)) AS LaggedErrorMessage
FROM #Errors
) AS ErrorLogInfo
WHERE TextDetails LIKE 'Error:%'
FOR XML PATH('')
)

--UPDATE into your logging table
UPDATE LoggingTable
SET RestoreErrorMessage = STUFF(@AllErrorMessages,LEN(@AllErrorMessages),3,'')
WHERE RestoreID = xxx

END

END CATCH

 

 

And here is an example of what @AllErrorMessages looks like:

 

2017-07-18 00_06_06-SQLQuery1.sql - LAPTOP-ADRIANB_SQLDEV2.master (ADASTRA_buckmana (59))_ - Microso

It reads:

“Error: 3013, Severity: 16, State: 1.RESTORE DATABASE is terminating abnormally.
Error: 3241, Severity: 16, State: 0.The media family on device ‘D:\Backups\SQLUndercover_FULL_20170717_200100.bak’ is incorrectly formed. SQL Server cannot process this media family. ”

 

So that’s it – that’s how we managed to log meaningful errors into our logging table for our auto restore job. We wouldn’t usually dump a load of SQL this size into a CATCH block but for this purpose its not about performance but rather accuracy.

This works nicely for us as we are using dedicated servers for the purpose of Test restores, therefore adding additional rows to the error log is not an issue.

 

Thanks for reading.

 

 

3 thoughts on “Using the SQL Error log to help log meaningful errors for your Automated Restore jobs.

Add yours

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Create a website or blog at WordPress.com

Up ↑

%d bloggers like this: