Тестирование логов: zaptest и observer

«При недоступности шлюза мы логируем Warn» — говорят на планёрке, а в коде это Info, и никто не заметил. Логи — часть контракта: дашборды, алерты и рантбуки завязаны на уровни, сообщения и поля, и молча испорченная запись ломает разбор инцидентов не хуже бага в бизнес-коде. Тестирование логов go-приложения закрывает это без моков и парсинга текста: observer даёт записи как объекты, zaptest — логгер для библиотек, который пишет в вывод go test. Оба инструмента идут в комплекте zap, ничего придумывать не нужно.

zaptest/observer: логи как записи в тесте#

Пакет go.uber.org/zap/zaptest/observer даёт пару: observer.New(zapcore.InfoLevel) возвращает ядро и накопитель ObservedLogs. Ядро подставляется в zap.New как обычный Core — код под тест не знает, что пишет в наблюдателя, и гоняет боевой zap.Logger, а не заглушку. Каждая запись попадает в накопитель как LoggedEntry: уровень, сообщение, время и слайс полей Context. Уровень enabler работает как в проде: записи ниже порога не сохраняются, и поведение логгера в тесте совпадает с боевым, включая With и Named. Это главное отличие от подхода «перехватим stdout и распарсим JSON»: формат вывода не тестируется вовсе, а проверяется то, что реально попадёт в систему сбора.

Полный тест на Warn-запись

func TestSlowSQLWarns(t *testing.T) {
        core, logs := observer.New(zapcore.InfoLevel)
        logger := zap.New(core)

        reportSlowSQL(logger, "orders", 350*time.Millisecond)

        entries := logs.All()
        if len(entries) != 1 {
                t.Fatalf("want 1 entry, got %d", len(entries))
        }
        if entries[0].Level != zapcore.WarnLevel {
                t.Errorf("level = %v, want warn", entries[0].Level)
        }
        if entries[0].Message != "slow sql" {
                t.Errorf("message = %q, want slow sql", entries[0].Message)
        }
        if ms := entries[0].ContextMap()["ms"]; ms != int64(350) {
                t.Errorf("ms = %v, want 350", ms)
        }
}

Порядок: собрать пару ядро-накопитель, передать логгер в код, вызвать, проверить. All возвращает снимок записей, Level и Message сравниваются напрямую, ContextMap достаёт поле по имени. zap.Int64 в коде совпадает с int64 в карте — типы полей сверяются буквально, и ошибка в типе поля ловится тестом раньше системы сбора. Первый ассерт — длина: при лишних записях ошибка говорит о шуме, а не о пропавшем поле, и виновника видно по соседним записям снимка. Формулировки t.Fatalf с фактическим значением экономят минуту на каждый прогон после правки.

API ObservedLogs: фильтры и Len#

ObservedLogs покрывает типовые проверки без ручных циклов. Len считает записи, All возвращает всё, TakeAll вынимает записи и очищает накопитель — удобно для сценария «первый вызов дал одну запись, второй не дал ничего». Фильтры FilterMessage, FilterMessageSnippet и FilterField возвращают укороченный ObservedLogs, и проверки читаются как предложения: логи, где сообщение про slow, где поле table равно orders. AllUntimed возвращает записи с обнулённым временем — для сравнения списков без меток. Уровень enabler — граница: всё, что ниже Info, копиться не будет. Если код под тест пишет Debug, ставьте DebugLevel в observer.New, иначе тест увидит пустоту и соврёт вам о поведении кода. Ещё один фильтр — FilterFieldSnippet(key, подстрока): записи, у которых строковое значение поля с данным ключом содержит фрагмент, — удобно для частичных совпадений без привязки к точной формулировке.

Типичная ошибка: observer под сэмплером

Если тестовый логгер собирается как боевой — с NewSamplerWithOptions поверх ядра, — observer получает прореженный поток: первые сто записей за тик, дальше по одной. Тест, рассчитанный на три записи, ловит одну и флакает от скорости машины: тик успел смениться или нет. В тестах сэмплер не ставят: observer должен видеть всё, что решил написать код, — прореживание это отдельное решение прод-конфигурации, а не поведение кода под тестом.

Проверка: порог enabler

observer.New(zapcore.InfoLevel). Код под тест вызывает logger.Debug("tick"). Сколько записей вернёт logs.All()?

Проверка полей, уровня и сообщения#

Проверяйте контракт, а не вывод: уровень — на него первым смотрит алерт, сообщение — его ищут в рантбуке, поля — на них построены дашборды. Сообщение проверяйте целиком или через FilterMessageSnippet: точная строка ломается от правки формулировки, но и сниппет держите осмысленным — slow sql, payment declined. Поля сравнивайте по типам: zap.Int64 в коде и int64 в ContextMap — совпадение буквальное. Чего проверять не стоит: формат JSON, порядок полей, метку времени. Это решения энкодера, а не вашего кода, и завязывать тест на них — ломать сборку из-за смены конфигурации вывода. Хорошая проверка логов хрупче боевого кода не становится.

Фильтры вместо циклов

if logs.FilterMessageSnippet("slow").Len() == 0 {
        t.Fatal("expected a slow sql warning")
}

orders := logs.FilterField(zap.String("table", "orders"))
if orders.Len() != 1 {
        t.Fatalf("want 1 entry with table=orders, got %d", orders.Len())
}

FilterField принимает zapcore.Field — тот же конструктор, что в записи: совпадают ключ, тип и значение. Фильтры возвращают ObservedLogs, поэтому фильтры компонуются: сначала по сообщению, потом по полю. Len после фильтра — это и есть ассерт количества. Такой стиль читается в ревью без разбора циклов, и упавший тест говорит, какой именно контракт нарушен.

Табличные тесты: контракт уровней#

Контракт «статус шлюза — уровень записи» — идеальный материал для табличного теста: список сценариев, один цикл, одна проверка. Сценарий — вход кода под тестом и ожидаемая запись: сообщение, уровень, ключевое поле. Перед каждой итерацией TakeAll очищает накопитель, и цикл смотрит только свои записи — ровно тот сценарий, ради которого TakeAll и придуман. Такой тест живёт рядом с политикой уровней из HTTP-урока и ловит то, о чём говорят на планёрках: кто-то поменял Warn на Info в одной ветке switch — табличный тест краснеет с названием сценария в сообщении. Пишется он один раз, при внедрении логирования, и правится вместе с политикой: цена строки в таблице несопоставима с ценой незаметно испорченного уровня в проде.

zaptest.Logger: логгер для библиотек#

Библиотечный код не навязывает конфигурацию логов: он принимает *zap.Logger и пишет в него. В тестах этой библиотеки логгер даёт пакет zaptest: zaptest.NewLogger(t) строит логгер, который пишет каждую запись через t.Log, и запускается обычным go test на локальном Go без всякой обвязки. Две приятности бесплатно: записи привязаны к тесту, а go test показывает их только для упавших тестов или с флагом -v — успешный прогон не утопает в логах. Опции есть: zaptest.Level поднимает порог, zaptest.WrapCore подменяет ядро — так observer встраивается внутрь zaptest-логгера, когда хочется одновременно вывод в тест и проверки полей. Для простой библиотеки хватает NewLogger без опций.

Проверка: порог zaptest.NewLogger

zaptest.NewLogger(t) вызван без опций. Записи какого уровня дойдут до вывода теста?

Библиотека под zaptest

func TestClientSilentOnSuccess(t *testing.T) {
        logger := zaptest.NewLogger(t)
        c := NewClient(logger)

        if err := c.Ping(context.Background()); err != nil {
                t.Fatalf("ping: %v", err)
        }
        // Записи уйдут в t.Log и появятся только при падении теста.
}

Клиент получает *zap.Logger как в проде — зависимость без особых интерфейсов. При падении теста вывод t.Log покажет записи с уровнями и полями, и причину видно по логам, а не по догадкам. Флаг -v покажет те же записи и для успешного прогона, если нужно посмотреть глазами.

Не оборачивайте логгер в свой интерфейс

Ради тестируемости часто заводят интерфейс-обёртку над zap.Logger. With и Named в такой интерфейс не ложатся, поля теряются, а тесты мокают то, что в бою никогда не выполнится. Observer уже делает логи проверяемыми без обёрток: принимайте *zap.Logger и тестируйте реальный логгер.

Детерминизм времени#

Каждая запись несёт время из реальных часов, и тест, сравнивающий Time с time.Now(), флакает: часы идут, планировщик дёргает, времена не равны. Практика, которая работает: время в тестах логов не сравнивать вообще. AllUntimed возвращает записи с обнулённым Time — сравниваются уровень, сообщение и поля, и тест перестаёт зависеть от скорости машины. Если логика завязана на длительность, проверяйте поле Duration, которое код посчитал сам, а не метку записи. Для кода, где время — часть контракта, например дедлайн в ошибке, значение прокидывайте отдельным полем из тестового таймера. Обёртка observer при этом синхронная: к моменту проверки записи уже лежат в накопителе, и никаких ожиданий в тест не нужно. У zaptest есть и управляемые часы — опция Clock: время в записях движется по шагу, а не по реальным ожиданиям; для ассертов это всё равно не аргумент — метки не сравниваются ни с реальными, ни с управляемыми часами.

Код под тест пишет из горутин#

Накопитель ObservedLogs защищён мьютексом: записи из горутин кода под тест не рвут данные, гонок внутри observer нет. Проблема в другом: тест проверяет накопитель раньше, чем фоновая горутина успела записать, — и All() честно возвращает меньше записей, чем есть на самом деле. Observer синхронен внутри вызова Write, но ждать ваши горутины он не обязан. Синхронизация — обычные приёмы: WaitGroup с сигналом о завершении записи, канал как точка встречи или проверка с коротким экспоненциальным ожиданием для интеграционных сценариев. Жёсткое правило: если запись делает горутина, тест не смотрит в накопитель без синхронизации — иначе сборка флакает на загруженном CI раз в неделю, и охота за «случайным» падением стоит дороже самого теста.

Гигиена тестов логов#

Порог observer равен боевому: тест с заниженным порогом пропустит исчезновение Info-записей.
Один сценарий на тест; сценариев больше — TakeAll между фазами.
Время, формат JSON и порядок полей не проверяются: это решения энкодера, а не кода.
Поля сравниваются с типами: zap.Int64 против int64 в ContextMap, а не против float64 на глаз.
Сэмплер в тестовый логгер не включается: observer обязан видеть всё.
Флакующий тест чинят синхронизацией, а не sleep подлиннее.

Проверка: AllUntimed

Чем удобен AllUntimed() в тестах?

Сколько вернёт Len после TakeAll?

Прочитайте код и выберите, что он выведет:

core, logs := observer.New(zapcore.InfoLevel)
logger := zap.New(core)
logger.Info("one")
fmt.Println(len(logs.TakeAll()))
fmt.Println(logs.Len())

Соберите тест наблюдателя

Восстановите каркас теста: порог, ядро, снимок записей.

func TestPaymentWarns(t *testing.T) { core, logs := observer.New(zapcore.Level) logger := zap.New() entries := logs.() if entries[0].Level != zapcore.WarnLevel { t.Fatal("want warn") } }

Соберите проверку записи

Расставьте строки теста по порядку.

Строки

Ваша программа

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

Карточки: zaptest и observer

Термин

observer.New

нажмите, чтобы перевернуть

Определение

Возвращает пару (zapcore.Core, *ObservedLogs): ядро уходит в zap.New, накопитель — в проверки теста.

1 / 6

Что дальше по курсу#

Логгер, который тесты не трогают, часто берут глобальным: когда это уместно и чем опасно, разбирает урок про ReplaceGlobals; уровни для тестов и прода настраиваются в уроке про конфиг zap. Тесты gRPC-сервисов, где логам перехватчиков тоже нужна проверка, — в уроке про тестирование gRPC; карта курса — на странице курса zap.

Песочница урока

Редактируйте код и запускайте его прямо здесь — интерпретатор работает в браузере, ничего устанавливать не нужно. За каждый запуск — +2 XP.

Вывод

Запустите код, чтобы увидеть вывод.

Коротко: что запомнить

Логи — часть контракта: дашборды и алерты завязаны на уровни, сообщения и поля.
observer.New возвращает ядро и накопитель: код под тест пишет в боевой zap.Logger.
Проверяйте уровень, сообщение и поля; формат вывода и метки времени не тестируются.
Фильтры ObservedLogs читаются как предложения: FilterMessageSnippet, FilterField, Len.
zaptest.NewLogger пишет в t.Log: вывод виден у упавших тестов и с флагом -v.
Time в записях не сравнивают: AllUntimed обнуляет метки.
Enabler работает как в проде: Debug ниже порога Info не записывается.

Домашнее задание

Напишите тест на middleware или перехватчик из прошлых уроков: observer.New(zapcore.DebugLevel), логгер уходит в код, проверяются уровень и поля latency, code, request_id. Добавьте второй тест на отсутствие записей в штатном сценарии — Len должен остаться нулём. Запустите оба обычным go test на локальном Go и убедитесь, что вывод логгера не мусорит успешный прогон. Затем соберите боевой логгер с сэмплированием 100/100 и повторите тест на три одинаковые записи подряд: зафиксируйте, сколько записей увидел observer, и выпишите вывод — почему в тестах сэмплер не ставят.

Вопросы и ответы по уроку

Чем observer лучше захвата stdout логгера?

Захват вывода заставит парсить JSON обратно в структуру и привяжет тест к формату. Observer держит записи как объекты: уровень, сообщение и поля в типах. Формат вывода меняется — тесты этого не замечают.

Можно ли одновременно писать в тест и в observer?

Да: zapcore.NewTee поверх двух ядер или zaptest.WrapCore с обёрткой. Вывод в t.Log идёт для человека, накопитель — для ассертов, и оба видят одни и те же записи.

Тестирует ли observer формат итогового JSON?

Нет, и это плюс: формат — ответственность энкодера из урока про JSON и console. Тестируйте содержимое записей; для формата есть отдельные тесты на конфигурацию логгера.

Термины урока

Ключевые понятия из этого урока — короткие определения в глоссарии. Наведите на термин, чтобы вспомнить, откройте карточку для подробностей и ссылки на практику.

Сравните с альтернативами

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