Qui a fait quoi sur ma table ?

Lors d’une discussion sur un réseau social bien connu avec Christian (@chrisql) et Isabelle (@sqlgrrl) autour du thème du qui a fait quoi dans une base, j’ai proposé une solution qui évitait le recours à des fonctionnalités de l’édition entreprise de SQL Server.

Et, au delà de cette discussion Francophone (Suisse, Belgique et France), la question m’a été souvent posée chez des clients.

Alors, bien sur la solution n’est pas parfaite, mais, elle fourni déjà beaucoup d’informations …

Reprenons l’histoire au début. Lorsque l’on veut savoir le qui-fait-quoi, dans SQL Server, il n’existe pas des dizaine de solutions.

• On peut utiliser l’API SQL Trace, communément utilisée au travers du Profiler SQL Server, qui permet de tracer toutes les requêtes qui arrivent sur SQL Server. Fonctionnel. Mais attention aux ressources consommées sur le serveur !!! Même si vous filtrez votre trace, sachez que le filtre ne s’applique que lors du stockage de l’information, pas lors de la capture. Donc SQL Trace capture toutes les requêtes ! Je vus laisse imaginer le résultat sur un environnement bien sollicité …
• Depuis SQL Server 2008 il est possible d’utiliser  les XEvent, les évènements étendus. Alors, oui, en 2008 et 2008R2, il fallait aimer el code SQL et le parsing de contenu XML pour s’en sortir. Autant le côté trace était opérationnel, autant le côté restitution laissait à désirer, soyons honnêtes. Enfin, en 2012, SSMS propose une IM qui permet à la fois de créer des sessions d’évènements étendus ET de visualiser / traiter le résultat. En live ou a postériori. Enfin une bonne solution, d’autant que le surtout n’est absolument pas comparable avec celui de SQL Trace. Cette fois ci le filtre se fait lors de la capture, bien plus efficace donc.
• On peut également mettre en place des triggers sur les tables. Bon ça reste un trigger, donc ….

Ces 3 techniques sont intéressantes, mais quelque peu “brutes”, dirons nous.

Depuis SQL Server 2008, il existe aussi les audits de sécurité. Au final, ce ne sont que des XEvents qui ont été packagés dans une IHM spécifique. Ainsi, il est possible, de manière extrêmement simple de mettre en place un audit sur des opérations de type INSERT / UPDATE / DELETE sur des tables. Tout comme on pourrait auditer l’accès à des données sensibles sur du SELECT, ou bien du EXEC de procédure stockée.

Bref, voici un petit exemple :

-- Création de l'audit et activation de celui-ci
CREATE SERVER AUDIT AuditDataAccess
TO FILE ( FILEPATH ='C:\SQLAudit\'
		  ,MAXSIZE = 0 MB
		  ,MAX_ROLLOVER_FILES = 2147483647
		  ,RESERVE_DISK_SPACE = OFF )
WITH
(	QUEUE_DELAY = 1000
	,ON_FAILURE = CONTINUE
)
GO

ALTER SERVER AUDIT AuditDataAccess WITH (STATE = ON);
GO

USE [AdventureWorks]
GO

-- Création d'une spécification d'audit pour tracer
-- - les écritures sur la table empployee
-- - les select sur l'intégralité sur schéma
CREATE DATABASE AUDIT SPECIFICATION [AuditSpecificationHR]
FOR SERVER AUDIT [AuditDataAccess]
ADD (INSERT,UPDATE,DELETE 
          ON OBJECT::[HumanResources].[Employee] BY [public]),
ADD (SELECT,EXECUTE       
          ON SCHEMA::[HumanResources]            BY [public])
WITH (STATE = ON) ;
GO

-- Consultation de l'audit
SELECT * 
FROM sys.fn_get_audit_file ('C:\SQLAudit\AuditDataAccess*.sqlaudit',
                                                    default,default);

La consultation peut aussi se faire dans SSMS, de manière graphique.

La mariée serait elle trop belle? Possible, car cela sous entend que la session d’audit existait déjà (alors qu’il est peut être trop tard … l’update a déjà été fait) et …. que … l’on dispose de l’édition entreprise de SQL Server.

Comment, donc, rechercher qui a effectué une modification de donnée (oui, la solution n’est pas parfaite car elle ne couvre pas le SELECT) qui s’est produite quelques heures/jours auparavant ?

La première chose, car il faut quand même quelques prérequis : la base doit être en mode de récupération complet ou bulklogged. Sinon le contenu du journal de transaction est vidé lors du checkpoint, qui est issu lorsque le journal dépasse un seuil de remplissage de 70%.

Le journal de transaction, donc, est chargé, comme son nom l’indique d’enregistrer les transactions. Cela tombe bien, on recherche une transaction, une modification de données effectuée par erreur, par exemple. Il faut donc explorer le journal de transaction. Cela peut se faire (attention si vous passez cette commande sur la prod …) a l’aide de la fonction fn_dblog. Sauf que cela suppose que le journal n’a pas été sauvegardé ! EN mode de récupération complet et bulklogged, le journal est vidé lorsque une sauvegarde du journal est effectuée.

Notre salut viendrait donc des sauvegardes du journal de transaction ! Il est possible de lire ces sauvegardes a l’aide de la fonction fn_dump_dblog. Attention, une nouvelle fois. Utiliser ces fonctions n’est pas un jeu !!!

Mettons en place un petit scénario. 3 utilisateurs qui vont effectuer des requêtes sur une table. Je vais en profiter pour utiliser els bases partiellement contenues (nouveauté SQL Server 2012). Cela n’est en rien obligatoire dans cette démo.

EXEC sys.sp_configure N'contained database authentication', N'1'
GO
RECONFIGURE WITH OVERRIDE
GO

CREATE DATABASE DemoDB
GO

ALTER DATABASE [DemoDB] SET CONTAINMENT = PARTIAL WITH NO_WAIT
GO


USE DemoDB
GO


CREATE TABLE DemoTable
(
	ID INT IDENTITY(1,1) PRIMARY KEY,
	filler CHAR(50)
)


CREATE USER [SQLUser1] WITH PASSWORD=N'Password1', DEFAULT_SCHEMA=[dbo];
CREATE USER [SQLUser2] WITH PASSWORD=N'Password1', DEFAULT_SCHEMA=[dbo];
CREATE USER [SQLUser3] WITH PASSWORD=N'Password1', DEFAULT_SCHEMA=[dbo];
GO


CREATE ROLE [db_MyAppRole] AUTHORIZATION [dbo];
GO

GRANT INSERT,DELETE,UPDATE,SELECT ON SCHEMA::[dbo] TO [db_MyAppRole];
GO

ALTER ROLE [db_MyAppRole] ADD MEMBER [SQLUser1];
ALTER ROLE [db_MyAppRole] ADD MEMBER [SQLUser2];
ALTER ROLE [db_MyAppRole] ADD MEMBER [SQLUser3];
GO


-- Une sauveagarde pour vider le journal de transactions
BACKUP DATABASE DemoDB
TO DISK = 'NUL'; -- Attention, pas en prod !!!

BACKUP LOG DemoDB
TO DISK = 'NUL'; -- Attention, pas en prod !!!
GO

A présent, les requêtes de test. Il s’agit ici de transactions imbriquées, mais encore une fois, cela fonctionne avec des transactions “simples”.

-- Login as SQLUser1
BEGIN TRANSACTION SQLUser1_Transaction
	
	SELECT USER_NAME();
	
	INSERT INTO DemoTable (filler)
	VALUES ('SQLUser 1 - Insert');

	-- Login as SQLUser2
	BEGIN TRANSACTION SQLUser2_Transaction

		SELECT USER_NAME();

		INSERT INTO DemoTable (filler)
		VALUES ('SQLUser 2 - Insert');

		UPDATE DemoTable 
		SET filler = 'SQLUser 2 - Update'
		WHERE ID = 2;

		-- Login as SQLUser3
		BEGIN TRANSACTION SQLUser3_Transaction

			SELECT USER_NAME();

			INSERT INTO DemoTable (filler)
			VALUES ('SQLUser 3 - Insert');

			UPDATE DemoTable 
			SET filler = 'SQLUser 3 - Update'
			WHERE ID = 3;

			DELETE FROM DemoTable 
			WHERE ID = 3;

		COMMIT TRANSACTION SQLUser3_Transaction

		DELETE FROM DemoTable 
		WHERE ID = 2;

	COMMIT TRANSACTION SQLUser2_Transaction


	UPDATE DemoTable 
	SET filler = 'SQLUser 1 - Update'
	WHERE ID = 1;

	DELETE FROM DemoTable 
	WHERE ID = 1;

COMMIT TRANSACTION SQLUser1_Transaction

A présent, un backup du journal de transaction. Ce backup, et donc les transactions qu’il contient, peuvent dater de maintenant, hier ou bien avant, cela ne modifie en rien le scénario.

BACKUP Log DemoDB
TO DISK = 'c:\temp\DemoDB.trn'

Il est temps à présent d’explorer cette sauvegarde. Je vous suggère de recopier les données dans une table temporaire, afin de pouvoir travailler plus facilement et plus rapidement par la suite.

SELECT *
INTO #temp_dump_dblog
FROM   fn_dump_dblog( DEFAULT, DEFAULT,DEFAULT, DEFAULT,  
'C:\temp\DemoDB.trn', 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 ) AS LogRecords;
GO

Maintenant, il ne reste plus qu’a requêter cette table temporaire, effectuer quelques opérations a l’aide de la clause OVER pour récupérer le début et la fin des transactions et de croiser les données avec database_pincipals. Je vous laisse ensuite remonter à server_principals et d’autres infos si vous le souhaitez.

-- Result ordered by LSN
WITH db_log AS 
(
SELECT [Current LSN],
FIRST_VALUE([Current LSN]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Begin_Tran_LSN],
LAST_VALUE([Current LSN])  OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]
	ROWS BETWEEN CURRENT ROW	
		AND UNBOUNDED FOLLOWING    ) AS [End_Tran_LSN],
[Transaction ID],  
FIRST_VALUE([Transaction SID]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Transaction SID],
FIRST_VALUE([Begin Time]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Begin_Transaction_DT],
LAST_VALUE([End Time])  OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]
	ROWS BETWEEN CURRENT ROW	
		AND UNBOUNDED FOLLOWING    ) AS [End_Transaction_DT],
FIRST_VALUE([Transaction Name]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Transaction Name],
[OPERATION]
FROM   #temp_dump_dblog l
		
),
    transaction_user AS
(
SELECT * 
FROM db_log l
INNER JOIN sys.database_principals p on p.sid = l.[Transaction SID] 
WHERE  [Transaction ID]  '0000:00000000'
AND [OPERATION] IN ('LOP_BEGIN_XACT','LOP_COMMIT_XACT',
'LOP_INSERT_ROWS','LOP_MODIFY_ROW','LOP_DELETE_ROWS') 
)
SELECT [Current LSN],[Begin_Tran_LSN],[End_Tran_LSN],
	   [Begin_Transaction_DT],[End_Transaction_DT],[Transaction Name],
	   [OPERATION],[Name] AS [User_Name]
FROM transaction_user
WHERE [Transaction Name] NOT IN ('Backup:CommitLogArchivePoint',
                                 'AllocFirstPage','Allocate Root') 
ORDER BY [Current LSN]





-- Result ordered by User / LSN
WITH db_log AS 
(
SELECT [Current LSN],
FIRST_VALUE([Current LSN]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Begin_Tran_LSN],
LAST_VALUE([Current LSN])  OVER (PARTITION BY [Transaction ID] 
    ORDER BY [Current LSN]
	ROWS BETWEEN CURRENT ROW	
	 AND UNBOUNDED FOLLOWING    ) AS [End_Tran_LSN],
[Transaction ID],  
FIRST_VALUE([Transaction SID]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Transaction SID],
FIRST_VALUE([Begin Time]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Begin_Transaction_DT],
LAST_VALUE([End Time])  OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]
	ROWS BETWEEN CURRENT ROW	
	 AND UNBOUNDED FOLLOWING    ) AS [End_Transaction_DT],
FIRST_VALUE([Transaction Name]) OVER (PARTITION BY [Transaction ID] 
	ORDER BY [Current LSN]) AS [Transaction Name],
[OPERATION],
CASE
WHEN [Begin Time] IS NOT NULL THEN 1
ELSE 0
END AS [Is_Begin_tran],
CASE
WHEN [End Time] IS NOT NULL THEN 1
ELSE 0
END AS [Is_End_tran]
FROM   #temp_dump_dblog l
),
    transaction_user AS
(
SELECT * 
FROM db_log l
INNER JOIN sys.database_principals p on p.sid = l.[Transaction SID] 
WHERE  [Transaction ID]  '0000:00000000'
AND [OPERATION] IN ('LOP_BEGIN_XACT','LOP_COMMIT_XACT',
'LOP_INSERT_ROWS','LOP_MODIFY_ROW','LOP_DELETE_ROWS') 
)
SELECT [Current LSN],[Begin_Tran_LSN],[End_Tran_LSN],
[Begin_Transaction_DT],[End_Transaction_DT],[Transaction Name],
[Name] AS [User_Name],
CASE
 WHEN Is_Begin_tran + Is_End_tran = 0 THEN '    |->  ' + [Operation]
 ELSE [Operation]
END As [Operation]
FROM transaction_user
WHERE [Transaction Name] NOT IN ('Backup:CommitLogArchivePoint',
                                 'AllocFirstPage','Allocate Root') 
ORDER BY [Name],[Current LSN]

Désolé pour l’indentation du code.

Si vous chercher qui a supprimé une table, cherchez des DROP …

Alors, qui a fait quoi ???

Enjoy