О логировании исключений и Exception.ToString

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

Очень неприятно, когда тебе приходится разбираться с проблемой на боевом сервере в час ночи, когда все, что ты видишь в логе – загадочную строку “Exception has been thrown by the target of an invocation” или “The type initializer for ‘YourBestTypeInTheWorld’ threw an exception”. А все потому, что кто-то умудрился сохранять в лог не все исключение, а лишь его сообщение.

Есть множество причин, почему за LogError(ex.Message) нужно отрывать ноги по самые гланды. Во-первых, существует правило, согласно которому более высокоуровневые модули могут (и должны) скрывать низкоуровневые исключения от вызывающего кода. Это значит, что вместо SocketException, при использовании WCF вы получите CommunicationException внутри которого будет содержаться «низкоуровневое» исключение о проблеме с сокетом. Во-вторых, есть ряд языковых конструкций, которые легко могут скрыть исходное сообщение от пользователя.

class SimpleClass
{
    public SimpleClass()
    {
        throw new InvalidOperationException(
            "Can't create an instance! Sorry for this!");
    }
}
 
static class Factory
{
    public static T Create<T>() where T : new()
    {
        return new T();
    }
}

Невинная конструкция, типа Factory.Create<SimpleClass>() приведет к тому, что исходное сообщение будет «завернуто» в TargetInvocationException, и попытка залогировать лишь ex.Message приведет к полной потере информации о проблеме.

class SimpleClassSingleton
{
    private static readonly SimpleClass instance = new SimpleClass();
    public static SimpleClass Instance { get { return instance; } }
}

В случае с «простым» Синглтоном, мы получим ту же самую проблему, но вместо TargetInvocationException мы получим TypeLoadException, а исходное сообщение будет таиться во внутренностях. Использование TPL приведет к тому, что наружу будет проскакивать AggregateException с многозначительным “One or more errors occurred”. (Использование async/await может помочь в этом вопросе, поскольку await «разворачивает» агрегированное исключение и пробрасывает первое. Но вы поняли идею).

Но есть случаи, когда даже «полная» печать исключения не даст нужного результата. И это очередной пример дырявых абстракций в .NET-е.

Давайте посмотрим, как реализован метод Exception.ToString:

public override string ToString()
{
    return ToString(true, true);
}
 
private string ToString(bool needFileLineInfo, bool needMessage)
{
    String message = (needMessage ? Message : null);
    String result = GetClassName();
 
    if (!string.IsNullOrEmpty(message))
        result += ": " + message;
 
    if (_innerException != null)
    {
        result = result + " ---> " + _innerException.ToString(needFileLineInfo, needMessage) + Environment.NewLine;
    }
 
    string stackTrace = GetStackTrace(needFileLineInfo);
    if (stackTrace != null)
    {
        result += Environment.NewLine + stackTrace;
    }
 
    return result;
}

Это несколько упрощенная версия, а «настоящую» реализацию можно найти в официальных исходниках на http://referencesource.microsoft.com: Exception.ToString.

Навскидку, тут видны две проблемы. Во-первых, у нас есть скрытый цикл обхода дерева исключений и никто не заморачивается использованием StringBuilder-а. Во-вторых, внутреннее исключение печатается не полностью. Причем это поведение даже невозможно изменить, поскольку для печати внутреннего исключения используется не _innerException.ToString(), а «рекурсивный вызов» текущего метода - _innerException.ToString(bool, bool).

Это значит, что как только появится исключение, которое содержит более одного «внутреннего» исключения, то мы получим беду. И такое исключение есть – System.AggregateException!

ToString и AggregateException

Добиться неприятного поведения с AggregateException достаточно просто. Для этого оно должно содержать более одного «внутреннего исключения» и должно быть упаковано в более высокоуровневое исключение в качестве InnerException-а:

var ex = new Exception("Oops!", new AggregateException("1",
    new[] { new Exception("2"), new Exception("3"), }));
 
Console.WriteLine("FullException: " + ex);
Console.WriteLine("Inner: " + ex.InnerException);

В первом случае мы увидим: “Oops! ---> 1 ---> 2, а во втором случае: 1 ---> 2 ---> 3. Фактически, в первом случае мы видим лишь первое вложенное исключение экземпляра AggregateException, а во-втором случае – все вложенные исключения – “2” и “3”.

Когда можно столкнуться с этой проблемой?

Проблема с AggregateException не является надуманной, буквально на днях я столкнулся с ней на практике.

Как уже было сказано выше, высокоуровневые модули могут (а по-хорошему, должны) скрывать внутренние проблемы от своих клиентов. Это значит, что наличие параллелизма в работе класса должно быть скрыто.

У меня есть класс, обрабатывающий большое количество входных элементов. Поскольку обработка каждого элемента представляла собой IO-Bound операцию, то их легко можно разбить на сегменты и обрабатывать пачками (*):

(*) Да, это связано с моей новой работе над VSO!

static Task ProcessBulkAsync(IList<string> list)
{
    var allTasks =
        Partitioner.Create(list)
            .GetPartitions(partitionCount: 4)
            .Select(ProcessChunk)
            .ToList();
 
    return Task.WhenAll(allTasks).ContinueWith(t =>
    {
        if (t.IsFaulted)
        {
            // Заворачиваем все ошибки в свое "высокоуровневое" исключение
            throw new ProcessBulkException("Failed to process bulk items", t.Exception);
        }
    });
}
 
static async Task ProcessChunk(IEnumerator<string> chunk)
{
    throw new Exception("Oops!");
}
 

try
{
    var bulk = Enumerable.Range(1, 10).Select(n => n.ToString()).ToList();
    await ProcessBulkAsync(bulk);
}
catch (ProcessBulkException be)
{
    Console.WriteLine("Failed to process data! " + be);          // 1
    Console.WriteLine("Inner Exception: " + be.InnerException);  // 2
}

В первом случае (строка 1), мы получим лишь текст самого исключения ProcessBulkException, и лишь первую ошибку из вложенного AggregateException-а, а во-второй строке, мы нормально распечатаем AggregateException со всеми его внутренностями.

Наличие ProcessBulkException привело к тому, что мы не видим все произошедшие исключения. Но поскольку мы пробрасываем свое собственное исключение, то легко можем решить эту проблему путем переопределения метода его метода ToString.

Заключение

Из всего этого нужно сделать такие выводы:

1. Реализация Exception.ToString рассчитывает лишь на одно «вложенное исключение».
2. Использование AggregateException в качестве вложенного исключения приведет к проблеме при «печати» «родительского» сообщения с помощью ToString.
3. Если вы контролируете этот процесс и создаете свой класс исключения, принимающий AggregateException, то переопределите метод ToString и выводите там все вложенные исключения.
4. Если же AggregateException попадает во вложенные исключения мимо вашей воли, будьте готовы делать метод расширения, который будет получать строковое представление исключения самостоятельно. Используйте затем этот метод для логирования исключений.