Journalisation et interception des opérations de base de données

Article
09/13/2023

Remarque

EF6 et versions ultérieures uniquement : Les fonctionnalités, les API, etc. décrites dans cette page ont été introduites dans Entity Framework 6. Si vous utilisez une version antérieure, certaines ou toutes les informations ne s’appliquent pas.

À partir d’Entity Framework 6, chaque fois qu’Entity Framework envoie une commande à la base de données, cette commande peut être interceptée par le code de l’application. Cela est le plus souvent utilisé pour la journalisation de SQL, mais peut également être utilisé pour modifier ou abandonner la commande.

Plus précisément, EF inclut :

Une propriété Log pour le contexte similaire à DataContext.Log dans LINQ to SQL
Un mécanisme permettant de personnaliser le contenu et la mise en forme des données envoyées au journal
Des blocs de construction de bas niveau pour l’interception permettent un meilleur contrôle et une plus grande flexibilité

Propriété Log de contexte

La propriété DbContext.Database.Log peut être définie comme un délégué pour n’importe quelle méthode utilisant une chaîne. Le plus souvent, elle est utilisée avec n’importe quel TextWriter en la définissant sur la méthode « Write » de ce TextWriter. Toutes les données SQL générées par le contexte actuel seront journalisées dans cet enregistreur. Par exemple, le code suivant journalisera SQL dans la console :

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

    // Your code here...
}

Notez que context.Database.Log est défini sur Console.Write. Voilà tout ce qu’il faut pour journaliser le code SQL sur la console.

Ajoutons un code simple de requête/insertion/mise à jour afin de pouvoir afficher une certaine sortie :

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

Cela générera la sortie suivante :

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

(Notez qu’il s’agit de la sortie en supposant qu’une initialisation de base de données a déjà eu lieu. Si l’initialisation de la base de données n’avait pas déjà eu lieu, il y aurait beaucoup plus de sortie montrant toutes les migrations de travail effectuées en arrière-plan pour vérifier la présence ou la création d’une nouvelle base de données.)

Qu’est-ce qui est journalisé ?

Lorsque la propriété Log est définie, toutes les opérations suivantes sont journalisées :

SQL pour tous les types de commandes. Par exemple :
- Requêtes, y compris les requêtes LINQ normales, les requêtes eSQL et les requêtes brutes issues de méthodes telles que SqlQuery
- Insertions, mises à jour et suppressions générées dans le cadre de SaveChanges
- Requêtes de chargement de relations telles que celles générées par le chargement différé
Paramètres
Exécution asynchrone ou non de la commande
Un timestamp indiquant le moment où la commande commence à être exécutée
La commande a abouti ou non, a échoué en levant une exception ou a été annulée dans le cas d’une commande asynchrone
Quelques indications sur la valeur du résultat
Le temps approximatif nécessaire à l’exécution de la commande. Notez qu’il s’agit du temps écoulé entre l’envoi de la commande et le retour de l’objet résultat. Il n’inclut pas le temps de lecture des résultats.

En examinant l’exemple de sortie ci-dessus, on remarque que chacune des quatre commandes journalisées est :

La requête résultant de l’appel à context.Blogs.First
- Notez que la méthode ToString permettant d’obtenir le code SQL n’aurait pas fonctionné pour cette requête, car « First » ne fournit pas d’IQueryable sur lequel ToString pourrait être appelé
La requête résultant du chargement différé de blog.Posts
- Notez que les détails du paramètre pour la valeur de clé pour laquelle le chargement différé se produit
- Seules les propriétés du paramètre qui sont définies sur des valeurs autres que celles par défaut sont journalisées. Par exemple, la propriété Size est affichée uniquement si elle n’est pas égale à zéro.
Deux commandes résultant de SaveChangesAsync ; l’une pour la mise à jour afin de modifier le titre du billet, l’autre pour l’insertion afin d’ajouter un nouveau billet
- Notez les détails du paramètre pour les propriétés FK et Title
- Notez que ces commandes sont exécutées de manière asynchrone

Journalisation à différents emplacements

Comme indiqué ci-dessus, la journalisation vers la console est très simple. Il est également facile d’enregistrer dans la mémoire, dans un fichier, etc. en utilisant différents types de TextWriter.

Si vous maîtrisez LINQ to SQL, vous remarquerez peut-être que dans LINQ to SQL, la propriété Log est définie sur l’objet TextWriter réel (par exemple, Console.Out) tandis que dans EF, la propriété Log est définie sur une méthode qui accepte une chaîne (par exemple, Console.Write ou Console.Out.Write). Cela permet de dissocier EF de TextWriter en acceptant n’importe quel délégué qui peut agir comme un récepteur pour les chaînes. Par exemple, imaginez que vous disposez déjà d’un framework de journalisation et qu’il définit une méthode de journalisation comme suit :

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

Elle pourrait être reliée à la propriété Log d’EF comme suit :

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

Journalisation des résultats

L’enregistreur d’événements par défaut journalise le texte de commande (SQL), les paramètres et la ligne « Exécution » avec un timestamp avant l’envoi de la commande à la base de données. Une ligne « terminée » contenant la durée calendaire est journalisée après l’exécution de la commande.

Notez que pour les commandes asynchrones, la ligne « terminée » n’est pas journalisée tant que la tâche asynchrone n’est pas terminée, échouée ou annulée.

La ligne « terminée » contient des informations différentes selon le type de commande et la réussite ou l’échec de l’exécution.

Exécution réussie

Pour les commandes qui se terminent correctement, la sortie est « Terminée dans x ms avec résultat : » suivi d’une indication sur le résultat. Pour les commandes qui renvoient un lecteur de données, l’indication de résultat est le type de DbDataReader renvoyé. Pour les commandes qui renvoient une valeur entière, telle que la commande de mise à jour présentée ci-dessus, le résultat affiché est cet entier.

Échec de l’exécution

Pour les commandes qui échouent en levant une exception, la sortie contient le message de l’exception. Par exemple, l’utilisation de SqlQuery pour effectuer une requête sur une table qui existe déjà entraînera une sortie de journal semblable à celle-ci :

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

Exécution annulée

Pour les commandes asynchrones où la tâche est annulée, le résultat pourrait être un échec avec une exception, car c’est ce que fait souvent le fournisseur ADO.NET sous-jacent lorsqu’une tentative d’annulation est réalisée. Si cela ne se produit pas et que la tâche est annulée correctement, la sortie se présentera comme suit :

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

Modification du contenu et de la mise en forme du journal

En arrière-plan, la propriété Database.Log utilise un objet DatabaseLogFormatter. Cet objet lie efficacement une implémentation IDbCommandInterceptor (voir ci-dessous) à un délégué qui accepte des chaînes et un DbContext. Cela signifie que les méthodes sur DatabaseLogFormatter sont appelées avant et après l’exécution des commandes par EF. Ces méthodes DatabaseLogFormatter rassemblent et mettent en forme la sortie du journal et l’envoient au délégué.

Personnalisation de DatabaseLogFormatter

La modification de ce qui est enregistré et de la façon dont c’est formaté peut être obtenue en créant une nouvelle classe qui dérive de DatabaseLogFormatter et qui substitue les méthodes selon les besoins. Les méthodes les plus courantes à substituer sont les suivantes :

LogCommand : substituez cette option pour modifier la manière dont les commandes sont journalisées avant d’être exécutées. Par défaut, LogCommand appelle LogParameter pour chaque paramètre ; vous pouvez choisir d’en faire de même avec votre substitution ou de gérer les paramètres différemment.
LogResult : substituez cette option pour modifier la façon dont le résultat de l’exécution d’une commande est journalisé.
LogParameter : substituez cette option pour modifier la mise en forme et le contenu de la journalisation des paramètres.

Par exemple, supposons que nous voulions journaliser une seule ligne avant que chaque commande ne soit envoyée à la base de données. Deux remplacements permettent d’y parvenir :

Substituer LogCommand pour mettre en forme et écrire une seule ligne de SQL
Substituer LogResult pour ne rien faire.

Le code se présenterait comme ceci :

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)
    {
    }
}

Pour journaliser la sortie, appelez simplement la méthode Write qui enverra la sortie au délégué d’écriture configuré.

(Notez que ce code effectue une suppression simpliste des sauts de ligne, à titre d'exemple. Il ne fonctionnera probablement pas correctement pour l’affichage d’un langage SQL complexe.)

Paramètre de DatabaseLogFormatter

Une fois qu’une nouvelle classe DatabaseLogFormatter a été créée, elle doit être inscrite auprès d’EF. Cette opération s’effectue à l’aide d’une configuration basée sur le code. En un mot, cela signifie qu’il faut créer une nouvelle classe qui dérive de DbConfiguration dans le même assembly que votre classe DbContext, puis appeler SetDatabaseLogFormatter dans le constructeur de cette nouvelle classe. Par exemple :

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

Utilisation du nouveau DatabaseLogFormatter

Ce nouveau DatabaseLogFormatter sera désormais utilisé chaque fois que Database.Log sera défini. Par conséquent, l’exécution du code de la partie 1 aboutira à la sortie suivante :

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

Blocs de construction d’interception

Jusqu’à présent, nous avons examiné comment utiliser DbContext.Database.Log pour journaliser le code SQL généré par EF. Mais ce code n’est en fait qu’une façade relativement mince sur des blocs de construction de bas niveau pour une interception plus générale.

Interfaces d’interception

Le code d’interception est conçu autour du concept d’interfaces d’interception. Ces interfaces héritent de IDbInterceptor et définissent des méthodes appelées quand EF effectue une action. L’objectif est d’avoir une interface par type d’objet intercepté. Par exemple, l’interface IDbCommandInterceptor définit les méthodes appelées avant qu’EF n’appelle ExecuteNonQuery, ExecuteScalar, ExecuteReader et les méthodes associées. De même, l’interface définit les méthodes appelées lorsque chacune de ces opérations se termine. La classe DatabaseLogFormatter que nous avons examinée ci-dessus implémente cette interface pour journaliser les commandes.

Le contexte d’interception

En examinant les méthodes définies sur l’une des interfaces d’intercepteur, il est évident que chaque appel reçoit un objet de type DbInterceptionContext ou un type dérivé de ce type tel que DbCommandInterceptionContext<>. Cet objet contient des informations contextuelles sur l’action qu’EF effectue. Par exemple, si l’action est effectuée pour le compte d’un DbContext, le DbContext est inclus dans le DbInterceptionContext. De même, pour les commandes exécutées de manière asynchrone, l’indicateur IsAsync est défini sur DbCommandInterceptionContext.

Traitement des résultats

La classe DbCommandInterceptionContext<> contient des propriétés appelées Result, OriginalResult, Exception et OriginalException. Ces propriétés sont définies sur null/zéro pour les appels aux méthodes d’interception appelées avant l’exécution de l’opération, c’est-à-dire pour les ... méthodes d’exécution. Si l’opération est exécutée et réussit, Result et OriginalResult sont définis sur le résultat de l’opération. Ces valeurs peuvent ensuite être observées dans les méthodes d’interception appelées après l’exécution de l’opération, c’est-à-dire dans les... méthodes exécutées. De même, si l’opération est levée, les propriétés Exception et OriginalException seront définies.

Suppression de l’exécution

Si un intercepteur définit la propriété Result avant l’exécution de la commande (dans l’une des... méthodes d’exécution) alors EF n’essaiera pas d’exécuter réellement la commande, mais se contentera d’utiliser l’ensemble des résultats. En d’autres termes, l’intercepteur peut supprimer l’exécution de la commande, mais permettre à EF de continuer comme si la commande avait été exécutée.

Le traitement par lots des commandes, traditionnellement effectué par un fournisseur d’enveloppes, est un exemple de l’utilisation de cette méthode. L’intercepteur stockerait la commande pour une exécution ultérieure en tant que lot, mais « feindrait » auprès d’EF que la commande s’est exécutée normalement. Notez qu’il en faut plus que cela pour implémenter le traitement par lots, mais il s’agit d’un exemple de la manière dont la modification du résultat de l’interception peut être utilisée.

L’exécution peut également être supprimée en définissant la propriété Exception dans l’un des ... méthodes d’exécution. Ainsi, EF continue comme si l’exécution de l’opération avait échoué en levant l’exception donnée. Cela peut, bien sûr, provoquer un incident dans l’application, mais il peut également s’agir d’une exception passagère ou d’une autre exception gérée par EF. Par exemple, cela peut être utilisé dans des environnements de test pour tester le comportement d’une application en cas d’échec de l’exécution de commande.

Modification du résultat après l’exécution

Si un intercepteur définit la propriété Result après l’exécution de la commande (dans l’une des... méthodes exécutées), EF utilisera le résultat modifié au lieu du résultat renvoyé par l’opération. De même, si un intercepteur définit la propriété Exception après l’exécution de la commande, EF lèvera l’exception définie comme si l’opération avait levé l’exception.

Un intercepteur peut également définir la propriété Exception à la valeur null pour indiquer qu’aucune exception ne doit être levée. Cela peut être utile si l’exécution de l’opération a échoué, mais que l’intercepteur souhaite que l’EF continue comme si l’opération avait réussi. Cela implique généralement de définir le résultat afin qu’EF puisse continuer à travailler sur la base d’une certaine valeur de résultat.

OriginalResult et OriginalException

Une fois qu’EF a exécuté une opération, les propriétés Result et OriginalResult sont définies si l'exécution n’a pas échoué ou les propriétés Exception et OriginalException si l’exécution n’a pas abouti à une exception.

Les propriétés OriginalResult et OriginalException sont en lecture seule et sont définies uniquement par EF après l’exécution d’une opération. Ces propriétés ne peuvent pas être définies par des intercepteurs. Cela signifie que tout intercepteur peut faire la distinction entre une exception ou un résultat qui a été défini par un autre intercepteur, par opposition à l’exception ou au résultat réel qui s’est produit lors de l’exécution de l’opération.

Inscription d’intercepteurs

Une fois qu’une classe qui implémente une ou plusieurs interfaces d’interception a été créée, elle peut être inscrite auprès d’EF à l’aide de la classe DbInterception. Par exemple :

DbInterception.Add(new NLogCommandInterceptor());

Les intercepteurs peuvent également être inscrits au niveau du domaine d’application à l’aide du mécanisme de configuration basé sur le code DbConfiguration.

Exemple : Journalisation vers NLog

Rassemblons tout cela dans un exemple qui utilise IDbCommandInterceptor et NLog pour :

Journaliser un avertissement pour toute commande exécutée de manière asynchrone
Journaliser une erreur pour toute commande qui est levée lors de l’exécution

Voici la classe qui effectue la journalisation, qui doit être inscrite comme indiqué ci-dessus :

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

Notez comment ce code utilise le contexte d’interception pour découvrir quand une commande est exécutée de manière asynchrone et pour découvrir quand une erreur s’est produite lors de l’exécution d’une commande.

Partager via