🎬 서론
이전부터 로그 관리의 중요성은 알고 있었지만, 계속해서 다른 것들에 우선순위가 밀리다 보니 제대로 다루지 못 했었다.
하지만 원타임 서비스의 사용자 수가 계속해서 늘어나며 모니터링과 성능 개선의 필요성도 크게 느끼게 되었고, 이를 위해서 우선 로깅부터 개선을 해 보고자 글을 적으려 한다.
🚨 기존 로그 문제점
2025-05-02T23:33:19.742+09:00 INFO 1 --- [nio-8090-exec-6] side.onetime.util.JwtUtil : JWT를 검증합니다.
Hibernate: select u1_0.users_id,u1_0.created_date,u1_0.email,u1_0.language,u1_0.marketing_policy_agreement,u1_0.name,u1_0.nickname,u1_0.privacy_policy_agreement,u1_0.provider,u1_0.provider_id,u1_0.service_policy_agreement,u1_0.sleep_end_time,u1_0.sleep_start_time,u1_0.updated_date from users u1_0 where u1_0.users_id=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.users_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_uuid=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.events_id=?
Hibernate: select m1_0.events_id,m1_0.members_id,m1_0.created_date,m1_0.members_uuid,m1_0.name,m1_0.pin,m1_0.updated_date from members m1_0 where m1_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_uuid=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_uuid=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.events_id=?
Hibernate: select s1_0.selections_id,s1_0.created_date,s1_0.members_id,s2_0.schedules_id,s2_0.created_date,s2_0.date,s2_0.day,s2_0.events_id,s2_0.time,s2_0.updated_date,s1_0.updated_date,s1_0.users_id from selections s1_0 join schedules s2_0 on s2_0.schedules_id=s1_0.schedules_id where s2_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_uuid=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.events_id=?
Hibernate: select m1_0.events_id,m1_0.members_id,m1_0.created_date,m1_0.members_uuid,m1_0.name,m1_0.pin,m1_0.updated_date from members m1_0 where m1_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_uuid=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.events_id=?
Hibernate: select e1_0.events_id,e1_0.category,e1_0.created_date,e1_0.end_time,e1_0.events_uuid,e1_0.qr_file_name,e1_0.start_time,e1_0.title,e1_0.updated_date from events e1_0 where e1_0.events_uuid=?
Hibernate: select ep1_0.event_participations_id,ep1_0.created_date,ep1_0.events_id,ep1_0.event_status,ep1_0.updated_date,ep1_0.users_id from event_participations ep1_0 where ep1_0.events_id=?
Hibernate: select s1_0.selections_id,s1_0.created_date,s1_0.members_id,s2_0.schedules_id,s2_0.created_date,s2_0.date,s2_0.day,s2_0.events_id,s2_0.time,s2_0.updated_date,s1_0.updated_date,s1_0.users_id from selections s1_0 join schedules s2_0 on s2_0.schedules_id=s1_0.schedules_id where s2_0.events_id=?기존의 조악한 로그를 보자. 여기에는 아래의 문제점들이 존재한다.
1. SQL문이 모두 출력됨
- 불필요한 정보가 과도하게 쌓이면서 로그 분석이 어려워질 뿐만 아니라, 로그 파일 용량도 빠르게 증가함
2. 어떤 API인지 알 수 없음
- Hibernate 쿼리만 나오기 때문에 요청한 API 엔드포인트 정보가 전혀 보이지 않음.
- 때문에 클라이언트가 어떤 요청을 보냈는지, 어떤 컨트롤러에서 처리됐는지 알 수 없어 디버깅 및 문제 재현이 어려움.
3. 요청 파라미터, 사용자 정보 없음
- 어떤 userId / eventId에 대한 요청인지 전혀 맥락이 없음.
- 특정 사용자의 요청이었는지, 관리자의 요청이었는지 구분 불가함
4. 처리 시간 로깅 없음 → 병목 파악 불가
- 처리 속도(time=xxxms)를 확인할 수 없기 때문에,
1) 어떤 요청이 느린지
2) 어떤 API가 병목인지
3) 어떤 DB 쿼리가 성능을 잡아먹는지 전혀 판단할 수 없음.- 때문에 성능 개선 및 스케일링 판단이 어려움
지금부터 여기에 있는 문제들을 하나씩 개선해보고자 한다.
💣 문제1 - SQL문이 모두 출력됨
server:
port: ${SERVER_PORT}
spring:
datasource:
url: ${DATABASE_URL}
username: ${DATABASE_USERNAME}
password: ${DATABASE_PW}
driver-class-name: com.mysql.cj.jdbc.Driver
jpa:
properties:
hibernate:
dialect: org.hibernate.dialect.MySQL8Dialect
hibernate:
ddl-auto: update
defer-datasource-initialization: true
open-in-view: false
generate-ddl: true
show-sql: true
sql:
init:
mode: always
(생략..)
기존에는 이런식으로 yaml 파일이 구성되어 있었기 때문에, 모든 SQL문이 그대로 출력되었다.
이는 보기에도 좋지 않을 뿐만 아니라, 보안상 안전하지 않을 수 있기 때문에 로컬에서만 출력되도록 하고 테스트 & 배포 서버에서는 출력되지 않도록 변경하였다.
✅ 해결 방법 - yaml 파일 분리
때문에 yaml 파일을 1) 로컬 2) 테스트 3) 배포 각각으로 분리를 하였고,
테스트와 배포 서버에서는 SQL문이 출력되지 않도록 아래와 같이 수정했다.(주석은 제거)
spring:
jpa:
show-sql: false # ❌ SQL 콘솔 출력 끔
properties:
hibernate:
format_sql: false
use_sql_comments: false # ❌ 주석 출력 끔
hibernate:
ddl-auto: validate # ✅ 운영환경에서는 스키마만 검증 (update → validate)
generate-ddl: false # ❌ DDL 자동 생성 끔
sql:
init:
mode: never # ❌ schema.sql, data.sql 실행 안 함
logging:
level:
org.hibernate.SQL: off # ❌ Hibernate SQL 로그 끔
org.hibernate.type.descriptor.sql.BasicBinder: off # ❌ SQL 파라미터 로그 끔또한 각각 테스트와 배포 환경이라는 것을 인식해야 하기 때문에, 도커 컨테이너를 띄울 때 아래와 같이 도커 컴포즈에 SPRING_PROFILES_ACTIVE 환경변수를 추가하여 주입해주었다.
environment:
- TZ=Asia/Seoul
- SPRING_PROFILES_ACTIVE=prod💫 결과
2025-05-03T00:56:15.988+09:00 ERROR 1 --- [nio-8090-exec-8] side.onetime.global.config.JwtFilter : JWT validation failed: Cannot invoke "String.substring(int)" because "authorizationHeader" is null
2025-05-03T00:56:16.278+09:00 INFO 1 --- [nio-8090-exec-7] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:56:16.308+09:00 INFO 1 --- [nio-8090-exec-7] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:56:16.350+09:00 INFO 1 --- [nio-8090-exec-3] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:56:16.399+09:00 INFO 1 --- [nio-8090-exec-6] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:56:17.099+09:00 INFO 1 --- [nio-8090-exec-9] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:57:06.516+09:00 INFO 1 --- [nio-8090-exec-5] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:57:06.515+09:00 INFO 1 --- [io-8090-exec-10] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:57:06.525+09:00 INFO 1 --- [nio-8090-exec-8] side.onetime.util.JwtUtil : JWT를 검증합니다.
2025-05-03T00:57:06.525+09:00 INFO 1 --- [nio-8090-exec-1] side.onetime.util.JwtUtil : JWT를 검증합니다.그 결과 이런식으로 로그를 제외하고는 SQL문이 뜨지 않게 되었다.
💣 문제2 - 어떤 API인지 알 수 없음 & 처리 시간 로깅 없음
현재로써는 어떠한 API 호출이 일어났는지를 알 수가 없기에, 만약 500에러가 발생하는 경우에는 해당 상황을 정확히 파악하기가 매우 어렵다.
때문에 모든 API 호출에 대해서 로깅을 진행해보려 한다.
✅ 해결 방법 - 인터셉터 구현
로깅을 구현하는 방법은 여러 가지가 있지만, 아래의 3가지 방법 중에서 고민을 했다.
1. Filter
- 장점 : 가장 하위레벨에서 동작(디스패처서블렛 이전)하기 때문에 API 뿐만 아니라 정적 리소스 요청과 같은 호출에 대해서도 처리가 가능함.
- 단점 : 하지만 어떠한 API 호출인지, 어떤 비즈니스 로직을 타고 가는지 등의 디테일한 정보는 파악하기가 어려움.
- 정리 글
2. Interceptor
- 장점 : Spring MVC 레이어에 속하며, 컨트롤러 요청 전후의 로직을 처리하기에 적합함. 또한 요청과 응답 정보까지 다룰 수 있기에 디테일한 처리가 가능함.
- 단점 : 컨트롤러 단, 즉 API 요청에 대해서만 처리가 가능하기에, 정적 리소스 요청에 대해서는 처리해줄 수 없음.
- 정리 글
3. AOP(Aspect-Oriented Programming)
- 장점 : 비즈니스 로직과 별개로 공통 관심사를 분리하여 모듈화 할 수 있기에, 깔끔한 관리가 가능함. API 뿐만 아니라 여러 메서드 호출 전 후에 필요한 로직을 커스터마이징 할 수 있음.
- 단점 : HTTP 요청/응답 객체에 직접 접근하기 어려워, 요청 바디나 응답 바디를 읽거나 가공하는 일은 거의 불가능에 가까움. 또한 요청 처리 속도를 파악할 수는 있지만, 인터셉터에 비해 정확성이 떨어질 수 있음.
결과적으로 요청 & 응답 데이터 가공이 가능하고, 정확한 API 요청 처리 속도를 계산할 수 있는 인터셉터를 구현하는 것으로 결정하게 되었다.
가. 의존성 추가
// Web
implementation 'org.springframework.boot:spring-boot-starter-web'
// Lombok
compileOnly 'org.projectlombok:lombok'
annotationProcessor 'org.projectlombok:lombok'인터셉터와 로깅을 사용해야 하기 때문에 위 의존성을 추가해주어야 한다.
나. LoggingInterceptor 클래스 구현
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;
@Slf4j
@Component
public class LoggingInterceptor implements HandlerInterceptor {
private static final String START_TIME = "startTime";
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
long now = System.currentTimeMillis();
request.setAttribute(START_TIME, now);
log.info("➡️ [{}] {} 요청 시작", request.getMethod(), request.getRequestURI());
return true;
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
Long start = (Long) request.getAttribute(START_TIME);
long duration = System.currentTimeMillis() - (start != null ? start : 0L);
int status = response.getStatus();
log.info("✅ [{}] {} 요청 완료 - {}ms | status={}", request.getMethod(), request.getRequestURI(), duration, status);
}
}로깅을 위한 인터셉터 클래스를 추가한다.
여기서 preHandle 메서드는 컨트롤러 호출 직전에 동작한다. 여기서 요청 처리 속도 계산을 위한 시작 시간 now를 설정해 주고, 어떠한 메서드 & URI인지를 로그로 찍어준다.
이후 컨트롤러 호출이 종료되고 로직이 진행된 후, afterCompletion 메서드가 동작하여 처리 속도 duration과 상태 코드 status를 로그로 찍어주는 구조이다.
다. WebConfig 클래스 구현
import lombok.RequiredArgsConstructor;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import side.onetime.global.interceptor.LoggingInterceptor;
@Configuration
@RequiredArgsConstructor
public class WebConfig implements WebMvcConfigurer {
private final LoggingInterceptor loggingInterceptor;
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(loggingInterceptor)
.addPathPatterns("/**");
}
}만들었다고 바로 적용되는 것은 아니다.
위에서 만든 인터셉터 bean을 WebMvcConfigurer를 구현한 WebConfig에 등록해주어야 한다.
현재는 모든 API 호출에 대해 적용할 것이기 때문에, "/**"로 두었다. 이는 상황에 따라 커스터마이징 가능하다.
💫 결과
이렇게 API 호출을 할 때 어떤 API인지 & 요청 처리 속도를 파악할 수 있게 되었다!
💣 문제3 - JWT 검증 로직이 중복됨
위에서도 볼 수 있듯이 JWT 검증 로직이 이상하게 여러 번 뜨는 것을 볼 수 있었다.
로깅과는 조금 거리가 있을 수 있으나, 개선하는 김에 같이 해보려고 한다.
나는 현재 JwtFilter + Spring Security를 이용중이기에 이를 파악해보았다.
JwtFilter
import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletException;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.springframework.security.authentication.UsernamePasswordAuthenticationToken;
import org.springframework.security.core.context.SecurityContextHolder;
import org.springframework.security.core.userdetails.UserDetails;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;
import side.onetime.auth.service.CustomUserDetailsService;
import side.onetime.util.JwtUtil;
import java.io.IOException;
@Slf4j
@Component
@RequiredArgsConstructor
public class JwtFilter extends OncePerRequestFilter {
private final JwtUtil jwtUtil;
private final CustomUserDetailsService customUserDetailsService;
/**
* 요청을 처리하며 JWT 검증 및 인증 설정을 수행합니다.
*
* @param request HTTP 요청 객체
* @param response HTTP 응답 객체
* @param filterChain 필터 체인 객체
* @throws ServletException 서블릿 예외 발생 시
* @throws IOException 입출력 예외 발생 시
*/
@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
try {
if (request.getMethod().equalsIgnoreCase("OPTIONS")) {
filterChain.doFilter(request, response);
return;
}
String token = jwtUtil.getTokenFromHeader(request.getHeader("Authorization"));
jwtUtil.validateToken(token);
Long userId = jwtUtil.getClaimFromToken(token, "userId", Long.class);
setAuthentication(userId);
} catch (Exception e) {
log.error("JWT validation failed: " + e.getMessage());
SecurityContextHolder.clearContext();
}
filterChain.doFilter(request, response);
}
/**
* 인증 정보를 SecurityContext에 설정합니다.
*
* @param userId 인증된 사용자의 ID
*/
private void setAuthentication(Long userId) {
UserDetails userDetails = customUserDetailsService.loadUserByUserId(userId);
UsernamePasswordAuthenticationToken authentication = new UsernamePasswordAuthenticationToken(
userDetails,
null,
userDetails.getAuthorities()
);
SecurityContextHolder.getContext().setAuthentication(authentication);
}
/**
* 특정 경로에 대해 JWT 검증을 생략합니다.
*
* @param request HTTP 요청 객체
* @return true일 경우 해당 요청에 대해 필터를 적용하지 않음
*/
@Override
protected boolean shouldNotFilter(HttpServletRequest request) {
String path = request.getServletPath();
return path.startsWith("/api/v1/users/onboarding");
}
}해당 필터는 모든 API 요청에 대해 동작한다. 로직은 아래와 같다.
- 헤더에서 토큰을 꺼낸다.
- 토큰을 검증한다.
- 유저 id를 claim에서 추출한다.
setAuthentication메서드를 호출한다.loadUserByUserId메서드를 호출한다.
/**
* 사용자 ID로 사용자 정보를 로드합니다.
*
* 데이터베이스에서 주어진 사용자 ID를 기반으로 사용자를 조회하고,
* CustomUserDetails 객체로 래핑하여 반환합니다.
*
* @param userId 사용자 ID
* @return 사용자 상세 정보 (CustomUserDetails 객체)
* @throws CustomException 사용자 ID에 해당하는 사용자가 없을 경우 예외를 발생시킵니다.
*/
public UserDetails loadUserByUserId(Long userId) throws UsernameNotFoundException {
User user = userRepository.findById(userId)
.orElseThrow(() -> new CustomException(UserErrorStatus._NOT_FOUND_USER_BY_USERID));
return new CustomUserDetails(user);
}CustomUserDetails객체로 래핑하여 반환한다.
import org.springframework.security.core.GrantedAuthority;
import org.springframework.security.core.userdetails.UserDetails;
import side.onetime.domain.User;
import java.util.Collection;
public record CustomUserDetails(User user) implements UserDetails {
@Override
public Collection<? extends GrantedAuthority> getAuthorities() {
return null;
}
@Override
public String getPassword() {
return null;
}
@Override
public String getUsername() {
return user.getName();
}
@Override
public boolean isAccountNonExpired() {
return true;
}
@Override
public boolean isAccountNonLocked() {
return true;
}
@Override
public boolean isCredentialsNonExpired() {
return true;
}
@Override
public boolean isEnabled() {
return true;
}
public Long getId() {
return user.getId();
}
public String getEmail() {
return user.getEmail();
}
}
-
UsernamePasswordAuthenticationToken에 해당 객체를 넣고 말아서SecurityContext에 설정한다. -
이후 프레젠테이션 or 애플리케이션 레이어에서 해당 컨텍스트에 있는 유저 객체를 꺼내 사용한다.
이러한 위 로직은 기본적으로 모든 HTTP 요청에 대해서 적용되고 있다.
다만 OPTIONS 요청과 shouldNotFilter에 등록해 둔 URI인 /api/v1/users/onboarding에 대해서는 제외된다.
해당 URI만 제외해 둔 이유는, UserController로 들어오는 API들 중 /api/v1/users/onboarding만 인증이 필요없기 때문이었다.
/**
* 유저 정보 조회 API.
*
* 로그인한 유저의 정보를 조회합니다.
*
* @param customUserDetails 인증된 사용자 정보
* @return 유저의 정보를 포함한 응답 객체
*/
@GetMapping("/profile")
public ResponseEntity<ApiResponse<GetUserProfileResponse>> getUserProfile(
@AuthenticationPrincipal CustomUserDetails customUserDetails) {
GetUserProfileResponse getUserProfileResponse = userService.getUserProfile(customUserDetails.user());
return ApiResponse.onSuccess(SuccessStatus._GET_USER_PROFILE, getUserProfileResponse);
}그렇기에 UserController에서는 위와 같이 @AuthenticationPrincipal CustomUserDetails customUserDetails를 통해서 Context에 있는 유저 객체를 정상적으로 가져와 활용하고 있었다.
/**
* 유저 참여 이벤트 목록 조회 API.
*
* 이 API는 인증된 유저가 참여한 모든 이벤트 목록을 조회합니다. 유저의 참여 상태, 이벤트 정보 등이 포함됩니다.
*
* @param authorizationHeader 인증된 유저의 토큰
* @return 유저가 참여한 이벤트 목록
*/
@GetMapping("/user/all")
public ResponseEntity<ApiResponse<List<GetUserParticipatedEventsResponse>>> getUserParticipatedEvents(
@RequestHeader("Authorization") String authorizationHeader) {
List<GetUserParticipatedEventsResponse> getUserParticipatedEventsResponses = eventService.getUserParticipatedEvents(authorizationHeader);
return ApiResponse.onSuccess(SuccessStatus._GET_USER_PARTICIPATED_EVENTS, getUserParticipatedEventsResponses);
}그러나 이외의 Controller들은 변경되지 않고 위와 같이 한 번 더 헤더에서 토큰을 꺼내 검증하는 로직이 그대로 남아있었고, 그 결과 불필요한 검증이 1번 더 일어났던 것이었다.
✅ 해결 방법
shouldNotFilter
/**
* 특정 경로에 대해 JWT Filter를 생략합니다.
*
* @param request HTTP 요청 객체
* @return true일 경우 해당 요청에 대해 필터를 적용하지 않음
*/
@Override
protected boolean shouldNotFilter(HttpServletRequest request) {
String path = request.getServletPath();
String method = request.getMethod();
return path.startsWith("/api/v1/admin") ||
path.startsWith("/api/v1/banners") ||
path.startsWith("/api/v1/members") ||
path.startsWith("/api/v1/tokens") ||
path.startsWith("/api/v1/urls") ||
(생략 ..)
}필터를 타지 않아도 되는 URI들에 대해서 지정해주었고, 나머지는 모두 Context에 있는 유저 객체를 꺼내 쓰도록 변경해주었다.
💫 결과
그 결과 JWT 검증이 1번만 이루어지는 것을 확인할 수 있었다!
또한 추가적으로 JWT 검증 성공에 대한 로그는 불필요할 것 같아, 예외 상황을 제외하고는 모두 제거해주었다.
💣 문제4 - 500에러도 동일하게 출력됨
이미지를 보면 500에러 임에도 불구하고 동일하게 요청 완료로 뜨는 것을 볼 수 있다.
✅ 해결 방법 - 판별 로직 추가
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
Long start = (Long) request.getAttribute(START_TIME);
long duration = System.currentTimeMillis() - (start != null ? start : 0L);
int status = response.getStatus();
if (status >= 400) {
log.error("❌ [{}] {} request failed - {}ms | status={}", request.getMethod(), request.getRequestURI(), duration, status);
} else {
log.info("✅ [{}] {} request completed - {}ms | status={}", request.getMethod(), request.getRequestURI(), duration, status);
}
}이렇게 4xx ~ 5xx 에러인 경우 요청 실패로 표시하도록 로직을 추가하였다.
💫 결과
해당 에러는 서비스에 문제를 야기할 수 있기에, 추후 디스코드나 슬랙 등으로 보내는 기능을 추가하면 좋을 것 같다.
💣 문제5 - 요청 정보가 없음
현재는 어떠한 API를 호출했는지, 그리고 처리 속도가 얼마나 되는지 정도만 로깅을 하고 있다.
만약 특정 상황에서 에러가 발생했거나 병목이 있을 때, 어떠한 요청 값으로 들어왔는지를 모른다면 문제를 해결하기 어려울 것이다.
때문에 Request Param, Request Body, PathVariable 을 각각 로깅하도록 구현하였다.
✅ 해결 방법
가. Request Param
쿼리 파라미터의 경우에는 주로 GET 메서드 호출에서 활용된다.
private Map<String, String> getRequestParams(HttpServletRequest request) {
Map<String, String> paramMap = new HashMap<>();
Enumeration<String> parameterNames = request.getParameterNames();
while (parameterNames.hasMoreElements()) {
String paramName = parameterNames.nextElement();
paramMap.put(paramName, request.getParameter(paramName));
}
return paramMap;
}위 메서드를 LoggingInterceptor 내부에 추가해 준다.
이는 HttpServletRequest의 getParameterNames()와 getParameter() 메서드를 사용해 쿼리 파라미터를 추출해서 Map 형태로 저장해주기에 이후 로깅에 활용할 수 있다.
if (request.getParameterNames().hasMoreElements()) {
log.info("📦️ [{}] {} \nqueryParams : {}", request.getMethod(), request.getRequestURI(), getRequestParams(request));
}또한 해당 조건을 preHandle 메서드 내부에 추가한다. 이는 파라미터가 존재하는 경우에만 동작한다.
나. Request Body
❗️ Request Body를 로깅할 때 주의할 점
- HttpServletRequest의 Request Body는 한 번 읽으면 다시 읽을 수 없음.
-> 내부 스트림은 한 번 소비되면 사라지기 때문!- 즉, Interceptor에서 Request Body를 읽어 로깅하면, 컨트롤러에서 해당 바디를 다시 읽을 수 없게 되어 정상적인 처리가 불가능해 짐.
때문에 CustomHttpRequestWrapper를 사용하여 요청 본문을 미리 캐싱해 두어야 한다.
Wrapper 클래스는 Request Body를 여러 번 읽을 수 있도록 InputStream을 내부적으로 캐싱하여 관리한다.
import jakarta.servlet.ReadListener;
import jakarta.servlet.ServletInputStream;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletRequestWrapper;
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
public class CustomHttpRequestWrapper extends HttpServletRequestWrapper {
private final byte[] requestBody;
public CustomHttpRequestWrapper(HttpServletRequest request) throws IOException {
super(request);
try (InputStream is = request.getInputStream(); ByteArrayOutputStream baos = new ByteArrayOutputStream()) {
byte[] buffer = new byte[1024];
int length;
while ((length = is.read(buffer)) != -1) {
baos.write(buffer, 0, length);
}
this.requestBody = baos.toByteArray();
}
}
@Override
public ServletInputStream getInputStream() {
ByteArrayInputStream bais = new ByteArrayInputStream(this.requestBody);
return new ServletInputStream() {
@Override public int read() {
return bais.read();
}
@Override public boolean isFinished() {
return bais.available() == 0;
}
@Override public boolean isReady() {
return true;
}
@Override public void setReadListener(ReadListener readListener) {
}
};
}
public byte[] getRequestBody() {
return this.requestBody;
}
}위 클래스를 생성해 준다.
해당 클래스는 HttpServletRequestWrapper를 상속 받아서 Request Body를 여러 번 읽을 수 있도록 처리해 준다.
this.requestBody = baos.toByteArray(); 여기서 내부 스트림을 1번 읽은 후에, 메모리에 바이트배열 복사본을 저장해 둔다. 이후로는 필요 시 복사본을 계속해서 사용하는 구조이다.
import jakarta.servlet.*;
import jakarta.servlet.http.HttpServletRequest;
import org.springframework.stereotype.Component;
import side.onetime.global.wrapper.CustomHttpRequestWrapper;
import java.io.IOException;
@Component
public class RequestWrapperFilter implements Filter {
@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
throws IOException, ServletException {
if (request instanceof HttpServletRequest httpRequest) {
CustomHttpRequestWrapper wrapper = new CustomHttpRequestWrapper(httpRequest);
chain.doFilter(wrapper, response);
} else {
chain.doFilter(request, response);
}
}
}
위에서 만든 CustomHttpRequestWrapper 클래스가 모든 요청에 대해서 적용될 수 있도록 위 필터를 추가해서 적용해 주자.
해당 필터는
1) javax.servlet.Filter를 구현했고,
2) @Component가 붙어 있어서 Spring Bean으로 등록된다.
따라서 별도로 필터 등록을 하지 않아도 된다.
단, 등록 순서 조정이나 필터 적용 URL 지정이 필요할 경우에는 FilterRegistrationBean으로 명시 등록이 필요하다.
if (request instanceof CustomHttpRequestWrapper wrapper) {
String body = new String(wrapper.getRequestBody());
if (!body.isBlank()) {
try {
ObjectMapper mapper = new ObjectMapper();
Object json = mapper.readValue(body, Object.class);
String prettyBody = mapper.writerWithDefaultPrettyPrinter().writeValueAsString(json);
log.info("📦 [{}] {} \nbody : {}", request.getMethod(), request.getRequestURI(), prettyBody);
} catch (Exception e) {
log.info("📦 [{}] {} \nbody(raw) : {}", request.getMethod(), request.getRequestURI(), body);
}
}
}마지막으로 위 부분을 preHandle 메서드 내에 추가한다.
다. PathVariable
if (handler instanceof HandlerMethod) {
Map<String, String> pathVariables =
(Map<String, String>) request.getAttribute(HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE);
if (pathVariables != null && !pathVariables.isEmpty()) {
log.info("📦 [{}] {} \npathVars : {}", request.getMethod(), request.getRequestURI(), pathVariables);
}
}마지막으로 PathVariable은 HandlerMethod를 확인함으로써 추출할 수 있다. 위 부분을 preHandle 메서드 내에 추가한다.
라. preHandle
위 3가지를 모두 적용한 preHandle 메서드는 아래와 같다.
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
if (handler instanceof HandlerMethod) {
Map<String, String> pathVariables =
(Map<String, String>) request.getAttribute(HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE);
if (pathVariables != null && !pathVariables.isEmpty()) {
log.info("📦 [{}] {} \npathVars : {}", request.getMethod(), request.getRequestURI(), pathVariables);
}
}
if (request.getParameterNames().hasMoreElements()) {
log.info("📦️ [{}] {} \nqueryParams : {}", request.getMethod(), request.getRequestURI(), getRequestParams(request));
}
if (request instanceof CustomHttpRequestWrapper wrapper) {
String body = new String(wrapper.getRequestBody());
if (!body.isBlank()) {
try {
ObjectMapper mapper = new ObjectMapper();
Object json = mapper.readValue(body, Object.class);
String prettyBody = mapper.writerWithDefaultPrettyPrinter().writeValueAsString(json);
log.info("📦 [{}] {} \nbody : {}", request.getMethod(), request.getRequestURI(), prettyBody);
} catch (Exception e) {
log.info("📦 [{}] {} \nbody(raw) : {}", request.getMethod(), request.getRequestURI(), body);
}
}
}
request.setAttribute("startTime", System.currentTimeMillis());
return true;
}💫 결과
2025-05-03T05:31:18.089+09:00 INFO 88263 --- [nio-8090-exec-6] s.o.g.interceptor.LoggingInterceptor : 📦️ [GET] /api/v1/admin/logging
queryParams : {name=temp}
2025-05-03T05:31:18.095+09:00 INFO 88263 --- [nio-8090-exec-6] s.o.g.interceptor.LoggingInterceptor : ✅ [GET] /api/v1/admin/logging request completed - 4ms | status=200
2025-05-03T05:31:26.955+09:00 INFO 88263 --- [nio-8090-exec-8] s.o.g.interceptor.LoggingInterceptor : 📦 [POST] /api/v1/admin/logging
body : {
"name" : "temp"
}
2025-05-03T05:31:26.965+09:00 INFO 88263 --- [nio-8090-exec-8] s.o.g.interceptor.LoggingInterceptor : ✅ [POST] /api/v1/admin/logging request completed - 9ms | status=200
2025-05-03T05:31:30.481+09:00 INFO 88263 --- [nio-8090-exec-7] s.o.g.interceptor.LoggingInterceptor : 📦 [PATCH] /api/v1/admin/logging/1
pathVars : {id=1}
2025-05-03T05:31:30.492+09:00 INFO 88263 --- [nio-8090-exec-7] s.o.g.interceptor.LoggingInterceptor : ✅ [PATCH] /api/v1/admin/logging/1 request completed - 11ms | status=200
테스트용 API를 만들고 호출해 보니, 위와 같이 3가지 경우 모두 잘 로깅되는 것을 볼 수 있다!
🏁 마무리
2025-05-03T05:23:19.179+09:00 INFO 1 --- [nio-8090-exec-4] s.o.g.interceptor.LoggingInterceptor : 📦 [GET] /api/v1/schedules/date/e7285da6-1d97-40cf-88d7-63c34285485e
pathVars : {event_id=e7285da6-1d97-40cf-88d7-63c34285485e}
2025-05-03T05:23:19.947+09:00 INFO 1 --- [nio-8090-exec-4] s.o.g.interceptor.LoggingInterceptor : ✅ [GET] /api/v1/schedules/date/e7285da6-1d97-40cf-88d7-63c34285485e request completed - 766ms | status=200
2025-05-03T05:23:20.087+09:00 INFO 1 --- [nio-8090-exec-5] s.o.g.interceptor.LoggingInterceptor : 📦 [GET] /api/v1/events/e7285da6-1d97-40cf-88d7-63c34285485e/most
pathVars : {event_id=e7285da6-1d97-40cf-88d7-63c34285485e}
2025-05-03T05:23:20.156+09:00 INFO 1 --- [nio-8090-exec-5] s.o.g.interceptor.LoggingInterceptor : ✅ [GET] /api/v1/events/e7285da6-1d97-40cf-88d7-63c34285485e/most request completed - 68ms | status=200최종적으로 위와 같은 형태의 로깅을 볼 수 있게 되었다.
아직 개선할 부분이 많지만, 그래도 이전에 비하면 많이 나아졌다고 생각한다.
느낀 점
- 이전에는 Filter에 대한 이해가 거의 없는 상태로 JwtFilter를 도입했더니, 검증을 2번 하는 문제도 발생했던 것 같다. 앞으로는 무엇인가를 도입하기 전에 더욱 꼼꼼히 공부를 해야할 것 같다.
- Spring Security에 대한 공부도 미룬지 몇 달 째인데, 시간이 날 때마다 공부를 하면서 개선해 봐야겠다.
- 배포 & 테스트 서버에서도 SQL문이 출력되도록 하는 등의 문제가 있던 것을 보아, 여전히 서비스를 운영하는 것에 대해 미숙함이 많은 것 같다. 더 많이 알아보고 공부해 보자.
- 로깅 -> 모니터링 -> 성능 개선의 사이클이 있는 것 같다. 로깅을 빠르게 마무리 하고 모니터링을 시작해야겠다.
앞으로 해야할 일
- 요청 별로 고유값 지정하여 빠른 검색 가능하게 하기
- LogBack 도입하여 로그 더욱 개선하기
- AWS Cloud Watch 도입 -> 에러 파악하여 디스코드로 연동하기
- 병목 지점 찾아서 성능 개선하기
참고한 블로그
https://velog.io/@dongjae0803/Spring-Boot-로그-관리-잘하고-계신가요-Logging
안녕하세요. 비즈니스를 이해하는 백엔드 개발자, 한상호입니다.
굿.. 저도 미루고 미룬 로그작업인데 해봐야겠어요 .. 여행도 부럽고 화이팅이에요