Spring Boot
Spring Boot Custom Logging: AOP, Request Logs, Appenders and Audit
Extend Spring Boot logging the safe way: AOP method logging, correlation IDs, HTTP request logging, a non-blocking custom Logback appender, metrics from logs, and audit logging. Includes built-in alternatives and troubleshooting.
What Is Custom Logging, and When Do You Need It?
Custom logging means adding behaviour on top of Spring Boot's standard Logback and SLF4J setup: logging method calls without touching business code, tagging every line with a request ID, sending alerts, or keeping a separate audit trail.
The goal is to log **less, more usefully, and safely**. Every pattern on this page has a failure mode (leaked secrets, blocked threads, duplicate lines), and the examples show how to avoid each.
Examples target Spring Boot 3.x with Logback. Package names follow your project (`com.myapp`).
Built-in Option or Custom Code?
Check this table first. Writing custom code for something Boot already provides adds maintenance and bugs.
| Need | Built-in option | Write custom code when |
|---|---|---|
| Request logging (method, URI, status, time) | Tomcat access log (`server.tomcat.accesslog.enabled`), `http.server.requests` metric | You need your own format or filtering rules |
| Request payload while debugging | `CommonsRequestLoggingFilter` | Almost never |
| Error and warning counts | `logback.events` metric | You count specific business events |
| JSON logs | `logging.structured.format.console` (Boot 3.4+) | You need a custom schema |
| Trace and request IDs | Micrometer Tracing puts `traceId` and `spanId` in MDC | You have no tracing and want a simple correlation ID |
| Method entry, exit and timing | None | An AOP aspect (this page) |
| Alerts on errors | Prometheus and Alertmanager on `logback.events` | You need an immediate message with no monitoring stack |
| Audit trail | None | A dedicated audit logger (this page) |
AOP Method Logging: Dependency
Aspects need the AOP starter. Without it the `@Aspect` class compiles and loads, but nothing is ever intercepted, and no error tells you why.
Spring AOP works through proxies, so it only intercepts calls **between Spring beans**. Calls to `this.otherMethod()` inside the same class (self-invocation), private methods and non-Spring objects are not logged.
XML
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>AOP Method Logging: The @Logged Annotation
Opt in with an annotation instead of logging every method. Keep both options **off by default**, because arguments and return values often contain passwords, tokens or personal data. Turn them on only for methods where you know the values are safe.
Java
@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
public @interface Logged {
/** Log argument values. Off by default: arguments may contain secrets or personal data. */
boolean logArgs() default false;
/** Log the return value. Off by default for the same reason. */
boolean logResult() default false;
}AOP Method Logging: The Aspect
The aspect below logs entry, exit and duration at DEBUG, and honours the annotation settings. Design points:
- **Logs under the target class**, so lines show `OrderService`, not `LoggingAspect`.
- **Skips all work** when DEBUG is disabled.
- **Uses `System.nanoTime()`** for durations, which is correct for measuring elapsed time.
- **Logs failures at DEBUG without a stack trace.** Log an exception once, where it is handled (see Global Exception Handling). Logging it here too creates duplicate entries.
- **Truncates values** so one huge argument cannot flood the log.
Avoid a second, broad pointcut such as `execution(* com.myapp.service.*Service.*(..))` alongside `@Logged`. Methods matching both get logged twice.
Java
@Aspect
@Component
public class LoggingAspect {
private static final int MAX_VALUE_LENGTH = 200;
@Around("@annotation(com.myapp.annotation.Logged) || @within(com.myapp.annotation.Logged)")
public Object logMethodCall(ProceedingJoinPoint pjp) throws Throwable {
Logger log = LoggerFactory.getLogger(pjp.getTarget().getClass());
if (!log.isDebugEnabled()) {
return pjp.proceed();
}
MethodSignature signature = (MethodSignature) pjp.getSignature();
Logged cfg = AnnotatedElementUtils.findMergedAnnotation(signature.getMethod(), Logged.class);
if (cfg == null) {
cfg = AnnotatedElementUtils.findMergedAnnotation(pjp.getTarget().getClass(), Logged.class);
}
boolean logArgs = cfg != null && cfg.logArgs();
boolean logResult = cfg != null && cfg.logResult();
String method = signature.getName();
log.debug("ENTER {}({})", method,
logArgs ? formatArgs(pjp.getArgs()) : pjp.getArgs().length + " args");
long start = System.nanoTime();
try {
Object result = pjp.proceed();
log.debug("EXIT {} returned {} in {}ms", method,
logResult ? summarize(result) : "(hidden)", elapsedMillis(start));
return result;
} catch (Throwable ex) {
log.debug("FAIL {} threw {} after {}ms", method,
ex.getClass().getSimpleName(), elapsedMillis(start));
throw ex; // rethrow; log the exception once, where it is handled
}
}
private static long elapsedMillis(long startNanos) {
return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNanos);
}
private static String formatArgs(Object[] args) {
return Arrays.stream(args)
.map(a -> a == null ? "null" : truncate(a.toString()))
.collect(Collectors.joining(", "));
}
private static String summarize(Object result) {
if (result == null) return "null";
if (result instanceof Collection<?> c) {
return result.getClass().getSimpleName() + "[" + c.size() + "]";
}
return truncate(result.toString());
}
private static String truncate(String value) {
return value.length() <= MAX_VALUE_LENGTH ? value : value.substring(0, MAX_VALUE_LENGTH) + "...";
}
}
// Usage
@Service
@Logged // all methods: timing only, no values
public class OrderService {
@Logged(logArgs = true) // this method: safe to log the arguments
public Order findById(Long id) { /* ... */ }
}Correlation IDs with MDC
A correlation ID ties together every log line produced by one request, which is what makes a busy log searchable. The filter reads an incoming `X-Correlation-Id` header (so IDs survive across services), generates one if it is missing, puts it in the **MDC** (a per-thread map that Logback can print), and returns it in the response.
**Validate the incoming value.** Accepting arbitrary header text lets a caller inject line breaks or fake log entries.
If you use Micrometer Tracing, `traceId` and `spanId` are already put in the MDC and serve the same purpose, so you may not need this filter.
MDC is thread-local. Work handed to another thread (`@Async`, executors) loses it unless you propagate it with a `TaskDecorator`.
Java
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class CorrelationIdFilter extends OncePerRequestFilter {
public static final String HEADER = "X-Correlation-Id";
public static final String MDC_KEY = "correlationId";
private static final Pattern VALID_ID = Pattern.compile("[A-Za-z0-9-]{8,64}");
@Override
protected void doFilterInternal(HttpServletRequest request,
HttpServletResponse response,
FilterChain chain) throws ServletException, IOException {
String id = request.getHeader(HEADER);
if (id == null || !VALID_ID.matcher(id).matches()) {
id = UUID.randomUUID().toString();
}
MDC.put(MDC_KEY, id);
response.setHeader(HEADER, id);
try {
chain.doFilter(request, response);
} finally {
MDC.remove(MDC_KEY); // threads are reused; always clean up
}
}
}Printing the Correlation ID
Add the MDC value to the log pattern. `%X{correlationId:-}` prints the value, or nothing when it is absent (for example during startup).
yaml
# application.yml
logging:
pattern:
level: "%5p [%X{correlationId:-}]"HTTP Request Logging Filter
This filter logs one line per request: method, path, status and duration. It deliberately **does not log bodies, headers or query strings**, which routinely carry passwords, tokens and personal data.
Design points:
- **No response wrapper.** The status is available from the normal response, and `ContentCachingResponseWrapper` buffers the whole body in memory, which breaks streaming, server-sent events and large downloads.
- **Skip logic in `shouldNotFilter`**, the standard place for exclusions.
- **Level by outcome:** 5xx at WARN, 4xx at INFO, success at DEBUG, so error traffic stands out.
- **Order:** it runs after `CorrelationIdFilter`, so the ID is already in the MDC.
If you only need this, the Tomcat access log (`server.tomcat.accesslog.enabled=true`) does the same job with no code.
Java
@Component
@Order(Ordered.HIGHEST_PRECEDENCE + 10)
public class HttpLoggingFilter extends OncePerRequestFilter {
private static final Logger log = LoggerFactory.getLogger(HttpLoggingFilter.class);
private static final Set<String> EXCLUDED_PATHS = Set.of(
"/actuator/health", "/actuator/info", "/favicon.ico");
@Override
protected boolean shouldNotFilter(HttpServletRequest request) {
String path = request.getRequestURI();
return EXCLUDED_PATHS.contains(path) || path.startsWith("/actuator/health/");
}
@Override
protected void doFilterInternal(HttpServletRequest request,
HttpServletResponse response,
FilterChain chain) throws ServletException, IOException {
long start = System.nanoTime();
try {
chain.doFilter(request, response);
} finally {
long ms = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
int status = response.getStatus();
if (status >= 500) {
log.warn("HTTP {} {} -> {} {}ms", request.getMethod(), request.getRequestURI(), status, ms);
} else if (status >= 400) {
log.info("HTTP {} {} -> {} {}ms", request.getMethod(), request.getRequestURI(), status, ms);
} else {
log.debug("HTTP {} {} -> {} {}ms", request.getMethod(), request.getRequestURI(), status, ms);
}
}
}
}Logging Request Bodies (Development Only)
When you really need to see payloads while debugging, use Spring's `CommonsRequestLoggingFilter` instead of writing your own, and register it **only in a dev profile**. It logs at DEBUG, so it also needs the log level raised for its class.
Never enable payload logging in production. Bodies contain credentials, tokens and personal data, and log files usually have wider access and longer retention than the database.
Java
@Configuration
@Profile("dev")
public class DevRequestLoggingConfig {
@Bean
CommonsRequestLoggingFilter requestLoggingFilter() {
CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter();
filter.setIncludeQueryString(true);
filter.setIncludePayload(true);
filter.setMaxPayloadLength(1000);
filter.setIncludeHeaders(false);
return filter;
}
}
# application-dev.yml
logging:
level:
org.springframework.web.filter.CommonsRequestLoggingFilter: DEBUGCustom Logback Appender: Java Class
A custom appender sends log events somewhere else: a webhook, queue or database. This one posts ERROR events to Slack. The key rule is that **an appender runs on the thread that logged**, so anything slow in `append()` slows the application.
This version avoids the usual traps:
- **Non-blocking.** It uses `HttpClient.sendAsync`, so the logging thread never waits on the network.
- **Rate-limited.** One alert per interval, so an error storm cannot flood the channel or hit Slack's limits.
- **Loop guard.** A thread-local flag stops it from re-entering itself if sending produces another log event.
- **No channel setting.** Modern Slack incoming webhooks are bound to one channel and ignore a `channel` override.
- **Message only.** It sends the logger name and a truncated message, never stack traces, which can contain sensitive data.
The appender is created by Logback, not Spring, so it cannot use `@Autowired` beans. Configure it through setters from `logback-spring.xml`.
For real alerting, an Alertmanager rule on `logback.events` is usually better than a webhook appender, because it handles grouping, silencing and escalation.
Java
public class SlackAlertAppender extends AppenderBase<ILoggingEvent> {
private static final ThreadLocal<Boolean> SENDING = ThreadLocal.withInitial(() -> false);
private final ObjectMapper mapper = new ObjectMapper();
private final AtomicLong lastSent = new AtomicLong(0);
private HttpClient client;
private String webhookUrl;
private String appName = "app";
private long minIntervalMillis = 60_000;
// Called by Logback from the XML configuration
public void setWebhookUrl(String webhookUrl) { this.webhookUrl = webhookUrl; }
public void setAppName(String appName) { this.appName = appName; }
public void setMinIntervalMillis(long millis) { this.minIntervalMillis = millis; }
@Override
public void start() {
if (webhookUrl == null || webhookUrl.isBlank()) {
addError("webhookUrl is required; Slack appender not started");
return;
}
client = HttpClient.newBuilder().connectTimeout(Duration.ofSeconds(3)).build();
super.start();
}
@Override
protected void append(ILoggingEvent event) {
if (SENDING.get()) {
return; // loop guard
}
long now = System.currentTimeMillis();
long last = lastSent.get();
if (now - last < minIntervalMillis || !lastSent.compareAndSet(last, now)) {
return; // rate limit
}
SENDING.set(true);
try {
String text = ":rotating_light: *" + appName + "* ERROR in `" + event.getLoggerName() + "`\n"
+ truncate(event.getFormattedMessage(), 500);
String json = mapper.writeValueAsString(Map.of("text", text));
HttpRequest request = HttpRequest.newBuilder(URI.create(webhookUrl))
.timeout(Duration.ofSeconds(5))
.header("Content-Type", "application/json")
.POST(HttpRequest.BodyPublishers.ofString(json))
.build();
client.sendAsync(request, HttpResponse.BodyHandlers.discarding())
.exceptionally(ex -> {
addWarn("Slack alert failed: " + ex.getMessage());
return null;
});
} catch (Exception ex) {
addWarn("Could not build Slack alert: " + ex.getMessage());
} finally {
SENDING.remove();
}
}
private static String truncate(String s, int max) {
return s.length() <= max ? s : s.substring(0, max) + "...";
}
}Custom Logback Appender: logback-spring.xml
Use **`logback-spring.xml`**, not `logback.xml`. Only the `-spring` variant supports `<springProfile>` and `<springProperty>`.
Points that often go wrong:
- `${spring:spring.application.name}` is not valid Logback syntax. Use `<springProperty>` to expose a Spring property as a Logback variable.
- `CONSOLE` is not defined automatically in a custom file. Include Boot's `defaults.xml` and `console-appender.xml` to get it.
- `${SLACK_WEBHOOK_URL:-}` gives an empty default when the variable is missing, so the appender refuses to start with a clear error instead of using a bogus URL.
- The appender is attached only in the `prod` profile.
XML
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
<springProperty scope="context" name="appName"
source="spring.application.name" defaultValue="app"/>
<springProfile name="prod">
<appender name="SLACK" class="com.myapp.logging.SlackAlertAppender">
<webhookUrl>${SLACK_WEBHOOK_URL:-}</webhookUrl>
<appName>${appName}</appName>
<minIntervalMillis>60000</minIntervalMillis>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>ERROR</level>
</filter>
</appender>
</springProfile>
<root level="INFO">
<appender-ref ref="CONSOLE"/>
<springProfile name="prod">
<appender-ref ref="SLACK"/>
</springProfile>
</root>
</configuration>Metrics from Logs: Use the Built-in logback.events
Spring Boot already registers Micrometer's `LogbackMetrics`, which counts log events by level as `logback.events` with a `level` tag. You do not need a custom `TurboFilter` to count errors and warnings. A hand-written one also has drawbacks: it runs for every logging call, counts events even when the logger level would discard them, and can recurse if creating a meter logs something.
Expose the metric through Actuator, then alert on it. In Prometheus, the counter is named `logback_events_total`.
yaml
# application.yml
management:
endpoints:
web:
exposure:
include: health,info,metrics,prometheus
# Check it:
# GET /actuator/metrics/logback.events?tag=level:error
# Prometheus alert rule (PromQL):
# increase(logback_events_total{level="error"}[5m]) > 10Business Event Metrics Next to Log Lines
For events that matter to the business (logins, payments), record a counter **and** write one log line. Rules for both:
- **Keep tag values bounded** (a fixed set like `success`, `bad_credentials`). Never tag by email, user ID or request ID, because each unique value creates a new time series and can exhaust memory.
- **Don't log personal data** such as email addresses on every attempt. They are personal data in your logs, and because they are user-supplied they allow log injection with line breaks. Log a stable internal ID where you must, or just the outcome.
- Don't log and metric the same thing in more places than needed.
Java
@Service
public class AuthenticationService {
private static final Logger log = LoggerFactory.getLogger(AuthenticationService.class);
private final MeterRegistry meterRegistry;
public AuthenticationService(MeterRegistry meterRegistry) {
this.meterRegistry = meterRegistry;
}
public AuthResponse login(LoginRequest request) {
try {
AuthResponse response = doLogin(request);
meterRegistry.counter("auth.login", "result", "success").increment();
return response;
} catch (BadCredentialsException ex) {
log.warn("Login failed reason=bad_credentials");
meterRegistry.counter("auth.login", "result", "failure", "reason", "bad_credentials").increment();
throw ex;
} catch (AccountLockedException ex) {
log.warn("Login blocked reason=account_locked");
meterRegistry.counter("auth.login", "result", "failure", "reason", "account_locked").increment();
throw ex;
}
}
}Audit Logging: Java
An audit log records **who did what, to what, and with what outcome**, for security investigation and compliance. Keep it separate from application logs: different retention, different readers, different sensitivity. A dedicated logger named `AUDIT` makes the routing explicit.
Design points:
- **Derive the actor from the security context**, not from a caller-supplied argument, so it cannot be forged by a bug.
- **Structured JSON**, one event per line, so it can be shipped and searched.
- **Keep `details` free of secrets and full personal data.** Record what changed (field names, IDs), not sensitive values.
- **Transactions:** if you log inside a transaction that later rolls back, the audit says something happened that did not. For mutations, record the event after commit, for example from a `@TransactionalEventListener(phase = AFTER_COMMIT)`.
- **IP address behind a proxy:** set `server.forward-headers-strategy=framework` so `request.getRemoteAddr()` reflects the real client, and never trust a raw `X-Forwarded-For` header yourself.
This is not the same as JPA auditing (`@CreatedDate`, `@LastModifiedBy`), which fills columns on entities. See the Auditing page for that.
Java
public record AuditEvent(
String action,
String actor,
String resourceType,
String resourceId,
String outcome, // SUCCESS or FAILURE
String ipAddress,
String correlationId,
Instant timestamp,
Map<String, String> details
) { }
@Component
public class AuditLogger {
// Dedicated logger name, routed to its own appender in logback-spring.xml
private static final Logger AUDIT = LoggerFactory.getLogger("AUDIT");
private static final Logger log = LoggerFactory.getLogger(AuditLogger.class);
private final ObjectMapper objectMapper;
public AuditLogger(ObjectMapper objectMapper) {
this.objectMapper = objectMapper;
}
public void record(String action, String resourceType, String resourceId,
String outcome, String ipAddress, Map<String, String> details) {
AuditEvent event = new AuditEvent(
action, currentActor(), resourceType, resourceId, outcome, ipAddress,
MDC.get(CorrelationIdFilter.MDC_KEY), Instant.now(),
details == null ? Map.of() : details);
try {
AUDIT.info(objectMapper.writeValueAsString(event));
} catch (JsonProcessingException ex) {
log.error("Failed to serialize audit event action={} resource={}/{}",
action, resourceType, resourceId, ex);
}
}
private String currentActor() {
Authentication auth = SecurityContextHolder.getContext().getAuthentication();
return (auth == null || !auth.isAuthenticated()) ? "anonymous" : auth.getName();
}
}
// Usage
auditLogger.record("USER_ROLE_CHANGED", "User", String.valueOf(userId),
"SUCCESS", clientIp, Map.of("newRole", "ADMIN"));Audit Logging: logback-spring.xml
Route the `AUDIT` logger to its own file with `additivity="false"`, so audit events never also appear in the console or application log. The encoder writes only the message, because it is already JSON.
Set retention from your actual compliance requirement. A rolling file on a server's disk is **not** a compliance archive. For anything regulated, ship audit events to central, access-controlled, tamper-evident storage (a log platform, object storage with retention locks, or a database table).
XML
<appender name="AUDIT_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>logs/audit.log</file>
<encoder>
<pattern>%m%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>logs/audit-%d{yyyy-MM-dd}.log.gz</fileNamePattern>
<maxHistory>365</maxHistory> <!-- set from your compliance requirement -->
<totalSizeCap>20GB</totalSizeCap>
</rollingPolicy>
</appender>
<logger name="AUDIT" level="INFO" additivity="false">
<appender-ref ref="AUDIT_FILE"/>
</logger>Testing Custom Logging
Spring Boot's `OutputCaptureExtension` captures console output, so you can assert that a log line was written. Raise the logger level in the test, because the aspect only logs at DEBUG.
Java
@SpringBootTest(properties = "logging.level.com.myapp=DEBUG")
@ExtendWith(OutputCaptureExtension.class)
class LoggingAspectTest {
@Autowired
private OrderService orderService; // annotated with @Logged
@Test
void loggedMethodWritesEntryAndExit(CapturedOutput output) {
orderService.findById(1L);
assertThat(output).contains("ENTER findById");
assertThat(output).contains("EXIT findById");
}
@Test
void argumentsAreHiddenByDefault(CapturedOutput output) {
orderService.create(new CreateOrderRequest("secret-note"));
assertThat(output).doesNotContain("secret-note");
}
}Troubleshooting Custom Logging
| Symptom | Usual cause | Fix |
|---|---|---|
| Aspect never logs | `spring-boot-starter-aop` missing, class isn't a Spring bean, or self-invocation | Add the starter, call through another bean, check the pointcut |
| Aspect logs nothing at all | Logger level is above DEBUG | Set `logging.level.com.myapp=DEBUG` |
| Every line shows `LoggingAspect` as the logger | Aspect uses its own logger | Use `LoggerFactory.getLogger(pjp.getTarget().getClass())` |
| Duplicate log lines | Two pointcuts match, or an appender is attached to both a logger and root | Remove the overlap; set `additivity="false"` on dedicated loggers |
| `correlationId` empty in some lines | Work ran on another thread, or code ran before the filter | Propagate MDC with a `TaskDecorator`; keep the filter at highest precedence |
| Literal `${spring:...}` in output | Invalid Logback syntax | Use `<springProperty>` in `logback-spring.xml` |
| `springProfile` or `springProperty` ignored or errors | File named `logback.xml` | Rename to `logback-spring.xml` |
| `Appender named [CONSOLE] not referenced` or missing console output | `CONSOLE` never defined | Include Boot's `defaults.xml` and `console-appender.xml` |
| Slack appender silently inactive | Webhook variable missing, so `start()` refused | Check the Logback status messages (`debug="true"` on `<configuration>`) |
| Slack flooded with alerts | No rate limit | Use `minIntervalMillis`, or alert from `logback.events` instead |
| `logback.events` metric missing | Metrics endpoint not exposed, or not using Logback | Expose `metrics`; confirm Logback is the active logging system |
| Audit entries missing | Logger name doesn't match, or level above INFO | Use exactly `AUDIT` in code and XML, level INFO |
| Response bodies broken or slow after adding a filter | Response wrapped in `ContentCachingResponseWrapper` | Don't wrap the response just to read the status |
Common Mistakes
- Logging request bodies, headers or full arguments in production.
- Logging passwords, tokens, card numbers or email addresses.
- Putting user-controlled text in logs without validation, which allows log injection.
- Doing slow or blocking work (HTTP calls, database writes) inside an appender.
- Logging the same exception at several layers. Log it once, where it is handled.
- Wrapping the response in a caching wrapper only to read the status code.
- Reimplementing `logback.events`, request logging or JSON logging that Boot already provides.
- Using unbounded values (emails, IDs, URLs with parameters) as metric tags.
- Forgetting to clear the MDC in a `finally` block on pooled threads.
- Treating a local log file as a compliance-grade audit store.
Which Approach Should You Choose?
- **See what requests are doing:** Tomcat access log or `HttpLoggingFilter`, and `http.server.requests` for metrics
- **Debug a payload locally:** `CommonsRequestLoggingFilter` in the `dev` profile only
- **Follow one request across logs:** correlation ID filter, or tracing if you already use it
- **Time and trace service methods:** `@Logged` aspect, with arguments off unless safe
- **Count errors and alert:** `logback.events` with Prometheus and Alertmanager
- **Send a quick error alert with no monitoring stack:** the rate-limited async Slack appender
- **Record who did what:** dedicated audit logger, shipped to central storage