Ведение журнала и перехват операций базы данных

Начиная с версии Entity Framework 6, каждый раз когда Entity Framework отправляет команду в базу данных, эта команда может быть перехвачена кодом приложения. Это чаще всего используется для ведения журнала SQL, но также можно использовать для изменения или прерывания команды.

В частности, EF включает:

• Свойство Log для контекста, аналогичного DataContext.Log в LINQ to SQL
• Механизм настройки содержимого и форматирования выходных данных, отправляемых в журнал
• Стандартные блоки низкого уровня для перехвата, что обеспечивает больший контроль и гибкость

Свойство Context Log

Свойство DbContext.Database.Log можно задать для делегата для любого метода, принимающего строку. Чаще всего он используется с любой текстовой машиной, задав его методу Write этого textWriter. Все SQL, созданные текущим контекстом, будут записаны в этот логгер. Например, следующий код записывает SQL в консоль:

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

    // Your code here...
}

Обратите внимание, что context.Database.Log установлен в Console.Write. Это все, что необходимо для записи SQL в консоль.

Давайте добавим простой код запроса, вставки и обновления, чтобы увидеть некоторые выходные данные:

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

Это приведет к возникновению следующих выходных данных:

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

(Обратите внимание, что это выходные данные, предполагающие, что инициализация базы данных уже произошла. Если инициализация базы данных еще не произошла, то будет гораздо больше выходных данных, показывающих всю работу, которую выполняют миграции в фоновом режиме для проверки или создания новой базы данных.)

Что регистрируется?

Если для свойства log задано все из следующих элементов, будет зарегистрировано следующее:

• SQL для всех различных видов команд. Например:
  • Запросы, включая обычные запросы LINQ, запросы eSQL и необработанные запросы из таких методов, как SqlQuery
  • Вставки, обновления и удаления, созданные в рамках SaveChanges
  • Запросы загрузки связей, такие как запросы, созданные с помощью отложенной загрузки
• Параметры
• Выполняется ли команда асинхронно
• Метка времени, указывающая, когда команда начала выполняться
• Выполнена ли команда успешно, завершилась с исключением или, в случае асинхронного выполнения, была отменена.
• Некоторые признаки значения результата
• Приблизительное время выполнения команды. Обратите внимание, что это время от отправки команды до получения объекта результата обратно. Оно не включает время для чтения результатов.

Рассматривая приведенный выше пример выходных данных, каждая из четырех команд была зарегистрирована в журнале.

• Запрос, полученный из вызова context.Blogs.First
  • Обратите внимание, что метод ToString для извлечения SQL не сработал бы для этого запроса, так как «First» не предоставляет IQueryable, на котором можно вызвать ToString.
• Запрос, полученный из-за отложенной загрузки сообщений блога
  • Обратите внимание на сведения о параметре для ключевого значения, для которого происходит отложенная загрузка
  • Регистрируются только свойства параметра, для которых заданы значения, не являющиеся значениями по умолчанию. Например, свойство Size отображается только в том случае, если оно не равно нулю.
• Две команды, полученные из SaveChangesAsync: одна для обновления, чтобы изменить заголовок поста, другая для вставки, чтобы добавить новый пост.
  • Обратите внимание на детали параметров свойств "FK" и "Title"
  • Обратите внимание, что эти команды выполняются асинхронно

Логирование в разных местах

Как показано выше, логирование в консоль очень просто. Кроме того, легко выполнять вход в память, файл и т. д. с помощью различных типов TextWriter.

Если вы знакомы с LINQ to SQL, вы можете заметить, что в LINQ to SQL свойство Log установлено в фактический объект TextWriter (например, Console.Out), тогда как в EF свойство Log задано для метода, который принимает строку (например, Console.Write или Console.Out.Write). Причина этого заключается в том, чтобы отделить EF от TextWriter, разрешив использовать любой делегат, который может действовать как приемник строк. Например, представьте, что у вас уже есть некоторые платформы ведения журнала, и он определяет метод ведения журнала, как показано ниже.

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

Это может быть подключено к свойству EF Log следующим образом:

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

Ведение журнала результатов

Логгер по умолчанию записывает текст команды (SQL), параметры и строку "Выполняется" с отметкой времени перед отправкой команды в базу данных. Строка "завершена", содержащая истекшее время, регистрируется после выполнения команды.

Обратите внимание, что для асинхронных команд строка "завершена" не регистрируется в журнале до тех пор, пока асинхронная задача фактически не завершится, не завершится с ошибкой или не будет отменена.

Строка "завершена" содержит разные сведения в зависимости от типа команды и успешного выполнения.

Успешное выполнение

Для команд, которые успешно завершены, вывод: "Завершено за x мс с результатом: ", за которым следует указание на то, каков результат. Для команд, возвращающих средство чтения данных, указание результата — это тип возвращаемого dbDataReader . Для команд, возвращающих целочисленное значение, например команду обновления, показанную выше, отображается целое число.

Сбой выполнения

Для команд, которые завершаются сбоем, вызывая исключение, выходные данные содержат сообщение из исключения. Например, использование SqlQuery для запроса к таблице, которая действительно существует, приведет к выводу журнала следующего вида:

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

Отмененное выполнение

Для асинхронных команд, где задача отменена, результат может быть сбоем с исключением, так как это то, что базовый поставщик ADO.NET часто делает при попытке отменить. Если это не происходит, и задача отменена корректно, выходные данные будут выглядеть следующим образом:

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

Изменение содержимого журнала и форматирования

Под капотом свойство Database.Log задействует объект DatabaseLogFormatter. Этот объект эффективно привязывает реализацию IDbCommandInterceptor (см. ниже) к делегату, который принимает строки и DbContext. Это означает, что методы DatabaseLogFormatter вызываются до и после выполнения команд EF. Эти методы DatabaseLogFormatter собирают и форматируют выходные данные журнала и отправляют его делегату.

Настройка DatabaseLogFormatter

Изменить логирование и его форматирование можно, создав новый класс, наследуемый от DatabaseLogFormatter, и переопределив методы по необходимости. Наиболее распространенными методами переопределения являются:

• LogCommand — переопределите это, чтобы изменить способ ведения журнала команд перед выполнением. По умолчанию LogCommand вызывает LogParameter для каждого параметра; Вместо этого вы можете сделать то же самое в переопределении или обрабатывать параметры по-другому.
• LogResult — переопределите этот метод, чтобы изменить способ ведения журнала результата выполнения команды.
• LogParameter — переопределите это, чтобы изменить форматирование и содержимое ведения журнала параметров.

Например, предположим, что мы хотели регистрировать только одну строку перед отправкой каждой команды в базу данных. Это можно сделать с двумя переопределениями:

• Переопределите LogCommand для форматирования и записи одной строки SQL.
• Переопределите LogResult, чтобы ничего не делать.

Код будет выглядеть примерно так:

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

Чтобы записать выходные данные, просто вызовите метод write, который будет отправлять выходные данные в настроенный делегат записи.

(Обратите внимание, что этот код упрощает удаление разрывов строк так же, как пример. Скорее всего, это не будет хорошо работать для просмотра сложного SQL.)

Настройка DatabaseLogFormatter

После создания нового класса DatabaseLogFormatter его необходимо зарегистрировать в EF. Это делается с помощью конфигурации на основе кода. В этом итоге создается новый класс, производный от DbConfiguration в той же сборке, что и класс DbContext, а затем вызывает SetDatabaseLogFormatter в конструкторе этого нового класса. Рассмотрим пример.

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

Использование нового DatabaseLogFormatter

Теперь новый компонент DatabaseLogFormatter будет использоваться каждый раз, когда задан Database.Log. Таким образом, выполнение кода из части 1 приведет к следующим выходным данным:

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

Элементы конструкции для перехвата

До сих пор мы рассмотрели, как использовать DbContext.Database.Log для регистрации SQL, созданного EF. На самом деле этот код служит относительно тонким фасадом, прикрывающим некоторые низкоуровневые компоненты для более общего перехвата.

Интерфейсы перехвата

Код перехвата основан на концепции интерфейсов перехвата. Эти интерфейсы наследуются от IDbInterceptor и определяют методы, которые вызываются при выполнении некоторых действий EF. Намерение заключается в обеспечении единого интерфейса для каждого типа объекта, который подвергается перехвату. Например, интерфейс IDbCommandInterceptor определяет методы, которые вызываются перед тем как EF вызывает ExecuteNonQuery, ExecuteScalar, ExecuteReader и другие связанные методы. Аналогичным образом интерфейс определяет методы, которые вызываются при завершении каждой из этих операций. Класс DatabaseLogFormatter, который мы рассмотрели выше, реализует этот интерфейс для выполнения команд журнала.

Контекст перехвата

Глядя на методы, определенные на любом из интерфейсов перехватчика, очевидно, что каждый вызов получает объект типа DbInterceptionContext или какой-либо тип, производный от этого, например DbCommandInterceptionContext<>. Этот объект содержит контекстные сведения о действии, которое выполняет EF. Например, если действие выполняется от имени DbContext, то DbContext включается в DbInterceptionContext. Аналогичным образом для команд, выполняемых асинхронно, флаг IsAsync задается в DbCommandInterceptionContext.

Обработка результатов

Класс DbCommandInterceptionContext<> содержит свойства с именем Result, OriginalResult, Exception и OriginalException. Эти свойства имеют значение NULL/ноль для вызовов методов перехвата, которые вызываются перед выполнением операции , то есть для ... Выполнение методов. Если операция выполняется и завершается успешно, то значения для Result и OriginalResult устанавливаются результатом этой операции. Затем эти значения можно наблюдать в методах перехвата, которые вызываются после выполнения операции, т. е. на методах …Executed. Аналогичным образом, если операция вызывается, будут заданы свойства Exception и OriginalException.

Подавление выполнения

Если перехватчик задает свойство Result перед выполнением команды (в одном из методов Executing), то EF не попытается выполнить команду, а вместо этого будет использовать результирующий набор. Другими словами, перехватчик может подавлять выполнение команды, но EF продолжит выполнение, как если бы команда была выполнена.

Пример того, как это может использоваться, — это пакетная обработка команд, которая традиционно была выполнена с поставщиком упаковки. Перехватчик будет хранить команду для последующего выполнения как пакет, но будет "притворяться" EF, что команда выполнялась как обычная. Обратите внимание, что для реализации пакетной обработки требуется больше, но это пример того, как можно использовать изменение результата перехвата.

Выполнение также можно отключить, установив свойство Exception в одном из методов …Executing. Это приводит к тому, что EF продолжает работу, как если бы выполнение операции завершилось сбоем, выбрасывая заданное исключение. Это может, конечно, привести к сбою приложения, но это также может быть временное исключение или другое исключение, которое обрабатывается EF. Например, это можно использовать в тестовых средах для проверки поведения приложения при сбое выполнения команды.

Изменение результата после выполнения

Если перехватчик задает свойство Result после выполнения команды (в одном из методов …Executed), тогда EF будет использовать измененный результат вместо результата, который был фактически возвращен из операции. Если перехватчик устанавливает свойство Exception после выполнения команды, то EF выдаст то исключение, которое было установлено, как если бы это исключение было вызвано самой операцией.

Перехватчик также может задать для свойства Exception значение NULL, чтобы указать, что исключение не должно быть создано. Это может быть полезно, если выполнение операции завершилось сбоем, но перехватчик хочет, чтобы EF продолжил работу так, как если бы операция завершилась успешно. Обычно это также включает установку результата, чтобы EF имело некоторое значение результата для последующей работы.

OriginalResult и OriginalException

После выполнения операции EF установит свойства Result и OriginalResult в случае успешного выполнения или свойства Exception и OriginalException в случае выполнения с исключением.

Свойства OriginalResult и OriginalException доступны только для чтения и задаются EF только после выполнения операции. Эти свойства не могут быть установлены с помощью перехватчиков. Это означает, что любой перехватчик может различать исключение или результат, заданный другим перехватчиком в отличие от реального исключения или результата, которое произошло при выполнении операции.

Регистрация перехватчиков

После создания класса, реализующего один или несколько интерфейсов перехвата, его можно зарегистрировать в EF с помощью класса DbInterception. Рассмотрим пример.

DbInterception.Add(new NLogCommandInterceptor());

Перехватчики также можно зарегистрировать на уровне домена приложения с помощью механизма конфигурации на основе кода DbConfiguration.

Пример: Логирование в NLog

Давайте поместим все это в пример, в котором используется IDbCommandInterceptor и NLog, чтобы:

• Запишите предупреждение для любой команды, которая выполняется неасинхронно.
• Зарегистрируйте ошибку для любой команды, которая выдаёт ошибку при выполнении

Ниже приведен класс, который выполняет ведение журнала, который должен быть зарегистрирован, как показано выше:

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

Обратите внимание, что этот код использует контекст перехвата для определения, выполняется ли команда не асинхронно, и для выявления ошибок при выполнении команды.