[Bug] Restore-DbaDatabase Fails To Process Other Databases After Failure #5400
Description
### PowerShell version:
Name Value
---- -----
PSVersion 5.1.14393.2879
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.14393.2879
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1
### dbatools Module version:
Name : dbatools
Path : C:\Program Files\WindowsPowerShell\Modules\dbatools\0.9.804\dbatools.psd1
Version : 0.9.804
SQL Server:
Microsoft SQL Server 2017 (RTM) - 14.0.1000.169 (X64) Aug 22 2017 17:04:49 Copyright (C) 2017 Microsoft Corporation Developer Edition (64-bit) on Windows Server 2016 Datacenter 10.0 <X64> (Build 14393: ) (Hypervisor) Errors Received
WARNING: [01:57:15][Restore-DbaDatabase] Failure | System.Data.SqlClient.SqlError: The log in this backup set begins at LSN 873000000062400001, which is too recent to apply to the database. An earlier log backup that includes LSN 850000002475000001 can be restored.Steps to Reproduce
Database Backups on File System
Use Ola Hallengren's maintenance solution default directory structure.
Have a number of backups that work and can be restored, and one whose LSN is too recent to apply to the FULL or DIFF.
In the case of the above warning/error, I saw this as well:
VERBOSE: [01:45:46][Test-DbaBackupInformation] Testing restore for DBWithWeirdLSN
VERBOSE: [01:45:46][Test-DbaBackupInformation] VerifyOnly = False
VERBOSE: [01:45:46][Test-DbaLsnChain] Testing LSN Chain
VERBOSE: [01:45:46][Test-DbaLsnChain] Testing LSN Chain - Type Type
VERBOSE: [01:45:46][Test-DbaLsnChain] Passed LSN Chain checks
VERBOSE: [01:45:47][Test-DbaBackupInformation] Marking DBWithWeirdLSN as verified
I am not certain how to reproduce this particular LSN issue, but it seems to require that it will pass the LSN Chain check, but not the actual restore. I'm not sure this particular case matters though.
Command I ran:
Restore-DbaDatabase -SqlInstance localhost -Path "E:\Restores" -DirectoryRecurse -MaintenanceSolutionBackup -UseDestinationDefaultDirectories -Verbose
Expected Behavior
The restore process would continue on after failing with one restore, restoring the rest as best as it could. Rather than giving up when an obstacle is found, it would try to do As Much As Possible, while still reporting failed parts to manually fix.
Actual Behavior
When the Restore-DbaDatabase started to actually restore databases after a lengthy check time, it was able to fully restore about 4% of the total databases before it started to restore the DB I'll call DBWithWeirdLSN. It restored the FULL backup of that DB, and then started applying LOGs to it, as the DIFF hadn't been taken yet for this database. It failed with the above warning message, and then all parts of the Restore-DbaDatabase ceased working, and I was back at the command prompt.
@potatoqualitee in the Slack channel mentioned that this was not the behavior they expected.
Backstory
I was testing out disaster recovery possibilities, using the most naive approach possible in case I was out. I had about 750 databases that needed to be restored, after pruning many of the databases for testing purposes, I had a small list of 180 or so databases I expected to be restored. Of those, only 56 or so were actually restored, and after modifying Select-DbaBackupInformation, I determined the problem: If a database had a DIFF in it, with no corresponding FULL, but the DIFF was still valid, Select-DbaBackupInformation would start to process this DB's backups, fail to find the FullName, and then stop all subsequent Selecting of valid Backups.
Examples:
2 DBs:
Parts_DB
Parts3_DB
As part of an application release process, Parts_DB is backed up, and restored under the name Parts3_DB, so at this point, the two DBs are essentially the same. ("A snapshot in time of the parts configuration".)
Full Backups are taken on Sunday, and it is Thursday. Diffs are taken on all other days, so a DIFF is taken today, using Ola's scripts. I'm not sure what's the best way to show this directory structure, so here goes:
Parts_DB Fulls
E:\Restores\Parts_DB\FULL\Parts_DB_FULL_Sunday1.bak
E:\Restores\Parts_DB\FULL\Parts_DB_FULL_Sunday2.bak
Parts_DB Diffs
E:\Restores\Parts_DB\DIFF\Parts_DB_DIFF_Monday1.bak
E:\Restores\Parts_DB\DIFF\Parts_DB_DIFF_Tuesday1.bak
...
E:\Restores\Parts_DB\DIFF\Parts_DB_DIFF_Thursday2.bak
E:\Restores\Parts3_DB\DIFF\Parts3_DB_DIFF_Thursday2.bak
E:\Restores\Parts3_DB\FULL DOES NOT EXIST
Since Parts_DB has a FULL backup that's valid, and Parts3_DB is restored from Parts_DB, then there's a valid FULL backup for Parts3_DB that a DIFF can go against, so the Ola scripts create the DIFF backup.
Fast forward to Select-DbaBackupInformation:
It receives the FormattedBackupInformation, and starts to process it to find valid backups: Once it starts to work on Parts3_DB.bak, it realizes that it can't find the Fullname property, and then stops processing all other 124 backups still left in the BackupHistory.
(Side note: There is nothing in here that will output the Database being processed, even in Verbose mode, so I had to add a number of print debug statements to figure out which DB was the problem. The new parameters for outputting the various BackupInformation variables were absolutely invaluable for determining which part of the script was dropping 75% of the databases from being restored!)
Once I deleted all the directories of DBs where DIFFs existed without FULLs, Select-DbaBackupInformation worked flawlessly (and then I ran into the above issue with LSNs).