Минимальные требования к самописному логгеру и чек-лист интеграционных тестов

Если можно взять готовый logging framework, так безопаснее. И всё же бывают ограничения приложения или условия эксплуатации, когда самописный logger не обойти. Тогда первым обычно встаёт вопрос: сколько реализовать, чтобы дизайн получился «не слишком грубым и не слишком тяжёлым».

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

Целевая аудитория и предпосылки статьи

Термины, которыми пользуется эта статья

Перед разговором о дизайне соберём слова, которые дальше появятся без пояснений.

Сначала проверить вариант «не писать свой»

Как сказано в начале, готовый logging framework безопаснее, если им можно пользоваться. Чтобы это можно было решить, назовём конкретные имена. Если их хватает, остаток статьи можно не читать.

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

Сначала вывод

В первой версии стоит закрепить следующее.

• Формат — UTF-8 JSON Lines
• Правило «одна запись — одна строка» не нарушать
• Обязательные поля: timestamp, level, category, message, структурированные fields, sessionId, processId
• База — один процесс, один файл
• При низкой нагрузке — синхронная запись, при большей — single writer + bounded queue
• Error / Critical и логи начала и конца сессии сбрасывать синхронным flush
• Ротацию и хранение закладывать уже в v1
• Если место назначения недоступно, молча не уводить запись в другое место

Если сузить требования примерно до этого, и реализация, и эксплуатация реже разъезжаются.

На схеме сплошная линия обозначает отношение, которое выполняется всегда, а пунктирная — условное отношение (условия указаны в пояснении к каждому отношению на странице сведений). Полный список отношений (всего 21, с доказательствами и степенью уверенности) и определения основных понятий собраны на странице сведений карты знаний (на японском). Данные: JSON-LD / Turtle

Сначала сузить область

Самописный logger обычно становится тяжёлым потому, что с самого начала пытаются закрыть всё. Стоит смешать в одном механизме диагностические логи, журнал аудита, измерение производительности, распределённую трассировку и анализ поведения пользователей — и требования взрываются сразу.

Здесь предмет — диагностические логи для локализации сбоев приложения. То есть в приоритете возможность потом восстановить, «когда», «в какой обработке», «что произошло» и «какой был контекст в тот момент». Одного этого сужения уже достаточно, чтобы первые решения по дизайну стали заметно проще.

Минимально необходимые требования

1. Формат — UTF-8 JSON Lines

Логи можно хранить и простой склейкой текста, но потом их трудно разбирать машиной. С другой стороны, сразу уйти в тяжёлый свой бинарный формат — значит потерять наблюдаемость в эксплуатации.

Удобная середина — UTF-8 JSON Lines. Если одна строка — одна запись, файл остаётся читаемым как текст и потом легко разбирается скриптами и инструментами. Даже если запись оборвалась посередине, проще понять, какая строка повреждена, — это практично.

В самом формате зафиксированы только три пункта.¹

• Одна строка — одно допустимое JSON-значение (пустых строк нет)
• Разделитель строк — \n
• Кодировка — UTF-8. BOM (U+FEFF) ставить нельзя

Расширение по обычаю — .jsonl. Запрет BOM легко пропустить, а эффект заметный. Если писать с BOM, первую строку другие инструменты не разберут, и это всплывает в неловкой форме «сломана только первая строка».

2. Сразу зафиксировать обязательные поля

Минимальный набор, который стоит иметь, — эти семь.

• timestamp
• level
• category
• message
• fields
• sessionId
• processId

Реальная запись выглядит, например, так (здесь перенесена из‑за ширины страницы, но в файле это одна строка без перевода).

{"ts":"2026-04-02T01:15:03.4821567Z","level":"Error","category":"import","message":"Не удалось выполнить импорт","fields":{"file":"orders.csv","row":128,"reason":"date parse failed"},"sessionId":"20260402-101500-8412-9f3c1d2a5b7e4f689a0c3d5e7f1b2c4d","pid":8412}

Если поставить рядом записи той же сессии, картина такая.

{"ts":"2026-04-02T01:15:00.1002233Z","level":"Info","category":"startup","message":"Приложение запущено","fields":{"version":"1.4.2"},"sessionId":"20260402-101500-8412-9f3c1d2a5b7e4f689a0c3d5e7f1b2c4d","pid":8412}
{"ts":"2026-04-02T01:15:03.4821567Z","level":"Error","category":"import","message":"Не удалось выполнить импорт","fields":{"file":"orders.csv","row":128,"reason":"date parse failed"},"sessionId":"20260402-101500-8412-9f3c1d2a5b7e4f689a0c3d5e7f1b2c4d","pid":8412}
{"ts":"2026-04-02T01:15:03.9900011Z","level":"Info","category":"shutdown","message":"Приложение завершает работу","fields":{"exitCode":1},"sessionId":"20260402-101500-8412-9f3c1d2a5b7e4f689a0c3d5e7f1b2c4d","pid":8412}

Имена ключей могут быть короткими, но важнее не менять их, когда уже зафиксировали. Если посередине смешаются ts и timestamp, разборные скрипты сразу становятся мучительными.

Лог из одной строки message ломается, когда позже появляются новые критерии поиска. Слишком много полей, наоборот, резко поднимает нагрузку на вызывающий код. Безопаснее сначала закрепить примерно такой набор и думать о добавлениях только когда они действительно понадобятся.

Что класть в sessionId

Раз поле обязательное, нужно решить, какую единицу оно обозначает. В этой статье один запуск процесса — одна сессия. Это не сеанс входа пользователя и не «сделка» в бизнес-смысле.

При таком определении получается следующее.

• Можно вытащить только логи одного запуска
• Даже если ротация разрезала файлы, логи того же запуска потом можно склеить
• Два сбоя на одном компьютере утром и вечером можно разбирать отдельно, не смешивая

Номер выдаётся один раз при старте процесса и живёт до его конца. Достаточно одного из двух способов.

Не ограничивайтесь временем запуска и ID процесса. ОС переиспользует processId. Если процесс в цикле падений перезапустился в ту же секунду или локальные часы откатились назад, может получиться ровно тот же sessionId, что в прошлый раз. Если то же значение стоит и в имени файла, в момент открытия в режиме дозаписи логи разных запусков смешаются в одном файле, и предпосылка «один запуск = одна сессия» тихо развалится. Ломается это тихо, поэтому потом не замечают.

processId держат отдельным полем как раз затем, чтобы sessionId отвечал на вопрос «какой запуск», а processId — «какой это был объект в ОС в тот момент».

3. База — один процесс, один файл

Дизайн, в котором несколько процессов дописывают один файл, даёт больше сбоев, чем кажется. Сразу усложняются взаимное исключение, частичные записи, момент ротации и разбор аварийного завершения.

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

4. Стратегию записи выбирать по нагрузке

Пока объём логов невелик, синхронная запись понятнее и удобнее для разбора сбоев. Если насильно уйти в асинхронность, легко потерять логи прямо перед завершением или размыть условия flush при исключениях.

Когда объём растёт и синхронный I/O становится узким местом, берут single writer + bounded queue. То есть вызывающий код только кладёт запись в очередь с верхней границей и возвращается, а в файл пишет одно место. Сама идея не экзотика: в рекомендациях по логированию .NET тоже предлагают не писать напрямую в медленное назначение, а синхронно класть в очередь в памяти и отдавать её фоновой обработке.²

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

5. Зафиксировать условия flush

Синхронный flush для Error и Critical, а также для логов начала и конца сессии, окупается при расследовании. Если сбрасывать всё вплоть до обычного Info, станет медленно, поэтому ко всему относиться одинаково нереалистично.

6. Ротацию и хранение закладывать уже в v1

Ротацию часто считают тем, что «можно добавить потом», но в эксплуатации её отсутствие внезапно больно бьёт. Способ любой — по размеру, по дням, на каждый запуск, — но как минимум должно быть решено, что файл «не растёт бесконечно» и «сколько файлов оставлять».

7. При сбое сохранения не уводить запись молча в другое место

Дизайн, который при недоступном месте назначения молча пишет куда-то ещё, потом мешает разбору. Оператору достаточно не найти логи «там, где они должны быть», и первая реакция на инцидент уже запаздывает.

Если сохранить нельзя, покажите сбой явным каналом: уведомление в приложении, журнал событий, стандартный поток ошибок. Как минимум не оставляйте состояние «никто не знает, куда это ушло».

Ориентир минимальной конфигурации v1

Для первой версии часто хватает примерно такого набора.

• UTF-8 JSON Lines
• Один процесс, один файл
• Имена файлов по сессиям
• Ротация по размеру или на каждый запуск
• Верхняя граница числа хранимых файлов
• Синхронный flush Error / Critical
• API, который принимает структурированные fields

Всё сверх этого лучше добавлять, когда реальная эксплуатация покажет, «что действительно мешало». Тогда сопровождать проще.

Как выглядит часть записи v1 на C#

Если из требований выше реализовать только формат, обязательные поля, single writer и условия flush, объём примерно такой (C# 12 / .NET 8). Ротацию и хранение сознательно не включаем — их добавляют следующим шагом.

using System.Text;
using System.Text.Json;

public sealed class JsonLinesLogger : IDisposable
{
    // Пишем не-ASCII как есть. Стандартный encoder переводит все не-ASCII в \uXXXX
    private static readonly JsonSerializerOptions JsonOptions = new()
    {
        Encoder = System.Text.Encodings.Web.JavaScriptEncoder.UnsafeRelaxedJsonEscaping,
    };

    private static readonly IReadOnlyDictionary<string, object?> NoFields =
        new Dictionary<string, object?>();

    private readonly object _gate = new();      // Этим lock защищаем single writer
    private readonly StreamWriter _writer;
    private readonly string _sessionId;
    private readonly int _processId = Environment.ProcessId;

    public JsonLinesLogger(string path, string sessionId)
    {
        _sessionId = sessionId;

        // JSON Lines запрещает BOM, поэтому явно задаём UTF-8 без BOM
        _writer = new StreamWriter(
            new FileStream(path, FileMode.Append, FileAccess.Write, FileShare.Read),
            new UTF8Encoding(encoderShouldEmitUTF8Identifier: false));
    }

    public void Write(
        string level,
        string category,
        string message,
        IReadOnlyDictionary<string, object?>? fields = null)
    {
        var record = new Dictionary<string, object?>
        {
            ["ts"] = DateTimeOffset.UtcNow.ToString("o"),
            ["level"] = level,
            ["category"] = category,
            ["message"] = message,
            ["fields"] = fields ?? NoFields,   // Не null: всегда все 7 полей
            ["sessionId"] = _sessionId,
            ["pid"] = _processId,
        };

        // Сначала сериализуем в JSON, потом пишем, чтобы message с переводами строк не ломал одну запись
        var line = JsonSerializer.Serialize(record, JsonOptions);

        lock (_gate)
        {
            _writer.WriteLine(line);
            if (level is "Error" or "Critical")
            {
                _writer.Flush();   // Синхронный flush только для серьёзных записей
            }
        }
    }

    public void Dispose()
    {
        lock (_gate)
        {
            _writer.Flush();   // При штатном завершении обязательно дописываем буфер
            _writer.Dispose();
        }
    }
}

Вызов выглядит так. sessionId задаётся один раз при старте и то же значение идёт в имя файла.

// Используем JsonLinesLogger, приведённый выше
var startedAt = DateTimeOffset.Now;

// Одних времени и PID недостаточно. Если процесс в цикле падений перезапустится
// в ту же секунду или локальные часы откатится назад, в сочетании с PID,
// который Windows переиспользовала, может получиться тот же ID, что в прошлый раз.
// JsonLinesLogger открывает файл в FileMode.Append, поэтому записи разных
// запусков смешаются в одном файле, и предпосылка «один запуск = одна сессия»
// тихо развалится
var sessionId = $"{startedAt:yyyyMMdd-HHmmss}-{Environment.ProcessId}-{Guid.NewGuid():N}";
var logDir = @"C:\ProgramData\MyApp\logs";
Directory.CreateDirectory(logDir);

using var logger = new JsonLinesLogger(Path.Combine(logDir, $"app-{sessionId}.jsonl"), sessionId);

logger.Write("Info", "startup", "Приложение запущено",
    new Dictionary<string, object?> { ["version"] = "1.4.2" });

logger.Write("Error", "import", "Не удалось выполнить импорт",
    new Dictionary<string, object?> { ["file"] = "orders.csv", ["row"] = 128 });

Код короткий, но все принятые решения в нём есть.

UnsafeRelaxedJsonEscaping не экранирует < > & ', поэтому этот вывод нельзя вставлять как есть в HTML-страницу или элемент script.⁶ Пользуйтесь им только чтобы читать файл как лог.

Частые антипаттерны

Типичное, чего лучше избегать.

• Запихнуть всё в строку message
• Делить один файл между несколькими процессами
• Уйти в полную асинхронность, не зафиксировав условия flush
• Откладывать ротацию и хранение
• При сбое сохранения молча уводить запись в другую папку
• Тащить в v1 сетевую передачу или сохранение в локальную БД

Каждый пункт с виду удобен, но все они утяжеляют локализацию проблем и эксплуатацию.

Интеграционные тесты думать на реальных файлах, потоках и процессах

Logger — та деталь, которой одних юнит-тестов мало. Проверка форматирования строк и сериализации в JSON не ловит то, что ломается в эксплуатации: I/O, конкурентность, ротацию, flush при завершении и ошибки прав.

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

Пункты интеграционных тестов, которые стоит прогнать

Целостность одиночной записи

• Является ли каждая строка ровно одной JSON-записью
• Читается ли обратно как UTF-8
• Есть ли обязательные поля каждый раз
• Не развалила ли встроенный перевод строки запись на несколько строк

Конкурентность внутри одного процесса

• Остаются ли записи целыми при одновременной записи из нескольких потоков
• Нет ли недостачи или избытка числа записей
• При очереди — совпадают ли порядок и потери со спецификацией

Поведение flush и завершения

• Сразу ли видны Error / Critical
• Пуста ли очередь после штатного завершения
• Остаются ли нужные финальные логи и на путях, близких к аварийному завершению

Ротация и хранение

• Переключается ли логгер на новый файл, когда условие ротации выполнено
• Удаляются ли старые файлы сверх лимита хранения согласно спецификации
• Остаются ли JSON-строки целыми непосредственно до и после ротации

Аварийные сценарии

• Поведение, если каталога назначения нет
• Поведение, если нет прав на запись
• Уведомление или возвращаемое значение при сбое вроде переполненного диска
• Поведение при переполнении очереди

Несколько процессов

Если спецификация — один процесс, один файл, объектом проверки может быть уже то, что другой процесс не лезет в тот же файл. Наоборот, при схеме с процессом-сборщиком нужно проверять и сбои передачи ему данных.

Как ловить «поломку»

Одного списка пунктов недостаточно, чтобы написать тесты. Из пунктов выше сложнее всего решить, как судить, что «запись не повреждена». Глазами этого точно не хватит, поэтому три проверки делают машиной.

«Первые 10 строк выглядят нормально» в тесте параллельной записи почти никогда не помогает. Ломается обычно ровно одна строка где-то в середине. Смысл есть только если прогнать все строки.

На PowerShell 7 эти три проверки вместе выглядят так. Предполагается вызов из пост-обработки теста.

# Проверяем все строки выведенного лога. Если сломана хотя бы одна — throw и падаем
$path     = 'C:\ProgramData\MyApp\logs\app-20260402-101500-8412-9f3c1d2a5b7e4f689a0c3d5e7f1b2c4d.jsonl'
$expected = 10000   # Сколько раз тестовая сторона вызвала Write

# Одного «имя свойства есть» недостаточно. У записи вроде `"level": null`
# имя свойства тоже есть, поэтому проверка только на наличие имени проходит.
# Чтобы поймать попавший null, нужно смотреть значение и тип
$required = [ordered]@{
    'ts'        = { param($v) $v -is [string] -and $v -ne '' }
    'level'     = { param($v) $v -is [string] -and $v -ne '' }
    'category'  = { param($v) $v -is [string] -and $v -ne '' }
    'message'   = { param($v) $v -is [string] }   # Пустая строка допустима, null — нет
    'fields'    = { param($v) $v -is [pscustomobject] }
    'sessionId' = { param($v) $v -is [string] -and $v -ne '' }
    'pid'       = { param($v) ($v -is [int] -or $v -is [long]) -and $v -gt 0 }
}

# BOM проверяем по сырым байтам до декодирования.
# Get-Content -Encoding utf8 пропускает ведущий BOM и только потом отдаёт строки,
# поэтому по уже декодированной строке попадание BOM не поймать,
# сколько ни смотри
# (в 5.1 вместо -AsByteStream используйте -Encoding Byte)
$head = @(Get-Content -LiteralPath $path -AsByteStream -TotalCount 3)
if ($head.Count -ge 3 -and $head[0] -eq 0xEF -and $head[1] -eq 0xBB -and $head[2] -eq 0xBF) {
    throw 'В начале файла есть UTF-8 BOM. Для JSON Lines это недопустимо'
}

$lines = @(Get-Content -LiteralPath $path -Encoding utf8)
if ($lines.Count -ne $expected) {
    throw "Число строк не совпадает. Ожидалось $expected / фактически $($lines.Count)"
}

$lineNo = 0
foreach ($line in $lines) {
    $lineNo++

    try {
        $record = $line | ConvertFrom-Json
    }
    catch {
        throw "Строка $lineNo не читается как JSON: $line"
    }

    $names = $record.PSObject.Properties.Name
    foreach ($name in $required.Keys) {
        if ($names -notcontains $name) {
            throw "В строке $lineNo нет обязательного поля: $name"
        }
        if (-not (& $required[$name] $record.$name)) {
            $shown = if ($null -eq $record.$name) { '(null)' } else { "'$($record.$name)'" }
            throw "В строке $lineNo недопустимое значение $name: $shown"
        }
    }
}

"OK: все $($lines.Count) строк читаются как одна запись на строку"

В таком виде скрипт сразу можно переиспользовать в следующих тестах.

• Параллельная запись: из нескольких потоков пишем n раз и ставим $expected равным n
• Ротация и хранение: после ротации ту же проверку гоняем по всем оставшимся файлам, число строк сверяем суммой
• drain при завершении: после завершения проверяем, совпадает ли число с тем, сколько положили в очередь

Аварийные сценарии этой формой не измерить — их смотрят отдельно. Сначала создают условие вроде «нет каталога назначения» или «нет прав на запись», затем инициализируют logger и проверяют, что сбой всплывает исключением, возвращаемым значением или уведомлением. Реализация, в которой «ничего не происходит и ошибку проглатывают», в эксплуатации — самый неприятный вид поломки.

Минимальное число тестов, которое стоит прогнать в v1

Если пытаться сразу закрыть всё, тесты становятся слишком тяжёлыми. Для v1 минимум — примерно эти шесть.

1. Нормальная запись из одного потока
2. Одновременная запись из нескольких потоков
3. Flush Error / Critical
4. Ротация и хранение
5. Уведомление о сбое, если место назначения недоступно
6. Drain и финальный flush при штатном завершении

Даже если проходят только эти шесть, вы уже далеко от «логгера, который печатает строки, но которому нельзя верить в эксплуатации».

Итог

Первая цель самописного logger — не богатство функций, а «чтобы ему можно было верить во время сбоя». Для этого полезно зафиксировать формат как UTF-8 JSON Lines, держать обязательные поля узкими, сделать базой один процесс, один файл и рано решить flush, ротацию, хранение и поведение при сбое.

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

Источники

Похожие статьи

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

Связанные темы

Эти страницы показывают тему статьи в более широком контексте услуг и решений.

Услуги по этой теме

Статья напрямую связана со следующими услугами.

Частые вопросы

Вопросы, которые часто возникают при консультациях по теме статьи.

Какой формат логов стоит выбрать для самописного логгера?

Удобный вариант — UTF-8 JSON Lines, где одна запись занимает ровно одну строку. Обычная склейка текста потом плохо поддаётся машинной обработке, а свой бинарный формат снижает наблюдаемость в эксплуатации. JSON Lines читается как текст, его легко разбирать скриптами и инструментами, а если запись оборвалась посередине, проще отделить повреждённую строку — это практично. Обязательные поля фиксируем семью: timestamp, level, category, message, структурированные fields, sessionId и processId.

Писать логи синхронно или асинхронно?

Стратегию выбирают по нагрузке. Пока объём невелик, синхронная запись понятнее и удобнее для разбора сбоев. Если насильно уйти в асинхронность, легко потерять логи прямо перед завершением или размыть условия flush при исключениях. Когда объём растёт и синхронный I/O становится узким местом, берут single writer + bounded queue и заранее решают политику при переполнении: отбрасывать старые записи или не принимать новые. Логи Error/Critical и записи начала и конца сессии лучше сбрасывать синхронным flush — это помогает при расследовании.

Можно ли нескольким процессам писать в один и тот же лог-файл?

Лучше не стоит. Если несколько процессов дописывают один файл, сразу усложняются взаимное исключение, частичные записи, момент ротации и разбор аварийного завершения — источников сбоев больше, чем кажется. База — один процесс, один файл. Если несколько процессов всё же нужно свести вместе, безопаснее агрегировать логи на следующем этапе или явно завести отдельный процесс-сборщик.

Что проверять интеграционными тестами самописного логгера?

Проверяйте на реальных файлах, потоках и процессах. Юнит-тесты форматирования строк и сериализации в JSON не ловят то, что ломается в эксплуатации: I/O, конкурентность, ротацию, flush при завершении и ошибки прав. Для v1 минимум шесть сценариев: нормальная запись из одного потока, одновременная запись из нескольких потоков, flush для Error/Critical, ротация и хранение, уведомление о сбое, если место назначения недоступно, а также drain и финальный flush при штатном завершении. Если эти шесть проходят, вы уже далеко от логгера, которому нельзя верить в инциденте.

Об авторе

Страница с профилем автора статьи.

Го Комура

Представитель KomuraSoft LLC

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