Registro e interceptación de operaciones de base de datos

Nota:

Solo ef6 y versiones posteriores : las características, las API, etc. que se describen en esta página se introdujeron en Entity Framework 6. Si usa una versión anterior, no se aplica parte o toda 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.

En concreto, 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 de la salida enviada al registro
  • Bloques de construcción de bajo nivel para la interceptación, lo que proporciona mayor control y flexibilidad

Context Log (propiedad)

La propiedad DbContext.Database.Log se puede establecer en un delegado para cualquier método que tome una cadena. Normalmente se usa con cualquier TextWriter asignándolo al método "Write" de ese TextWriter. Todas las consultas SQL generadas por el contexto actual se registrarán en ese registro. 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 se establece en 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();
}

Esto generará la siguiente salida:

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 esta es la salida en la 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 una salida mucho más en la 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 registrarán todas las siguientes acciones:

  • 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
  • Indica si el comando se está ejecutando de forma asincrónica
  • Marca de tiempo que indica cuándo se inició la ejecución del comando
  • Ya sea que el comando se completó correctamente, falló lanzando una excepción o, para operaciones asíncronas, fue cancelado.
  • Alguna indicación del valor de resultado
  • Cantidad aproximada de tiempo que tardó en ejecutar el comando. Tenga en cuenta que este es el tiempo desde el envío del comando hasta la recepción del objeto de resultado. No incluye tiempo para leer los resultados.

Al examinar la salida 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 IQueryable en el que se podría llamar a ToString.
  • La consulta resultante de la carga diferida de las entradas del blog.
    • 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; una para la actualización para cambiar un título de publicación, la otra 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 datos en la memoria, en los archivos, etc., mediante 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 conectarse a la propiedad de registro 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. Una línea "completada" que contiene el tiempo transcurrido se registra después de la ejecución del comando.

Tenga en cuenta que, en el caso de 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 "completado" 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, la salida es "Completado en x ms con el resultado: " seguido de alguna indicación de lo que fue el 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 fallida

En el caso de los comandos que producen un error al iniciar una excepción, la salida contiene el mensaje de la excepción. Por ejemplo, el uso de SqlQuery para consultar en una tabla que existe dará como resultado una salida de registro similar a la 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 un intento. Si esto no ocurre y la tarea se cancela limpiamente, la salida 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 de DatabaseLogFormatter recopilan y formatean la salida del log y la envían al delegado.

Personalización de DatabaseLogFormatter

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

  • LogCommand: invalide esta opción 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 esta opción para cambiar cómo se registra el resultado de ejecutar un comando.
  • LogParameter: invalide esta opción 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. Esto se puede hacer con dos invalidaciones:

  • Sobrescribir LogCommand para dar formato y escribir una sola línea de SQL
  • Sobrescriba LogResult para que no realice ninguna acción.

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 la salida, simplemente llame al método Write que enviará la salida 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 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 del nuevo DatabaseLogFormatter

Este nuevo 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 la siguiente salida:

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 construcció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 realmente una capa superficial sobre algunos bloques de construcció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 este tipo, 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 un DbContext, entonces el DbContext se incluye en el DbInterceptionContext. Del mismo modo, para los comandos que se ejecutan de forma asincrónica, la marca IsAsync se establece en DbCommandInterceptionContext.

Gestión 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 ... de ejecución. Si la operación se ejecuta con éxito, 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 una vez ejecutada la operación, es decir, en ... Métodos ejecutados. Del mismo modo, si la operación lanza una excepció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 se haya ejecutado el comando (en uno de los ... Ejecutar métodos) entonces 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 ajuste. El interceptor almacenaría el comando para su ejecución posterior como un lote, pero haría creer a EF que el comando se había ejecutado de manera normal. Tenga en cuenta que requiere más de esto para implementar el procesamiento por lotes, pero se trata de un ejemplo de cómo se puede usar 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 de ejecución. Esto hace que EF continúe como si se hubiera producido un error en la ejecución de la operación lanzando 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 la ejecución del comando (en uno de los métodos ...Executed), entonces 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. Estos 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 en el que se usa IDbCommandInterceptor y NLog para:

  • Registre una advertencia para cualquier comando que se ejecute de forma no asincrónica
  • Registre un error para cualquier comando que falle al ejecutarse

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.

  • Last updated on