LY Corporation Tech Blog

Quảng bá công nghệ và văn hoá phát triển hỗ trợ cho các dịch vụ cung cấp bởi LY Corporation và LY Corporation Group (LINE Plus, LINE Taiwan, LINE Vietnam).

Xử lý ứng dụng Springboot khởi động lỗi do không tương thích với Logback level

Spring framework đã và đang là một trong những sự lựa chọn hàng đầu cho các ứng dụng doanh nghiệp triển khai bằng ngôn ngữ Java bởi tính ổn định cùng với sự hỗ trợ lớn từ phía cộng đồng.

Spring có các module riêng biệt được kiểm thử cẩn thận, nổi bật có thể kể đến như:

  • Spring Boot cung cấp bản cài đặt minimal, cho phép lập trình viên đơn giản hoá việc cấu hình để có thể khởi chạy ứng dụng.
  • Spring JPA đơn giản hoá việc tương tác với database, ngoài ra hỗ trợ out-of-the-box việc xử lý transaction.
  • Spring Web cho phép lập trình viên có thể tạo một ứng dụng web theo mô hình MVC hay RESTFul một cách dễ dàng.
  • Spring Security là một framework bảo mật mạnh mẽ và có thể tùy chỉnh cao, cung cấp các giải pháp toàn diện cho xác thực và kiểm soát quyền truy cập trong các ứng dụng Spring.

Tuy vậy, trong quá trình làm việc với các framework này, đôi lúc chúng ta không tránh khỏi những vấn đề tưởng chừng như không ngờ tới.

Dưới đây là một vấn đề tôi đã gặp phải khi sử dụng module JPA.

Tìm hiểu vấn đề

Ở trong ứng dụng SpringBoot, việc tương tác với query phần lớn đều thông qua JPA (cụ thể là module spring-boot-starter-data-jpa ) trong đó Hibernate là một triển khai phổ biến. 

Spring framework cho phép lập trình viên có nhiều cách để có thể viết được các câu query của mình, ví dụ như:

  • Dùng JPQL để khai báo câu query
@Query("SELECT u FROM User u WHERE u.email = :email")
User findByEmail(@Param("email") String email);
  • Dùng Native sql query
@Query(value = "SELECT * FROM users WHERE email = :email", nativeQuery = true)
User findByEmailNative(@Param("email") String email);
List<User> findByLastNameAndFirstName(String lastName, String firstName);
  • Ngoài ra Spring còn cho phép sử dụng các phương pháp tạo query một cách type safe như dùng Criteria API/Specification
CriteriaBuilder cb = entityManager.getCriteriaBuilder();
CriteriaQuery<User> cq = cb.createQuery(User.class);
Root<User> user = cq.from(User.class);
cq.select(user).where(cb.equal(user.get("email"), email));
TypedQuery<User> query = entityManager.createQuery(cq);
return query.getSingleResult();
  • Và tất nhiên, chúng ta có thể  dùng JdbcTemplate để chạy các statement như bên dưới
@Repository
@RequiredArgsConstructor
public class UserRepository {
 
    private final JdbcTemplate jdbcTemplate;
 
    public List<User> findAll() {
        return jdbcTemplate.query(
            "SELECT id, name, email FROM users",
            (rs, rowNum) -> new User(rs.getLong("id"), rs.getString("name"), rs.getString("email"))
        );
    }
}

Vấn đề gặp phải

Để kiểm tra các câu query đã viết chính xác hay chưa, tôi dự định sẽ in ra các câu lệnh SQL khi JPA method khởi chạy.

Set logback sang level DEBUG, nhưng khi khởi động ứng dụng thì xuất hiện log lỗi như

Caused by: java.lang.IllegalArgumentException: Validation failed for query for method public abstract long com.linecorp.ai.qna.repository.AnswerRepository.countSearchAnswerByProfileIdList(java.util.List,java.lang.String)
...
Caused by: java.util.UnknownFormatConversionException: Conversion = '''

Trong đó, phương thức countSearchAnswerByProfileIdList được cài đặt như sau
SQL

@Query(value = "SELECT COUNT(a) FROM Answer a WHERE a.isHide = false AND a.profileId IN :profileIdList AND a.content LIKE %:keyword%")
long countSearchAnswerByProfileIdList(@Param("profileIdList") List<Long> profileIdList, @Param("keyword") String keyword);

Nhìn sơ qua câu lệnh thì có vẻ không có gì sai cả, trong khi đây là nội dung PR liên quan

Rõ ràng chỉ mỗi dòng thay đổi level log mà khiến ứng dụng bị lỗi.

Chúng ta hãy đi sâu vào phân tích để tìm hiểu vì sao chỉ với dòng code tưởng chừng vô hại lại gây ra vấn đề lớn như thế nhé.

Quá trình điều tra

Dựa trên những kết quả thu thập được ban đầu, tôi đã tiến hành điều tra theo các bước như sau:

1. Tái hiện vấn đề

Viết một test case để gọi đến method lỗi
Debug

1
2
3
4
5
6
7
8
9
10
11

@SpringBootTest
@ActiveProfiles("alpha")
public class QueryVerificationTest {
    @Autowired
    private AnswerRepository answerRepository;
 
    @Test
    void verifyQuery() {
        answerRepository.countSearchAnswerByProfileIdList(List.of(1L), "keyword"); // Set break-point here
    }
}

Do chương trình bị crash ngay, báo lỗi việc không thể khởi tạo được bean Repository chứa phương thức bị lỗi nên breakpoint không được xử lý.

Conditional breakpoint

Dựa vào trace log, thì method cuối cùng được gọi là phương thức `QueryExecutorMethodInterceptor#lookupQuery`.
Đây là lúc chúng ta tận dụng tính năng Breakpoint có điều kiện  của IDE trong IntelliJ.

Hãy set điều kiện của phương thức nếu query của chúng ta tên là  `countSearchAnswerByProfileIdList`.

2. Phân tích dữ liệu debug

Thường thì tôi hay dùng bút chì/notes app để note lại những thông tin quan trọng như phương thức, các giá trị của biến để dễ lần ra hơn.

Dưới đây là tổng kết trace, sau khi đơn giản hoá và tập trung vào những phương thức chính.

Các giá trị được debug ra như sau

- loggerClassName = org.jboss.logging.DelegatingBasicLogger
- format = HQL : SELECT COUNT(a) FROM Answer a WHERE a.isHide = false AND a.profileId IN :profileIdList AND a.content LIKE CONCAT('%',:keyword,'%')
- parameters = empty object array (length = 0)

Ở đây, dừng lại ở hàm #debugf(), chúng ta hãy đi sâu vào tìm hiểu method này được triển khai như thế nào.

if (isEnabled(level)) {
    final String text = parameters == null ? String.format(format) : String.format(format, parameters);
    doLog(logger, loggerClassName, translate(level), text, thrown);
}

Với log level DEBUG →  isEnable(level) cho ra kết quả TRUE.
Với parameters == null →  trigger method String#format cho chuỗi chứa ký tự %  không tham số → Đây chính là nguyên nhân gây ra lỗi.

Các bạn có thể thử lại với test case để mô phỏng lại lỗi này

@Test
public void checkInvalidQuery() {
    assertThrows(UnknownFormatConversionException.class, () -> {
        var format = "HQL : SELECT COUNT(a) FROM Answer a WHERE a.isHide = false AND a.profileId IN :profileIdList AND a.content LIKE CONCAT('%',:keyword,'%')";
        var out = String.format(format);
    });
}

3. Kiểm tra lại ở các phần xử lý tương tự (Parallel checking)

Mở rộng cách thức query được xử lý thì các trường hợp sau cũng sẽ xảy ra lỗi tương tự nếu như câu query

  • Sử dụng positional parameter 
@Query(value = "SELECT COUNT(a) FROM Answer a.content LIKE %?1%")
long countAnswerHaving(String keyword);
  • Sử dụng named parameter 
@Query("select u from User u where u.lastname like %:#{[0]}% and u.lastname like %:lastname%")
List<User> findByLastnameWithSpelExpression(@Param("lastname") String lastname);
  • Dùng CONCAT 
@Query(value = "SELECT COUNT(a) FROM Answer a WHERE a.isHide = false AND a.profileId IN :profileIdList AND a.content LIKE CONCAT('%',:keyword,'%'")
long countSearchAnswerByProfileIdList(@Param("profileIdList") List<Long> profileIdList, @Param("keyword") String keyword);

Đề xuất các phương án xử lý

Sau khi đã tìm ra nguyên nhân và hiểu được lý do thì chúng ta có các phương án xử lý sau, tuỳ thuộc vào yêu cầu của bài toán:

  • Biện pháp thay thế:  Do query có chứa %  nên thay vào đó, sẽ dùng Query creation hay CriteriaBuilder để build query

Lưu ý: Cách này sẽ khá tốn thời gian vì cần viết lại các câu query.
Chưa kể nếu gặp các câu query dài và phức tạp thì việc chuyển sang dùng Specification cũng tiềm ẩn nhiều rủi ro phát sinh lỗi.

long countByProfileIdInAndContentContains(@Param("profileIdList") List<Long> profileIdList, @Param("keyword") String keyword)
  • Sửa chữa lỗi : Vấn đề này được Spring fix ở version V6.2.6, tương đương với bản Boot 3.1.2

Do đó, chúng ta có các cách xử lý sau:

  1. Nâng cấp Spring Boot version (bản 3.1.2 or cao hơn) 
    Cách này có ưu điểm là: Nhanh, đơn giản, sự thay đổi các thư viện đồng bộ. Tuy nhiên các bạn cần check qua release note để kiểm tra các dependency khác có update hay không để tiến hành chạy lại test nhé.
    plugins {
        id 'org.springframework.boot' version '3.1.2'
    }
  2. Nâng cấp thư viện org.hibernate.orm độc lập.
    Cách này về mặt lý thuyết thì ổn nhưng thực tế thì không khuyến khích. Vì khi nâng cấp hibernate thì các thư viện phụ thuộc cũng sẽ cần nâng cấp theo,
    hơn nữa sẽ xuất hiện sự không đồng bộ của các package sử dụng thư viện org.hibernate.orm , điều này sẽ chứa nhiều rủi ro hơn.
  • Tránh gặp lỗi: Không logging hoặc thay đổi log level chỉ cho package org.hibernate.orm 
    Có các cách sau có thể cân nhắc, gồm: 
  1. Không set log level debug cho toàn dự án;
  2. Vẫn set log level nhưng với package bị lỗi thì không set log level DEBUG để tránh sự cố này.
logging:
  level:
    root: DEBUG
    org.hibernate.orm.query.hql: INFO

Bài học kinh nghiệm rút ra

Sự cố này sẽ xảy ra nếu như ứng dụng của các bạn có các điều kiện sau

  • Dùng Springboot version 3.1.1 hoặc bản thấp hơn (tương đương dùng package org.hibernate version 6.2.5 hoặc bản thấp hơn) và;
  • Sử dụng @SQL annotation để viết câu query có chứa ký tự % và;
  • Log level của dự án hoặc của package org.hibernate đang để DEBUG hoặc thấp hơn;

Các bước thứ tự tôi đã thực hiện khi gặp lỗi:

  • Phát hiện lỗi
  • Tái hiện lỗi
  • Điều tra lỗi
  • Xử lý lỗi

Hi vọng những thông tin tôi chia sẻ trong bài viết sẽ giúp ích, nếu các bạn gặp vấn đề này.