O log de transações do SQL Server contém todo o histórico de cada ação realizada em um (ou mais) bancos de dados. Ler e interpretar o log muitas vezes pode ser o último recurso para investigar como e quando determinadas mudanças ocorreram. É uma das principais ferramentas forenses à sua disposição quando é preciso identificar o autor de uma alteração indesejada ou de um problema. Entender o log e procurar pelo problema pode ser uma árdua tarefa, e definitivamente não é para aquelas pessoas de coração fraco. E o fato de que a saída ::fn_dblog pode facilmente resultar em milhões de linhas não ajuda muito. Mas vou dar alguns exemplos de práticas simples que podem ajudá-lo a percorrer o longo caminho em busca de informações através dos arquivos de log do SQL Server.
O registro prévio da escrita (WAL), também conhecido como journaling, é melhor descrito na documentação do ARIES, mas podemos começar a determiná-la com uma descrição menos acadêmica: o SQL Server primeiro descreve no log qualquer mudança que esteja prestes a fazer, antes de modificar quaisquer dados. Há uma breve descrição desse protocolo no documento O básico sobre entrada e saída de dados do SQL Server 2000, e o time do CSS realizou uma apresentação muito importante presente no documento Como funciona: apresentação de Bob Dorr sobre entrada e saída de dados do SQL Server. O que é importante para nós, no contexto deste artigo, é que uma das consequências do protocolo WAL é que qualquer mudança que tenha ocorrido em qualquer um dos dados armazenados no SQL Server deve ser armazenada em algum lugar do log. É importante lembrar que todos os objetos de banco de dados (tabelas, views, procedures, usuários, permissões etc.) são armazenados como dados no banco de dados (sim, metadados ainda são dado) assim, qualquer mudança que tenha ocorrido em qualquer objeto do banco de dados também será descrita em algum lugar do log. E quando digo todas as mudanças, realmente quero dizer qualquer operação, incluindo mudanças muitas vezes mínimas, operações sem muita importância e as chamados operações “não-registradas”, como a sintaxe TRUNCATE. Na verdade, não existe essa coisa de operação não-registrada. Para todos os efeitos práticos, absolutamente tudo é registrado e deixará obrigatoriamente um rastro no log que pode ser descoberto.
A imagem acima mostra como três operações simultâneas foram colocadas para fora no log: a primeira operação contém duas operações de insert e uma operação de delete, a segunda contém um insert, mas havia feito um roll back e portanto contém um delete compensatório, e a última comitou duas operações delete e uma insert. Embora todas as três transações ocorram simultaneamente, a verdadeira ordem de realização da transação é aquela registrada no log, dada pela LSN. Normalmente, quando analisamos o log, precisamos olhar para operações relacionadas a transações específicas. O campo de chave é a coluna [Transaction ID] que contém o ID da transação gerado pelo sistema para cada operação registrada. Todas as operações registradas por uma transação terão o mesmo valor na coluna [Transaction ID].
Vamos criar um pequeno exemplo e verificar o log gerado:
create table demotable (
id int not null identity(1,1) primary key,
data char(20),
created_at datetime default getutcdate());
go
insert into demotable (data) values ('standalone xact');
go 5
begin transaction
go
insert into demotable (data) values ('one xact');
go 5
commit;
go
delete from demotable
where id in (2,5,6,9);
go
A primeira ação que vou fazer será olhar para as operações LOP_BEGIN_XACT. Esse registro de log marca o início de uma transação e é muito importante na análise de log, porque é o único registro de log que contém a data e a hora em que a transação foi iniciada, além de conter ainda o SID do usuário que emitiu a declaração. Veja um exemplo de consulta para essas operações:
select [Current LSN], [Operation], [Transaction ID], [Parent Transaction ID], [Begin Time], [Transaction Name], [Transaction SID] from fn_dblog(null, null) where [Operation] = 'LOP_BEGIN_XACT'
Podemos reconhecer algumas das operações registradas no log, presentes na sintaxe acima. Lembre-se de que o SQL Server sempre irá registrar a transação executada, se ela não for registrada explicitamente, o próprio SQL Server irá iniciar um registro para a declaração que está sendo executada. No LSN 20:5d:2, começamos a transação 2d0 com o comando CREATE TABLE, então essa deve ser a transação implícita que começou com a instrução CREATE TABLE. No LSN 20:9b:2, a transação id 2d6 chamada INSERT é para nossa primeira declaração standalone INSERT, e da mesma forma LSNs 20:a0:2 inicia a transação 2d9, o LSN 20:A1:1 inicia a 2da, o LSN 20:a2:1 inicia XACT 2db, o LSN 20:A3: 1 inicia 2db xact e o LSN 20:A3:1 inicia xact 2DC, respectivamente. Para quem detectar um certo padrão na numeração do LSN, a explicação é simples: confira o documento LSN: Log Sequence Number para entender melhor. E se o número hexadecimal for familiar para você, veja que o ID da transação é basicamente um número de incremento.
O LSN 20:a4:1 que inicia 2dd xact é um pouco diferente, porque é nomeado como user_transaction. Isso acontece porque uma transação explícita começou com o comando BEGIN TRANSACTION. Não há transações mais implícitas do que as operação de inclusão, como as 5 instruções INSERT existentes dentro da transação explícita, já que a instrução INSERT não necessariamente precisa iniciar uma transação implícita: ela utiliza a transação explícita iniciada pela instrução BEGIN TRANSACTION. Finalmente, o LSN 20:aa:1 inicia o 2df xact implícito para a instrução DELETE.
Além disso, vemos uma série de transações que não podemos correlacionar diretamente com uma determinada declaração. Transações 2D2, 2D3, 2d4 e 2D5 são consideradas transações SplitPage, ou seja, são uma forma que o SQL Server utiliza para manter as restrições de ordem de chaves estruturais B-Trees e há ampla literatura sobre o assunto, como a página de rastreamento usando o log de transações ou o documento Quão custosas são as divisões de página em termos de log de transações? Observe que todas essas transações possuem o mesmo ID pai de transação, que é 2d0 (que é o xact CREATE TABLE). Estas são divisões de página que ocorrem nas tabelas do catálogo de metadados que estão sendo modificados pela operação CREATE TABLE.
Também podemos ver que, logo após o primeiro comando INSERT de uma transação, o argumento Allocate Rows foi iniciado. As tabelas são normalmente criadas sem qualquer página, e o primeiro INSERT irá acionar a atribuição da primeira página para a tabela. A alocação ocorre em uma transação separada e que é executada imediatamente, portanto permite que outras inserções na tabela sejam realizadas para que o processamento das instruções continue mesmo que a inserção que realmente desencadeou as alocações de linhas não seja executada ou mesmo possa ser revertida. Essa capacidade de iniciar e confirmar transações em uma sessão, independentemente de a transação principal existir no SQL Server, não está exposta de forma alguma na superfície de programação básica do T-SQL.
A coluna Transaction SID mostra o SID da sessão que iniciou a transação. Você pode usar o SUSER_SNAME, que é uma função para recuperar o login de usuário real.
Um olhar detalhado para uma transação
select [Current LSN], [Operation], [AllocUnitName], [Page ID], [Slot ID], [Lock Information], [Num Elements], [RowLog Contents 0], [RowLog Contents 1], [RowLog Contents 2] from fn_dblog(null, null) where [Transaction ID]='0000:000002d6'
Vamos olhar mais de perto para o ID xact 2D6, que é a primeira operação INSERT. O resultado pode parecer misterioso, mas há diversas informações úteis quando se sabe para onde olhar. Primeiro, o trivial: o xact 2D6 tem 4 operações registradas no log. Toda transação deve ter um LOP_BEGIN_XACT e um registro para fechá-lo, geralmente LOP_COMMIT_XACT. Os outros dois são uma operação de gravação de conclusão do comando (LOP_LOCK_XACT) e uma modificação de dados real (LOP_INSERT_ROWS). O restante vem com a operação de modificação de dados, mas vamos veremos isso mais adiante, por exemplo, sobre como o LOP_LOCK_XACT também pode ser extremamente útil na análise.
Operações que modificam dados, como LOP_INSERT_ROWS, sempre registram os detalhes físicos da operação (ID de página, número de registro) e o objeto que foi modificado: o ID de unidade de alocação (leia o documento sys.allocation_units para mais detalhes) e o ID de partição (leia o documento sys.partitions para mais detalhes). Lembre-se de que as tabelas ainda não particionadas ainda serão representados em sys.partitions, mas você pode pensar nelas como sendo particionadas sob a forma de uma única partição para a tabela inteira. A coluna AllocUnitName na saída fn_dblog mostra a maneira mais simples de identificar quais operações afetaram uma tabela específica.
As colunas Page Id e Slot ID vão dizer exatamente o registro e em qual página foram modificadas por essa transação. 4f hex é 79 decimal e no meu caso, meu ID de banco de dados é 5:
dbcc traceon(3604,-1); dbcc page(5,1,79,3); Slot 0 Offset 0x60 Length 39 Record Type = PRIMARY_RECORD Record Attributes = NULL_BITMAP Record Size = 39 Memory Dump @0x000000000EB0A060 0000000000000000: 10002400 01000000 7374616e 64616c6f 6e652078 ..$.....standalone x 0000000000000014: 61637420 20202020 912ba300 b6a10000 030000 act +£.¶¡..... Slot 0 Column 1 Offset 0x4 Length 4 Length (physical) 4 id = 1 Slot 0 Column 2 Offset 0x8 Length 20 Length (physical) 20 data = standalone xact Slot 0 Column 3 Offset 0x1c Length 8 Length (physical) 8 created_at = 2013-05-06 09:54:05.070 Slot 0 Offset 0x0 Length 0 Length (physical) 0 KeyHashValue = (8194443284a0)
Na verdade, a página 5:1:79 no slot 0 contém o primeiro comando INSERT do script. A saída fn_dblog corresponde ao que encontramos no banco de dados. Além do interesse acadêmico, essa informação tem utilidade prática: se queremos saber que transação modificou um determinado registro e sabemos a posição de registro (página, slot), podemos procurar o log de registros atualizados que determina sua posição. Infelizmente, essa abordagem tem suas desvantagens. O maior problema é que em B-Trees a posição de um registro é móvel, o que dificulta as coisas. Operações de divisão da página movem registros e mudam sua localização física, tornando mais difícil encontrar as transações que modificaram o registro.
A coluna Lock Informations é realmente a minha coluna de análise forense favorita. Nela estão todos os conteúdos necessários para a operação LOP_INSERT_ROWS presente no meu exemplo: HoBt 72057594039042048: ACQUIRE_LOCK_IX OBJETO: 5: 245575913: 0; ACQUIRE_LOCK_IX PAGE: 5: 1: 79; ACQUIRE_LOCK_X CHAVE: 5: 72057594039042048 (8194443284a0). Temos aqui o object_id real da tabela, novamente o ID de página e, em seguida, o bloqueio de chaves. Para B-Trees, o bloqueio de chaves é um hash do valor da chave e, portanto, pode ser usado para localizar a linha, mesmo que esta tenha sido modificada após divisões de página:
select %%lockres%%, * from demotable where %%lockres%% = '(8194443284a0)';
Voltamos a localizar na mesma linha o primeiro comando INSERT. Lembre-se de que os hashes de recursos de bloqueio, por definição, podem produzir falsos positivos, devido à colisão de hash. Mas a probabilidade é baixa o suficiente para valer o risco e deve-se simplesmente usar de bom senso se a colisão for encontrada (por exemplo, o comando SELECT acima retorna mais de uma linha para o hash desejado).
A última coluna que vou abordar são as colunas de conteúdo do log. Essas colunas contêm o registro ‘payload’ para operações de dados. A carga varia de acordo com o tipo de operação, mas deve conter informações suficientes para que a recuperação da informação seja possível no momento de refazer ou desfazer a operação. Para um INSERT, isso significa que o conteúdo completo da linha inserida deve estar presente no registro de log.
Vamos olhar para o conteúdo do registro 0:
0x10002400010000007374616E64616C6F6E6520786163742020202020912BA300B6A10000030000
Parece tudo grego, eu sei, mas basta olhar novamente na saída DBCC PAGE:
0000000000000000: 10002400 01000000 7374616e 64616c6f 6e652078 ..#8230;..standalone x
0000000000000014: 61637420 20202020 912ba300 b6a10000 030000 act +£.¶¡…..
O conteúdo é idêntico. Isso significa que a o log da operação LOP_INSERT_ROWS conterá a imagem real da linha, uma vez que foi inserida na página do log. E isso nos dá a última, e muitas vezes mais difícil, maneira de descobrir os registros de log que afetaram uma determinada linha: analisar o conteúdo do registro de log real em busca de padrões que identificam a linha. Caso esteja familiarizado com a anatomia de um registro, poderá ainda identificar as partes da gravação do log:
- 10002400 é o cabeçalho do registro
- 01000000 é a primeira coluna fixa (id, int)
- 0x7374616E64616C6F6E6520786163742020202020 é a segunda coluna de tamanho fixo (20)
- 0x912ba300b6a10000 é a coluna datetime created_at
- 0x030000 é o bitmap NULL
Vamos considerar agora um exemplo de como usar esse know-how recém-adquirido. Eu fiz algumas modificações para a tabela:
insert into demotable (data) values ('junk'), ('important'), ('do not change!');
update demotable set data='changed' where data = 'do not change!';
update demotable set created_at = getutcdate() where data = 'changed';
delete from demotable where data='important'
Agora, a tabela contém uma linha que não deveria estar lá (considerada lixo), uma linha que era “importante” está em falta e uma linha que não deve ter sido alterada foi modificada. Podemos localizar as operações de log correspondentes? Vamos começar com o caso fácil: o registro que contém lixo ainda está presente para que possamos simplesmente procurar o registro de log que o inseriu. Vamos usar o recurso de bloqueio de hash para localizar o registro de log:
declare @lockres nchar(14); select top (1) @lockres = %%lockres%% from demotable where data = 'junk'; declare @xact_id nvarchar(14) select top (1) @xact_id = [Transaction ID] from fn_dblog(null, null) where charindex(@lockres, [Lock Information]) > 0; select [Current LSN], [Operation], [Transaction ID], [Transaction SID], [Begin Time], [End Time] from fn_dblog(null, null) where [Transaction ID] = @xact_id;
O script encontra o valor do hash com recurso de bloqueio para a linha com o valor de dados considerado lixo, confere em seguida o ID da transação que travou essa linha e, finalmente, mostra todas as operações que essa transação fez. Há alguns pontos de destaque aqui: presumimos que o hash com recurso de bloqueio é único e também que a primeira operação que bloqueia essa linha é a operação em que estamos interessados. Na vida real, o cenário pode ficar significativamente mais complexo, porque colisões de hash podem existir e porque pode haver várias transações que encerram a linha com o recurso de bloqueio em que estamos interessados, dificultando sua localização.
O próximo desafio é localizar a transação que modificou os dados que não deveriam ter sido alterados. Podemos executar o mesmo script como ilustrado acima, mas isso resultaria em encontrar a transação que fez o INSERT original da linha, não a que fez a atualização. Então, em vez disso, permite encontrar todas as transações bloqueadas com hash de bloqueio da linha:
declare @lockres nchar(14); select top (1) @lockres = %%lockres%% from demotable where data = 'changed'; declare @xact_id table (id nvarchar(14)); insert into @xact_id (id) select [Transaction ID] from fn_dblog(null, null) where charindex(@lockres, [Lock Information]) > 0; select [Current LSN], [Operation], [Transaction ID], [Transaction SID], [Begin Time], [End Time], [Num Elements], [RowLog Contents 0], [RowLog Contents 1], [RowLog Contents 2], [RowLog Contents 3], [RowLog Contents 4], [RowLog Contents 5] from fn_dblog(null, null) where [Transaction ID] in (select id from @xact_id);
Isso mostra três transações (2E0, 2e2 e 2e4), sendo a primeira o INSERT original e, em seguida, duas transações de atualização: o LOP_MODIFY_ROW é o registro de log para atualizar uma linha. Como podemos saber qual atualização é a que modificou os dados que não deveriam mudar? Desta vez, incluí no resultado [RowLog Contents 0] através de [RowLog Contentes 5], porque o elemento [Num Elements] é 6, o que indica que o registro de log contém 6 resultados. Lembre-se de que o registro de log deve conter informações suficientes para que seja possível refazer ou desfazer a operação, de modo que esses resultados devem conter o valor a ser alterado, tanto antes como depois da alteração. Os registros LOP_MODIFY_ROWS presentes no LSN 20:B4:2 têm resultados como 0x646F206E6F74206368616E676521 0 e 0x6368616E67656420202020202020, que são claramente strings ASCII:
select cast(0x646F206E6F74206368616E676521 as varchar(20)), cast(0x6368616E67656420202020202020 as varchar(20)); -------------------- -------------------- do not change! changed (1 row(s) affected)
O comando UPDATE que nos interessa é o 2e2 xact. A partir da operação de log LOP_BEGIN_XACT para esse xact específico, podemos, mais uma vez, descobrir quando é que ocorreu a mudança e quem fez isso.
O desafio final foi descobrir quando o registro considerado importante foi excluído. Uma vez que o registro está faltando, não podemos usar novamente o recurso de bloqueio %%lockres%%. Se quisermos conhecer o ID do registro excluído, poderíamos utilizar alguns truques, porque, se recriar um registro na mesma tabela com a mesma tecla em que a linha foi excluída, então ele vai ter o mesmo recurso de bloqueio de hash e podemos buscar exatamente por esse hash. Mas não sabemos o ID da linha excluída, apenas o valor na coluna de dados. Se o valor é diferente o suficiente para valer a busca por ele, podemos tentar buscar a linha por força bruta, pesquisando o resultado dos registros:
select *
from fn_dblog(null, null)
where charindex(cast('important' as varbinary(20)), [Log Record]) > 0;
Encontramos três operações que tiveram a string ‘importante’ no resultado de registro do log. Sabemos que xact 2e0 é o INSERT original, e encontramos o xact 2e3 que contém um LOP_DELETE_ROWS, que é o registro de log para operações de exclusão. Usando essa abordagem de força bruta encontramos a transação que excluiu o registro que continha a string ‘importante’. É importante lembrar que meu exemplo utiliza uma sequência de caracteres ASCII simples. Deve-se entender como os valores são representados em binário para procurar os resultados do log para valores conhecidos. Isso é bastante complicado para os valores mais complexos, como os necessários para encontrar o formato de representação interna (por exemplo, tipos numéricos/decimais) e ser capaz de escrever corretamente para a plataforma Intel LSB correta o valor para determinados tipos, como int ou datetime.
Sendo assim, o que acontece com os LOP_MODIFY_ROWS em 2e1 xact, uma vez que não modificaram a linha com o valor ‘importante’ em nosso script de teste? Mais uma vez, o registro no log conterá todos os detalhes:
select [Current LSN], [Operation], [AllocUnitName], [Transaction Name] from fn_dblog(null, null) where [Transaction ID] = '0000:000002e1';
A transação possui o status auto-update. A sequência real contendo a string ‘importante’ foi copiada para as estatísticas do log quando estas foram geradas automaticamente onde foram criadas e, portanto, o registro de log para a operação de atualização dos dados obviamente contém a string ‘importante’.
***
Na próxima e última parte, veremos o que acontece após o truncamento, quando as informações de bloqueio não ajudam, considerações práticas, mudanças DDL e uso do Object ID.
***
Artigo traduzido pela Redação iMasters com autorização do autor. Publicado originalmente em http://rusanu.com/2014/03/10/how-to-read-and-interpret-the-sql-server-log/
De 0 a 10, o quanto você recomendaria este artigo para um amigo?