3

Attempting to restore a small backup from the Azure BLOB 

RESTORE DATABASE MY_DATABASE FROM  URL = 'https://somelocation.blob.core.windows.net/mydatabase.bak' 
WITH FILE=1
,MOVE N'MY_DATABASE'TO N'D:\DATA\MY_DATABASE.mdf'
,MOVE N'MY_DATABASE_log'TO N'D:\LOG\MY_DATABASE_log.ldf'
,NOUNLOAD,  REPLACE,  STATS = 2, CREDENTIAL = 'somecredential'

And somewhere at about 98%, the restore just dies

86 percent processed.
88 percent processed.
90 percent processed.
92 percent processed.
94 percent processed.
96 percent processed.
98 percent processed.
Msg 3013, Level 16, State 1, Line 8
RESTORE DATABASE is terminating abnormally.

Here is the output from the log with the trace flags on

2016-01-08 08:59:52.780 spid63  RestoreDatabase: Database MY_DATABASE
2016-01-08 08:59:52.790 spid63  Opening backup set
2016-01-08 08:59:52.790 spid63  VDI: "C:\Program Files\Microsoft SQL Server\MSSQL12.DATA\MSSQL\Binn\BackupToUrl.exe" "r" "p" "680074007400700073003A002F002F006B0039003900730074006F003000300032002E0062006C006F0062002E0063006F00720065002E00770069006E0064006F00770073002E006E00650074002F006B0030003100730071006C002D0063006C0075002D0032002F004C005F0043004100540041004C004F0047005F00430044004900530043004F0055004E0054005F004D004900440044004C00450043004D0053005F0032003000310036005F00300031005F00300033005F003000310030003300350038002E00620061006B00" "6B0039003900730074006F00300030003200" "01000000D08C9DDF0115D1118C7A00C04FC297EB010000007D2AFDE19FCC3F4FBB113683EF29D7B5000000001200000061007A007500720065006B0065007900000003660000C000000010000000ED978F2ACEBB06BA73899E4D62DCEED10000000004800000A000000010000000FC5DAF946420975518E0336799E9FA2F48000000A5B7746C13945ABD05048D8CE67E8ACCF4A429616B12B1C1FBAA7B6C0AC4F8466F63644135D0C88F6DBA6D76BB18A550B81C15005FB538B4EA3C109B91549E3DE8872F460703247F14000000EE9427440D53CEEF53072D911D1CF92CA7BC1A2B" "NOFORMAT" "4C005F0043004100540041004C004F004700" "D:\DATA\SYSTEM\MSSQL12.DATA\MSSQL\Log" "DB" "54004500530054005F004D004900440044004C00450043004D005300" "NOTRACE"
2016-01-08 08:59:52.790 spid63  BackupToUrl process initiated with PID: 17796, for database name [MY_DATABASE]
2016-01-08 09:00:12.410 spid63  SetTargetRestoreAge: 0
2016-01-08 09:00:12.410 spid63  Restore: Configuration section loaded
2016-01-08 09:00:12.410 spid63  Restore: Backup set is open
2016-01-08 09:00:12.410 spid63  Restore: Planning begins
2016-01-08 09:00:12.440 spid63  Halting FullText crawls on database MY_DATABASE
2016-01-08 09:00:12.440 spid63  Dismounting FullText catalogs
2016-01-08 09:00:12.440 spid63  X-locking database: MY_DATABASE
2016-01-08 09:00:12.440 spid63  Restore: Planning complete
2016-01-08 09:00:12.450 spid63  Restore: BeginRestore (offline) on MY_DATABASE
2016-01-08 09:00:12.760 spid63  Restore: PreparingContainers
2016-01-08 09:00:14.210 spid63  Restore: Containers are ready
2016-01-08 09:00:14.210 spid63  Zeroing D:\DATA\MY_DATABASE_8.ldf from page 1 to 295800 (0x2000 to 0x906f0000)
2016-01-08 09:00:14.260 spid63  Restore: Restoring backup set
2016-01-08 09:00:14.260 spid63  Restore: Transferring data to MY_DATABASE
2016-01-08 09:01:14.370 spid63  Zeroing completed on D:\DATA\MY_DATABASE_8.ldf
2016-01-08 09:01:14.370 spid63  Zeroing D:\DATA\MY_DATABASE_log2.ldf from page 1 to 295800 (0x2000 to 0x906f0000)
2016-01-08 09:01:18.950 spid63  Restore: Waiting for log zero on MY_DATABASE
2016-01-08 09:02:16.370 spid63  Zeroing completed on D:\DATA\MY_DATABASE_log2.ldf
2016-01-08 09:02:16.370 spid63  Zeroing D:\DATA\MY_DATABASE_log3.ldf from page 1 to 295800 (0x2000 to 0x906f0000)
2016-01-08 09:03:15.440 spid63  Zeroing completed on D:\DATA\MY_DATABASE_log3.ldf
2016-01-08 09:03:15.440 spid63  Zeroing D:\DATA\MY_DATABASE_log4.ldf from page 1 to 295800 (0x2000 to 0x906f0000)
2016-01-08 09:04:13.620 spid63  Zeroing completed on D:\DATA\MY_DATABASE_log4.ldf
2016-01-08 09:04:13.620 spid63  Zeroing D:\DATA\MY_DATABASE_log5.ldf from page 1 to 244456 (0x2000 to 0x775d0000)
2016-01-08 09:05:06.270 spid63  Zeroing completed on D:\DATA\MY_DATABASE_log5.ldf
2016-01-08 09:05:06.270 spid63  FileHandleCache: 0 files opened. CacheSize: 14
2016-01-08 09:05:06.480 spid63  Resuming any halted fulltext crawls

Had the backup completed successfully, I would have seen this line just after the fulltext crawl message

2016-01-08 08:53:38.720 spid63  Restore: Writing history records
2016-01-08 08:53:38.720 Backup  Database was restored: Database: MY_DATABASE_log5, creation date(time): 2014/12/10(22:04:35), first LSN: 71976:92071:1, last LSN: 71976:100304:1, number of dump devices: 1, device information: (FILE=1, TYPE=URL: {'https://somelocation.blob.core.windows.net/MY_DATABASE_2016_01_08_010437.bak'}). Informational message. No user action required.

As to the error message, I found this

Error message when you perform a database backup to disk or tape or a database restore from disk or tape: "3266," "3013"

The RESTORE VERIFYONLY completes successfully.

Other database restores from the same location have completed successfully. A restore of the same backup locally on the server works fine. Just takes forever to recover because of the > 1000 VLFs.

The only information in the logs is this

BackupToUrl process initiated with PID: 4632, for database name [MY_DATABASE]

Why is the restore database failing and not restore verifyonly?

If this were an issue caused by very slow download times, would there be a timeout error somewhere?

I now believe that the problem is being caused by the high number of VLFs and that the session may still somehow be dependent on the connection to Azure's blob storage.

Improve this question
3
  • What's the size of your backup file and what's the available free space on drive D:\ ?
    – Jefferson B. Elias
    Commented Jan 5, 2016 at 15:43
  • 1
    So maybe there is some timeout inherent in the FROM URL syntax. If you look at this page, there is a mention of SLAs that suggest you test throughput: Windows Azure storage SLA’s [sic] have maximum processing times for blobs that you can take into consideration. Unfortunately the link it points to, which could provide more details, is 404. It may mean to point here, but I'm not sure. In any case, the best fix is obviously to fix the VLFs.
    – Aaron Bertrand
    Commented Jan 5, 2016 at 18:30
  • Hi @AaronBertrand, I updated my question and added an answer. I opened up a case with Microsoft, perhaps they will find a way to make the restore from URL work with so many vlfs to restore.
    – Craig Efrein
    Commented Jan 8, 2016 at 9:20

1 Answer 1

Reset to default
1

To resolve this issue permanently, the support at Microsoft has offered two choices.

Install SQL Server 2014 SP1 + CU4

or

Install SQL Server 2014 CU7

FIX: You cannot restore a SQL Server 2012 or 2014 database in the Microsoft Azure binary large object storage service

When a SQL Server 2012 or SQL Server 2014 database contains a large transaction log file, you cannot restore the database in the Microsoft Azure binary large objects (BLOB) storage service. For example, if the transaction log file is so large that it takes longer than 3 minutes to restore it, you cannot restore the database.

The alternative was to shrink the ldf(s) thus reducing the number of VLF's to recover during database startup.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.