Правила логирования в ReadLater Starter

1. Роль правил логирования

Отдельные правила уже разобрали по кускам. Теперь соберём их в один baseline проекта, чтобы app, service и client говорили на одном языке, а не каждый на своём диалекте логов.

Когда приложение маленькое, кажется, что “логов и так достаточно”: где-то написали Started, где-то Done, где-то Oops. Но как только появляется несколько режимов запуска, внешний HTTP-клиент и конфигурация, логи начинают жить своей жизнью — и очень быстро превращаются в шум. Правила нужны не ради бюрократии, а ради предсказуемости: чтобы по любому запуску можно было понять, что происходило, без чтения исходников с лупой.

Представьте, что вы запускаете ReadLater Starter через неделю после паузы (классика учебных проектов): вы помните идею, но детали уже размылись. Хорошие логи — это как записка самому себе из прошлого: “я сделал вот это, вот с такими параметрами, вот что получил”. Плохие логи — это как записка “я что-то делал… удачи”.

И есть ещё одна причина: мы стоим на пороге server-фазы. Когда завтра мы поднимем HttpServer, логи станут не “приятным дополнением”, а единственным нормальным способом понять, почему запросы падают, какие маршруты реально дергают, и где мы ошиблись в обработке входа.

2. Единый стиль сообщений

Стиль логов — это не про красоту и не про “как правильнее по учебнику”. Это про то, чтобы вы могли глазами быстро сканировать строки и выцеплять важные параметры. Самый практичный компромисс для учебного проекта: короткая фраза действия плюс параметры в стиле ключ=значение, которые легко читать.

Хорошая новость: в SLF4J это естественно получается через placeholders {}. Мы пишем шаблон, а значения подставляются параметрами. Это и быстрее, и чище, и избавляет от бесконечных "... " + x + " ...".

Плохая привычка выглядит так: сообщение каждый раз уникальное, как произведение искусства. В результате поиском по логам вы ничего не найдёте. Хорошая привычка: у вас есть 2–3 устойчивых глагольных формы (например, started, completed, failed), и вы их повторяете.

Вот пример того, как один и тот же смысл может выглядеть “хаотично” и “стандартно”.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LoggingStyleDemo {
    private static final Logger log = LoggerFactory.getLogger(LoggingStyleDemo.class);

    public void bad(String query, int count) {
        // Плохой пример: конкатенация строк усложняет поиск по логам и может быть дороже по производительности
        log.info("Ну мы короче вроде поискали: " + query + ", и нашли " + count);
    }

    public void good(String query, int count) {
        // Хороший пример: стабильный шаблон + параметры ключ=значение через placeholders {}
        log.info("Catalog search completed, query={} resultsCount={}", query, count);
    }
}

Во втором варианте вы можете легко искать по фразе Catalog search completed и сравнивать запуски. А параметры query и resultsCount у вас везде будут называться одинаково — значит, мозг перестаёт “парсить литературу” и просто читает логи как данные.

Отдельное правило, которое сэкономит нервы: не превращайте лог в дамп всего объекта. Логировать config.toString() приятно (одно действие вместо пяти), но опасно: туда легко уедет лишнее, а иногда и чувствительное. Лучше логировать сводку — конкретные поля, которые реально помогают.

3. Где логировать: app, service, client

Одна из самых частых проблем в логах — дублирование. Когда и ReadLaterApplication, и CatalogService, и CatalogHttpClient дружно пишут “начали поиск”, “закончили поиск”, “получили ответ”… и всё на info. В итоге у вас тройная бухгалтерия одного события, а когда реально случилась ошибка — искать источник становится сложнее.

Чтобы этого избежать, полезно держать простую карту: у каждого слоя свой тип логов. В app мы логируем “жизнь приложения” (режим запуска, старт, конфигурация). В service мы логируем “прикладной сценарий” (поиск по запросу, получение деталей по ID, сколько результатов). В client мы логируем “транспорт” (URI, статус, длительность, сетевые сбои) — и чаще всего эти детали уместнее на debug, чтобы не превращать info в свалку.

В виде очень упрощённой схемы это можно представить так:

flowchart TD
    A["ReadLaterApplication / app"] --> B["CatalogService / service"]
    B --> C["CatalogClient / client"]
    C --> D["External HTTP API"]

    A -->|"INFO: mode + config summary"| A
    B -->|"INFO: scenario started/completed"| B
    C -->|"DEBUG: uri + status + duration"| C
    C -->|"ERROR: exception with context"| C

Обратите внимание: мы не пытаемся строить “идеальную архитектуру логирования”. Мы просто договариваемся, что один слой не повторяет чужую работу, а дополняет.

И ещё одно правило, которое лучше зафиксировать сразу: если внешний HTTP-вызов сорвался, stack trace остаётся на client / integration boundary. service выше не печатает второй такой же ERROR.

Мини-пример того, как service может логировать сценарий, не лезя в детали HTTP:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class CatalogService {
    private static final Logger log = LoggerFactory.getLogger(CatalogService.class);
    private final CatalogClient client;

    public CatalogService(CatalogClient client) {
        // Зависимость на клиент (транспорт) внедряем извне, чтобы сервис отвечал за сценарий, а не за HTTP
        this.client = client;
    }

    public void search(String query) {
        // INFO: старт бизнес-сценария + важный входной параметр
        log.info("Catalog search started, query={}", query);

        var items = client.search(query);

        // INFO: факт завершения сценария + сводка результата
        log.info("Catalog search completed, query={} resultsCount={}", query, items.size());
    }
}

А вот client (транспортный слой) может дать детали — но лучше на debug, чтобы включать их точечно для пакета catalog:

import java.net.URI;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class HttpCatalogClient {
    private static final Logger log = LoggerFactory.getLogger(HttpCatalogClient.class);

    public void call(URI uri) {
        // DEBUG: транспортные детали обычно нужны только при расследовании
        log.debug("Catalog HTTP request prepared, method=GET uri={}", uri);

        // ... send request ...

        // DEBUG: фиксируем статус и длительность (это самые полезные метрики при проблемах с сетью)
        log.debug("Catalog HTTP response received, method=GET uri={} statusCode={} durationMs={}", uri, 200, 137);
    }
}

А если вызов вообще сорвался, CatalogClient пишет один ERROR с exception; service этот же stack trace уже не повторяет.

Так вы можете держать приложение на INFO, а когда нужно расследование — временно поднять com.example.readlater.catalog на DEBUG в logback.xml.

4. Обязательные события в ReadLater Starter

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

Ключевая идея: у нас есть обязательные точки, которые должны появляться в логах при любом запуске. Мы не пытаемся логировать каждый шаг алгоритма. Мы логируем именно “контрольные точки”: старт, выбранный режим, сводка безопасной конфигурации, начало/конец операции, и ошибки (с контекстом).

Старт приложения: режим и аргументы

Первое, что вы хотите видеть в логах — факт старта приложения и выбранный launch mode. Это кажется очевидным, пока вы не запустите случайно “не то” или не забудете, с какими аргументами запускались. В этот момент лог Application started внезапно превращается из банальности в спасательный круг. Поэтому фиксируем: старт, количество аргументов, и отдельным сообщением — распознанный режим.

package com.example.readlater.app;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ReadLaterApplication {
    private static final Logger log = LoggerFactory.getLogger(ReadLaterApplication.class);

    public static void main(String[] args) {
        // INFO: базовая контрольная точка — факт запуска приложения
        log.info("Application started, argsCount={}", args.length);

        String mode = args.length > 0 ? args[0] : "<missing>";

        // INFO: контрольная точка — какой режим выбрали (потом это сильно экономит время)
        log.info("Launch mode selected, mode={}", mode);

        // дальше уже вызываем нужный сценарий
    }
}

Заметьте, мы не логируем весь args как строку (хотя иногда хочется). В учебном проекте это, скорее всего, безопасно, но привычку лучше строить правильную: “в логах — только то, что точно не секрет”. Если завтра у вас появится токен в аргументах (в реальной жизни такое бывает), вы будете рады, что не привыкли печатать всё подряд.

Сводка конфигурации

После того как мы прочитали application.properties, env vars и args, крайне полезно зафиксировать сводку: какой base URL, какие таймауты, какой режим real/mock, какой порт сервера. Это помогает отлавливать 80% проблем “у меня не работает”, потому что половина таких проблем — “у тебя другой baseUrl”.

Но делаем это аккуратно: логируем только “нечувствительные” поля и только те, которые реально влияют на поведение. Никаких “вывалим весь объект config”.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class CatalogConfigLogger {
    private static final Logger log = LoggerFactory.getLogger(CatalogConfigLogger.class);

    public void logCatalogConfig(String mode, String baseUrl, int requestTimeoutMs) {
        // INFO: печатаем только безопасную сводку (без токенов, ключей и прочих секретов)
        log.info("Catalog config, mode={} baseUrl={} requestTimeoutMs={}", mode, baseUrl, requestTimeoutMs);
    }
}

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

catalog search: INFO у сценария, ERROR на boundary

Для catalog search на уровне use-case достаточно двух INFO: старт сценария и его успешное завершение. Это именно duration сценария целиком, а не одного HTTP round-trip.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class CatalogSearchUseCase {
    private static final Logger log = LoggerFactory.getLogger(CatalogSearchUseCase.class);

    public void run(String query, CatalogClient client) {
        // Таймер здесь измеряет весь use-case, а не только transport-вызов
        long startedAt = System.nanoTime();

        // INFO: старт сценария
        log.info("Catalog search started, query={}", query);

        var items = client.search(query);

        long durationMs = (System.nanoTime() - startedAt) / 1_000_000;

        // INFO: итог сценария — сколько нашли и сколько времени заняло
        log.info("Catalog search completed, query={} resultsCount={} durationMs={}", query, items.size(), durationMs);
    }
}

Если client.search(query) бросит исключение, этот метод не печатает второй ERROR. Technical failure и stack trace уже должны жить в CatalogClient, рядом с URI и transport-duration. А если поиск ничего не нашёл, это по-прежнему не ошибка системы: сценарий завершился честно, просто результат пустой.

catalog details: те же правила

С catalog details всё почти то же самое, только главным параметром становится externalId. Стиль сообщений должен быть тем же, чтобы по логам было видно, что это “родственные” сценарии.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class CatalogDetailsUseCase {
    private static final Logger log = LoggerFactory.getLogger(CatalogDetailsUseCase.class);

    public void run(String externalId, CatalogClient client) {
        // Таймер по той же причине: это duration сценария целиком
        long startedAt = System.nanoTime();

        // INFO: старт сценария с ключевым параметром
        log.info("Catalog details started, externalId={}", externalId);

        var details = client.details(externalId);

        long durationMs = (System.nanoTime() - startedAt) / 1_000_000;

        // INFO: завершение сценария (детали целиком в логи не вываливаем)
        log.info("Catalog details completed, externalId={} durationMs={}", externalId, durationMs);

        // details выводим пользователю отдельно (stdout)
    }
}

Правило то же: service даёт started/completed, а technical failure остаётся на boundary. Если вызов сорвался, completed просто не появится, а нужный ERROR останется в клиенте вместе с exception.

server: старт сервера

Режим server мы начнём реализовывать уже на следующем дне, но правило логирования для него стоит зафиксировать сейчас: старт сервера должен логироваться всегда, причём так, чтобы потом по одному сообщению было понятно, где он слушает. Когда мы будем принимать входящие запросы, мы добавим лог “method + path + status + duration”. Но это уже завтрашний разговор.

Пока минимально достаточно вот такого старта:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ServerMode {
    private static final Logger log = LoggerFactory.getLogger(ServerMode.class);

    public void start(String host, int port) {
        // INFO: по одной строке должно быть понятно, куда подключаться клиенту (host/port)
        log.info("Server mode started, host={} port={}", host, port);

        // завтра здесь появится запуск HttpServer
    }
}

Даже это сообщение уже помогает: если вы случайно подняли сервер на другом порту, вы увидите это сразу, а не после десяти минут “почему Postman не коннектится”.

5. Пользовательский вывод и логи: stdout/stderr

Когда у вас CLI-режимы (catalog search, catalog details), пользовательский вывод — часть интерфейса. Но логи — это диагностика. Если всё летит в одну консоль одной кашей, пользовательский вывод становится нечитаемым, а логи трудно отличить от “результата программы”. Самый простой трюк, который не требует никаких библиотек: пользовательский вывод оставляем в System.out, а логи отправляем в System.err.

Это не “продакшен-архитектура”, а просто очень практичная привычка. В будущем, если вы будете перенаправлять stdout в файл или пайпить вывод, это сыграет вам на руку. А сегодня это просто делает интерфейс аккуратнее.

Нам здесь нужна ровно одна project-specific деталь logback.xml: диагностический appender уходит в System.err.

Фрагмент src/main/resources/logback.xml

<appender name="STDERR" class="ch.qos.logback.core.ConsoleAppender">
    <target>System.err</target>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level %logger - %msg%n</pattern>
    </encoder>
</appender>

Дальше этот appender подключается к root, и диагностический поток идёт своей дорогой.

А пользовательский вывод остаётся обычным:

System.out.println("Found books: " + items.size()); // Found books: 3

Получается простая договорённость: out — “ответ пользователю”, err — “диагностика”. И вы сразу видите, что относится к чему.

6. Мини-чеклист правил логирования проекта

Сейчас зафиксируем правила в максимально прикладном виде. Таблица — это не “канцелярщина”, а способ сделать стандарт коротким: открыл, проверил, понял.

Перед таблицей важная оговорка: это минимум. Если вы добавляете новые фичи — вы расширяете стандарт, но не ломаете его. То есть стиль и ключевые события сохраняются.

Ниже уже не теория про уровни, а project-rule: кто именно пишет событие и зачем.

Если вы сейчас смотрите на эту таблицу и думаете “много сообщений”, то хорошая новость: это не “всё в каждом запуске”. В каждом запуске у вас сработает 5–8 строк, и это как раз тот объем, который можно глазами удержать.

7. Чтение логов на примере catalog details

Чтобы правила не выглядели абстракцией, давайте представим типичную ситуацию. Вы запускаете:

./gradlew run --args="catalog details OL12345M"

И вдруг “ничего не работает”. Без логов вы видите только: “ошибка”. С логами вы видите историю.

Например, в логах вы находите:

12:00:01.120 INFO  com.example.readlater.app.ReadLaterApplication - Application started, argsCount=3
12:00:01.123 INFO  com.example.readlater.app.ReadLaterApplication - Launch mode selected, mode=catalog
12:00:01.125 INFO  com.example.readlater.app.ReadLaterApplication - Catalog config, mode=real baseUrl=https://openlibrary.org requestTimeoutMs=2000
12:00:01.200 INFO  com.example.readlater.catalog.service.CatalogService - Catalog details started, externalId=OL12345M
12:00:03.205 ERROR com.example.readlater.catalog.client.OpenLibraryCatalogClient - Catalog HTTP call failed, operation=details externalId=OL12345M durationMs=2005

Одна эта последовательность уже говорит многое: приложение стартануло, режим распознался, baseUrl нормальный, сценарий начался, а через две секунды транспортный вызов сорвался. Это почти наверняка таймаут (или сетевой сбой), а не “не нашли книгу”. И вы даже не читая stack trace можете сразу проверить настройки таймаута или доступность сети.

Здесь нет Catalog details completed, и это правильно: сценарий не завершился успешно. Зато техническая ошибка зафиксирована один раз — в catalog.client, где есть лучший transport-контекст. Stack trace будет сразу под последней строкой, а не размазан по service и app.

Если же вы видите completed, durationMs=50, но пользователь говорит “ничего не нашлось”, то это уже бизнес-сценарий: возможно, ID неверный. И это нормально — мы не делаем из этого error.

В этом и смысл правил: логи не обязаны быть красивыми, но они обязаны быть расследуемыми.

8. Типичные ошибки при логировании

Ошибка №1: “у нас есть логирование”, но старт и режим не логируются.
Это классика. Вы добавили логи в CatalogClient, но забыли написать Application started и Launch mode selected. В итоге у вас есть технические детали, но нет контекста. Логи без контекста похожи на фразу “всё сломалось где-то там”. Исправляется очень просто: два обязательных info в main() и вы уже на порядок счастливее.

Ошибка №2: каждый класс пишет сообщения в своём стиле, как будто это личный блог.
Один пишет Start, другой Started, третий BEGIN, четвёртый Поехали!. На чтение таких логов мозг тратит силы, которые должны уходить на поиск причины. Решение — не “поставить линтер на логи”, а договориться о 2–3 шаблонах (started/completed/failed) и повторять их, пока не надоест. Когда надоест — вы поймёте, что стандарт реально прижился.

Ошибка №3: всё логируется на info, потому что “иначе я не увижу”.
info — это не мусорное ведро. Если на info вы пишете каждую подготовку URI, каждый заголовок и каждый кусок JSON, через два дня вы перестанете читать логи вообще. Нормальная стратегия: info — ключевые события, debug — детали расследования, а warn/error — сигналы проблем. А чтобы “увидеть детали”, вы поднимаете уровень для пакета catalog в logback.xml на время.

Ошибка №4: error используется для ожидаемых ситуаций (“ничего не нашли”).
Пустой результат поиска — это не ошибка системы. Это нормальный исход сценария. Если вы будете писать error на такие случаи, вы приучите себя игнорировать error вообще (“да это опять просто не нашли книгу”). А когда реально будет падение по исключению — вы его пропустите. Это как кричать “пожар” каждый раз, когда закончился чай.

Ошибка №5: логируется всё подряд, включая чувствительные данные и большие payload-ы.
Даже в учебном проекте лучше тренировать правильный рефлекс: токены, ключи, секреты — не логируем. Большие тела ответов — тоже не логируем на info. Если очень надо, делайте это на debug, с ограничением длины, и включайте только временно. И всегда помните: “лог — это не архив интернета, это диагностическая сводка”.

Ошибка №6: один и тот же stack trace дублируется в client, service и app.
Так вы не усиливаете сигнал, а размазываете один сбой по всему логу. Полный technical error с exception должен жить на integration boundary, где есть URI, статус и duration. Выше, если очень надо, оставляйте только короткое сообщение без повторения stack trace.