Sql-server – RESTORE FROM URL dies during database recovery

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.