Gå direkte til indhold

SQL Server – CSI

lästid I minuter: 4

Tidigare på den här bloggen har jag beskrivit hur vi kan se vem som tagit bort tabeller etc från en databas, men ibland behöver fler detaljer eller veta vem som har uppdaterat en rad eller när en specifik rad togs bort. Om databasen är konfigurerad att använda full recovery model och/eller har transactionsloggsbackupper från tidsintervallet där det du är intresserad av går det att läsa en del information från dessa eller från den aktiva transaktionsloggen. Här kan du läsa det äldre blogginlägget jag refererar till.

Transaktionsloggen och backupper av denna innehåller historiken om alla händelser som har modifierat något i databasen. Men att läsa från transaktionloggen är oftast sista utvägen och är ganska omständigt. Det är oftast hudratusentals poster att analysera och de är inte läsbara utan måste först behandlas. Men ofta är det enda sättet att ta fram detaljer när oönskade förändringar skett.

Det finns flera tredjepartsverktygen som t ex Quests LiteSpeed och ApexSQLLog har inbyggda funktioner för att analysera och generera återställningsskript etc om backupperna är gjorda via dem eller med SQL Servers inbyggda backuppfunktionalitet. Tyvärr fungerar många av dem inte helt om t ex den inbyggda backuppkomprimeringen är påslagen. Men annars är vår erfarenhet av dem väldigt positivt.

Det finns även två inbyggda funktioner i SQL Server, fn_dblog() för att läsa från den aktiva transaktionsloggen samt fn_dump_dblog() för att läsa backuppfiler. Tyvärr är båda odokumenterade och därför är det inte supporterat eller rekommenderat av Microsoft att använda dem utan de är bara tänkta för internt bruk. Det är känt att de har haft (eller kanske har) en del buggar som bla gjort att det krävt omstarter etc så det är inte rekommenderat att köra dessa i produktionsmiljöer. De returnerar dock bara rådata och kräver en del för att analysera och förstå och här kommer jag bara visa ett väldigt enkelt exempel för fn_dump_dblog().

Vi börjar med att skapa en enkel tabell som testobjekt, lägger till och modifierar rader och tar en transaktionsloggsbackupp på den.

CREATE TABLE demo (
id int NOT NULL IDENTITY(1,1) PRIMARY KEY,
comment char(20),
createDate datetime DEFAULT GETDATE());


INSERT INTO demo (comment) VALUES ('Exempel'), ('Exempel: Att ta bort'), ('Exempel: Att ändra');

UPDATE demo SET comment='Exempel: Ändrat' WHERE comment = 'Exempel: att ändra';

DELETE FROM demo WHERE comment='Exempel: Att ta bort'

GO

I tabellen finns nu två rader kvar

SELECT [id], [comment], [createDate] FROM [dbo].[demo]

Uppgiften är nu att försöka lista ut vem som la till, modifierade och tog bort raderna samt när.

För att använda fn_dump_dblog() för att läsa transactionsloggsbackuppen måste samtliga 68(!) inparametrar anges, men de flesta kan använda DEFAULT värdet. I ordning är de:

Start LSN, oftast NULL som ger alla

Slut LSN, ocskå oftast NULL som ovan

Typ av fil, DISK eller TAPE, i vårt fall DISK

Backuppnummer i backuppfilen, 1 om inte multi-backupp media set används

Samtliga filnamn för alla media families för media setet, oftast används bara en fil men om man stripar backuppen till multipla filer måste alla anges här. Annars gäller ”DEFAULT”.

För att förenkla lite är det första vi gör att läsa in all data vi behöver i en tabell som vi sedan använder i stället för att anropa funktionen.

SELECT [Current LSN]

, [Operation]

, [Transaction ID]

, [Parent Transaction ID]

, [Begin Time]

, [Transaction Name]

, [Transaction SID]

, [AllocUnitName]

, [Page ID]

, [Slot ID]

, [Lock Information]

, [Num Elements]

, [RowLog Contents 0]

, [RowLog Contents 1]

, [Log Record]

INTO dump_dblog

FROM fn_dump_dblog (

NULL, NULL, 'DISK', 1, 'C:tempItm8DBA_demo.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)

 

 

Första kontrollen jag gör är att titta efter operationen LOP_BEGIN_XACT. Dessa logg rader markerar början på respektive transaktion och är de enda som har med starttid för transaktionen och vilken SID som startat den. För att få fram vilket login det sedan är kan man t ex använda SUSER_SNAME().

SELECT [Operation]

, [Transaction ID]
, [Begin Time]
, [Transaction Name]
, [Transaction SID]

FROM dump_dblog

WHERE [Operation] = 'LOP_BEGIN_XACT'

För vissa av dessa rader ser transaction name väldigt bekanta ut, CREATE TABLE, INSERT, UPDATE och DELETE.

Vi tittar närmre på detaljerna för INSERT, UPDATE och DELETE transaktionerna.

SELECT [Operation]

, [Lock Information]

, [Num Elements]

, [RowLog Contents 0]

, [RowLog Contents 1]

FROM dump_dblog

WHERE [Transaction ID] IN ('0000:00000337', '0000:0000033b', '0000:0000033c')

Kolumnen Lock Information innehåller information om de lås som tagit för respektive aktivitet:

HoBt 72057594048845440:ACQUIRE_LOCK_IX OBJECT: 0:325576198:0 ;ACQUIRE_LOCK_IX PAGE: 0:1:277 ;ACQUIRE_LOCK_X KEY: 0:72057594038845440 (61a06abd401c)

Bl a objekt id:t för aktuellt objekt hämtas med hjälp av OBJECT_ID(’demo’), i mitt fall 325576198,  och med hjälp av detta kan man göra ytterligare en filtrering på specifikt objekt: AND [Lock Information] LIKE N’%:325576198:%’. Men i vårt enkla fall ger det samma rader.

Operationen LOP_INSERT_ROWS innehåller all information om de tillagda raderna, LOP_MODIFY_ROW om den vi gjorde UPDATE på och LOP_DELETE_ROWS för den vi tog bort.

Log content kolumnerna innehåller all information som behövs för en eventuell redo eller undo operation för respektive modifiering. Dock skiljer sig formatet mellan olika typer av operationer och vissa är ganska lätta att tyda men i de flesta fall är det betydligt mer komplicerat.

Om vi börjar med LOP_MODIFY_ROW och tittar på värdena i [RowLog Contents 0], [RowLog Contents 1] vet vi att de är binära versioner av strängar så vi testar att konvertera dem:

SELECT CAST(0xC46E64726174202020 AS varchar(50)),CAST(0x41747420E46E647261 AS varchar(50))

Alltså precis den rad vi letar efter!

För LOP_INSERT_ROWS och LOP_DELETE_ROWS är det lite värre att tyda Log content, för dem måste man ha kännedom om hur en log record är uppbyggd och för detta hänvisar jag till t ex Paul Randals post Anatomy of a record. För enkla text fält kan vi med hjälp av lite brute force med ganska stor sannolikhet lista ut vilken rad som är rätt.

För att t ex kontrollera om den LOP_DELETE_ROWS vi hittat är för raden med comment=’Exempel: Att ta bort’ kan vi kontrollera om log content för transaktionen 0000:0000033c innehåller den binära representationen av strängen.

SELECT [Transaction ID]

, [Operation]

FROM dump_dblog

WHERE [Transaction ID] = '0000:0000033c'

AND [Operation] = 'LOP_DELETE_ROWS'

AND CHARINDEX(CAST('Exempel: Att ta bort' AS varbinary(25)), [Log Record]) > 0

Alltså ser det ut som om den DELETE vi hittade är rätt! Men observera att CHARINDEX(CAST(’Exempel: Att ta bort’ AS varbinary(20)), [Log Record]) kommer att ge alla rader där strängen ”Exempel: Att ta bort” ingår, men i vårt fall visste vi att det bara fanns ett.

För vårt enkla exempel var det lätt att hitta rätt rader men det bli fort mycket mer data att analysera och få ut all data för en borttagen rad är ganska komplext utan andra hjälpmedel men det går!

Hör gärna av er med frågor och kommentarer!

Ska vi träffas och prata om vad vi konkret kan göra för dig?