Compartilhar via

Registro em log e interceptação de operações de banco de dados

  • Artigo

Observação

EF6 em diante apenas: os recursos, as APIs etc. discutidos nessa página foram introduzidos no Entity Framework 6. Se você estiver usando uma versão anterior, algumas ou todas as informações não se aplicarão.

A partir do Entity Framework 6, sempre que o Entity Framework envia um comando para o banco de dados, esse comando pode ser interceptado pelo código do aplicativo. Isso é mais comumente usado para registro em log do SQL, mas também pode ser usado para modificar ou anular o comando.

Especificamente, o EF inclui:

  • Uma propriedade Log para o contexto semelhante a DataContext.Log no LINQ to SQL
  • Um mecanismo para personalizar o conteúdo e a formatação da saída enviada para o log
  • Blocos de construção de baixo nível para interceptação proporcionando maior controle/flexibilidade

Propriedade Log de Contexto

A propriedade DbContext.Database.Log pode ser definida como um delegado para qualquer método que usa uma cadeia de caracteres. Geralmente, ela é usada com qualquer TextWriter definindo-a como o método "Write" desse TextWriter. Todo o SQL gerado pelo contexto atual será registrado nesse gravador. Por exemplo, o código a seguir registrará o SQL no console:

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    // Your code here...
}

Observe que context.Database.Log está definido como Console.Write. Isso é tudo o que é necessário para registrar o SQL no console.

Vamos adicionar um código simples de consulta/inserção/atualização para que possamos ver alguma saída:

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    var blog = context.Blogs.First(b => b.Title == "One Unicorn");

    blog.Posts.First().Title = "Green Eggs and Ham";

    blog.Posts.Add(new Post { Title = "I do not like them!" });

    context.SaveChanges();
}

Isso gerará a seguinte saída:

SELECT TOP (1)
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title]
    FROM [dbo].[Blogs] AS [Extent1]
    WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 4 ms with result: SqlDataReader

SELECT
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title],
    [Extent1].[BlogId] AS [BlogId]
    FROM [dbo].[Posts] AS [Extent1]
    WHERE [Extent1].[BlogId] = @EntityKeyValue1
-- EntityKeyValue1: '1' (Type = Int32)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

UPDATE [dbo].[Posts]
SET [Title] = @0
WHERE ([Id] = @1)
-- @0: 'Green Eggs and Ham' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 12 ms with result: 1

INSERT [dbo].[Posts]([Title], [BlogId])
VALUES (@0, @1)
SELECT [Id]
FROM [dbo].[Posts]
WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity()
-- @0: 'I do not like them!' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

(Observe que essa é a saída supondo que qualquer inicialização de banco de dados já tenha acontecido. Se a inicialização do banco de dados ainda não tivesse acontecido, haveria muito mais saída mostrando todo o trabalho que as Migrações fazem "por baixo dos panos" para verificar ou criar um novo banco de dados.)

O que é registrado?

Quando a propriedade Log for definida, todos os itens a seguir serão registrados em log:

  • SQL para todos os tipos diferentes de comandos. Por exemplo:
    • Consultas, incluindo consultas LINQ normais, consultas eSQL e consultas brutas de métodos como SqlQuery
    • Inserções, atualizações e exclusões geradas como parte de SaveChanges
    • Consultas de carregamento de relação, como as geradas por carregamento lento
  • Parâmetros
  • Se o comando está sendo executado de forma assíncrona ou não
  • Um carimbo de data/hora que indica quando o comando começou a ser executado
  • Se o comando foi concluído com êxito ou não, se houve falha ao lançar uma exceção ou, para assíncrono, se foi cancelado
  • Alguma indicação do valor do resultado
  • O tempo aproximado necessário para executar o comando. Observe que este é o momento de enviar o comando para obter o objeto de resultado de volta. Ele não inclui tempo para ler os resultados.

Examinando a saída de exemplo acima, cada um dos quatro comandos registrados são:

  • A consulta resultante da chamada para context.Blogs.First
    • Observe que o método ToString para obter o SQL não teria funcionado para essa consulta, pois "First" não fornece um IQueryable no qual ToString poderia ser chamado
  • A consulta resultante do carregamento lento de blog.Posts
    • Observe os detalhes do parâmetro para o valor da chave para o qual o carregamento lento está acontecendo
    • Somente as propriedades do parâmetro definidas como valores não padrão são registradas. Por exemplo, a propriedade Size só será mostrada se não for zero.
  • Dois comandos resultantes de SaveChangesAsync; um para a atualização para alterar um título de postagem, o outro para uma inserção para adicionar uma nova postagem
    • Observe os detalhes do parâmetro para as propriedades FK e Title
    • Observe que esses comandos estão sendo executados de forma assíncrona

Registrar em log em locais diferentes

Conforme mostrado acima, fazer logon no console é super fácil. Também é fácil fazer logon na memória, arquivo e etc. usando diferentes tipos de TextWriter.

Se você estiver familiarizado com o LINQ to SQL, poderá observar que, no LINQ to SQL, a propriedade Log está definida como o objeto TextWriter real (por exemplo, Console.Out) enquanto no EF a propriedade Log está definida como um método que aceita uma cadeia de caracteres (por exemplo, Console.Write ou Console.Out.Write). O motivo para isso é separar o EF do TextWriter aceitando qualquer delegado que possa atuar como um coletor para cadeias de caracteres. Por exemplo, imagine que você já tenha alguma estrutura de registro em log e ela defina um método de registro em log da seguinte maneira:

public class MyLogger
{
    public void Log(string component, string message)
    {
        Console.WriteLine("Component: {0} Message: {1} ", component, message);
    }
}

Isso pode ser conectado à propriedade Log do EF da seguinte maneira:

var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);

Log de resultados

O agente padrão registra texto de comando (SQL), parâmetros e a linha "em execução" com um carimbo de data/hora antes que o comando seja enviado para o banco de dados. Uma linha "concluído" que contém o tempo decorrido é registrada após a execução do comando.

Observe que, para comandos assíncronos, a linha "concluído" não é registrada até que a tarefa assíncrona seja realmente concluída, falhe ou seja cancelada.

A linha "concluído" contém informações diferentes dependendo do tipo de comando e se a execução foi ou não bem-sucedida.

Execução bem-sucedida

Para comandos que são concluídos com êxito, a saída é "Concluída em x ms com o resultado: " seguida de alguma indicação de qual foi o resultado. Para comandos que retornam um leitor de dados, a indicação de resultado é o tipo de DbDataReader retornado. Para comandos que retornam um valor inteiro, como o comando de atualização mostrado acima, o resultado mostrado é esse inteiro.

Execução com falha

Para comandos que falham lançando uma exceção, a saída contém a mensagem da exceção. Por exemplo, o uso do SqlQuery para consultar uma tabela que existe resultará em uma saída de log semelhante a:

SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.

Execução cancelada

Para comandos assíncronos em que a tarefa é cancelada, o resultado pode ser uma falha com uma exceção, pois é isso que o provedor de ADO.NET subjacente geralmente faz quando é feita uma tentativa de cancelamento. Se isso não acontecer e a tarefa for cancelada de forma limpa, a saída será semelhante a esta:

update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms

Alterar o conteúdo e a formatação do log

Por baixo dos panos, a propriedade Database.Log usa um objeto DatabaseLogFormatter. Esse objeto associa efetivamente uma implementação IDbCommandInterceptor (veja abaixo) a um delegado que aceita cadeias de caracteres e um DbContext. Isso significa que os métodos no DatabaseLogFormatter são chamados antes e depois da execução de comandos pelo EF. Esses métodos DatabaseLogFormatter coletam e formatam a saída do log e a enviam para o delegado.

Personalizar o DatabaseLogFormatter

Alterar o que é registrado e como ele é formatado pode ser obtido criando uma nova classe que deriva do DatabaseLogFormatter e substitui os métodos conforme apropriado. Os métodos mais comuns a serem substituídos são:

  • LogCommand – substitua-o para alterar a forma como os comandos são registrados antes de serem executados. Por padrão, LogCommand chama LogParameter para cada parâmetro; você pode optar por fazer o mesmo em sua substituição ou manipular parâmetros de forma diferente.
  • LogResult – substitua-o para alterar como o resultado da execução de um comando é registrado.
  • LogParameter – substitua-o para alterar a formatação e o conteúdo do registro em log de parâmetros.

Por exemplo, suponha que queríamos registrar apenas uma única linha antes de cada comando ser enviado para o banco de dados. Isso pode ser feito com duas substituições:

  • Substitua LogCommand para formatar e gravar a única linha do SQL
  • Substitua LogResult para não fazer nada.

O código seria semelhante a isto:

public class OneLineFormatter : DatabaseLogFormatter
{
    public OneLineFormatter(DbContext context, Action<string> writeAction)
        : base(context, writeAction)
    {
    }

    public override void LogCommand<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Write(string.Format(
            "Context '{0}' is executing command '{1}'{2}",
            Context.GetType().Name,
            command.CommandText.Replace(Environment.NewLine, ""),
            Environment.NewLine));
    }

    public override void LogResult<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
    }
}

Para registrar a saída em log, basta chamar o método Write que enviará a saída para o delegado de gravação configurado.

(Observe que esse código faz a remoção simplista de quebras de linha apenas como um exemplo. Provavelmente não funcionará bem para exibir SQL complexo.)

Definir o DatabaseLogFormatter

Depois que uma nova classe DatabaseLogFormatter tiver sido criada, ela precisará ser registrada no EF. Isso é feito usando a configuração baseada em código. Em poucas palavras, isso significa criar uma nova classe que deriva de DbConfiguration no mesmo assembly que sua classe DbContext e, em seguida, chamar SetDatabaseLogFormatter no construtor dessa nova classe. Por exemplo:

public class MyDbConfiguration : DbConfiguration
{
    public MyDbConfiguration()
    {
        SetDatabaseLogFormatter(
            (context, writeAction) => new OneLineFormatter(context, writeAction));
    }
}

Usar o novo DatabaseLogFormatter

Esse novo DatabaseLogFormatter agora será usado sempre que Database.Log estiver definido. Portanto, a execução do código a partir da parte 1 agora resultará na seguinte saída:

Context 'BlogContext' is executing command 'SELECT TOP (1) [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title]FROM [dbo].[Blogs] AS [Extent1]WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)'
Context 'BlogContext' is executing command 'SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1'
Context 'BlogContext' is executing command 'update [dbo].[Posts]set [Title] = @0where ([Id] = @1)'
Context 'BlogContext' is executing command 'insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()'

Blocos de construção de interceptação

Até agora, analisamos como usar DbContext.Database.Log para registrar o SQL gerado pelo EF. Mas esse código é, na verdade, uma fachada relativamente fina sobre alguns blocos de construção de baixo nível para interceptação mais geral.

Interfaces de interceptação

O código de interceptação é criado com base no conceito de interfaces de interceptação. Essas interfaces herdam do IDbInterceptor e definem métodos que são chamados quando o EF executa alguma ação. A intenção é ter uma interface por tipo de objeto sendo interceptado. Por exemplo, a interface IDbCommandInterceptor define métodos que são chamados antes que o EF faça uma chamada para ExecuteNonQuery, ExecuteScalar, ExecuteReader e métodos relacionados. Da mesma forma, a interface define métodos que são chamados quando cada uma dessas operações é concluída. A classe DatabaseLogFormatter que examinamos acima implementa essa interface para comandos de log.

O contexto de interceptação

Examinando os métodos definidos em qualquer uma das interfaces do interceptor, é evidente que cada chamada recebe um objeto do tipo DbInterceptionContext ou algum tipo derivado disso, como DbCommandInterceptionContext<>. Este objeto contém informações contextuais sobre a ação que o EF está tomando. Por exemplo, se a ação estiver sendo tomada em nome de um DbContext, o DbContext será incluído no DbInterceptionContext. Da mesma forma, para comandos que estão sendo executados de forma assíncrona, o sinalizador IsAsync é definido em DbCommandInterceptionContext.

Tratamento de resultado

A classe DbCommandInterceptionContext<> contém as propriedades chamadas Result, OriginalResult, Exception e OriginalException. Essas propriedades são definidas como nulas/zero para chamadas aos métodos de interceptação que são chamados antes que a operação seja executada – ou seja, para os ...Métodos de execução. Se a operação for executada e bem-sucedida, Result e OriginalResult serão definidos como o resultado da operação. Esses valores podem ser observados nos métodos de interceptação que são chamados após a execução da operação – ou seja, nos ...Métodos executados. Da mesma forma, se a operação for lançada, as propriedades Exception e OriginalException serão definidas.

Suprimir a execução

Se um interceptor definir a propriedade Resultado antes que o comando tenha sido executado (em um dos ...Métodos de execução), o EF não tentará realmente executar o comando, mas usará apenas o conjunto de resultados. Em outras palavras, o interceptor pode suprimir a execução do comando, mas fazer com que o EF continue como se o comando tivesse sido executado.

Um exemplo de como isso pode ser usado é o envio em lote de comandos que tradicionalmente foi feito com um provedor de encapsulamento. O interceptor armazenaria o comando para execução posterior como um lote, mas "fingiria" ao EF que o comando havia sido executado normalmente. Observe que é necessário mais do que isso para implementar o envio em lote, mas este é um exemplo de como a alteração do resultado da interceptação pode ser usada.

A execução também pode ser suprimida definindo a propriedade Exception em um dos ...Métodos de execução. Isso faz com que o EF continue como se a execução da operação tivesse falhado em lançar a exceção determinada. Isso pode, naturalmente, fazer com que o aplicativo falhe, mas também pode ser uma exceção transitória ou alguma outra exceção que é tratada pelo EF. Por exemplo, isso pode ser usado em ambientes de teste para testar o comportamento de um aplicativo quando a execução do comando falhar.

Alterar o resultado após a execução

Se um interceptor definir a propriedade Result após a execução do comando (em um dos ...Métodos executados) em seguida, o EF usará o resultado alterado em vez do resultado que foi realmente retornado da operação. Da mesma forma, se um interceptor definir a propriedade Exception após a execução do comando, o EF lançará a exceção definida como se a operação tivesse gerado a exceção.

Um interceptor também pode definir a propriedade Exception como nula para indicar que nenhuma exceção deve ser gerada. Isso pode ser útil se a execução da operação tiver falhado, mas o interceptor desejar que o EF continue como se a operação tivesse sido bem-sucedida. Isso geralmente também envolve a configuração do Result para que o EF tenha algum valor de resultado para trabalhar à medida que ele continua.

OriginalResult e OriginalException

Depois que o EF executar uma operação, ele definirá as propriedades Result e OriginalResult se a execução não falhar ou as propriedades Exception e OriginalException se a execução falhar com uma exceção.

As propriedades OriginalResult e OriginalException são somente leitura e são definidas apenas pelo EF depois de realmente executar uma operação. Essas propriedades não podem ser definidas por interceptores. Isso significa que qualquer interceptor pode distinguir entre uma exceção ou resultado que foi definido por algum outro interceptor em oposição à exceção real ou ao resultado que ocorreu quando a operação foi executada.

Registrar interceptores

Depois que uma classe que implementa uma ou mais interfaces de interceptação tiver sido criada, ela poderá ser registrada no EF usando a classe DbInterception. Por exemplo:

DbInterception.Add(new NLogCommandInterceptor());

Interceptores também podem ser registrados no nível de domínio do aplicativo usando o mecanismo de configuração baseado em código DbConfiguration.

Exemplo: fazer logon no NLog

Vamos juntar tudo isso em um exemplo que usa IDbCommandInterceptor e NLog para:

  • Registrar um aviso para qualquer comando executado de forma não assíncrona
  • Registrar um erro em log para qualquer comando que seja gerado quando executado

Aqui está a classe que faz o registro em log, que deve ser registrado conforme mostrado acima:

public class NLogCommandInterceptor : IDbCommandInterceptor
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

    public void NonQueryExecuting(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void NonQueryExecuted(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    public void ReaderExecuting(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void ReaderExecuted(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    public void ScalarExecuting(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogIfNonAsync(command, interceptionContext);
    }

    public void ScalarExecuted(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogIfError(command, interceptionContext);
    }

    private void LogIfNonAsync<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (!interceptionContext.IsAsync)
        {
            Logger.Warn("Non-async command used: {0}", command.CommandText);
        }
    }

    private void LogIfError<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (interceptionContext.Exception != null)
        {
            Logger.Error("Command {0} failed with exception {1}",
                command.CommandText, interceptionContext.Exception);
        }
    }
}

Observe como esse código usa o contexto de interceptação para descobrir quando um comando está sendo executado de forma não assíncrona e descobrir quando houve um erro ao executar um comando.