Mini-challenge: trace 1 request từ main() và log mọi bean tạo
Bài thực hành khép lại phần Spring Boot Foundations — build 1 Boot app nhỏ, instrument logging để trace toàn bộ vòng đời: từ main(), bean nào tạo theo thứ tự, request đi qua filter chain, controller, service, response. Output là 1 sequence diagram thực tế từ log.
TL;DR: Bài thực hành khép module: build một Boot app 3 layer rồi instrument logging để nhìn thấy vòng đời thực tế — BeanPostProcessor log thứ tự mọi bean được tạo lúc startup, MDC gắn correlation ID theo từng request qua Controller, Service, Repository. Output cuối là một sequence diagram vẽ từ log thật, không phải từ tài liệu. Dành ~30 phút, có starter code và test workflow từng bước.
Phần Spring Boot Foundations đã bóc 6 thứ: Spring Boot trụ cột, starter, auto-config, externalized config, profile, logging. Bài cuối này không thêm khái niệm — bạn build 1 Boot app, instrument logging để sờ tận tay toàn bộ vòng đời: từ main(), qua request, đến response.
Sau bài này, bạn:
- Có 1 Boot app làm sample reference cho course Spring REST & Data tiếp theo.
- Hiểu thứ tự bean instantiate qua log thực tế.
- Vẽ được sequence diagram 1 HTTP request từ Tomcat connector → controller → service → response — bằng chứng từ log, không phải lý thuyết.
- Có template để debug startup + request flow trong production.
🎯 Đề bài
Build 1 Boot 3.4 app với 4 yêu cầu:
1. Setup project
- Boot 3.4.x + Java 21 + Maven.
- Starter:
spring-boot-starter-web,spring-boot-starter-actuator. - 1 endpoint:
GET /api/orders/\{id\}trảOrderDto. - Cấu trúc package:
com.olhub.demo(root) →controller,service,repository.
2. 4 layer + log
flowchart LR
Req[HTTP Request]
F["LoggingFilter<br/>(custom Filter)"]
C["OrderController<br/>(@RestController)"]
S["OrderService<br/>(@Service)"]
R["OrderRepository<br/>(@Repository - in-memory)"]
Res[HTTP Response]
Req --> F --> C --> S --> R --> S --> C --> F --> Res
style F fill:#fef3c7Mỗi layer log:
- Entry: thời điểm request đến + parameter.
- Exit: thời điểm trả về + duration.
- Bao gồm correlation ID (MDC) để trace cross-layer.
3. Trace startup
Log mọi bean tạo theo thứ tự:
- Tự build
BeanPostProcessorlog mỗi bean instantiate. - Bean của bạn (
@Componentuser-defined): log đầy đủ. - Bean Spring infrastructure: log compact (chỉ tên, không detail).
4. Output
App chạy mvn spring-boot:run, gửi request curl http://localhost:8080/api/orders/42, log console show:
[STARTUP]
...
10:00:00.123 [main] INFO CustomBeanLogger : Created bean: orderRepository (com.olhub.demo.repository.OrderRepository)
10:00:00.456 [main] INFO CustomBeanLogger : Created bean: orderService (com.olhub.demo.service.OrderService)
10:00:00.789 [main] INFO CustomBeanLogger : Created bean: orderController (com.olhub.demo.controller.OrderController)
10:00:01.012 [main] INFO com.olhub.demo.App : Started App in 1.234 seconds
[REQUEST]
10:00:05.001 [http-nio-8080-exec-1] INFO [a1b2c3] LoggingFilter : >>> GET /api/orders/42
10:00:05.005 [http-nio-8080-exec-1] INFO [a1b2c3] OrderController : getOrder(42)
10:00:05.007 [http-nio-8080-exec-1] INFO [a1b2c3] OrderService : findById(42)
10:00:05.008 [http-nio-8080-exec-1] DEBUG [a1b2c3] OrderRepository : queryById(42)
10:00:05.012 [http-nio-8080-exec-1] INFO [a1b2c3] OrderRepository : found Order#42 in 4ms
10:00:05.013 [http-nio-8080-exec-1] INFO [a1b2c3] OrderService : returned OrderDto in 6ms
10:00:05.015 [http-nio-8080-exec-1] INFO [a1b2c3] OrderController : 200 OK in 10ms
10:00:05.016 [http-nio-8080-exec-1] INFO [a1b2c3] LoggingFilter : <<< 200 in 15ms
[a1b2c3] là correlation ID từ MDC — trace toàn request.
🔍 Phân tích I-P-O
Input: HTTP GET request đến endpoint.
Processing:
- Filter capture request, gen correlation ID, set MDC.
- DispatcherServlet route đến
OrderController.getOrder(id). - Controller call
service.findById(id). - Service call
repository.queryById(id). - Repository return
Ordertừ in-memory map. - Service map
Order→OrderDto. - Controller wrap
OrderDtothànhResponseEntity. - Filter clear MDC, log response.
Output: JSON OrderDto + log console show toàn bộ flow với correlation ID.
📦 Concept dùng trong bài
| Concept | Bài | Dùng ở đây |
|---|---|---|
@SpringBootApplication | Spring Boot là gì | Entry point |
Starter web + actuator | Starter & BOM | HTTP server + health |
| Auto-config | Enable autoconfiguration | Tomcat, Jackson tự setup |
application.yml | PropertySource & binding | Logging pattern, port |
| Logging + MDC | Structured logging | Correlation ID per request |
BeanPostProcessor | Bean lifecycle phases | Hook log bean instantiate |
@Component/@Service/@Repository | Stereotypes & component scan | 3 layer bean |
@RestController | (course Spring REST & Data) | HTTP endpoint |
▶️ Starter code
Cấu trúc project:
demo/
├── pom.xml
└── src/main/
├── java/com/olhub/demo/
│ ├── App.java
│ ├── config/
│ │ ├── LoggingFilter.java
│ │ └── BeanCreationLogger.java
│ ├── controller/
│ │ └── OrderController.java
│ ├── service/
│ │ └── OrderService.java
│ ├── repository/
│ │ └── OrderRepository.java
│ └── model/
│ ├── Order.java
│ └── OrderDto.java
└── resources/
└── application.yml
pom.xml:
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.4.0</version>
</parent>
<groupId>com.olhub</groupId>
<artifactId>demo</artifactId>
<version>1.0.0</version>
<properties>
<java.version>21</java.version>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
<optional>true</optional>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
Dành 30 phút tự build. Hint ở dưới khi kẹt.
💡 Gợi ý
App.java — entry point:
package com.olhub.demo;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
@SpringBootApplication
public class App {
public static void main(String[] args) {
SpringApplication.run(App.class, args);
}
}
Order.java — domain (record):
package com.olhub.demo.model;
import java.math.BigDecimal;
public record Order(Long id, String customer, BigDecimal total) {}
OrderDto.java — response DTO:
package com.olhub.demo.model;
import java.math.BigDecimal;
public record OrderDto(Long id, String customer, BigDecimal total) {
public static OrderDto from(Order o) {
return new OrderDto(o.id(), o.customer(), o.total());
}
}
OrderRepository.java — in-memory data:
package com.olhub.demo.repository;
import com.olhub.demo.model.Order;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Repository;
import java.math.BigDecimal;
import java.util.Map;
import java.util.Optional;
@Slf4j
@Repository
public class OrderRepository {
private final Map<Long, Order> data = Map.of(
42L, new Order(42L, "Alice", new BigDecimal("99.99")),
43L, new Order(43L, "Bob", new BigDecimal("149.50"))
);
public Optional<Order> queryById(Long id) {
long start = System.currentTimeMillis();
log.debug("queryById({})", id);
Optional<Order> result = Optional.ofNullable(data.get(id));
long elapsed = System.currentTimeMillis() - start;
result.ifPresent(o -> log.info("found Order#{} in {}ms", o.id(), elapsed));
return result;
}
}
OrderService.java:
package com.olhub.demo.service;
import com.olhub.demo.model.OrderDto;
import com.olhub.demo.repository.OrderRepository;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;
import java.util.Optional;
@Slf4j
@Service
public class OrderService {
private final OrderRepository repo;
public OrderService(OrderRepository repo) {
this.repo = repo;
}
public Optional<OrderDto> findById(Long id) {
long start = System.currentTimeMillis();
log.info("findById({})", id);
Optional<OrderDto> dto = repo.queryById(id).map(OrderDto::from);
long elapsed = System.currentTimeMillis() - start;
log.info("returned OrderDto in {}ms", elapsed);
return dto;
}
}
OrderController.java:
package com.olhub.demo.controller;
import com.olhub.demo.model.OrderDto;
import com.olhub.demo.service.OrderService;
import lombok.extern.slf4j.Slf4j;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
@Slf4j
@RestController
@RequestMapping("/api/orders")
public class OrderController {
private final OrderService service;
public OrderController(OrderService service) {
this.service = service;
}
@GetMapping("/{id}")
public ResponseEntity<OrderDto> getOrder(@PathVariable Long id) {
long start = System.currentTimeMillis();
log.info("getOrder({})", id);
ResponseEntity<OrderDto> response = service.findById(id)
.map(ResponseEntity::ok)
.orElseGet(() -> ResponseEntity.notFound().build());
long elapsed = System.currentTimeMillis() - start;
log.info("{} in {}ms", response.getStatusCode().value(), elapsed);
return response;
}
}
LoggingFilter.java — capture request + MDC:
package com.olhub.demo.config;
import jakarta.servlet.*;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import java.io.IOException;
import java.util.UUID;
@Slf4j
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class LoggingFilter implements Filter {
@Override
public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
throws IOException, ServletException {
HttpServletRequest httpReq = (HttpServletRequest) req;
HttpServletResponse httpRes = (HttpServletResponse) res;
String requestId = httpReq.getHeader("X-Request-Id");
if (requestId == null) {
requestId = UUID.randomUUID().toString().substring(0, 8);
}
long start = System.currentTimeMillis();
try (MDC.MDCCloseable mdc = MDC.putCloseable("requestId", requestId)) {
log.info(">>> {} {}", httpReq.getMethod(), httpReq.getRequestURI());
httpRes.setHeader("X-Request-Id", requestId);
chain.doFilter(req, res);
long elapsed = System.currentTimeMillis() - start;
log.info("<<< {} in {}ms", httpRes.getStatus(), elapsed);
}
}
}
BeanCreationLogger.java — log mọi bean tạo:
package com.olhub.demo.config;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.BeansException;
import org.springframework.beans.factory.config.BeanPostProcessor;
import org.springframework.stereotype.Component;
@Slf4j
@Component
public class BeanCreationLogger implements BeanPostProcessor {
private static final String APP_PACKAGE = "com.olhub.demo";
@Override
public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
String className = bean.getClass().getName();
if (className.startsWith(APP_PACKAGE)) {
log.info("Created bean: {} ({})", beanName, className);
}
// Bo qua bean infrastructure cua Spring/Boot
return bean;
}
}
application.yml:
server:
port: 8080
spring:
application:
name: trace-demo
logging:
level:
root: INFO
com.olhub.demo: DEBUG
com.olhub.demo.config.BeanCreationLogger: INFO
pattern:
console: "%d{HH:mm:ss.SSS} [%thread] %-5level [%X{requestId:-no-req}] %logger{30} : %msg%n"
management:
endpoints:
web:
exposure:
include: health, info, beans, conditions, mappings, loggers
✅ Test workflow
Build + run:
mvn spring-boot:run
Output startup (rút gọn):
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.4.0)
10:00:00.123 [main] INFO [no-req] com.olhub.demo.App : Starting App using Java 21
10:00:01.234 [main] INFO [no-req] com.olhub.demo.config.BeanCreationLogger : Created bean: loggingFilter (com.olhub.demo.config.LoggingFilter)
10:00:01.456 [main] INFO [no-req] com.olhub.demo.config.BeanCreationLogger : Created bean: orderRepository (com.olhub.demo.repository.OrderRepository)
10:00:01.567 [main] INFO [no-req] com.olhub.demo.config.BeanCreationLogger : Created bean: orderService (com.olhub.demo.service.OrderService)
10:00:01.678 [main] INFO [no-req] com.olhub.demo.config.BeanCreationLogger : Created bean: orderController (com.olhub.demo.controller.OrderController)
10:00:01.890 [main] INFO [no-req] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port 8080
10:00:02.001 [main] INFO [no-req] com.olhub.demo.App : Started App in 1.987 seconds
Send request:
curl -v http://localhost:8080/api/orders/42
Output request:
10:00:05.001 [http-nio-8080-exec-1] INFO [a1b2c3] LoggingFilter : >>> GET /api/orders/42
10:00:05.005 [http-nio-8080-exec-1] INFO [a1b2c3] OrderController : getOrder(42)
10:00:05.007 [http-nio-8080-exec-1] INFO [a1b2c3] OrderService : findById(42)
10:00:05.008 [http-nio-8080-exec-1] DEBUG [a1b2c3] OrderRepository : queryById(42)
10:00:05.012 [http-nio-8080-exec-1] INFO [a1b2c3] OrderRepository : found Order#42 in 4ms
10:00:05.013 [http-nio-8080-exec-1] INFO [a1b2c3] OrderService : returned OrderDto in 6ms
10:00:05.015 [http-nio-8080-exec-1] INFO [a1b2c3] OrderController : 200 in 10ms
10:00:05.016 [http-nio-8080-exec-1] INFO [a1b2c3] LoggingFilter : <<< 200 in 15ms
Send request với custom requestId:
curl -H "X-Request-Id: my-trace-123" http://localhost:8080/api/orders/42
→ MDC sẽ dùng my-trace-123 thay UUID generate.
Test 404:
curl -v http://localhost:8080/api/orders/999
→ Response 404, log show 404 in Xms.
🎓 Mở rộng
Mức 1 — Trace startup time:
Thêm @EventListener(ApplicationReadyEvent.class) log "App ready in N ms", measure từ main() đến ready.
Mức 2 — Inspect autoconfig:
Curl /actuator/conditions thấy autoconfig nào active. Đếm số autoconfig pass vs skip.
Mức 3 — Dynamic log level:
# Bat DEBUG cho OrderService runtime
curl -X POST http://localhost:8080/actuator/loggers/com.olhub.demo.service.OrderService \
-H "Content-Type: application/json" \
-d '{"configuredLevel": "TRACE"}'
→ Log thay đổi ngay lập tức không restart.
Mức 4 — Structured logging:
Đổi pattern sang JSON Boot 3.4:
logging:
structured:
format:
console: ecs
→ Log thành JSON ECS, parse được bởi ELK/Loki.
Mức 5 — Profile-specific logging:
Tạo application-dev.yml với logging.level.com.olhub.demo: TRACE và application-prod.yml với WARN. Run với --spring.profiles.active=dev vs prod, so sánh log output.
Mức 6 — @RestControllerAdvice cho global error:
@RestControllerAdvice
public class ErrorHandler {
@ExceptionHandler(Exception.class)
public ResponseEntity<Map<String, Object>> handle(Exception e) {
log.error("Unhandled error", e);
return ResponseEntity.status(500).body(Map.of("error", e.getMessage()));
}
}
→ Mọi exception trong controller được catch + log + trả 500 đẹp.
🤔 Tự kiểm tra
Q1Log startup cho thấy bean được tạo theo thứ tự repository, rồi service, rồi controller — dù bạn không khai báo thứ tự ở đâu cả. Cơ chế nào quyết định thứ tự này?▸
Container resolve theo dependency graph: controller phụ thuộc service, service phụ thuộc repository, nên để instantiate controller, Spring phải tạo service trước, và muốn có service thì phải tạo repository trước nữa — kết quả là một topological sort của đồ thị phụ thuộc.
Đây chính là cơ chế bạn đã tự code trong mini-challenge mini-IoC ở Module 02. Điểm hay của bài này là bạn nhìn thấy nó trong log thật, không phải tin vào lý thuyết.
Lưu ý: giữa các bean không phụ thuộc nhau, thứ tự không được đảm bảo — đừng viết code dựa vào thứ tự tạo bean, trừ khi dùng @DependsOn hoặc @Order có chủ đích.
Q2Correlation ID được set vào MDC ở filter, nhưng mọi log trong Service và Repository đều in ra đúng ID đó — dù bạn không truyền ID qua tham số method nào. Vì sao điều này hoạt động, và khi nào nó sẽ vỡ?▸
MDC lưu trên ThreadLocal: filter set ID vào MDC của thread đang xử lý request, và vì toàn bộ Controller, Service, Repository chạy trên cùng thread đó (mô hình thread-per-request của Tomcat), mọi log statement đọc được cùng giá trị.
Nó sẽ vỡ khi xử lý nhảy sang thread khác: @Async, CompletableFuture với executor riêng — thread mới có MDC rỗng, log mất correlation ID.
Khi cần async, fix bằng TaskDecorator copy MDC sang thread mới, hoặc Micrometer Context Propagation. Đây cùng gốc cơ chế với pitfall ThreadLocal bạn đã gặp ở bài request scope.
Q3BeanPostProcessor của bạn log được mọi bean — nghĩa là nó phải được tạo trước tất cả bean khác. Spring làm điều đó bằng cách nào, và điều này gợi ý gì về giới hạn của chính BeanPostProcessor?▸
Trong refresh(), bước registerBeanPostProcessors chạy trước finishBeanFactoryInitialization (bước tạo các singleton thường) — Spring tách riêng pha khởi tạo hạ tầng và pha khởi tạo bean ứng dụng.
Giới hạn suy ra từ đó: những bean được tạo trước hoặc cùng pha với BeanPostProcessor (các BFPP, BPP khác, bean mà BPP của bạn phụ thuộc) sẽ không đi qua callback của bạn — log sẽ thiếu chúng. Spring còn in warning "is not eligible for getting processed" cho trường hợp này.
Vậy nên nếu log thiếu vài bean hạ tầng, đó không phải bug — đó là thứ tự pha trong refresh() mà bạn đã học ở bài refresh lifecycle.
✨ Điều bạn vừa làm được
Hoàn thành mini-challenge này, bạn đã:
- Build Boot app từ scratch với 3 layer chuẩn (Controller → Service → Repository).
- Trace startup: log mọi bean tạo qua
BeanPostProcessor. Thấy thứ tự thực tế (repository trước service trước controller — topological sort). - Trace request: correlation ID qua MDC, log từng layer entry/exit với duration.
- Đo Boot 5 trụ cột vào practice: starter (web + actuator), autoconfig (Tomcat tự start), externalized config (
application.yml), profile (extension), logging stack (Logback + MDC). - Có template debug production: pattern này deploy được — chỉ cần thêm Spring Security cho
/actuator/loggers, structured logging ECS cho ELK ingest.
App này là starter template — các course sau sẽ extend nó: thêm validation, OpenAPI, exception handler, security, JPA, test. Mỗi course là 1 layer thêm vào codebase này.
Chúc mừng — bạn đã hoàn thành course Spring Core! Bạn đã hiểu Spring Boot ở mức bytecode: 5 trụ cột, starter, autoconfig, config, profile, logging. Course Spring REST & Data sẽ chính thức bước vào Web layer: Spring MVC architecture, DispatcherServlet, @RestController đầy đủ, validation, exception handling, OpenAPI/Swagger. Đây là lúc TaskFlow domain (capstone xuyên suốt track) bắt đầu — bạn sẽ build REST API CRUD đầu tiên.
Bài này có giúp bạn hiểu bản chất không?
Hỏi đáp về bài này
Chưa có câu hỏi
Có gì chưa rõ trong bài? Đặt câu hỏi đầu tiên — câu trả lời từ cộng đồng giúp bạn (và người sau).
Đặt câu hỏi đầu tiên