1. Шум в логах: почему это больно
Когда вы начинаете писать логи, обычно происходит типичная стадия «всё логируем, потом разберёмся». Это как поставить в комнате десять будильников «на всякий случай» — в итоге вы просыпаетесь не раньше, а в панике. Шум в логах — это ситуация, когда важные события (ошибка, предупреждение, ключевой шаг сценария) теряются среди десятков строк «мы вошли в функцию», «мы вышли из функции», «мы прочитали пробел».
Проблема шума не только эстетическая. Слишком подробные логи усложняют диагностику: вы тратите время на поиск, а мозг перегружается одинаковыми сообщениями. Плюс избыточное логирование иногда заметно замедляет программу (даже консольную): строковая интерполяция, сборка больших сообщений, формирование контекста — всё это работа, которую вы делаете, даже если потом решите эти сообщения не показывать.
Чтобы было проще мыслить, удобно представить уровни логирования не как «красивые слова», а как договорённость:
| Уровень | Смысл | Должно ли быть видно по умолчанию? |
|---|---|---|
|
детали для разработчика, «внутренняя кухня» | обычно нет |
|
нормальные важные этапы сценария | обычно да |
|
подозрительно, но программа продолжает работать | да |
|
ошибка, сценарий не смог выполниться | да |
Наша цель сегодня — научиться включать/выключать детали без переписывания программы и без «комментирования println руками», а ещё научиться не писать лишнего (особенно лишнего и опасного).
2. Режим подробных логов
Verbose-флаг и выбор minLevel
Verbose-режим — это простой переключатель «побольше деталей». В консольных приложениях его очень удобно привязать к аргументам запуска: запускаем обычно — видим INFO/WARN/ERROR, запускаем с "--verbose" — видим ещё и DEBUG. Это не «фича для больших компаний», это буквально способ не засорять вывод в обычном сценарии и включать подробности, когда что-то пошло странно.
Начнём с самой простой проверки: есть ли "--verbose" среди аргументов main(args: Array<String>). В Kotlin это делается почти как по-русски:
fun isVerbose(args: Array<String>): Boolean =
args.contains("--verbose")
Теперь связываем verbose с минимальным уровнем логирования. Если verbose выключен — логируем начиная с INFO. Если включен — начиная с DEBUG.
fun chooseMinLevel(args: Array<String>): LogLevel {
return if (isVerbose(args)) LogLevel.DEBUG else LogLevel.INFO
}
И уже в main создаём логгер:
fun main(args: Array<String>) {
val logger = Logger(minLevel = chooseMinLevel(args))
logger.info("App started") // выведется почти всегда
logger.debug { "Details..." } // выведется только с --verbose
}
На этом месте обычно возникает вопрос: «А почему не сделать по умолчанию DEBUG и не париться?» Потому что тогда вы быстро перестанете читать логи. А если разработчик перестаёт читать логи, логи превращаются в декорацию. Красивую, но бесполезную.
Ленивый DEBUG: debug { ... } вместо debug("...$heavy")
Даже если вы фильтруете по уровню, есть коварная ловушка: сообщение часто строится ещё до того, как логгер решит его печатать. Например, интерполяция строк в Kotlin делает работу сразу:
logger.debug { "state=${heavyStateDump()}" } // так правильно: вычислится только в DEBUG
Если же вы напишете «раннюю» сборку строки, то вычисления начнутся независимо от того, включён DEBUG или нет:
val message = "state=${heavyStateDump()}" // heavyStateDump() вызовется всегда
logger.debug { message }
В маленьких примерах это не видно, но в реальных программах (особенно когда вы делаете joinToString, сериализацию, форматирование таблиц) это может стать неприятно: вы «не печатаете», но продолжаете тратить CPU, память и время.
Решение — сделать debug ленивым: принимать не String, а лямбду () -> String, и вызывать её только если уровень включён.
Ниже — компактная версия логгера с ленивым DEBUG и поддержкой контекста. Важный момент: контекст мы форматируем централизованно, чтобы не повторять этот код в каждом месте.
enum class LogLevel { DEBUG, INFO, WARN, ERROR }
class Logger(private val minLevel: LogLevel) {
private fun isEnabled(level: LogLevel): Boolean =
level.ordinal >= minLevel.ordinal
fun debug(message: () -> String, ctx: Map<String, String> = emptyMap()) {
if (!isEnabled(LogLevel.DEBUG)) return
log(LogLevel.DEBUG, message(), ctx)
}
fun info(message: String, ctx: Map<String, String> = emptyMap()) =
log(LogLevel.INFO, message, ctx)
fun warn(message: String, ctx: Map<String, String> = emptyMap()) =
log(LogLevel.WARN, message, ctx)
fun error(message: String, ctx: Map<String, String> = emptyMap()) =
log(LogLevel.ERROR, message, ctx)
private fun log(level: LogLevel, message: String, ctx: Map<String, String>) {
if (!isEnabled(level)) return
val ts = System.currentTimeMillis()
println("$ts [$level] $message${formatCtx(ctx)}")
}
private fun formatCtx(ctx: Map<String, String>): String {
val safe = sanitizeCtx(ctx)
if (safe.isEmpty()) return ""
return safe.entries.joinToString(prefix = " ", separator = " ") { (k, v) -> "$k=$v" }
}
private fun sanitizeCtx(ctx: Map<String, String>): Map<String, String> {
return ctx.mapValues { (k, v) ->
if (looksSensitiveKey(k)) maskSecret(v) else v
}
}
private fun looksSensitiveKey(key: String): Boolean {
val k = key.lowercase()
return k.contains("token") || k.contains("password") || k.contains("secret") || k.contains("api_key")
}
}
Кстати, если вы форматируете контекст через joinToString(), это тоже может быть «не бесплатным». joinToString() — нормальный и читаемый инструмент сборки текста из коллекции, но лучше не строить итоговую строку без необходимости, особенно в DEBUG. В примере выше это учтено: форматирование произойдёт только если уровень реально печатается.
3. Где поставить лог, чтобы он помог
Очень хочется дать правило «логируй всё на каждом шаге», но это как совет «чтобы не потерять ключи, приклей их к руке скотчем». Формально ключи не потеряются, но жить станет сложнее. В логировании полезнее думать не про количество строк, а про точки смысла.
Хорошая интуиция такая: INFO — это «крупные вехи» сценария, DEBUG — «внутренние детали», WARN — «подозрительное, но терпимое», ERROR — «мы не смогли выполнить действие». Тогда вы начинаете ставить логи не «везде», а на границах.
Например, обработка команды в консольном приложении — отличный кандидат на «границу операции». Там у вас есть контекст (requestId, команда, аргументы), и там логично:
- записать старт обработки (INFO),
- в DEBUG записать детали разбора аргументов,
- при странных входных данных дать WARN,
- при исключении или провале — ERROR,
- записать завершение (INFO), возможно с таймингом.
Внутренние циклы, где вы перебираете список из 1000 элементов, как правило не стоит логировать на INFO — иначе вы получите лог-флуд. Если очень нужно, ставьте такой лог на DEBUG и делайте его ленивым (через лямбду), иначе вы получите шум плюс лишнюю стоимость формирования сообщения.
4. Безопасность: что нельзя писать в логи
Самая опасная фраза в истории разработки — «я это добавлю временно, чтобы отладить». Временный код живёт дольше многих отношений, а логи иногда «уезжают» в баг-репорты, в историю терминала, в CI, в скриншоты, в корпоративные чаты. И вот там-то и обнаруживается, что «временно» вы логировали пароль.
Важно принять как правило: логи — публичнее, чем кажется. Даже если у вас локальная консольная программа, вы сами можете отправить лог другу/преподавателю/в тикет, и внезапно это уже утечка.
Самые типичные «нельзя» в логах:
- пароли, PIN-коды, одноразовые коды (OTP),
- токены авторизации (API keys, bearer tokens),
- секретные ключи, приватные ключи,
- номера карт целиком,
- иногда — e-mail/телефон (зависит от политики проекта), но в учебном проекте лучше тренироваться «не логировать лишнее».
Отдельно неприятная категория — контекст логов. Мы его любим за структуру key=value, но это и ловушка: вы можете машинально положить туда token=..., потому что «контекст же, не сообщение». Для безопасности нет разницы, где вы это написали: в тексте или в контексте. Если оно попало в вывод, оно попало в лог.
5. Маскирование данных: полезно, но не опасно
Маскирование — это компромисс: мы не хотим хранить секрет целиком, но хотим иметь возможность понять «это тот же токен или другой». Поэтому часто оставляют небольшой «хвост», а остальное заменяют на ****. Это позволяет отличить token=...1234 от token=...9876, не раскрывая весь секрет.
Начнём с базовой функции. Она специально короткая, чтобы вам было легко понять логику, а не утонуть в «магии».
fun maskSecret(value: String): String {
if (value.length <= 4) return "****"
val tail = value.substring(value.length - 4)
return "****$tail"
}
Пример использования:
fun main() {
val token = "abcd-efgh-ijkl-1234"
println(maskSecret(token)) // ****1234
}
Дальше вопрос практики: «А как быть с контекстом?»
Идея простая: если ключ в контексте выглядит как секретный (token, password, secret), то значение нужно маскировать автоматически. В этой лекции мы делаем простое правило по имени ключа. В реальных проектах вместо «содержит слово token» могут быть более строгие правила, но принцип тот же: безопасность должна быть по умолчанию.
Обратите внимание: маскирование — это не «раз и навсегда». Оно работает, если вы договорились о ключах контекста. Если один разработчик пишет authToken, а другой token, а третий t, то автоматическое правило начнёт пропускать секреты. Поэтому в реальных проектах договариваются об именах ключей. В учебном проекте мы делаем то же самое, только без бюрократии.
6. Сшиваем вместе: "--verbose" и безопасный контекст
Сейчас мы аккуратно сошьём всё вместе на примере небольшого фрагмента консольного приложения. Смысл примера не в том, чтобы «написать целую систему», а в том, чтобы увидеть: verbose, ленивый debug и маскирование реально сочетаются и не требуют героизма.
Представим, что у нас есть команда "login", которая принимает токен. В реальной жизни токен логировать нельзя. Но при отладке нам хочется понимать, что токен вообще пришёл и какой он «примерно» (чтобы отличить один от другого). Значит, логируем только маску.
Сначала соберём контекст операции и requestId:
fun makeRequestId(): String = "req-${System.currentTimeMillis()}"
fun makeBaseCtx(requestId: String, command: String): Map<String, String> {
return mapOf("requestId" to requestId, "command" to command)
}
Дальше — обработчик команды:
fun handleLogin(rawToken: String, logger: Logger) {
val requestId = makeRequestId()
val ctx = makeBaseCtx(requestId, "login")
logger.info("Login started", ctx)
// Важно: даже в DEBUG пишем только маску, а не секрет целиком
logger.debug({ "rawToken=${maskSecret(rawToken)}" }, ctx)
logger.info("Login finished", ctx)
}
Обратите внимание на «психологический» момент. Мы могли бы написать безопасно и без лямбды (например, собрать строку заранее), но привычка «всё debug — лениво и аккуратно» дисциплинирует: вы реже делаете ошибки, потому что чаще задаёте себе вопрос, что именно вы логируете и когда это строится.
Теперь соберём main, который включает verbose по флагу:
fun main(args: Array<String>) {
val logger = Logger(minLevel = chooseMinLevel(args))
val token = readln().trim()
handleLogin(rawToken = token, logger = logger)
}
В обычном запуске (INFO) пользователь не увидит диагностических деталей. В verbose-режиме ("--verbose") увидит DEBUG-строку с маской токена. И это ровно тот баланс, который нам нужен: по умолчанию тихо, при проблеме — подробно, но безопасно.
7. Типичные ошибки
Ошибка №1: verbose включён всегда, потому что «так удобнее».
Когда DEBUG постоянно включён, очень быстро происходит привыкание: вы перестаёте отличать важное от шума. В результате при настоящей проблеме вы снова идёте «добавлять ещё логов», хотя проблема была не в количестве, а в дисциплине. Держите DEBUG как режим диагностики, а не как стиль жизни.
Ошибка №2: сборка тяжёлого сообщения даже при выключенном DEBUG.
На словах кажется, что раз DEBUG выключен — «ничего не происходит». На деле вычисления могут происходить, просто вы не видите результата. В маленьких программах это незаметно, но в реальной логике (формирование больших строк, joinToString, сериализация, форматирование таблиц) вы платите за отладку даже в обычном режиме. Делайте DEBUG ленивым: debug { ... }, и не собирайте строку заранее.
Ошибка №3: маскирование только в одном месте, а дальше «где-то забудем».
Если вы маскируете секреты вручную в каждом вызове логгера, вы рано или поздно забудете это сделать. Самый надёжный путь — санитайзить контекст и чувствительные значения централизованно (внутри Logger или в одной утилите), чтобы безопасность была «по умолчанию».
Ошибка №4: «я выведу токен только в DEBUG, это же безопасно».
DEBUG — не «секретный уровень». Это всего лишь уровень детализации. Логи могут попасть куда угодно вне зависимости от уровня. Если значение нельзя показывать — его нельзя показывать ни на каком уровне. Максимум — маска или короткий идентификатор.
Ошибка №5: логирование ошибок не тем уровнем, чтобы «не пугать».
Иногда хочется написать «ну это же ожидаемая ошибка, давайте INFO». Если ошибка действительно ожидаемая и сценарий корректно продолжается — возможно, это WARN (и то не всегда). Если сценарий провалился — это ERROR. Когда уровни используются честно, потом гораздо легче фильтровать события и понимать, что происходит.
ПЕРЕЙДИТЕ В ПОЛНУЮ ВЕРСИЮ