Mini-challenge: trace 1 request từ main() và log mọi bean tạo
Bài thực hành khép lại Module 02 — 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.
Module 02 đã 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 để see chạm tay toàn bộ vòng đời từ main() → request → response.
Sau bài này, bạn:
- Có 1 Boot app làm sample reference cho Module 03+ 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 | Module 02 bài 01 | Entry point |
Starter web + actuator | Module 02 bài 02 | HTTP server + health |
| Auto-config | Module 02 bài 03 | Tomcat, Jackson tự setup |
application.yml | Module 02 bài 04 | Logging pattern, port |
| Logging + MDC | Module 02 bài 06 | Correlation ID per request |
BeanPostProcessor | Module 01 bài 04 | Hook log bean instantiate |
@Component/@Service/@Repository | Module 01 bài 06 | 3 layer bean |
@RestController | Module 01 bài 03 | 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.
✨ Đ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 — Module 03+ sẽ extend nó: thêm validation, OpenAPI, exception handler, security, JPA, test. Mỗi module là 1 layer thêm vào codebase này.
Chúc mừng — bạn đã hoàn thành Module 02! Bạn đã hiểu Spring Boot ở mức bytecode: 5 trụ cột, starter, autoconfig, config, profile, logging. Module 03 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 khoá) 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?
Bình luận (0)
Đang tải...