0

Point-in-time recovery et fn_dump_dblog()

Posted on by David Baffaleuf
twitterlinkedinmail

Point-in-time recovery désigne une restauration de base de données consistante à un point précis soit dans le temps (STOPAT), soit dans une séquence de transactions (STOPATMARK, STOPBEFOREMARK). On ne peut faire du PIT recovery que lorsque la base est en mode de restauration complet.

Le problème inhérent à ce genre de restauration, c’est qu’on ne sait pas exactement jusqu’où restaurer. Lorsque votre collègue vous dit qu’il a supprimé accidentellement les données de la table principale vers 13h45, c’est assez vague comme réponse. Si vous restaurez à 13h44, que fait-on des transactions validées entre 13h44 et le moment précis où le delete a été exécuté ? Il faut jouer avec RESTORE LOG WITH STOPAT, STANDBY pour déterminer le point dans le temps où les données ne sont plus dans la table. Milliseconde par milliseconde ? Bof bof bof…

L’alternative est d’utiliser des marques de transactions:

BEGIN TRAN MiseAJourProduits
GO
DELETE FROM PRODUITS -- WHERE ID_PRODUIT = @id_produit (aïeuuu)
GO
...
COMMIT TRAN MiseAJourProduits
GO

Dès lors il est possible de restaurer avant la transaction qui pose problème en utilisant l’option STOPBEFOREMARK de RESTORE LOG:

RESTORE LOG maBASE FROM DISK='C:\UTRECHT\MSSQL.1\MSSQL\Backup\maBase.20110712.trn'
WITH RECOVERY, STOPBEFOREMARK = 'MiseAJourProduits'
GO

Seul problème, c’est à l’initiative du développeur de le faire, or la plupart du temps les transactions sont non marquées, je ne vous parle même pas des progiciels…

Fiat lux:

J’ai longtemps regretté l’absence d’un outil built-in tel que LogMiner pour pouvoir lire le contenu d’un backup log, et pouvoir effectuer une restauration précise à la transaction près. En effet,  STOPATMARK / STOPBEFOREMARK permettent d’utiliser une syntaxe telle que :

RESTORE LOG ... WITH STOPBEFOREMARK = 'lsn:<LSN number>'.

Seulement voilà, comment connaître les différentes transactions embarquées dans un backup log ? fn_dblog() permet d’obtenir cette information sur le journal lui-même, mais quid des backups…

Et il y a quelques jours, je joue avec OPENROWSET() et là je tombe sur une fonction système non-documentée dans la base resource : fn_dump_dblog(). En lisant le nom, l’émotion m’étreint. Le souffle court, je jette un coup d’oeil au source de la fonction:

create function sys.fn_dump_dblog  
 (  
    @start    nvarchar (25) = NULL,  
    @end      nvarchar (25) = NULL,  
    @devtype  nvarchar (260) = NULL, -- NULL(DISK) | DISK | TAPE | VIRTUAL_DEVICE  
    @seqnum   Int         = 1,  
    @fname1   nvarchar (260) = NULL,  
    @fname2   nvarchar (260) = NULL,  
    @fname3   nvarchar (260) = NULL, 
    ...
    @fname64   nvarchar (260) = NULL  
 )  
returns table  
as  
 return select  
     [Current LSN],  [Operation],  [Context],  [Transaction ID],   [Tag Bits],  
     [Log Record Fixed Length],  [Log Record Length],   [Previous LSN],  
     (...)
     from OpenRowset (DBLog, @start, @end, @devtype, @seqnum,  
     @fname1,  @fname2,  @fname3,  @fname4,  @fname5, 
     (...)
     @fname62,  @fname63,  @fname64)

En lisant le paramètre @devtype j’avale mon sandwich indien poulet-curry de travers. Ça fait dix mois que je bosse sur un provider OLEDB qui permette de lire dans un backup full (un peu l’équivalent de l’Archive Database Access sous Sybase ASE), et là je découvre qu’il existe une fonction qui fait la même chose sur les backups log. Depuis la 2005 RTM. Argl.

Et puis en gouglant un peu, je tombe sur cet article de Dimitri Furman, une personne de MS Consulting Services à New-York qui décrit brièvement la fonction et ses arguments. Je ne peux pas résister, il va falloir tester ça.

Scénario de test:

On va donc créer une base de démo, peupler une table et supprimer des intervalles de valeurs en les entrelaçant de backup logs. On arrive à une suppression par erreur, et on souhaite remonter les données juste à la transaction d’avant, sachant que les transactions ne sont pas marquées.

/*************************************************************************************
 Obj:       DEMO RESTAURATION SUITE A ERREUR MANUELLE
            UTILISATION DU MODE STANDBY POUR EFFECUTER UN POINT-IN-TIME RECOVERY
 Aut:       dbaffaleuf@capdata
 Crdate:    2011/07/13
*/

-- Population de la base
use master
GO
if exists (select 1 from sys.databases where name='demorecovery')
 drop database demorecovery
GO
create database demorecovery
GO

use demorecovery
GO
create table T1(
 a numeric identity,
 b char(4000) default replicate('b',4000),
 c bigint default round(rand()*100,0))
GO
insert into T1 default values
GO 1000
create unique clustered index IDX_T1C on T1(a)
GO
create index IDX_T1NC__c on T1(c)
GO

-- Activation du mode de récupération complet
alter database demorecovery set recovery full
GO
backup database demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_FULL.bak' with init, stats
GO

-- Quelques transactions et quelques backups de transactions
delete from T1 where a < 10
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG1.bak' with init, stats
GO
delete from T1 where a < 20
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG2.bak' with init, stats
GO
delete from T1 where a < 30
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG3.bak' with init, stats
GO

-- Trois autres transactions à suivre, la dernière (a<60) est une erreur manuelle
delete from T1 where a < 40
GO
delete from T1 where a < 50
GO
delete from T1 where a < 60  -- <-- CES DONNEES SONT EFFACEES PAR ERREUR !!!
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with init, stats
GO

-- Une autre transaction valide passe entre-temps
delete from T1 where a > 990
GO

-- Le téléphone sonne, l'utilisateur demande s'il est possible de récupérer les données avant le delete where a < 60
use master
GO
-- tail log backup
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_TAILLOG.bak' with init, stats, NO_TRUNCATE, NORECOVERY
GO
select state_desc from sys.databases where name='demorecovery'
GO

state_desc
------------------------------------------------------------
RESTORING

-- On identifie le backup de journal qui embarque l'erreur: demorecovery_LOG4.bak
-- on recherche les différentes transactions contenues à l'intérieur avec fn_dump_dblog():
select *, [Current LSN]
 ,Operation
 ,[Transaction ID]
 ,AllocUnitId
 ,[Begin Time]
 ,[Transaction Name]
 ,[End Time]
 ,[Description]
from fn_dump_dblog(DEFAULT, DEFAULT,DEFAULT, DEFAULT,
'C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak',
DEFAULT,DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT)
where Operation  = 'LOP_BEGIN_XACT'

Current LSN             Operation         Transaction ID  Begin Time               Transaction Name    Description
----------------------- ----------------- --------------  ------------------------ ------------------- -----------------------------------------------------------------------
00000041:00000338:000e  LOP_BEGIN_XACT    0000:000008b8   2011/07/13 15:59:43:580  DELETE              DELETE;0x0105000000000005150000006aa3aebb1b5c3491642b62e2e8030000
00000042:00000021:0001  LOP_BEGIN_XACT    0000:000008b9   2011/07/13 15:59:43:587  DELETE              DELETE;0x0105000000000005150000006aa3aebb1b5c3491642b62e2e8030000
00000042:00000076:0001  LOP_BEGIN_XACT    0000:000008ba   2011/07/13 15:59:43:630  DELETE              DELETE;0x0105000000000005150000006aa3aebb1b5c3491642b62e2e8030000


-- On restaure jusqu'au N-1 backup log avant pb
restore database demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_FULL.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG1.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG2.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG3.bak' with stats, norecovery
GO

-- On restaure en standby mode à la première transaction pour déterminer si les données entre 50 et 60 sont toujours là
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
standby='C:\UTRECHT\MSSQL.1\MSSQL\Backup\stdby_files.bak', stopbeforemark='lsn:0x00000042:00000021:0001'
GO

select state_desc, is_in_standby from sys.databases where name='demorecovery'
GO

state_desc    is_in_standby
------------- --------------
ONLINE        1

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----
40     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 31
41     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 28
42     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 77
43     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 18
44     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 12
45     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 42
46     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
47     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 46
48     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 39
49     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 74
50     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 45
51     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
52     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 32
53     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 10
54     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
55     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 99
56     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 71
57     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 38
58     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
59     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 41

-- OK, allons voir à la transaction suivante
use master
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
standby='C:\UTRECHT\MSSQL.1\MSSQL\Backup\stdby_files.bak', stopbeforemark='lsn:0x00000042:00000076:0001'
GO

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----
50     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 45
51     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
52     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 32
53     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 10
54     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
55     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 99
56     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 71
57     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 38
58     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
59     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 41

-- On dirait bien qu'on est dans l'état attendu. Allons voir à la dernière transaction pour confirmer:
use master
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
standby='C:\UTRECHT\MSSQL.1\MSSQL\Backup\stdby_files.bak'
GO

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----

-- Ouaip, donc il faut revenir au point précédent, en rechargeant tout depuis le backup FULL:
use master
GO
restore database demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_FULL.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG1.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG2.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG3.bak' with stats, norecovery
GO

restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
stopbeforemark='lsn:0x00000042:00000076:0001', recovery
GO

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----
50     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 45
51     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
52     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 32
53     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 10
54     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
55     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 99
56     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 71
57     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 38
58     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
59     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 41

-- Note: la transaction suivante (a>990) est perdue. On ne peut pas la recharger car il y aurait une cassure dans la chaîne de LSNs.
-- Si on avait tenté de restaurer le tail-log à la suite:
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_TAILLOG.bak' with stats, recovery
GO

Msg 4305, Niveau 16, État 1, Ligne 1
Le journal dans ce jeu de sauvegarde commence au numéro de séquence d'enregistrement 66000000017600001, ce qui est trop récent
pour une application à la base de données. Une sauvegarde de fichier journal antérieure qui inclut le numéro de séquence
d'enregistrement 66000000009200001 peut être restaurée.
Msg 3013, Niveau 16, État 1, Ligne 1
RESTORE LOG s'est terminé anormalement.

Donc voilà enfin une méthode pour récupérer une base pile à l’endroit où on veut la récupérer, encore une fois grâce à une fonction non documentée qui mériterait d’être plus connue.

A+. David B.

Continuez votre lecture sur le blog :

twitterlinkedinmail

David Baffaleuf

More Posts

Laisser un commentaire

Votre adresse e-mail ne sera pas publiée. Les champs obligatoires sont indiqués avec *

Ce site utilise Akismet pour réduire les indésirables. En savoir plus sur comment les données de vos commentaires sont utilisées.