Spring Core & Boot/Mini-challenge: trace 1 request từ main() và log mọi bean tạo
32/41
Bài 32 / 41~30 phútSpring Boot & Auto-configurationMiễn phí lượt xem

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:#fef3c7

Mỗ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 BeanPostProcessor log mỗi bean instantiate.
  • Bean của bạn (@Component user-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:

  1. Filter capture request, gen correlation ID, set MDC.
  2. DispatcherServlet route đến OrderController.getOrder(id).
  3. Controller call service.findById(id).
  4. Service call repository.queryById(id).
  5. Repository return Order từ in-memory map.
  6. Service map OrderOrderDto.
  7. Controller wrap OrderDto thành ResponseEntity.
  8. 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

ConceptBàiDùng ở đây
@SpringBootApplicationSpring Boot là gìEntry point
Starter web + actuatorStarter & BOMHTTP server + health
Auto-configEnable autoconfigurationTomcat, Jackson tự setup
application.ymlPropertySource & bindingLogging pattern, port
Logging + MDCStructured loggingCorrelation ID per request
BeanPostProcessorBean lifecycle phasesHook log bean instantiate
@Component/@Service/@RepositoryStereotypes & component scan3 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 ý

💡 Gợi ý — đọc khi bị kẹt

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

✅ Sau khi implement xong, chạy như sau

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: TRACEapplication-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

Tự kiểm tra
Q1
Log 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.

Q2
Correlation 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.

Q3
BeanPostProcessor 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

Đặt 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