Security-aware logging

1. Цели security-логирования

Если вы только начинаете, логирование часто воспринимается как что-то вроде “ну давайте напишем log.info("hello"), чтобы было не так страшно”. В security-контексте это не работает: нам нужен лог не ради шума, а ради ответа на конкретные вопросы. И одновременно — мы обязаны помнить, что лог сам по себе может стать источником утечки.

Security-aware logging решает две практические задачи. Первая — диагностика: почему пользователь получил 401 или 403, где именно было принято решение, какой слой “отказал”, не перепутали ли мы роли/authorities/ownership. Вторая — минимальный аудит: когда админ менял роли, кого блокировали, кто пытался лезть в чужие черновики. Это не “enterprise SIEM”, но это уже взрослая привычка: важные security-события оставляют след.

При этом логи — это не секретный сейф. Это скорее “чёрный ящик самолёта”, который вы потом будете читать в стрессовой ситуации. И если вы туда записали пароль или токен, то поздравляю: вы устроили утечку своими руками, даже если база данных у вас идеальна. В security-логировании есть неприятная правда: мы хотим максимум полезной информации при минимуме чувствительных данных.

До этого момента у нас уже собрался понятный маршрут: security-слой определяет current user, сервис решает owner-only доступ, а Authentication и БД делят между собой работу по access-решению. Теперь нужен ещё один слой — след этих решений. Иначе 401, 403 и admin-операции будут происходить, но потом вы не поймёте, кто именно, где и почему упёрся в запрет.

2. Security-события в Secure Content Platform API

Когда говорят “логируй security”, новичок часто начинает логировать всё подряд: каждый запрос, каждую проверку, каждый if — и через день лог превращается в шум, где полезное утонуло. Поэтому лучше заранее договориться, какие события считаем “достойными записи”, а какие — обычной рабочей рутиной, которую можно увидеть и так (например, по обычным application-логам или по JSON-ответу).

В нашем проекте Secure Content Platform API security-события довольно естественные, потому что у нас есть понятные зоны: /api/me, черновики, editor/admin операции, плюс account states (enabled, locked). Если перевести это на язык событий, получится примерно такая “карта”:

Обратите внимание на важную грань. Не каждый 403 — это “ошибка приложения”. Иногда 403 — это нормальное поведение: пользователь без права пытается сделать действие. Поэтому логирование тут должно быть аккуратным: мы хотим видеть важные события, но не хотим, чтобы мониторинг кричал “всё упало” из-за того, что обычный USER полез в /api/admin/**.

3. Где логировать: граница, контроллер, сервис

Самый популярный путь новичка — логировать везде, потому что “ну а вдруг пригодится”. Получается ситуация: контроллер пишет “запрос пришёл”, сервис пишет “доступ запрещён”, потом AccessDeniedHandler пишет “403”, потом ещё global exception handler пишет AccessDeniedException. И вы смотрите на 4 одинаковые строки и думаете: “а какая из них правда?” Spoiler: все, но пользы мало.

Правило, которое хорошо работает в учебном (и реальном) проекте: логируем там, где принимается решение, и стараемся делать это один раз. Если решение “свой/чужой” происходит в сервисе — значит лог там. Если решение про 401/403 формируется в AuthenticationEntryPoint/AccessDeniedHandler — значит там. Контроллер в идеале остаётся тонким: он собирает параметры, вызывает сервис и возвращает ответ. Контроллеру не нужно “объяснять миру”, кто плохой, он не судья.

Чтобы лучше почувствовать место логирования, полезно мысленно нарисовать путь запроса (упрощённо, без деталей filter chain, которые мы уже проходили):

flowchart TD
    A[HTTP request] --> B[Spring Security boundary]
    B -->|401/403 decision| C[EntryPoint / AccessDeniedHandler]
    B -->|ok| D[Controller]
    D --> E[Service]
    E -->|owner check, business auth| F[Access decision in service]
    E --> G[Repository/DB]

Если событие касается “попытки войти в закрытую зону без аутентификации”, оно чаще всего видно на boundary-уровне. Если событие касается “пользователь уже внутри private зоны, но пытается взять чужой объект”, решение чаще всего принимается в сервисе после загрузки объекта. И именно там лог будет точным: у вас есть draftId, есть currentUserId, есть факт “не совпало”.

4. Формат security-лога: actor/action/target/result

Логи должны быть такими, чтобы через неделю вы открыли файл и за минуту поняли, что произошло. Если вы пишете “Access denied” — это технически правда, но практически бесполезно. Поэтому мы формируем небольшой “минимальный контракт” лога. Он очень похож на то, как мы проектировали JSON error contract: стабильный формат, предсказуемые поля, без “лирики”.

Хороший security-лог обычно отвечает на четыре вопроса. Кто совершал действие (actor), что пытался сделать (action), с чем (target), и чем закончилось (result). Иногда добавляют краткую причину (reason), но аккуратно: причина не должна тащить чувствительные данные. В нашем проекте actor — это чаще всего username или userId. Для аудит-логов admin-действий actor почти всегда нужен, иначе запись “роль поменялась” превращается в загадку.

В Java и Spring Boot мы обычно пишем через SLF4J и параметризованные сообщения. Это полезно и для производительности (строка не собирается заранее), и для читаемости (видно места для переменных), и для того, чтобы не случайно “склеить” в строку что-то лишнее.

Мини-пример “правильного формата” (ключи можно выбрать свои, главное — последовательность):

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

class SecurityLogDemo {
    // Логгер обычно делают static final: один на класс, без лишних аллокаций.
    private static final Logger log = LoggerFactory.getLogger(SecurityLogDemo.class);

    void denied(String actor, String action, Long targetId) {
        // Параметризованный лог — чтобы не склеивать строки руками
        // и не "протаскивать" случайно чувствительные данные.
        log.warn("access_denied actor={} action={} targetId={}", actor, action, targetId);
    }
}

Здесь actor — строка (например, username), action — человекочитаемая метка (“read_draft”, “update_profile”), targetId — id объекта. И это уже можно искать, фильтровать, анализировать. Не нужно делать из этого “большую систему”, но структуру полезно держать даже в учебном проекте.

5. Запрещённые данные в security-логах

В security-логировании есть набор данных, которые нельзя писать почти никогда. Даже если вы уверены, что это “только локально”. Даже если это “только на время, потом уберу”. Это как “временно положу кирпич на педаль газа” — возможно, вы правда хотели только чуть-чуть ускориться, но последствия обычно слишком творческие.

Самое очевидное — raw passwords. Их нельзя логировать ни при каких обстоятельствах. Не в контроллере, не в сервисе, не в exception handler. Дальше идут значения, которые фактически дают доступ или облегчают атаку: session id (JSESSIONID), CSRF token, и целиком заголовок Authorization. В Authorization может лежать Basic auth (а это фактически логин+пароль в Base64), а может лежать другой тип credentials. В любом случае логировать его целиком — плохая идея.

Ещё одна категория — “слишком много персональных данных”. Да, иногда хочется логировать email, displayName, bio, полный профиль “для удобства”. Но вы быстро вырастите лог-файл в “теневую базу данных”, причём без ограничений доступа и без нормальной политики хранения. В учебном проекте можно ограничиться userId и username. Если нужно, можно добавить targetUserId, draftId, но не таскать в логи весь контент статьи или профиль.

Очень типичная ловушка связана с “логированием запросов”. Вы включаете какой-нибудь request logging filter, он начинает писать body, а там — пароль при регистрации или обновлении профиля. Вы вроде бы не писали пароль в лог руками, но он всё равно там оказался. Поэтому “не логируй чувствительное” — это не только про ваш log.info("..."), но и про любые автоматические механизмы логирования запросов/ответов.

6. Уровни логирования и debug/trace в Spring Security

Лог-уровни — это не декоративная часть, а способ договориться с будущим собой. INFO — это “полезная бизнес/операционная история”, WARN — “подозрительное или важное отклонение”, ERROR — “реально сломалось”. DEBUG/TRACE — это “режим микроскопа”, который нужен для диагностики, но обычно не должен быть включён постоянно.

Для security-событий в нашем проекте часто хорошо работают такие интонации. Admin actions (роль поменяли, аккаунт заблокировали) — обычно INFO, потому что это ожидаемые действия, но важные. Owner violation и forbidden access — чаще WARN, потому что это попытка получить доступ к чужому или к запрещённому. А вот технические падения, неожиданные исключения в security-инфраструктуре — это ERROR.

Отдельная тема — логи самого Spring Security. Они могут быть очень подробными и очень полезными, особенно когда вы расследуете “почему у меня 403, хотя вроде всё правильно”. Но держать TRACE постоянно — значит утонуть в шуме. Поэтому нормальная практика: включать подробный уровень адресно и временно, чаще всего в local профиле.

Мини-конфигурация (часто достаточно для диагностики chain и решений доступа):

logging:
  level:
    # Подробные логи Spring Security включаем обычно временно (например, в local-профиле).
    org.springframework.security: TRACE

Если вы видите, что Spring Security начал печатать слишком много, можно сузить: например, включать DEBUG вместо TRACE, или настраивать только нужные пакеты. Важно другое: подробные security-логи — это инструмент диагностики, а не “обычный режим”.

7. Примеры: access denied, owner, admin

Сейчас соберём несколько мини-фрагментов кода так, чтобы они были похожи на то, что реально окажется у вас в Secure Content Platform API. Идея простая: лог короткий, понятный, без секретов; место логирования — там, где решение принимается.

Начнём с owner-only проверки в сервисе черновиков. Пусть у нас уже есть draftId, мы загрузили ContentItem из БД и увидели authorId. Если не совпало — это не “ошибка сервера”, это “доступ запрещён”, но событие полезное для журнала.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.security.access.AccessDeniedException;
import org.springframework.stereotype.Service;

@Service
class DraftAccessService {
    private static final Logger log = LoggerFactory.getLogger(DraftAccessService.class);

    void assertOwner(Long draftId, Long draftAuthorId, Long currentUserId) {
        // Решение "свой/чужой" принимается здесь — поэтому и логируем здесь (один раз).
        if (!draftAuthorId.equals(currentUserId)) {
            // Логируем только минимально нужные идентификаторы, без содержимого черновика.
            log.warn("owner_violation actorUserId={} draftId={}", currentUserId, draftId);

            // Сообщение исключения — для клиента/ошибки, но в логи секреты всё равно не пишем.
            throw new AccessDeniedException("Чужой черновик");
        }
    }
}

Обратите внимание, что мы не логируем содержимое черновика, не логируем чужой authorId (хотя могли бы), не пишем лишнюю “лирику”. Для расследования достаточно “кто” и “какой draft”.

Теперь пример admin-действия. Здесь лог особенно полезен, потому что админ меняет модель доступа, а потом через два дня кто-то спрашивает: “почему этот пользователь стал EDITOR?”. И очень приятно, когда ответ находится в одном поиске по логам, а не в гадании на кофейной гуще.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Service;

@Service
class AdminUserService {
    private static final Logger log = LoggerFactory.getLogger(AdminUserService.class);

    void lockUser(String adminUsername, Long targetUserId) {
        // Это аудит-лог: фиксируем, кто сделал admin-действие и к какой цели оно применено.
        log.info("admin_action action=lock_user actor={} targetUserId={}", adminUsername, targetUserId);

        // ... здесь реальная блокировка в БД
        // Важно: в аудит-логах обычно не пишут "весь объект пользователя" целиком.
    }
}

Здесь actor — admin username, target — id пользователя. Этого хватает для базового аудита. Если захотите, можно добавить result=success, но это уже вкусовщина.

И третий пример — централизованная фиксация 403 на уровне AccessDeniedHandler. Это место полезно тем, что оно ловит все запреты “снаружи”, включая запреты по ролям/authorities на уровне request rules и method security. Лог тут не должен быть слишком подробным, но должен дать след: какой метод, какой путь, и что случилось.

import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.security.access.AccessDeniedException;
import org.springframework.security.web.access.AccessDeniedHandler;
import java.io.IOException;

class JsonAccessDeniedHandler implements AccessDeniedHandler {
    private static final Logger log = LoggerFactory.getLogger(JsonAccessDeniedHandler.class);

    @Override
    public void handle(HttpServletRequest req, HttpServletResponse res, AccessDeniedException ex) throws IOException {
        // На boundary-уровне логируем общий факт запрета доступа и контекст запроса.
        // Важно: не логируем заголовок Authorization, cookies и прочие потенциальные секреты.
        log.warn("access_denied method={} path={}", req.getMethod(), req.getRequestURI());

        // Для обычного 403 stack trace обычно не нужен: это ожидаемое поведение.
        res.setStatus(403);

        // JSON-тело ошибки может формироваться отдельно (например, в фильтре/handler-е выше),
        // здесь мы показываем только минимальный пример.
    }
}

Заметьте: мы не логируем Authorization header, не логируем cookies, не печатаем stack trace для обычного 403. Нам важно оставить “след”, но не устроить “утечку через диагностику”.

Если вы сейчас подумали “а где взять actor в AccessDeniedHandler?” — хороший вопрос. Технически можно достать его из SecurityContextHolder, но делать это нужно аккуратно и не превращать handler в мегасервис. На старте курса нормально, если actor будет логироваться в сервисных owner-check местах и в admin-сервисах, а handler будет давать общий след “403 случился тут”. Это лучше, чем “всё и сразу”, которое потом не поддерживается.

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

Ошибка №1: логировать секреты “просто на время”.
Чаще всего это начинается невинно: “давайте выведем Authorization header, чтобы проверить, что он пришёл”, или “ну я пароль не храню, просто в лог выведу, чтобы убедиться, что DTO доехал”. Проблема в том, что логи живут долго, копируются в CI, улетают в общие хранилища, читаются другими людьми. “Временно” очень быстро становится “навсегда”.

Ошибка №2: писать слишком общие сообщения без actor/action/target.
log.warn("Access denied") выглядит как будто вы что-то делаете правильно, но через неделю это превращается в белый шум. Нормальный security-лог должен быть поисковым: вы должны уметь найти “все owner violation по draftId=42” или “все admin_action по targetUserId=10”. Для этого нужны хотя бы 2–3 поля, а не одна грустная фраза.

Ошибка №3: дублировать одно и то же событие в трёх слоях.
Когда и контроллер, и сервис, и AccessDeniedHandler пишут одно и то же, вы получаете эффект “эхо в пещере”. В итоге непонятно, где именно было принято решение, и вы тратите время на расшифровку. Лучше выбрать одно место, где решение действительно принимается, и логировать там, а на остальных уровнях оставить тишину.

Ошибка №4: логировать ожидаемые 403 как ERROR.
ERROR — это “сломалось”. А 403 — очень часто “работает как задумано”. Если вы будете писать каждый запрет как ошибку, мониторинг начнёт орать по ложным поводам, а настоящие ошибки будут теряться. Для access denied чаще подходят WARN или даже INFO (в зависимости от продукта), а ERROR оставляем для реальных исключений и поломок.

Ошибка №5: включить TRACE для Spring Security и забыть выключить.
TRACE — шикарный микроскоп для диагностики. Но если держать его постоянно, вы получите гигантский объём логов и потеряете способность находить важное. В учебном проекте это ещё “просто неудобно”, а в реальном — дорого и опасно. Правильный стиль: включили, нашли проблему, выключили.