Write a Servlet Filter that logs request method/URI and elapsed time, and explain the before/after structure.
answer
- Pre-processing before chain.doFilter; post after
- Wrap chain.doFilter in try/finally to always log
- Read getStatus() AFTER delegating
- Register outermost (HIGHEST_PRECEDENCE) to see raw req + final status
- Use nanoTime for elapsed; clear MDC in finally
basics
~20 sImplement Filter.doFilter: record the start time, call chain.doFilter to run the rest of the chain, then in a finally block compute elapsed time and log the method, URI, and duration. The code before the call is pre-processing; the code after is post-processing.
solid answer
~40 sYou implement jakarta.servlet.Filter and override doFilter(request, response, chain). The body has three parts that mirror the chain's nested structure: pre-processing before chain.doFilter (capture the start time, maybe a correlation id), the delegation call chain.doFilter(request, response) which runs all downstream filters and the servlet synchronously, and post-processing after it returns (compute elapsed time, read the final status, log). Wrap the delegation in try/finally so the logging happens even if downstream throws. Cast to HttpServletRequest/HttpServletResponse to read the method, URI, and status. Register it with explicit order (FilterRegistrationBean.setOrder or @Order) so it sits outermost and sees the untouched request and final response. This is the canonical before/after hook that the Chain of Responsibility nesting gives you for free.
go deeper
Can place start-time before and logging after chain.doFilter and call chain.doFilter once.
Writes a correct filter with try/finally, casts to HTTP types, reads status after delegation, and registers it with explicit order.
Adds robustness: MDC/thread-local cleanup in finally, nanoTime, secret redaction, and reasons about response wrappers when the body is needed.
Considers observability strategy holistically (correlation ids, sampling, cost of response wrapping, where filters vs. interceptors vs. tracing agents belong).
### Goal Write a filter that logs, for every HTTP request, the method (GET/POST…), the URI, the response status, and how long the whole downstream processing took. This is a textbook cross-cutting concern and a perfect fit for a filter. ### The before/after structure Recall the nesting: when your filter calls `chain.doFilter(request, response)`, **all** downstream filters and the target servlet run *inside* that single synchronous call, and control returns to you only after they finish. Therefore a filter naturally has two hook points: - **Pre-processing**: the code **before** `chain.doFilter` — runs on the way *in*. - **Post-processing**: the code **after** `chain.doFilter` — runs on the way *out* (the unwind). For timing, you capture the start time in pre-processing and compute elapsed time in post-processing. Because downstream may throw, you wrap the delegation in **`try { ... } finally { ... }`** so you always log. ### Key terms - **`Filter`** (`jakarta.servlet.Filter`): the interceptor interface with `doFilter` (and default no-op `init`/`destroy`). - **`FilterChain`**: the handle to the rest of the chain; `chain.doFilter` advances it. - **`HttpServletRequest` / `HttpServletResponse`**: HTTP-specific subtypes you cast to in order to read method/URI/status. - **`FilterRegistrationBean`**: Spring Boot registration object that lets you set URL patterns and an explicit order. ### The code ```java import jakarta.servlet.*; import jakarta.servlet.http.*; import java.io.IOException; public class RequestLoggingFilter implements Filter { private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(RequestLoggingFilter.class); @Override public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) throws IOException, ServletException { HttpServletRequest httpReq = (HttpServletRequest) req; HttpServletResponse httpRes = (HttpServletResponse) res; long start = System.nanoTime(); // pre-processing try { chain.doFilter(req, res); // run the rest of the chain + servlet } finally { // post-processing (always runs) long ms = (System.nanoTime() - start) / 1_000_000; log.info("{} {} -> {} ({} ms)", httpReq.getMethod(), httpReq.getRequestURI(), httpRes.getStatus(), ms); } } } ``` Registration in Spring Boot, placing it outermost: ```java @Bean FilterRegistrationBean<RequestLoggingFilter> loggingFilter() { var bean = new FilterRegistrationBean<>(new RequestLoggingFilter()); bean.addUrlPatterns("/*"); bean.setOrder(Ordered.HIGHEST_PRECEDENCE); // runs first → sees raw request, final status return bean; } ``` ### Why each piece is the way it is - **`finally`**: guarantees the log line even when a downstream handler throws — otherwise you would silently lose error timings. - **`getStatus()` after the call**: the status is only meaningful *after* downstream set it; reading it in pre-processing would log a default. - **`HIGHEST_PRECEDENCE`**: the outermost filter sees the request before any other filter mutates it and the response after every other filter is done — the right vantage point for logging. - **`nanoTime`** (not `currentTimeMillis`): monotonic, intended for elapsed-time measurement, immune to clock adjustments. ### Variations / pitfalls - If you need the **response body** length you cannot read it after the buffer is flushed; you would wrap the response in a `ContentCachingResponseWrapper`-style wrapper (Spring) — but that adds cost. - Do **not** log secrets (auth headers, tokens). Sanitize. - If you put MDC (logging context) values in pre-processing, **clear them in the `finally`** so threads in a pool do not leak context across requests. This filter is a minimal but complete Chain-of-Responsibility handler: it does work on the way in, delegates, and does work on the way out, without ever short-circuiting.
- Why wrap chain.doFilter in try/finally?So the post-processing (logging, MDC cleanup) runs even when a downstream filter or the servlet throws; otherwise error cases are never logged and thread-locals leak.
- Why read response.getStatus() after the call rather than before?Downstream handlers set the status while processing; before delegating the status is still the default (often 200), so it would be wrong.
saying these in an interview costs you the question
- Logging status before chain.doFilter (it isn't set yet)
- Forgetting finally, so errors skip the log
- Using currentTimeMillis for elapsed timing
- Not clearing thread-local/MDC context, leaking across pooled threads
- Logging secret headers