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.

DBRestoring

  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…

3013_Error

Let see what happens without Try/Catch:


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

 

Standard_andThrow

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

 

Standard_andThrow

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

 

sysmessagesOFF

 

Is_Event_Logged = 0 , Lets change that:

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

 

sysmessagesON

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

 

errorlog

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:

 

finale 4305error

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.

One thought on “The dreaded SQL server error 3013 ‘RESTORE LOG is terminating abnormally’ the bane of my life, until recently…

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: