Compartir a través de

Registro e interceptación de operaciones de base de datos

  • Artículo

Nota:

Solo EF6 y versiones posteriores: las características, las API, etc. que se tratan en esta página se han incluido a partir de Entity Framework 6. Si usa una versión anterior, no se aplica parte o la totalidad de la información.

A partir de Entity Framework 6, cada vez que Entity Framework envía un comando a la base de datos, el código de la aplicación puede interceptar este comando. Esto se usa normalmente para registrar SQL, pero también se puede usar para modificar o anular el comando.

Específicamente, EF incluye:

  • Una propiedad Log para el contexto similar a DataContext.Log en LINQ to SQL.
  • Un mecanismo para personalizar el contenido y el formato del resultado enviado al registro.
  • Bloques de creación de bajo nivel para la interceptación, lo que proporciona mayor control o flexibilidad.

Propiedad Context Log

La propiedad DbContext.Database.Log se puede establecer en un delegado para cualquier método que tome una cadena. Lo más común es que se utilice con cualquier TextWriter estableciéndolo en el método "Write" de ese TextWriter. Todo el SQL generado por el contexto actual se registrará en ese escritor. Por ejemplo, el código siguiente registrará SQL en la consola:

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

    // Your code here...
}

Observe que context.Database.Log está configurado como Console.Write. Esto es todo lo que se necesita para registrar SQL en la consola.

Vamos a agregar código simple de consulta, inserción y actualización para que podamos ver algunos resultados:

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();
}

Se generará el siguiente resultado:

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

(Tenga en cuenta que este es el resultado en el que se supone que ya se ha producido cualquier inicialización de base de datos. Si aún no se hubiera producido la inicialización de la base de datos, habría un resultado mayor en el que se muestra todo el trabajo que las migraciones realizan en segundo plano para comprobar o crear una nueva base de datos).

¿Qué se registra?

Cuando se establece la propiedad Log, se registra todo lo siguiente:

  • SQL para todos los distintos tipos de comandos. Por ejemplo:
    • Consultas, incluidas las consultas LINQ normales, las consultas eSQL y las consultas sin procesar de métodos como SqlQuery.
    • Inserciones, actualizaciones y eliminaciones generadas como parte de SaveChanges.
    • Consultas de carga de relaciones como las generadas por la carga diferida.
  • Parámetros
  • Si el comando se está ejecutando de forma asincrónica.
  • Marca de tiempo que indica cuándo se inició la ejecución del comando.
  • Si el comando se completó correctamente, si se produjo un error al iniciar una excepción o, para la opción asincrónica, si se canceló.
  • Alguna indicación del valor de resultado.
  • La cantidad aproximada de tiempo que tardó el comando en ejecutarse. Tenga en cuenta que este es el tiempo que transcurre desde que se envía el comando hasta que se obtiene el resultado. No incluye tiempo para leer los resultados.

Al examinar el resultado de ejemplo anterior, cada uno de los cuatro comandos registrados son:

  • La consulta resultante de la llamada a context.Blogs.First.
    • Tenga en cuenta que el método ToString para obtener SQL no habría funcionado para esta consulta, ya que "First" no proporciona un valor IQueryable en el que se podría llamar a ToString.
  • La consulta resultante de la carga diferida de blog.Posts.
    • Observe los detalles del parámetro para el valor de clave para el que se está produciendo una carga diferida.
    • Solo se registran las propiedades del parámetro que se establecen en valores no predeterminados. Por ejemplo, la propiedad Size solo se muestra si no es cero.
  • Dos comandos resultantes de SaveChangesAsync; uno para la actualización para cambiar un título de publicación, el otro para una inserción para agregar una nueva publicación.
    • Observe los detalles del parámetro para las propiedades FK y Title.
    • Observe que estos comandos se ejecutan de forma asincrónica.

Registro en diferentes lugares

Como se muestra anteriormente, el registro en la consola es muy fácil. También es fácil registrar en memoria, archivo, etc. utilizando diferentes tipos de TextWriter.

Si está familiarizado con LINQ to SQL, es posible que observe que en LINQ to SQL la propiedad Log está establecida en el objeto TextWriter real (por ejemplo, Console.Out), mientras que en EF la propiedad Log está establecida en un método que acepta una cadena (por ejemplo, Console.Write o Console.Out.Write). El motivo de esto es desacoplar EF de TextWriter aceptando cualquier delegado que pueda actuar como receptor para las cadenas. Por ejemplo, imagine que ya tiene algún marco de registro y define un método de registro como el siguiente:

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

Esto podría enlazarse a la propiedad Log de EF de la siguiente manera:

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

Registro de resultados

El registrador predeterminado registra el texto del comando (SQL), los parámetros y la línea "Executing" con una marca de tiempo antes de enviar el comando a la base de datos. Tras la ejecución del comando, se registra una línea "completed" que contiene el tiempo transcurrido.

Tenga en cuenta que, para los comandos asincrónicos, la línea "completed" no se registra hasta que la tarea asincrónica se completa, produce un error o se cancela.

La línea "completed" contiene información diferente en función del tipo de comando y de si la ejecución se realizó correctamente o no.

Ejecución correcta

Para los comandos que se completan correctamente, el resultado es "Completed in x ms with result:" seguido de alguna indicación del resultado. Para los comandos que devuelven un lector de datos, la indicación de resultado es el tipo de DbDataReader devuelto. Para los comandos que devuelven un valor entero, como el comando update mostrado anteriormente, el resultado mostrado es ese entero.

Ejecución con errores

En el caso de los comandos que producen un error al iniciar una excepción, el resultado contiene el mensaje de la excepción. Por ejemplo, el uso de SqlQuery para consultar en una tabla que existe dará como resultado un resultado de registro similar al siguiente:

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

Ejecución cancelada

En el caso de los comandos asincrónicos en los que se cancela la tarea, el resultado podría ser un error con una excepción, ya que esto es lo que suele hacer el proveedor de ADO.NET subyacente cuando se intenta cancelar. Si esto no ocurre y la tarea se cancela limpiamente, el resultado tendrá un aspecto similar al siguiente:

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

Cambio del contenido y el formato del registro

En segundo plano, la propiedad Database.Log usa un objeto DatabaseLogFormatter. Este objeto enlaza eficazmente una implementación de IDbCommandInterceptor (vea a continuación) a un delegado que acepta cadenas y dbContext. Esto significa que EF llama a los métodos de DatabaseLogFormatter antes y después de la ejecución de comandos. Estos métodos DatabaseLogFormatter recopilan y formatean el resultado del registro y lo envían al delegado.

Personalización de DatabaseLogFormatter

El cambio de lo que se registra y el formato que se le aplica se puede lograr mediante la creación de una nueva clase que se deriva de DatabaseLogFormatter e invalida los métodos según corresponda. Los métodos más comunes para invalidar son:

  • LogCommand: invalide esto para cambiar cómo se registran los comandos antes de que se ejecuten. De forma predeterminada, LogCommand llama a LogParameter para cada parámetro; puede optar por hacer lo mismo en la invalidación o controlar los parámetros de forma diferente.
  • LogResult: invalide esto para cambiar cómo se registra el resultado de ejecutar un comando.
  • LogParameter: invalide esto para cambiar el formato y el contenido del registro de parámetros.

Por ejemplo, supongamos que queríamos registrar una sola línea antes de que cada comando se envíe a la base de datos. Se puede hacer con dos invalidaciones:

  • Invalidar LogCommand para dar formato y escribir una sola línea de SQL.
  • Invalidar LogResult para no hacer nada.

El código debería tener un aspecto parecido al siguiente:

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 el resultado, simplemente llame al método Write que enviará el resultado al delegado de escritura configurado.

(Tenga en cuenta que este código realiza una eliminación simplista de saltos de línea como ejemplo. Es probable que no funcione bien para ver SQL complejo).

Configuración de DatabaseLogFormatter

Una vez creada una nueva clase DatabaseLogFormatter, debe registrarse con EF. Esto se hace mediante la configuración basada en código. En pocas palabras, esto significa crear una nueva clase que se derive de DbConfiguration en el mismo ensamblado que la clase DbContext y, a continuación, llamar a SetDatabaseLogFormatter en el constructor de esta nueva clase. Por ejemplo:

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

Uso de DatabaseLogFormatter

Este nuevo valor DatabaseLogFormatter se usará ahora en cualquier momento en que se establezca Database.Log. Por lo tanto, la ejecución del código de la parte 1 ahora dará como resultado el siguiente resultado:

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()'

Bloques de creación de interceptación

Hasta ahora hemos visto cómo usar DbContext.Database.Log para registrar el SQL generado por EF. Pero este código es en realidad una fachada relativamente delgada sobre algunos bloques de creación de bajo nivel para una interceptación más general.

Interfaces de interceptación

El código de interceptación se basa en el concepto de interfaces de interceptación. Estas interfaces heredan de IDbInterceptor y definen métodos a los que se llama cuando EF realiza alguna acción. La intención es tener una interfaz por tipo de objeto que se intercepta. Por ejemplo, la interfaz IDbCommandInterceptor define métodos a los que se llama antes de que EF realice una llamada a ExecuteNonQuery, ExecuteScalar, ExecuteReader y métodos relacionados. Del mismo modo, la interfaz define los métodos a los que se llama cuando se completa cada una de estas operaciones. La clase DatabaseLogFormatter que hemos examinado anteriormente implementa esta interfaz para registrar comandos.

Contexto de interceptación

Al examinar los métodos definidos en cualquiera de las interfaces del interceptor, es evidente que cada llamada recibe un objeto de tipo DbInterceptionContext o algún tipo derivado de esto, como DbCommandInterceptionContext<>. Este objeto contiene información contextual sobre la acción que realiza EF. Por ejemplo, si la acción se realiza en nombre de dbContext, dbContext se incluye en DbInterceptionContext. Del mismo modo, para los comandos que se ejecutan de forma asincrónica, la marca IsAsync se establece en DbCommandInterceptionContext.

Control de resultados

La clase dbCommandInterceptionContext<> contiene propiedades denominadas Result, OriginalResult, Exception y OriginalException. Estas propiedades se establecen en nulo/cero para las llamadas a los métodos de interceptación a los que se llama antes de que se ejecute la operación, es decir, para los métodos …Executing. Si la operación se ejecuta correctamente, Result y OriginalResult se establecen en el resultado de la operación. Estos valores se pueden observar en los métodos de interceptación a los que se llama después de ejecutar la operación; es decir, en los métodos ...Executed. Del mismo modo, si se produce la operación, se establecerán las propiedades Exception y OriginalException.

Supresión de la ejecución

Si un interceptor establece la propiedad Result antes de que el comando se haya ejecutado (en uno de los métodos …Executing), EF no intentará ejecutar realmente el comando, sino que simplemente usará el conjunto de resultados. En otras palabras, el interceptor puede suprimir la ejecución del comando, pero hacer que EF continúe como si se hubiera ejecutado el comando.

Un ejemplo de cómo se puede usar es el procesamiento por lotes de comandos que se ha realizado tradicionalmente con un proveedor de encapsulado. El interceptor almacenaría el comando para su posterior ejecución como un lote, pero "fingiría" ante EF que el comando se había ejecutado de forma normal. Tenga en cuenta que se requiere más que esto para implementar el procesamiento por lotes, pero este es un ejemplo de cómo se podría utilizar el cambio del resultado de la interceptación.

La ejecución también se puede suprimir estableciendo la propiedad Exception en uno de los métodos ...Executing. Esto hace que EF continúe como si la ejecución de la operación hubiera dado un error iniciando la excepción dada. Esto puede, por supuesto, provocar que la aplicación se bloquee, pero también puede ser una excepción transitoria o alguna otra excepción controlada por EF. Por ejemplo, esto podría usarse en entornos de prueba para probar el comportamiento de una aplicación cuando se produce un error en la ejecución del comando.

Cambio del resultado después de la ejecución

Si un interceptor establece la propiedad Result después de que el comando se haya ejecutado (en uno de los métodos …Executed ), EF usará el resultado cambiado en lugar del resultado que se devolvió realmente de la operación. Del mismo modo, si un interceptor establece la propiedad Exception después de que se haya ejecutado el comando, EF iniciará la excepción establecida como si la operación hubiera producido la excepción.

Un interceptor también puede establecer la propiedad Exception en NULL para indicar que no se debe producir ninguna excepción. Esto puede ser útil si se produjo un error en la ejecución de la operación, pero el interceptor desea que EF continúe como si la operación se hubiera realizado correctamente. Normalmente, esto también implica establecer el resultado para que EF tenga algún valor de resultado con el que trabajar a medida que continúa.

OriginalResult y OriginalException

Una vez que EF haya ejecutado una operación, establecerá las propiedades Result y OriginalResult si la ejecución no produjo un error o las propiedades Exception y OriginalException si se produjo un error en la ejecución con una excepción.

Las propiedades OriginalResult y OriginalException son de solo lectura y solo las establece EF después de ejecutar realmente una operación. Los interceptores no pueden establecer estas propiedades. Esto significa que cualquier interceptor puede distinguir entre una excepción o un resultado establecido por algún otro interceptor en lugar de la excepción real o el resultado que se produjo cuando se ejecutó la operación.

Registro de interceptores

Una vez que se ha creado una clase que implementa una o varias de las interfaces de interceptación, se puede registrar con EF mediante la clase DbInterception. Por ejemplo:

DbInterception.Add(new NLogCommandInterceptor());

Los interceptores también se pueden registrar en el nivel de dominio de la aplicación mediante el mecanismo de configuración basado en código DbConfiguration.

Ejemplo: Registro en NLog

Vamos a reunir todo esto en un ejemplo que usa IDbCommandInterceptor y NLog para:

  • Registrar una advertencia para cualquier comando que se ejecute de forma no asincrónica
  • Registrar un error para cualquier comando que se inicie cuando se ejecute

Esta es la clase que realiza el registro, que debe registrarse como se muestra anteriormente:

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 cómo este código usa el contexto de interceptación para detectar cuándo se ejecuta un comando de forma no asincrónica y detectar cuándo se produjo un error al ejecutar un comando.