Debug Spring trên production: từ lỗi khởi động tới endpoint chậm

Đọc từ dưới lên, tìm dòng Caused by cuối cùng. Lỗi khởi động của Spring luôn là một chuỗi exception lồng nhau, và nguyên nhân thật nằm ở đáy.

1. Bài toán: pod restart liên tục sau khi deploy

kubectl logs shop-app-7f9c -p     # -p: log của lần chạy trước (đã chết)

***************************
APPLICATION FAILED TO START
***************************
Description:
Parameter 1 of constructor in com.shop.order.OrderService required a bean
of type 'com.shop.payment.PaymentClient' that could not be found.

Action:
Consider defining a bean of type 'com.shop.payment.PaymentClient' in your configuration.

2. Vấn đề

• Local chạy được, production không: khác profile, khác biến môi trường, khác classpath.
• Stack trace dài hàng trăm dòng, người mới đọc từ trên xuống và lạc.
• Không thể gắn debugger vào production. Phải dựa vào log, Actuator, metrics.

3. Giải pháp: phân loại lỗi rồi dùng đúng công cụ

4. Code từng bước

Bước 1: Các lỗi khởi động hay gặp

// a) Thiếu bean: PaymentClient có @ConditionalOnProperty mà prod thiếu property
@Bean
@ConditionalOnProperty(name = "shop.payment.enabled", havingValue = "true")
PaymentClient paymentClient() { ... }

// b) Circular dependency (Boot 2.6+ mặc định cấm)
@Service class OrderService   { OrderService(ProductService p) {...} }
@Service class ProductService { ProductService(OrderService o) {...} }

The dependencies of some of the beans in the application context form a cycle:
┌─────┐
|  orderService defined in file [OrderService.class]
↑     ↓
|  productService defined in file [ProductService.class]
└─────┘

Cách sửa đúng là tách vòng: tách phần dùng chung ra service thứ ba, hoặc dùng event (bài 4.1.7). spring.main.allow-circular-references=true hay @Lazy chỉ là băng dán.

Bước 2: Conditions report. Muốn biết vì sao auto-config (bài 4.1.4) không chạy:

java -jar shop-app.jar --debug
# hoặc: logging.level.org.springframework.boot.autoconfigure=DEBUG

============================
CONDITIONS EVALUATION REPORT
============================
Negative matches:
-----------------
   RedisAutoConfiguration:
      Did not match:
         - @ConditionalOnClass did not find required class
           'org.springframework.data.redis.core.RedisOperations'

--debug chỉ bật debug cho core loggers, không làm app chậm như --trace.

Bước 3: Soi app đang chạy bằng Actuator (port 8081 nội bộ, bài 4.1.9)

management:
  endpoints:
    web:
      exposure:
        include: health,info,prometheus,beans,env,configprops,loggers,conditions

# Bean này có tồn tại không, class thật là gì (proxy?), phụ thuộc gì?
curl -s localhost:8081/actuator/beans | jq '.contexts[].beans.orderService'
{ "scope":"singleton",
  "type":"com.shop.order.OrderService$$SpringCGLIB$$0",
  "dependencies":["orderRepository","productService","meterRegistry"] }

# Property lấy giá trị từ nguồn nào?
curl -s localhost:8081/actuator/env/spring.datasource.url
{ "property": { "source":"systemEnvironment", "value":"jdbc:postgresql://db-prod:5432/shop" } }

Bước 4: Đổi log level lúc runtime, không restart

curl -X POST localhost:8081/actuator/loggers/com.shop.order \
     -H "Content-Type: application/json" -d '{"configuredLevel":"DEBUG"}'

curl localhost:8081/actuator/loggers/com.shop.order
{"configuredLevel":"DEBUG","effectiveLevel":"DEBUG"}

# xong nhớ trả lại
curl -X POST localhost:8081/actuator/loggers/com.shop.order \
     -H "Content-Type: application/json" -d '{"configuredLevel":null}'

Lưu ý: chỉ đổi trên một pod mà bạn gọi tới. 3 pod thì phải gọi cả 3 (hoặc dùng Spring Cloud Bus / config tập trung).

5. Cách hoạt động: quy trình khi app không start

Pod CrashLoopBackOff
     |
kubectl logs -p  → tìm "APPLICATION FAILED TO START" / Caused by cuối
     |
     +-- "required a bean ... could not be found"
     |       → bean có điều kiện? profile? package ngoài @ComponentScan?
     |       → chạy --debug, đọc Negative matches
     |
     +-- "form a cycle"            → tách vòng phụ thuộc
     |
     +-- "Failed to bind properties" / "Could not resolve placeholder"
     |       → thiếu env var, sai kiểu (ví dụ "30s" cho int)
     |
     +-- "Failed to configure a DataSource" / Connection refused
     |       → sai URL, secret, network policy
     |
     +-- "Port 8080 was already in use"   → chủ yếu ở local

6. So sánh công cụ

7. Khi nào nên / không nên

• Nên: chuẩn bị sẵn từ trước khi có sự cố: Actuator nội bộ, log có traceId, dashboard metrics.
• Không nên: SSH vào pod sửa file, hay bật DEBUG toàn bộ root logger trên prod.

Đi từ rộng tới hẹp: metrics để biết có chậm thật không và chậm khi nào, trace để biết chậm ở bước nào, thread dump nếu thread đang kẹt.

1. Metrics   : p99 của /orders tăng lúc nào? cùng lúc với gì?
2. Trace     : request chậm đó tốn thời gian ở span nào?
3. Nguồn lực : hikari pending? GC? thread pool đầy?
4. Thread dump: thread đang chờ cái gì?

Bước 1: Metric có sẵn

# p99 latency theo uri (PromQL)
histogram_quantile(0.99,
  sum by (le, uri) (rate(http_server_requests_seconds_bucket{uri="/orders"}[5m])))

# DB pool có cạn không?
hikaricp_connections_pending{pool="HikariPool-1"}

Cần bật histogram: management.metrics.distribution.percentiles-histogram.http.server.requests=true.

Bước 2: Tracing với Micrometer Tracing (Boot 3 thay Spring Cloud Sleuth):

<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-exporter-otlp</artifactId>
</dependency>

management:
  tracing:
    sampling:
      probability: 0.1     # 10% request, đừng để 1.0 trên prod tải cao

Trace 4bf92f35...  POST /orders   5.2s
├─ OrderService.createOrder        5.1s
│  ├─ ProductService.findById      0.02s
│  ├─ SELECT product ... FOR UPDATE 4.8s   ← chờ lock dòng sản phẩm hot
│  └─ INSERT orders                 0.03s
└─ serialize response               0.01s

Bước 3: Thread dump khi đang chậm: curl localhost:8081/actuator/threaddump (hoặc jstack). Nhiều thread http-nio-* cùng WAITING ở HikariPool.getConnection nghĩa là pool cạn.

Chi tiết hơn về DB lock, N+1, tối ưu query xem chương Spring Data JPA.

Có: MDC (Mapped Diagnostic Context). Nó là một Map gắn với thread hiện tại; logger tự in các giá trị trong MDC ra mọi dòng log.

Nếu đã bật Micrometer Tracing như trên, Boot 3 tự đưa traceId, spanId vào MDC. Chỉ cần thêm vào pattern:

logging:
  pattern:
    level: "%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]"

Muốn thêm thông tin nghiệp vụ (userId) thì tự viết filter:

@Component
public class MdcUserFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res,
                                    FilterChain chain) throws ServletException, IOException {
        try {
            String user = req.getUserPrincipal() != null ? req.getUserPrincipal().getName() : "anonymous";
            MDC.put("userId", user);
            chain.doFilter(req, res);
        } finally {
            MDC.remove("userId");      // thread quay về pool, phải dọn
        }
    }
}

INFO [shop-app,4bf92f35,a1b2] userId=alice  OrderController : POST /orders
INFO [shop-app,4bf92f35,c3d4] userId=alice  OrderService    : reserve stock productId=7
ERROR[shop-app,4bf92f35,c3d4] userId=alice  OrderService    : Insufficient stock

Kibana: traceId:"4bf92f35"  → ra đúng 3 dòng, dù nằm ở pod nào

Bẫy: MDC là ThreadLocal. Sang @Async (bài 4.1.7) là mất, trừ khi cấu hình TaskDecorator copy MDC, hoặc dùng context propagation của Micrometer. Và luôn remove trong finally, nếu không request sau dùng lại thread sẽ mang userId của người trước.

Bạn nghĩ đúng hướng: lúc sự cố mà mới sửa config rồi deploy lại thì vừa chậm vừa có thể làm mất trạng thái lỗi. Thực tế hay làm thế này:

• Bật sẵn loggers, beans, conditions, configprops, env nhưng chỉ trên management port nội bộ + role OPS (bài 4.1.9).
• env, configprops giữ show-values: never (mặc định Boot 3) hoặc when-authorized.
• heapdump, shutdown tắt hẳn; cần heap dump thì dùng jcmd trong pod theo quy trình có kiểm soát.

management:
  endpoint:
    env:
      show-values: when-authorized
      roles: OPS
    heapdump:
      enabled: false

Q1. App Spring Boot không khởi động được trên production, bạn xử lý thế nào?

🇻🇳 Tiếng Việt:

Tôi đọc log của lần chạy trước, tìm phần "APPLICATION FAILED TO START" và Caused by cuối cùng. Thường gặp: thiếu bean do điều kiện hoặc profile, circular dependency, thiếu property hoặc biến môi trường, không kết nối được DB. Nếu nghi auto-configuration thì chạy với --debug để xem conditions report. So sánh profile và env giữa local và production.

🇬🇧 English:

I read the logs from the previous run and look for "APPLICATION FAILED TO START" and the last Caused by. Common causes are a missing bean due to a condition or profile, a circular dependency, a missing property or environment variable, or a database that cannot be reached. If I suspect auto-configuration, I run with --debug to see the conditions report, and I compare profiles and environment between local and production.

Q2. Một endpoint chậm thất thường trên production, bạn tìm nguyên nhân thế nào?

🇻🇳 Tiếng Việt:

Bắt đầu bằng metrics: p99 của http.server.requests theo uri, so với Hikari pending, GC, CPU để thấy tương quan. Sau đó xem distributed trace của request chậm để biết span nào tốn thời gian. Nếu thread đang kẹt thì lấy thread dump. Khi cần thêm chi tiết thì tạm nâng log level qua /actuator/loggers mà không restart, xong thì trả lại.

🇬🇧 English:

I start with metrics: the p99 of http.server.requests for that URI, correlated with Hikari pending connections, GC and CPU. Then I look at distributed traces of slow requests to find the slow span. If threads seem stuck, I take a thread dump. When I need more detail, I raise the log level temporarily through /actuator/loggers without a restart, and reset it afterwards.

Q3. MDC là gì, dùng để làm gì?

🇻🇳 Tiếng Việt:

MDC là map theo thread mà logging framework in kèm mọi dòng log. Dùng để gắn traceId, userId vào log, nhờ đó lọc được toàn bộ log của một request dù chạy trên nhiều pod. Vì dựa trên ThreadLocal nên phải dọn trong finally và phải truyền sang thread khác khi dùng async.

🇬🇧 English:

MDC is a per-thread map that the logging framework prints with every log line. We use it to attach a trace ID or user ID, so we can filter all logs of one request across many pods. Because it is ThreadLocal-based, it must be cleared in a finally block and propagated explicitly to async threads.

Cách nhớ ngắn gọn

• Không start: đọc Caused by cuối, --debug cho auto-config.
• Soi context đang chạy: /beans, /env, /conditions.
• Cần log ngay: /loggers, nhớ trả lại.
• Chậm: metrics → trace → thread dump.
• Gom log: traceId trong MDC.