[HikariCP][ASM] JDBC 쿼리 로깅하기(ProxyConnection)

 

ProxyConnection

ProxyConnection은 java.sql.connection 인터페이스를 구현한 프록시 클래스이다.

 

그럼 실제 Connection을 하는 객체는?

Springboot 등에서 실제 Connection 구현체는 사용하는 데이터베이스와 JDBC Driver에 따라 달라진다.

예를 들어, MySQL을 사용한다면 com.mysql.cj.jdbc.ConnectionImpl이 될 수 있으며, PostgreSQL을 사용한다면 org.postgresql.jdbc.PgConnection이 될 수도 있다.

 

스프링 부트는 자동 구성(DataSource를 생성하는 기본 로직과 유사하게)을 통해 데이터 소스를 설정하고, 애플리케이션에서 사용하는 구체적인 JDBC 드라이버에 맞는 Connection 구현체를 사용하게 된다.

 

HikariProxyConnection의 역할과 분리 이유

 

HikariProxyConnection은 ProxyConnection을 상속받아, HikariCP 연결 풀에 특화된 추가적인 기능이나 최적화를 제공한다. ProxyConnection이 일반적인 프록시 로직을 제공한다면, HikariProxyConnection은 HikariCP가 제공하는 특정 기능(예: 메트릭 수집, 연결 상태 검사, 커스텀 로직 통합)을 위한 확장 포인트를 제공한다.

 

따라서, 이번 로깅 프로젝트는 ProxyConnection에 진행할 것이다.

이는 Hikari Database 인스턴스를 구동한 환경에서는

1. 해당 추상 클래스를 상속받은 구현체가 존재한다면 로깅이 가능하기 때문이고, (반대로 이야기한다면, 여기 로깅하지 않으면 상속받은 구현체를 추적하는 것은 불가능하다.)

2. 기본적으로 HikariProxyConnection 객체 역시 super.return 등의 상속 클래스 호출이 잦기 때문이다.

 

 

로깅 포인트

고수준 JDBC 구현체에서 사용되는 PreparedStatement의 SQL 값을 로깅하는 것이 나의 목표이다.

이 경우 SQL 쿼리가 실제로 생성되고 실행되는 지점을 고려해야 한다.

 

이전 내용에서 보았듯, executeQuery(String sql)은 이번 로깅의 성격과 맞지 않는다.

하지만 넓은 의미로 사용할 수 있으니 로깅 포인트로 추가하기는 할 것이다.

 

HikariProxyConnection 객체에서 로깅을 잡을만한 메서드는 다음과 같다.

 

1. createStatement() 메서드

 

createStatement() 메서드는 데이터베이스에 대한 일반적인 SQL 문(예: SELECT, UPDATE, DELETE, INSERT)을 실행하기 위한 Statement 객체를 생성한다. 이 객체는 SQL 문자열을 인자로 받지 않으며, 실행할 SQL 문은 Statement 객체의 executeQuery(String sql), executeUpdate(String sql) 등의 메서드를 통해 지정된다.

 

Statement statement = connection.createStatement();
ResultSet rs = statement.executeQuery("SELECT * FROM users");

 

statement는 일반적인 sql 쿼리를 실행하는데 사용된다. 매개변수를 전달할 수도 없고 실행할 때마다 컴파일을 하게된다.

따라서 성능적인 면에서 안좋을 수 밖에 없고, 유연하지 못하다.

그래서 대부분의 statement 구문은 DDL문(create, alter, drop …)에서 주로 사용된다.

 

 

prepareStatement(String sql) 메서드들

SQL 쿼리 실행을 위한 PreparedStatement 객체를 생성한다. 이 객체는 SQL 문 내에 파라미터를 동적으로 바인딩할 수 있게 해, SQL 인젝션 공격을 방지하고(?파라미터에 값을 넣어야 하니..) 성능을 향상시킨다.

 

쉽게 말하면 Statement()와 달리 준비된 구문을 사용한다. (statement를 확장한다)

미리 컴파일을 되어 준비하기 때문에 statement에 비해 우위가 있으며, 매개변수 값만을 변환한다.

 

String sql = "UPDATE classTable SET name = ?, phone = ?, address = ?";
PreparedStatement ps = conn.prepareStatement(sql);
ps.setString(1, "이름");
ps.setString(2, "010-1234-5678");
ps.setString(3, "서울시 강서구");
ResultSet rs = ps.executeQuerey();

//이런 식으로, sql 구문을 파싱할 수 있다. (?파라미터가 붙어 있긴 하지만)

 

prepareCall(String sql) 메서드들

저장 프로시저 호출을 위한 CallableStatement 객체를 생성한다.

이 객체는 PrepareStatement의 확장이며, DB에 저장된 프로시저를 호출하는 로직이다.

 

*저장 프로시저 : SQL 쿼리와 프로그래밍 로직(조건문, 반복문 등)을 결합하여 데이터베이스에 저장된 실행 가능한 코드 블록

 

CallableStatement cstmt = connection.prepareCall("{call getUserById(?)}");
cstmt.setInt(1, 10); // '10'은 사용자 ID 파라미터
ResultSet rs = cstmt.executeQuery();

 

 

 

 

실제 코드

Premain 및 transfrom 내부 구문은 생략한다.

해당 코드들은  HikariProxyConnection 바이트코드를 Accept하는 ClassNode 값을 input으로 받는다.

 

1. HikariProxyConnection 내부 Method 탐색

package org.sch.asm_tree_api.code.hikari;

import org.objectweb.asm.tree.*;
import org.sch.asm_tree_api.LoggerUtil;

import static org.sch.asm_tree_api.code.util.GetInputParamInMethods.findInputParameter;

/**
 * ProxyConnection 객체 내부 탐색 후 , prepareStatement / prepareCall /createStatement 구문에 로깅 진행
 * 이 클래스들은 PSTMT 생성 및 SQL 쿼리에 관련된다.
 */
public class AddLoggerHikariProxyConnection {
    public static void apply(ClassNode cn) {
        for (MethodNode mn : cn.methods) {
            switch (mn.name) { //특정 method에 변조 작업 진행
                //현재는 동일하게 동작하나, 추후 세분화에 따라 모듈화 필요 가능성이 있어 분리하였음.
                case "prepareStatement" -> {setPrepareStatement(cn, mn);}
                case "prepareCall" -> {setPrepareCall(cn, mn);}
                case "createStatement" -> {setCreateStatement(cn,mn);}
                default -> {} //pass
            }
        }
    }

    public static void setPrepareStatement(ClassNode cn, MethodNode mn){
            InsnList il = new InsnList();
            int loggerIndex = LoggerUtil.loggerInstanceInit(cn, mn, il);
            LoggerUtil.sendLogString(il, loggerIndex, "setPrepareStatement 동작 : " + mn.name, LoggerUtil.LogType.info);
            findInputParameter(cn, mn, il); //입력 변수 로깅
            mn.instructions.insert(il);
    }

    public static void setPrepareCall(ClassNode cn, MethodNode mn){
        InsnList il = new InsnList();
        int loggerIndex = LoggerUtil.loggerInstanceInit(cn, mn, il);
        LoggerUtil.sendLogString(il, loggerIndex, "setPrepareCall 동작 : " + mn.name, LoggerUtil.LogType.info);
        findInputParameter(cn, mn, il); //입력 변수 로깅
        mn.instructions.insert(il);
    }

    public static void setCreateStatement(ClassNode cn, MethodNode mn){
        InsnList il = new InsnList();
        int loggerIndex = LoggerUtil.loggerInstanceInit(cn, mn, il);
        LoggerUtil.sendLogString(il, loggerIndex, "setCreateStatement 동작 : " + mn.name, LoggerUtil.LogType.info);
        findInputParameter(cn, mn, il); //입력 변수 로깅
        mn.instructions.insert(il);
    }




}

 

 

2. 메서드 내부 값 파싱(findInputParamteter)

 

원래는 같은 input parameter의 다른 내용들도 파싱하고자 하였으나, 이 값이 현실적으로 불필요하며 유지보수 상 문제가 있다고 판단하여(Hikari 구현체에서 내부 method 코드를 변경한다면, 이 로직도 같이 변경해야 한다.) 제외하였다.

 

(*정확히 말하자면 바이트코드 단에서 입력 파라미터 변수의 특정 명칭을 알기 힘들기에, 이 로직은 불필요하다 판단하였다.)

하지만 아래의 코드에서는 일단 다른 변수값까지 파싱하는 내용을 담았으니 참고할 것.

 

package org.sch.asm_tree_api.code.util;

import lombok.extern.slf4j.Slf4j;
import org.objectweb.asm.Opcodes;
import org.objectweb.asm.Type;
import org.objectweb.asm.tree.*;
import org.sch.asm_tree_api.LoggerUtil;

import java.util.Arrays;

import static org.objectweb.asm.Opcodes.*;

/**
 * Method 내부의 입력 파라미터 관련 로직
 */
@Slf4j
public class GetInputParamInMethods {

    //메서드 내부에 입력 파라미터가 있다면 로그로 뽑아내기
    public static void findInputParameter(ClassNode cn, MethodNode mn, InsnList il) {
        Type[] argumentTypes = Type.getArgumentTypes(mn.desc); // 파라미터 타입 가져오기
        if (argumentTypes.length == 0) return; //입력 파라미터가 없다면 스킵

        boolean isStatic = (mn.access & ACC_STATIC) != 0; //Static 메서드 체크
        int localIndex = isStatic ? 0 : 1; //정적 변수의 경우 지역변수 인덱스가 0부터 시작
        int loggerIndex = LoggerUtil.loggerInstanceInit(cn, mn, il); //로깅 인스턴스 생성

        for (Type argumentType : argumentTypes) {
            String content = "입력 파라미터 타입(argumentType) : " + argumentType + " 지역 변수 인덱스(localIdx) : " + localIndex;
            LoggerUtil.sendLogString(il, loggerIndex, content, LoggerUtil.LogType.warn);

            switch (argumentType.toString()) {
                case "Ljava/lang/String;" -> {
                    il.add(new VarInsnNode(Opcodes.ALOAD, loggerIndex));    // 로거 객체 스택에 저장
                    il.add(new VarInsnNode(Opcodes.ALOAD, localIndex));     //내 지역 변수 인덱스에서 값을 받아서 스택에 저장
                    il.add(new MethodInsnNode(INVOKEINTERFACE, "org/slf4j/Logger", "warn", "(Ljava/lang/String;)V", true)); // 로그 메서드 호출
                }
                case "I" -> {
                    il.add(new VarInsnNode(Opcodes.ALOAD, loggerIndex));    // 로거 객체 스택에 저장
                    il.add(new VarInsnNode(Opcodes.ILOAD, localIndex));     //내 지역 변수 인덱스에서 값을 받아서 스택에 저장
                    //String.valueOf() 호출
                    il.add(new MethodInsnNode(INVOKESTATIC, "java/lang/String", "valueOf", "(I)Ljava/lang/String;", false));
                    il.add(new MethodInsnNode(INVOKEINTERFACE, "org/slf4j/Logger", "warn", "(Ljava/lang/String;)V", true)); // 로그 메서드 호출
                }
                case "[I", "[Ljava/lang/String;" -> {
                    il.add(new VarInsnNode(Opcodes.ALOAD, loggerIndex));    // 로거 객체 스택에 저장
                    il.add(new VarInsnNode(Opcodes.ALOAD, localIndex));     //내 지역 변수 인덱스에서 값을 받아서 스택에 저장
                    //Arrays.toString() 호출
                    il.add(new MethodInsnNode(INVOKESTATIC, "java/util/Arrays", "toString", "([I)Ljava/lang/String;", false));
                    il.add(new MethodInsnNode(INVOKEINTERFACE, "org/slf4j/Logger", "warn", "(Ljava/lang/String;)V", true)); // 로그 메서드 호출
                }
                default -> {
                    log.warn("[INFO][{}]{} Class {} Method 내부 지역변수 argumentType이 다음과 같아 무시됨 : {}",
                            GetInputParamInMethods.class.getName(), cn.name, mn.name, argumentType.toString());
                }
            }

            localIndex += argumentType.getSize(); //지역 변수 인덱스
        }
    }
}

 

결과

 

 

2024-03-05T16:18:28.171+09:00  WARN 18352 --- [           main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2024-03-05T16:18:28.406+09:00  INFO 18352 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port 8080 (http) with context path ''
2024-03-05T16:18:28.414+09:00  INFO 18352 --- [           main] c.d.jdbcserver.JdbcServerApplication     : Started JdbcServerApplication in 3.143 seconds (process running for 3.757)
2024-03-05T16:18:30.621+09:00  INFO 18352 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-03-05T16:18:30.621+09:00  INFO 18352 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2024-03-05T16:18:30.622+09:00  INFO 18352 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
Hibernate: insert into sql_dummy (etc,send_time) values (?,?)
2024-03-05T16:18:30.659+09:00  INFO 18352 --- [nio-8080-exec-1] c.z.hikari.pool.HikariProxyConnection    : setPrepareStatement 동작 : prepareStatement
2024-03-05T16:18:30.660+09:00  WARN 18352 --- [nio-8080-exec-1] c.z.hikari.pool.HikariProxyConnection    : insert into sql_dummy (etc,send_time) values (?,?)
Hibernate: delete from sql_dummy where etc like replace(?,'\\','\\\\')
2024-03-05T16:18:30.711+09:00  INFO 18352 --- [nio-8080-exec-1] c.z.hikari.pool.HikariProxyConnection    : setPrepareStatement 동작 : prepareStatement
2024-03-05T16:18:30.711+09:00  WARN 18352 --- [nio-8080-exec-1] c.z.hikari.pool.HikariProxyConnection    : delete from sql_dummy where etc like replace(?,'\\','\\\\')

 

쿼리 실행시 내 바이트코드 변조에 의해, Hibernate가 파싱하는 값과 같은 값을 로깅하는 것을 확인할 수 있다.

이것을 이제 gRPC 등으로 Collector에 전송하면 호출 로그를 만들 수 있을 것이다.