Spring Boot/Mini-challenge: trace 1 request từ main() và log mọi bean tạo
~30 phútSpring Boot FoundationsMiễn phí

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:#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
@SpringBootApplicationModule 02 bài 01Entry point
Starter web + actuatorModule 02 bài 02HTTP server + health
Auto-configModule 02 bài 03Tomcat, Jackson tự setup
application.ymlModule 02 bài 04Logging pattern, port
Logging + MDCModule 02 bài 06Correlation ID per request
BeanPostProcessorModule 01 bài 04Hook log bean instantiate
@Component/@Service/@RepositoryModule 01 bài 063 layer bean
@RestControllerModule 01 bài 03HTTP 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.

✨ Đ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...