The dreaded SQL server error 3013! ‘RESTORE LOG is terminating abnormally’ the bane of my life, until recently

The dreaded ‘3013 – RESTORE LOG is terminating abnormally’ message! the bane of my life, until recently…
So I find myself looking through our automated backup restore job history, and i see a bunch of the ‘3013’ errors and I am wondering what on earth is going wrong here, this could be anything! The error just gives me nothing to go on apart from that there is an issue restoring a transaction log file,  I do not have the time to go through every database that has the error and try and manually restore them file by file (of course I may have done this had i not have done my homework prior to seeing these , I knew the log chains were in tact 🙂 ) but seeing these errors was quite frustrating and I wanted to be able to find a more meaningful error….

So i got cracking…

I found an example database from the restore history job and attempted to restore to a point in time using the job, as expected it failed with the 3013 error! after checking the code being executed by the job I could see that this error was being captured within a Try/Catch block so I did some testing with the Files manually without the Try/Catch.

Using the same sequence of files used by the job there was in fact a log file missing from the normal directory where the transaction log backups were  located but without the try/catch I got a meaningful error message (Error number 4305) immediately followed by the 3013 error.

I wanted to test this out and see if I could come up with something to capture the ‘error before the error’ so that I could log something meaningful to the job history log tables, so I put this to the test using the below contrived example:

1. Restored the Full Database backup file to a database called 4305ErrorTest with NORECOVERY.

1. Took a Transaction log backup (to be ignored so that we can produce the 4305 error)
2. Took another log Transaction backup (this one is to be used in the example)

All pretty boring so far….

I promise – it gets better 🙂

Using the transaction Log backup taken in step 3 I am able to reproduce the issue by running the following statement:

-- SELECT ERROR_NUMBER(),ERROR_MESSAGE() EXAMPLE
BEGIN TRY
RESTORE LOG [4305ErrorTest] FROM DISK = N'C:\Backups\4305ErrorTest_LOG_150500.TRN' WITH NORECOVERY
END TRY
BEGIN CATCH
SELECT CAST(ERROR_NUMBER() AS VARCHAR(6)) + ' - ' +ERROR_MESSAGE() AS ErrorMessage
END CATCH

There it is! the dreaded 3013 with its lack of detail…

Let see what happens without Try/Catch:

--WITHOUT TRY/CATCH
RESTORE LOG [4305ErrorTest] FROM DISK = N'C:\Backups\4305ErrorTest_LOG_150500.TRN' WITH NORECOVERY

 

Aha! here is the answer to why the restore is failing – but how can we get both errors out??
Lets Try using THROW:

-- THROW EXAMPLE
BEGIN TRY
RESTORE LOG [4305ErrorTest] FROM DISK = N'C:\Backups\4305ErrorTest_LOG_150500.TRN' WITH NORECOVERY
END TRY
BEGIN CATCH
THROW
END CATCH

 

Oh THROW you are truly beautiful …BUT .. You only output as a message so you won’t do , what I need is a way to log this error to my Auto Restore job logging table , I don’t need a real-time error visual , I need something that will log the error so that I can see it when I next do my auto restore checks….hmmm…
So I had an idea… What if I could log occurrences of the error message 4305 to the error log, if I could do that then I could put an error log lookup in my catch block!

DISCLAIMER ALERT! I used this example on a dedicated Restore box , please take careful consideration where you are to use this (if you choose to of course) I can imagine that if you do not frequently cycle your logs and/or you have many errors populating the current log file then this could perform badly for you, but for my dedicated restore box example this was perfect.

So here is what i did:
First I checked sys.messages:

SELECT TOP 1 *
FROM SYS.MESSAGES
WHERE message_id = 4305

 

 

Is_Event_Logged = 0 , Lets change that:

EXEC master..sp_altermessage 4305, 'WITH_LOG', TRUE
GO

 

Now Is_Event_Logged = 1

 

A Quick test running the following code (Same code used in our first Try/Catch example) puts an entry into the error log:

-- SELECT ERROR_NUMBER(),ERROR_MESSAGE() EXAMPLE
BEGIN TRY
RESTORE LOG [4305ErrorTest] FROM DISK = N'C:\Backups\4305ErrorTest_LOG_150500.TRN' WITH NORECOVERY
END TRY
BEGIN CATCH
SELECT CAST(ERROR_NUMBER() AS VARCHAR(6)) + ' - ' +ERROR_MESSAGE() AS ErrorMessage
END CATCH

 

Great!

Now lets give this unusual example a go:

BEGIN TRY
RESTORE LOG [4305ErrorTest] FROM DISK = N'C:\Backups\4305ErrorTest_LOG_150500.TRN' WITH NORECOVERY
END TRY
BEGIN CATCH

DECLARE @ErrorDatetime DATETIME
DECLARE @ErrorDatetimePlusSecond DATETIME
SELECT @ErrorDatetime = DATEADD(SECOND,-1,GETDATE())
SET @ErrorDatetimePlusSecond = DATEADD(SECOND,2,@ErrorDatetime)

--Capture the 4305 if this occured
DECLARE @Error4305Exists DATETIME
DECLARE @Error4305Message NVARCHAR(255)
DECLARE @Table TABLE
(
LogDate DATETIME,
ProcessInfo NVARCHAR(10),
TextDetails NVARCHAR(255)
)
INSERT INTO @Table
EXEC xp_ReadErrorLog 0, 1, N'4305', NULL,@ErrorDatetime,@ErrorDatetimePlusSecond,N'DESC'

SELECT @Error4305Exists = LogDate FROM @Table

DELETE FROM @Table

IF @Error4305Exists IS NOT NULL
BEGIN
INSERT INTO @Table
EXEC xp_ReadErrorLog 0, 1, N'The log in this backup set begins at', NULL,@ErrorDatetime,@ErrorDatetimePlusSecond,N'DESC'

SELECT @Error4305Message = TextDetails FROM @Table

SET @Error4305Message = '4305 - ' + @Error4305Message + ' , ' + CAST(ERROR_NUMBER() AS VARCHAR(6)) + ' - ' +ERROR_MESSAGE()

SELECT @Error4305Message AS ErrorMessage

DELETE FROM @Table

END
ELSE
BEGIN
SELECT CAST(ERROR_NUMBER() AS VARCHAR(6)) + ' - ' +ERROR_MESSAGE() AS ErrorMessage
END

END CATCH

The Result:

 

There we have it!  meaningful error messages which directly relate to my restore issue.

Here is an explanation of the script:

The Try part is untouched
In the catch we have the following logic:

Get the current Time and date – GETDATE() , take a second off of this time (DATEADD(SECOND,-1,GETDATE())) and insert this into the Variable @ErrorDatetime.

Add 2 seconds @ErrorDatetime using (DATEADD(SECOND,2,@ErrorDatetime)) and insert this value into variable @ErrorDatetimePlusSecond

These will act as our TO and FROM DATETIME’s in our Error log search later in the query.

I declare a couple of Variables for storage of the 4305 error existing and its error message
DECLARE @Error4305Exists DATETIME
DECLARE @Error4305Message NVARCHAR(255)
Declare a Table Variable to hold the data returned by the xp_ReadErrorLog command
Do a String search of the error log using searching for 4305, for the period of the time the error occured less 1 second and plus 1 second.
EXEC xp_ReadErrorLog 0, 1, N’4305′, NULL,@ErrorDatetime,@ErrorDatetimePlusSecond,N’DESC’

Assign the variable @Error4305Exists to the LogDate from my table variable – IF a 4305 error occured this will assign a value to @Error4305Exists otherwise it will be NULL
Clear the table as i am no longer interested in the code information in the table.
DELETE FROM @Table

IF @Error4305Exists IS NOT NULL then go an get the corresponding error message that goes with the 4305 error using the same xp_ReadErrorLog but searching for ‘The log in this backup set begins at’ for the SAME timeframe inserting into the table variable @Table, Assign the Error message value to the variable @Error4305Message and then add the string ‘4305 -‘ to the beginning of the message and also append any other error that may have occured using ‘+ CAST(ERROR_NUMBER() AS VARCHAR(6)) + ‘ – ‘ +ERROR_MESSAGE()’

IF the @Error4305Exists variable is NULL however just return ERRROR_NUMBER() AND ERROR_MESSAGE():
SELECT CAST(ERROR_NUMBER() AS VARCHAR(6)) + ‘ – ‘ +ERROR_MESSAGE() AS ErrorMessage

IF @Error4305Exists IS NOT NULL
BEGIN
INSERT INTO @Table
EXEC xp_ReadErrorLog 0, 1, N'The log in this backup set begins at', NULL,@ErrorDatetime,@ErrorDatetimePlusSecond,N'DESC'

SELECT @Error4305Message = TextDetails FROM @Table

SET @Error4305Message = '4305 - ' + @Error4305Message + ' , ' + CAST(ERROR_NUMBER() AS VARCHAR(6)) + ' - ' +ERROR_MESSAGE()

SELECT @Error4305Message AS ErrorMessage

DELETE FROM @Table

END
ELSE
BEGIN
SELECT CAST(ERROR_NUMBER() AS VARCHAR(6)) + ' - ' +ERROR_MESSAGE() AS ErrorMessage
END

So in Summary:

Try/Catch will only return the most recent occurence of an error – in this case it was the 3013 error and not the 4305 that preceeded it.
THROW does return all messages but displays this as a message rather than a form that can be logged to a table.
With the use of Logging the 4305 error message to the SQL error log we can use xp_ReadErrorLog to find this information provided we keep the filtering as strict as possible.
For more database restore related errors be sure to check out Using the SQL Error log to help log meaningful errors for your Automated Restore jobs. Here you will find a list of common database restore related error codes and messages and instructions on how to log them to the Error log.

 

Thanks for reading 🙂