[P6Spy] p6spy 설정 시 두 번 찍히는 경우

p6spy 설정 후 쿼리는 잘 찍히는데, 두 번씩 찍히는 문제가 생겼습니다.

Connection ID 가 다르니.. 두 번찍히는게 분명합니다.

24-02-01 23:03:378 [http-nio-7000-exec-2] DEBUG              org.hibernate.SQL.logStatement [ 144 line ] [ ThreadId-119 ] - insert into users (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
24-02-01 23:03:379 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [1] as [TIMESTAMP] - [2024-02-01T23:03:31.343042800]
24-02-01 23:03:381 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [2] as [VARCHAR] - [admin]
24-02-01 23:03:382 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [3] as [TIMESTAMP] - [2024-02-01T23:03:31.343042800]
24-02-01 23:03:382 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [4] as [VARCHAR] - [admin]
24-02-01 23:03:383 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [5] as [VARCHAR] - [test@naver.com]
24-02-01 23:03:383 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [6] as [VARCHAR] - [$2a$10$XGfAOKzfhDz7N6bkfBjpXOA5t7skfsieH.Za1BLAQzjcK7Kd9zfAW]
24-02-01 23:03:383 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [7] as [VARCHAR] - [test]
24-02-01 23:03:384 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [8] as [VARCHAR] - [테스트]
24-02-01 23:03:384 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [9] as [VARCHAR] - [USER]
24-02-01 23:03:387 [http-nio-7000-exec-2] INFO                           p6spy.logSQL [ 60 line ] [ ThreadId-119 ] - [statement] | 1 ms | 
    insert 
    into
        users
        (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) 
    values
        ('2024-02-01T23:03:31.343+0900', 'admin', '2024-02-01T23:03:31.343+0900', 'admin', 'test@naver.com', '$2a$10$XGfAOKzfhDz7N6bkfBjpXOA5t7skfsieH.Za1BLAQzjcK7Kd9zfAW', 'test', '테스트', 'USER')

	Connection ID:1 | Excution Time:1 ms

	Excution Time:1 ms

	Call Stack :
		1.com.octopus.base.security.filter.JwtFilter.doFilterInternal(JwtFilter.java:88)
		2.com.octopus.login.controller.UsersController$$EnhancerBySpringCGLIB$$1.signup(<generated>)
		3.com.octopus.base.intercepter.TrackingAspect.loggingControllerAround(TrackingAspect.java:63)
		4.com.octopus.login.controller.UsersController$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		5.com.octopus.login.controller.UsersController.signup(UsersController.java:31)
		6.com.octopus.login.service.UserService$$EnhancerBySpringCGLIB$$1.registerUser(<generated>)
		7.com.octopus.login.service.UserService$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		8.com.octopus.login.service.UserService.registerUser(UserService.java:51)
		9.com.octopus.base.config.P6SpySqlFormatter.formatMessage(P6SpySqlFormatter.java:32)
		10.com.octopus.base.config.P6SpySqlFormatter.createStack(P6SpySqlFormatter.java:52)

--------------------------------------
24-02-01 23:03:388 [http-nio-7000-exec-2] INFO                           p6spy.logSQL [ 60 line ] [ ThreadId-119 ] - [statement] | 3 ms | 
    insert 
    into
        users
        (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) 
    values
        ('2024-02-01T23:03:31.343+0900', 'admin', '2024-02-01T23:03:31.343+0900', 'admin', 'test@naver.com', '$2a$10$XGfAOKzfhDz7N6bkfBjpXOA5t7skfsieH.Za1BLAQzjcK7Kd9zfAW', 'test', '테스트', 'USER')

	Connection ID:14 | Excution Time:3 ms

	Excution Time:3 ms

	Call Stack :
		1.com.octopus.base.security.filter.JwtFilter.doFilterInternal(JwtFilter.java:88)
		2.com.octopus.login.controller.UsersController$$EnhancerBySpringCGLIB$$1.signup(<generated>)
		3.com.octopus.base.intercepter.TrackingAspect.loggingControllerAround(TrackingAspect.java:63)
		4.com.octopus.login.controller.UsersController$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		5.com.octopus.login.controller.UsersController.signup(UsersController.java:31)
		6.com.octopus.login.service.UserService$$EnhancerBySpringCGLIB$$1.registerUser(<generated>)
		7.com.octopus.login.service.UserService$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		8.com.octopus.login.service.UserService.registerUser(UserService.java:51)
		9.com.octopus.base.config.P6SpySqlFormatter.formatMessage(P6SpySqlFormatter.java:32)
		10.com.octopus.base.config.P6SpySqlFormatter.createStack(P6SpySqlFormatter.java:52)

--------------------------------------

설정 문제 인 듯한데, 한 참을 뒤지고 다녔네요.

---

설정하는 방식이 두 가지 였던겁니다.

1. implementation 'p6spy:p6spy:3.9.1'  를 사용하는 방법
2. implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.8.1' 를 사용하는 방법

---

1. implementation 'p6spy:p6spy:3.9.1'  를 사용하는 방법

build.gradle

	// jpa query logging
	// p6spy dependency
	//implementation 'p6spy:p6spy:3.9.1'         // 사용 중인 버전에 맞게 설정
    implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.8.1'

application.yml ( driver-class-name, url 설정에 주의 하세요. )

spring: 
  datasource:
    driver-class-name: com.p6spy.engine.spy.P6SpyDriver
    url: jdbc:p6spy:postgresql://localhost:5432/springboot
    username: hermeswing
    password: pass

---

2. implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.8.1' 를 사용하는 방법

build.gradle

	// p6spy dependency
    implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.8.1'

application.yml  ( driver-class-name, url 설정에 주의 하세요. )

spring: 
  datasource:
    class-name: org.postgresql.Driver                   # p6spy-spring-boot-starter 를 설정할 경우
    url: jdbc:postgresql://localhost:5432/springboot           # p6spy-spring-boot-starter 를 설정할 경우
    username: hermeswing
    password: pass

---

저의 경우는 두번째 (  implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.8.1' ) 로 설정하고 있었습니다. application.yml 설정에서 첫번째 설정으로 되어 있어서 두번 출력이 되는 것이였습니다.

추가적으로 ?, ?, ? 는 계속 찍네요.

24-02-01 23:01:825 [http-nio-7000-exec-2] INFO                           p6spy.logSQL [ 60 line ] [ ThreadId-120 ] - 
24-02-01 23:01:902 [http-nio-7000-exec-2] DEBUG com.octopus.login.service.UserService.registerUser [ 47 line ] [ ThreadId-120 ] - encodedPassword :: $2a$10$ySx8fYvTVor2FeI6xXuGqOAGSznXYjrswvHk4JXhVaFRLKuSnflM2
24-02-01 23:01:966 [http-nio-7000-exec-2] DEBUG              org.hibernate.SQL.logStatement [ 144 line ] [ ThreadId-120 ] - insert into users (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
24-02-01 23:01:968 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [1] as [TIMESTAMP] - [2024-02-01T23:01:45.932715700]
24-02-01 23:01:969 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [2] as [VARCHAR] - [admin]
24-02-01 23:01:969 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [3] as [TIMESTAMP] - [2024-02-01T23:01:45.932715700]
24-02-01 23:01:970 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [4] as [VARCHAR] - [admin]
24-02-01 23:01:970 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [5] as [VARCHAR] - [test@naver.com]
24-02-01 23:01:971 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [6] as [VARCHAR] - [$2a$10$ySx8fYvTVor2FeI6xXuGqOAGSznXYjrswvHk4JXhVaFRLKuSnflM2]
24-02-01 23:01:971 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [7] as [VARCHAR] - [test]
24-02-01 23:01:971 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [8] as [VARCHAR] - [테스트]
24-02-01 23:01:972 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-120 ] - binding parameter [9] as [VARCHAR] - [USER]
24-02-01 23:01:975 [http-nio-7000-exec-2] INFO                           p6spy.logSQL [ 60 line ] [ ThreadId-120 ] - [statement] | 1 ms | 
    insert 
    into
        users
        (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) 
    values
        ('2024-02-01T23:01:45.932+0900', 'admin', '2024-02-01T23:01:45.932+0900', 'admin', 'test@naver.com', '$2a$10$ySx8fYvTVor2FeI6xXuGqOAGSznXYjrswvHk4JXhVaFRLKuSnflM2', 'test', '테스트', 'USER')

	Connection ID:4 | Excution Time:1 ms

	Excution Time:1 ms

	Call Stack :
		1.com.octopus.base.security.filter.JwtFilter.doFilterInternal(JwtFilter.java:88)
		2.com.octopus.login.controller.UsersController$$EnhancerBySpringCGLIB$$1.signup(<generated>)
		3.com.octopus.base.intercepter.TrackingAspect.loggingControllerAround(TrackingAspect.java:63)
		4.com.octopus.login.controller.UsersController$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		5.com.octopus.login.controller.UsersController.signup(UsersController.java:31)
		6.com.octopus.login.service.UserService$$EnhancerBySpringCGLIB$$1.registerUser(<generated>)
		7.com.octopus.login.service.UserService$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		8.com.octopus.login.service.UserService.registerUser(UserService.java:51)
		9.com.octopus.base.config.P6SpySqlFormatter.formatMessage(P6SpySqlFormatter.java:32)
		10.com.octopus.base.config.P6SpySqlFormatter.createStack(P6SpySqlFormatter.java:52)

--------------------------------------

---

이제는 아래의 부분도 지웠으면 하네요.

24-02-01 23:03:378 [http-nio-7000-exec-2] DEBUG              org.hibernate.SQL.logStatement [ 144 line ] [ ThreadId-119 ] - insert into users (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
24-02-01 23:03:379 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [1] as [TIMESTAMP] - [2024-02-01T23:03:31.343042800]
24-02-01 23:03:381 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [2] as [VARCHAR] - [admin]
24-02-01 23:03:382 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [3] as [TIMESTAMP] - [2024-02-01T23:03:31.343042800]
24-02-01 23:03:382 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [4] as [VARCHAR] - [admin]
24-02-01 23:03:383 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [5] as [VARCHAR] - [test@naver.com]
24-02-01 23:03:383 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [6] as [VARCHAR] - [$2a$10$XGfAOKzfhDz7N6bkfBjpXOA5t7skfsieH.Za1BLAQzjcK7Kd9zfAW]
24-02-01 23:03:383 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [7] as [VARCHAR] - [test]
24-02-01 23:03:384 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [8] as [VARCHAR] - [테스트]
24-02-01 23:03:384 [http-nio-7000-exec-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind [ 64 line ] [ ThreadId-119 ] - binding parameter [9] as [VARCHAR] - [USER]

application.xml

logging:
  level:  # 각 package 별로 로깅 레벨을 지정할 수 있다.
    root : INFO
    org:
      hibernate:
        type:
          descriptor:
            sql:
              BasicBinder: INFO              # TRACE org.hibernate.type.descriptor.sql.BasicBinder.bind 로그를 지웁니다.
        SQL: INFO                            # DEBUG              org.hibernate.SQL.logStatement 를 지웁니다.

이제는 안보이네요.

24-02-01 23:08:207 [http-nio-7000-exec-2] INFO                           p6spy.logSQL [ 60 line ] [ ThreadId-119 ] - [statement] | 1 ms | 
    insert 
    into
        users
        (crt_dt, crt_id, mdf_dt, mdf_id, email, password, user_id, user_nm, user_role) 
    values
        ('2024-02-01T23:08:37.172+0900', 'admin', '2024-02-01T23:08:37.172+0900', 'admin', 'test@naver.com', '$2a$10$C2UBS7qklm1q/19vWxaf9e9p8Y8U8l.uBiBl.SSbYgzuGxjhLfucC', 'test', '테스트', 'USER')

	Connection ID:4 | Excution Time:1 ms

	Excution Time:1 ms

	Call Stack :
		1.com.octopus.base.security.filter.JwtFilter.doFilterInternal(JwtFilter.java:88)
		2.com.octopus.login.controller.UsersController$$EnhancerBySpringCGLIB$$1.signup(<generated>)
		3.com.octopus.base.intercepter.TrackingAspect.loggingControllerAround(TrackingAspect.java:63)
		4.com.octopus.login.controller.UsersController$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		5.com.octopus.login.controller.UsersController.signup(UsersController.java:31)
		6.com.octopus.login.service.UserService$$EnhancerBySpringCGLIB$$1.registerUser(<generated>)
		7.com.octopus.login.service.UserService$$FastClassBySpringCGLIB$$1.invoke(<generated>)
		8.com.octopus.login.service.UserService.registerUser(UserService.java:51)
		9.com.octopus.base.config.P6SpySqlFormatter.formatMessage(P6SpySqlFormatter.java:32)
		10.com.octopus.base.config.P6SpySqlFormatter.createStack(P6SpySqlFormatter.java:52)

--------------------------------------

---

https://hermeslog.tistory.com/551

[SpringBoot] JPA 개발 시 p6spy를 이용해서 쿼리 로그 남기기

https://www.inflearn.com/questions/501492/p6spy-%EB%A1%9C%EA%B7%B8-%EB%91%90-%EB%B2%88-%EC%B0%8D%ED%9E%88%EB%8A%94-%EC%9D%B4%EC%9C%A0

p6spy 로그 두 번 찍히는 이유 - 인프런