목차
들어가기 전에
현재 운영중인 서비스는 API 로그를 파일로 기록하고 있다. 그런데 서버가 이중화되어 있고 그 외에도 몇가지 불편한 점이 있어서 DB에 로깅을 해보면 어떨까 하는 생각이 들었다.
- 서버가 이중화되어 있다보니 특정 로그를 확인하려면 양쪽 서버 모두 확인해야 한다. → 사실상 가장 불편했던 점
- 특정 요청건에 대한 로그를 찾아보기 어렵다.
- 요청 일자가 모호할 경우에 여러 파일을 열어서 확인해야하는 경우 등
- 일자별, 시간대별 요청 건수 확인이 어렵다.
- 특정 요청이 처리되고 있는 도중에 다른 요청이 들어오면 로그에 혼선이 생겨서 어떤 요청에 대한 응답인지 파악하기 어려워진다.
이런 이유들로 인해 파일 대신 DB에 API로그를 남겨보려고 했는데 어차피 모든 API의 중복 로직이니까 AOP를 사용해서 처리해보자고 마음먹었다.
어떤식으로 로그를 기록할 것인가?
우선 어떤 방식으로 로그를 기록할지 두가지 방식을 생각해봤다.
- 요청이 들어올 때 요청에 대한 데이터만 먼저 DB에 기록하고(INSERT) 응답이 나갈 때 응답에 대한 로그를 갱신한다(UPDATE).
- 요청이 들어와서 처리된 후 응답을 반환할 때만 DB에 요청과 응답에 대한 데이터를 기록한다.
1번의 경우에는 쿼리가 두번 실행되다보니 성능에 끼치는 영향이 우려되었고, 2번의 경우에는 응답이 반환되기 전에는 기록이 아예 남지 않는점과 먼저 들어온 요청이 나중에 들어온 요청보다 응답이 늦을 경우에는 나중에 들어온 요청의 로그가 먼저 기록되는 점이 우려되었다.
결국 둘중 어느 방식을 사용할지는 트레이드오프의 영역이라고 생각했는데, 그래도 응답이 반환되기 전에도 요청에 대한 기록은 있는게 좋다고 생각해서 1번 방식을 사용하기로 했다. 또한, 혹시 모르는 상황에 대비해 기존에 사용하던 파일 로깅 방식도 완전히 제거하진 않았다.
구현 방법을 생각해보자
사실 가장 먼저 생각했던 구현 방법은 JPA의 변경 감지를 통해 API 응답을 기록하는 것이었다. API의 프로세스가 끝날 때까지 로그를 기록하는 메소드에서 요청에 대한 로그 엔티티 객체를 계속 갖고 있을테니 어떤 요청에 대한 응답인지 확실하게 보장할 수 있다고 생각했기 때문이다.
그런데 구현하면서 테스트를 해보니까 컨트롤러 클래스나 메소드에 @Transactional 어노테이션을 붙여주지 않으면 @Aspect 부분에서 변경 감지가 동작하지 않았다.
그렇다고 모든 컨트롤러에 @Transactional을 붙이자니 번거로울 것 같고 그 외에도 여러가지 부작용이 발생하진 않을지 걱정되다보니, JPA의 변경 감지를 사용하는 것은 포기하고 대신 JPQL로 응답을 기록할 UPDATE 쿼리를 작성해서 구현해보려고 했다.
로그 엔티티를 어떻게 구성할까?
DB에 API 로그를 기록할거니까 우선 로그가 저장될 테이블의 엔티티를 어떻게 구성할지 고민했다.
@Entity
class ApiLog(
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
val seq: Long? = null,
val serverIp: String,
@Column(length = 4096)
val requestUrl: String,
val requestMethod: String,
var responseStatus: Int? = null,
val clientIp: String,
@Column(length = 4096)
val request: String,
@Column(length = 4096)
var response: String? = null,
val requestTime: LocalDateTime = LocalDateTime.now(),
var responseTime: LocalDateTime?= null
)
여기서 requestMethod를 굳이 추가한 이유는 동일한 URL으로 호출하지만 HTTP Method에 따라 구분되는 API들이 있었기 때문이다.
serverIp는 서버가 이중화되어 있어서 어떤 서버에 도달한 요청인지 파악하기 위해 추가했다.
request와 response는 요청 파라미터와 응답 데이터를 저장하기 위해 길이 제한을 최대로 잡았다.
요청에 대한 HTTP 상태코드를 나타낼 responseStatus와 클라이언트의 IP, 요청 시간 및 응답 시간 등도 기록하기로 했다.
요청이 발생할 때 요청에 대한 정보만 우선적으로 DB에 INSERT하기 위해 응답에 대한 정보의 기본값은 모두 null으로 했다. 변경 감지를 사용하지 않을 것이기 때문에 UPDATE를 위한 메소드를 별도로 작성하진 않았다.
레포지토리에 응답 데이터를 갱신하는 쿼리 작성
응답 데이터를 갱신하는건 해당 로그의 키를 받아서 응답 정보만 갱신하면 되므로 간단하게 작성했다.
interface ApiLogRepository : JpaRepository<ApiLog, Long> {
@Transactional
@Modifying
@Query("""
UPDATE ApiLog a
SET a.responseStatus = :status, a.response = :response, a.responseTime = CURRENT_TIMESTAMP
WHERE a.seq = :seq
""")
fun updateResponse(seq: Long, status: Int, response: String)
}@Modifying은 해당 쿼리가 UPDATE 또는 DELETE 쿼리라는 것을 나타내기 위해 붙여준다. 해당 어노테이션이 없다면 실행 시 InvalidDataAccessApiUsageException이 발생한다.
@Transactional의 경우에는 트랜잭션이 굳이 필요한 것은 아니지만 붙이지 않으면 TransactionRequiredException이 발생해서 붙여주었다.
이제 로그를 기록하는 로직을 작성해보자!
본격적으로 로그를 기록하기 위한 로직을 작성해보자.
@Aspect
@Component
class AopLogging(
private val apiLogRepository: ApiLogRepository
) {
@Around("execution(public * com.colabear754.aop_db_logging.controllers.*.*(..))")
fun log(joinPoint: ProceedingJoinPoint): Any? {
val requestAttributes = RequestContextHolder.currentRequestAttributes() as ServletRequestAttributes
val httpRequest = requestAttributes.request
val log = apiLogRepository.save(
ApiLog(
serverIp = InetAddress.getLocalHost().hostAddress,
requestUrl = httpRequest.requestURL.toString(),
requestMethod = httpRequest.method,
clientIp = httpRequest.getHeader("X-FORWARDED-FOR")?.takeUnless { it.isBlank() } ?: httpRequest.remoteAddr,
request = getRequestString(joinPoint)
)
)
try {
val response = joinPoint.proceed() as ResponseEntity<*>
apiLogRepository.updateResponse(log.seq!!, response.statusCode.value(), response.body.toString())
return response
} catch (e: Exception) {
apiLogRepository.updateResponse(log.seq!!, exceptionToStatus(e).value(), e.message ?: "error")
throw e
}
}
private fun getRequestString(joinPoint: ProceedingJoinPoint): String {
val signature = joinPoint.signature
val parameterNames = if (signature is MethodSignature) signature.parameterNames else return ""
val parameterValues = joinPoint.args
return parameterNames.zip(parameterValues).joinToString(", ") { "${it.first}=${it.second}" }
}
}우선 @Around 어노테이션을 통해 controllers 패키지에 있는 모든 클래스의 public 메소드가 실행될 때 로깅 메소드가 실행되도록 설정해준다. 만약 특정 패키지 내의 클래스에서만 동작하게 하고싶다면 패키지 경로를 적당히 수정해주면 된다.
API의 요청 정보를 받아오기 위해 RequestContextHolder에서 현재 요청에 대한 정보를 받아온다. RequestContextHolder.currentRequestAttributes()의 반환 타입인 RequestAttribute는 인터페이스이기 때문에 해당 인터페이스의 구현체를 상속받는 ServletRequestAttributes 타입으로 형변환을 해줘야 한다.
요청을 받는 서버의 IP는 InetAddress에서 받아오고, 그 외의 정보는 HttpServletRequest 객체에서 얻는다.
log()에서 파라미터로 받는 ProceedingJoinPoint 객체는 AOP에서 감싸고 있는, 실제 로직이 실행되는 메소드에 대한 정보들을 담고 있다. 해당 ProceedingJoinPoint 객체를 통해 실제 로직이 실행되는 메소드의 파라미터 정보를 가져오기 위해 getRequestString()라는 메소드를 별도로 작성했다.
레포지토리의 save() 결과는 변수로 저장해둔다. 이렇게 해서 해당 요청 로그의 키를 알아낼 수 있다.
요청 로그를 DB에 INSERT 했으니 이제 joinPoint.proceed()를 통해 메소드를 실행하고 그 결과값을 받아온다. 실제 프로젝트에서 모든 컨트롤러의 메소드 반환 타입이 ResponseEntity이기 때문에 메소드의 결과값을 ResponseEntity로 형변환했다.
응답 처리는 예외 처리를 @RestControllerAdvice와 @ExceptionHandler로 진행하다보니 조금 복잡해졌는데, 예외가 발생하지 않으면 ResponseEntity를 토대로 응답 데이터를 기록하지만 컨트롤러 이하의 계층에서 예외가 발생하면 별도로 처리를 해야했다. 그래서 exceptionToStatus()를 통해 예외의 종류에 따라 반환할 HTTP 상태 코드를 얻어와서 별도로 응답 데이터를 갱신해주고 @ExceptionHandler에서 예외를 처리할 수 있도록 다시 예외를 던져줬다.
exceptionToStatus()는 아래와 같은 느낌처럼 예외를 인자로 받아서 예외의 종류에 따라서 HttpStatus Enum 객체를 반환하는 메소드이다.
fun exceptionToStatus(e: Exception): HttpStatus {
return when (e) {
is IllegalArgumentException -> HttpStatus.BAD_REQUEST
is AccessDeniedException -> HttpStatus.FORBIDDEN
else -> HttpStatus.INTERNAL_SERVER_ERROR
}
}제대로 로그가 찍히는지 테스트해보자
테스트를 위한 컨트롤러 작성
로그가 제대로 찍히는지 테스트를 하기 위해 간단한 컨트롤러를 작성했다.
@RestController
class TestController {
@GetMapping("/200ok")
fun ok(name: String, message: String) = ResponseEntity.ok(mapOf("name" to name, "message" to message))
@GetMapping("/400bad")
fun bad(name: String, message: String): Nothing = throw IllegalArgumentException("Invalid argument")
@GetMapping("/500error")
fun error(name: String, message: String): Nothing = throw RuntimeException("error")
@PostMapping("/post")
fun post(message: String, @RequestBody body: Map<String, String>) = ResponseEntity.ok(body.toMutableMap().apply { put("message", message) })
}ok()과 post()는 각각 GET과 POST 요청을 받아서 요청 파라미터를 그대로 JSON 형태로 반환해주는 메소드이고, bad()와 error()는 각기 다른 예외를 발생시키는 메소드이다.
테스트 코드를 작성해서 테스트하자!
API를 호출해서 로그가 제대로 찍히는지 확인할 테스트 코드를 작성해보자.
@SpringBootTest
@AutoConfigureMockMvc
class AspectTest @Autowired constructor(
private val apiLogRepository: ApiLogRepository,
private val mock: MockMvc
) {
@BeforeEach
fun reset() = apiLogRepository.deleteAllInBatch()
@Test
fun `GET 로그 테스트`() {
// given
// when
mock.perform(get("/200ok?name=colabear754&message=hello").contentType(MediaType.APPLICATION_JSON))
// then
val log = apiLogRepository.findAll()[0]
assertThat(log.request).isEqualTo("name=colabear754, message=hello")
assertThat(log.responseStatus).isEqualTo(200)
assertThat(log.serverIp).isEqualTo("192.168.0.120")
assertThat(log.requestUrl).isEqualTo("http://localhost/200ok")
assertThat(log.requestMethod).isEqualTo("GET")
assertThat(log.clientIp).isEqualTo("127.0.0.1")
assertThat(log.response).isEqualTo("{name=colabear754, message=hello}")
}
@Test
fun `BAD REQUEST 로그 테스트`() {
// given
// when
mock.perform(get("/400bad?name=ciderbear754&message=hi").contentType(MediaType.APPLICATION_JSON))
// then
val log = apiLogRepository.findAll()[0]
assertThat(log.request).isEqualTo("name=ciderbear754, message=hi")
assertThat(log.responseStatus).isEqualTo(400)
assertThat(log.serverIp).isEqualTo("192.168.0.120")
assertThat(log.requestUrl).isEqualTo("http://localhost/400bad")
assertThat(log.requestMethod).isEqualTo("GET")
assertThat(log.clientIp).isEqualTo("127.0.0.1")
assertThat(log.response).isEqualTo("입력값을 확인해주세요.")
}
@Test
fun `INTERNAL SERVER ERROR 로그 테스트`() {
// given
// when
mock.perform(get("/500error?name=fantabear754&message=yes").contentType(MediaType.APPLICATION_JSON))
// then
val log = apiLogRepository.findAll()[0]
assertThat(log.request).isEqualTo("name=fantabear754, message=yes")
assertThat(log.responseStatus).isEqualTo(500)
assertThat(log.serverIp).isEqualTo("192.168.0.120")
assertThat(log.requestUrl).isEqualTo("http://localhost/500error")
assertThat(log.requestMethod).isEqualTo("GET")
assertThat(log.clientIp).isEqualTo("127.0.0.1")
assertThat(log.response).isEqualTo("서버 에러가 발생했습니다.")
}
@Test
fun `POST 로그 테스트`() {
// given
// when
mock.perform(post("/post?message=hello").contentType(MediaType.APPLICATION_JSON).content("{\"name\":\"colabear754\"}"))
// then
val log = apiLogRepository.findAll()[0]
assertThat(log.request).isEqualTo("message=hello, body={name=colabear754}")
assertThat(log.responseStatus).isEqualTo(200)
assertThat(log.serverIp).isEqualTo("192.168.0.120")
assertThat(log.requestUrl).isEqualTo("http://localhost/post")
assertThat(log.requestMethod).isEqualTo("POST")
assertThat(log.clientIp).isEqualTo("127.0.0.1")
assertThat(log.response).isEqualTo("{name=colabear754, message=hello}")
}
}테스트 코드를 실행해보면 테스트가 정상적으로 통과되는 것을 볼 수 있다.
콘솔 로그를 보면 쿼리도 정상적으로 나가는 것을 볼 수 있다.
프로젝트를 실행하여 DB를 확인했을 때도 정상적으로 반영되어 있다.
마치며
사실 전체 API 호출 이력을 굳이 DB에 기록할 필요까진 없을 가능성이 높다. 혹은 DB에 로그를 기록하더라도 도메인마다 다른 구조로 로그를 기록해야할 수도 있다.
그렇다고 해도 AOP를 활용하면 하나의 메소드만 작성해도 수많은 중복 코드를 줄일 수 있을테니 유용하지 않을까 싶다.
@RestControllerAdvice와 병행해서 사용하다보니 예외 처리가 조금 복잡해진 면이 있는데 이 부분은 더 개선할 수 있을지, 그 외에도 로그 기록 방식을 더 개선할 수 있는지는 더 찾아보는게 좋을 것 같다.
'Development > Spring & Spring Boot' 카테고리의 다른 글
| [Spring Boot] 스프링 인터셉터(Spring Interceptor)를 활용해서 API 로그를 DB에 기록해보자 (0) | 2024.03.01 |
|---|---|
| [Spring Boot] @Value 대신 생성자 바인딩을 통해 프로퍼티 값을 바인딩하고 관리해보자 (0) | 2023.12.21 |
| [Spring Boot] H2 DB Embedded Mode 사용하기 (0) | 2023.10.04 |
| [Spring Boot] 스프링이 제공하는 다양한 어노테이션을 통한 유효성 검사와 응답 처리 (0) | 2023.08.28 |
| [Spring Security] 스프링 시큐리티를 적용하고 예외가 발생했을 때 403 Forbidden이 발생하는 원인과 처리 방안 (0) | 2023.08.05 |
댓글