안녕하세요! Betalabs의 백엔드 개발팀의 Soora 입니다.
서비스를 정상적으로 오픈 후 어느 날 갑자기 전혀 예상치 못한 ElastiCache
의 Redis
에서 Memory Leak
이 발생했습니다. 당황하지 않고 안전한 운영을 위한 응급처치와 해결하기 위해서 노력했던 방법을 이번 글에서 소개해보려 합니다.
Spring Boot
를 사용하기 위해 AWS EC2
를 N대 이상을 사용하고 있습니다. 사용자의 인증/인가를 위해 Spring Security
를 사용하고 있으며, 사용자의 로그인 정보를 모든 서버에 공유, 데이터 캐싱을 위해서 위해서 AWS ElastiCache
의 Redis
를 사용하고 있습니다.
서비스를 오픈 후 안정적인 운영을 하던 어느 날, 갑자기 OutOfMemory
에러 알림 채널을 통해 Error Log
가 엄청나게 쏟아져나오기 시작했습니다.
Error: *Error in execution; nested exception is io.lettuce.core.RedisCommandExecutionException: OOM command not allowed when used memory > 'maxmemory'.*
org.springframework.data.redis.RedisSystemException: Error in execution; nested exception is io.lettuce.core.RedisCommandExecutionException: OOM command not allowed when used memory > 'maxmemory'.
Error Log
를 확인해보면 Redis
의 Memory
가 부족하다는 의미였습니다. 하지만 문제가 발생한 Redis
에는 많은 데이터가 쌓이지 않고, 시간이 지나면 자동으로 제거가 될 수 있도록 설정했습니다. 결국 문제가 어디서 발생했는지 예측하기 어려웠고, 혼란에 빠지기 시작했습니다. 원인을 파악하고 수정하는 것은 오래 걸릴 것이라는 판단하였고, 우선 서비스의 안정적인 운영을 위해 AWS ElastiCache
의 Redis
를 Scale Up
을 하기로 했습니다.
AWS ElasticCache
를 통해 모니터링을 하면 다음과 같이 Memory
가 줄어드는 것이 확인할 수 있었습니다.
데이터를 가져오는 API
중 어떤 데이터는 항상 DB
에서 가져와야 할 것이지만, 꼭 그렇지 않은 데이터도 있습니다. 문제가 된다고 생각한 데이터는 항상 최신의 데이터가 필요했던 것은 아니었고, 요구사항을 생각해보면 Redis
에서 제공하는 기능을 이용하는 것이 낫다고 판단하여 Redis
에 저장하고 있었습니다. 이 데이터의 개수는 100,000
건이 넘었고, 각각의 용량은 매우 적었습니다. 하지만 이 데이터 때문에 Memory
가 부족할 수도 있지 않을까? 라는 작은 의심을 하고 있었습니다. 결국 데이터가 사용하고 있는 Memory
의 총합은 100MB
도 안되었고, 데이터를 한번 저장하면 늘어나거나, 줄어드는 일이 전혀 없었기에 큰 문제가 되지 않았습니다.
한 서버에서 발생한 메시지는 모든 서버에 전파가 되어야 하는 요구사항이 있었기에 Redis
의 Pub/Sub
을 사용하고 있었습니다. 발행되는 메시지는 사용자의 행동으로 발행이 되었고, 결국 사용자가 늘어나면 더 많은 메시지가 발행이 되는 구조였습니다. 만약 메시지가 발행이 되고, 삭제가 안 된다면 당연히 Memory Leak
으로 연결될 것이 였습니다. 다른 Redis
의 자료구조는 Memory
를 사용하여 저장하고 있지만, Pub/Sub
은 다른 구조라고 생각이 들어서 어떻게 동작하는지 확인이 필요했습니다. 여러 문서를 찾아본 결과 Pub/Sub
의 메시지는 Memory
에 저장하지 않고, 사라지는 구조였습니다. 어느 정도 확신했지만, 결국 Pub/Sub
문제는 아니었습니다.
https://redis.com/redis-best-practices/communication-patterns/pub-sub/
문제를 파악하기 위해 그래프를 분석하기 시작했고, 특정 시간대에 Memory
가 급격히 줄어드는 패턴을 보이기 시작했습니다. 특정 시간대는 사용자의 활동이 가장 많은 시간대였고, 결국 SET
, Pub/Sub
도 아닌 상황에서 사용자의 활동과 가장 관련이 있던 부분은 여러 서버에서 로그인 정보 공유를 위한 Session Clustering
라고 확신을 갖기 시작했습니다. 하지만 어느 문서를 찾아봐도 Session Clustering
의 문제로 Memory Leak
이 되었다는 문서를 찾지 못했지만, 확신이 생기기 시작했습니다.
가장 확신이 있던 Session Clustering
에 대해서 깊게 분석할 필요가 있었습니다.
로그인하면 유의미하게 KEY
개수가 변화하는지 확인이 필요했습니다. 확인을 위해서 Redis
의 DBSIZE
명령어를 사용했고, 5일 정도 모니터링을 진행했습니다. 하지만 유의미하게 KEY
의 개수는 늘어나거나 줄어들지는 않았고, Memory
의 사용량은 지속해서 늘어나고 있었습니다. 결국 KEY
가 늘어나서 Memory
가 부족했던 것은 아니고, 어떤 KEY
가 시간이 지날수록 더 많은 Memory
를 사용하고 있다는 것을 확신했습니다.
어떤 KEY
가 시간이 지날수록 더 많은 Memory
를 사용하고 있는지 파악하기 위해서 KEYS *
명령어를 통해서 생성된 KEY
를 확인했습니다. 그리고 다음과 같은 패턴의 KEY
를 확인할 수 있었습니다.
spring:session:expirations:{date}
spring:session:sessions:{sessionId}
spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:{userId}
spring:session:sessions:expires:{sessionId}
KEY
가 사용하고 있는 Memory
를 확인하기 위해 MEMORY USAGE {key}
를 사용했습니다. 모든 KEY
는 정상적인 범주 안에서 Memory
를 사용하고 있었지만, spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:{userId}
(이하 PRINCIPAL_NAME_INDEX_NAME:{userId}
)의 KEY
는 범주를 넘어서는 Memory
를 사용하고 있었습니다. 그리고 오래된 사용자일 수록 사용중인 100MB
가 넘는 Memory
를 사용하고 있었습니다. 이 KEY
가 문제라는것을 증명해야 했고, 며칠간의 모니터링을 진행한 결과 의심된 KEY
가 사용하는 Memory
의 양은 줄어들지 않고, 시간이 지날수록 늘어나고 있었습니다. 모니터링 결과 어떤 KEY
가 문제인지 알게 되었습니다.
Redis
에서 KEY
를 생성할 때 만료 시간을 주어 자동으로 삭제할 수 있도록 설정이 가능합니다. 만약에 PRINCIPAL_NAME_INDEX_NAME:{userId}
가 TTL
이 적용이 되어있었다면, 자동으로 삭제가 되어 Memory
문제는 없었을 것입니다. 하지만 TTL
명령어를 통해 확인해본 결과 -1(만료시간 없음)
로 설정이 되어있음을 확인했습니다.
ttl spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:user
:-1
ttl spring:session:sessions:expires:45bdf32d-53dd-4d03-827b-cb94c99a862e
:90
ttl spring:session:sessions:45bdf32d-53dd-4d03-827b-cb94c99a862e
:387
ttl spring:session:expirations:1658884020000
:384
문제를 해결하기 위한 단순한 방법으로 배치를 이용하여 KEY
를 주기적으로 삭제해줘도 충분했지만, KEY
의 생명 주기와 사용하는 이유가 매우 궁금해졌습니다. 운영 환경에서는 테스트 시 어떤 문제가 발생할지 모르니, Local
에 같은 환경 세팅을 하여 분석하기 시작했습니다.
사용자에게 할당된 모든 sessionId
를 얻으려면 매우 복잡할 것 입니다. 하지만 PRINCIPAL_NAME_INDEX_NAME:{userId}
를 이용하면 사용자에게 할당된 모든 sessionId
를 얻어올 수 있습니다. 이 sessionId
를 통해 역으로 session
을 추적할 수 있고, 필요에 따라 세션을 제거할 수 있게 됩니다.
예를 들어 사용자가 비밀번호를 변경하면 다른 기기에서는 로그아웃이 되어야 한다는 정책이 있다고 생각해봅니다. 그러면 사용자에게 할당된 모든 sessionId
를 찾아서 삭제해줘야 합니다. 이때 PRINCIPAL_NAME_INDEX_NAME:{userId}
를 통해 사용자의 모든 sessionId
를 제거해서 로그아웃시킬 수 있게 됩니다.
Spring Session
의존성을 추가하게 되면, SessionRepositoryFilter
를 자동으로 추가가 됩니다. 이 필터는 다른 필터를 실행하고, 마지막으로 wrappedRequest.commitSession();
을 실행하는 코드를 가지고 있습니다.
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
request.setAttribute(SESSION_REPOSITORY_ATTR, this.sessionRepository);
SessionRepositoryFilter<S>.SessionRepositoryRequestWrapper wrappedRequest = new SessionRepositoryFilter.SessionRepositoryRequestWrapper(request, response);
SessionRepositoryFilter.SessionRepositoryResponseWrapper wrappedResponse = new SessionRepositoryFilter.SessionRepositoryResponseWrapper(wrappedRequest, response);
try {
filterChain.doFilter(wrappedRequest, wrappedResponse);
} finally {
wrappedRequest.commitSession();
}
}
wrappedRequest.commitSession()
에서는 SessionRepositoryFilter.this.sessionRepository.save(session)
코드를 실행하여 sessionRepository
에 사용자의 session
을 저장합니다.
private void commitSession() {
SessionRepositoryFilter<S>.SessionRepositoryRequestWrapper.HttpSessionWrapper wrappedSession = this.getCurrentSession();
if (wrappedSession == null) {
if (this.isInvalidateClientSession()) {
SessionRepositoryFilter.this.httpSessionIdResolver.expireSession(this, this.response);
}
} else {
S session = wrappedSession.getSession();
this.clearRequestedSessionCache();
SessionRepositoryFilter.this.sessionRepository.save(session);
String sessionId = session.getId();
if (!this.isRequestedSessionIdValid() || !sessionId.equals(this.getRequestedSessionId())) {
SessionRepositoryFilter.this.httpSessionIdResolver.setSessionId(this, this.response, sessionId);
}
}
}
여기서 sessionRepository
는 Interface
이기 때문에, 어떤 구현체를 사용하는지에 따라 원인 생성이 되는 시점 확인이 가능해 보였습니다.
Redis
를 통해 세션 관리를 하기 위해서 @EnableRedisHttpSession
를 사용합니다. 이 어노테이션을 사용하게 되면, @Import({RedisHttpSessionConfigurati.class})
를 통해 RedisHttpSessionConfiguration
이 추가되는 것이 확인이 가능합니다.
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.TYPE})
@Documented
@Import({RedisHttpSessionConfiguration.class})
@Configuration(
proxyBeanMethods = false
)
public @interface EnableRedisHttpSession {
}
여기서 RedisHttpSessionConfigurati
를 확인해보면 public RedisIndexedSessionReposito sessionRepository()
를 통해 RedisIndexedSessionRepository
를 Bean
으로 올리는 것이 확인이 가능합니다.
@Bean
public RedisIndexedSessionRepository sessionRepository() {
// ...
RedisIndexedSessionRepository sessionRepository = new RedisIndexedSessionRepository(redisTemplate);
// ...
return sessionRepository;
}
그렇다면 sessionRepository
의 구현체는 RedisIndexedSessionReposito
를 사용하고 있었고, save(session)
메서드의 구현체 확인이 가능해졌습니다. RedisIndexedSessionReposito.save(session)
은 session.save()
를 다시 호출하는 것을 확인할 수 있었습니다.
public void save(RedisIndexedSessionRepository.RedisSession session) {
session.save();
// ...
}
session.save()
은 다시 session.saveDelta()
를 호출하는 것이 확인이 가능합니다.
private void save() {
this.saveChangeSessionId();
this.saveDelta();
}
session.saveDelta()
에서 PRINCIPAL_NAME_INDEX_NAME:{userId}
의 KEY
에 sessionId
를 저장하는 것을 확인할 수 있었습니다.
private void saveDelta() {
if (!this.delta.isEmpty()) {
String sessionId = this.getId();
RedisIndexedSessionRepository.this.getSessionBoundHashOperations(sessionId).putAll(this.delta);
String principalSessionKey = RedisIndexedSessionRepository.getSessionAttrNameKey(FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME);
String securityPrincipalSessionKey = RedisIndexedSessionRepository.getSessionAttrNameKey("SPRING_SECURITY_CONTEXT");
if (this.delta.containsKey(principalSessionKey) || this.delta.containsKey(securityPrincipalSessionKey)) {
if (this.originalPrincipalName != null) {
String originalPrincipalRedisKey = RedisIndexedSessionRepository.this.getPrincipalKey(this.originalPrincipalName);
RedisIndexedSessionRepository.this.sessionRedisOperations.boundSetOps(originalPrincipalRedisKey).remove(new Object[]{sessionId});
}
Map<String, String> indexes = RedisIndexedSessionRepository.this.indexResolver.resolveIndexesFor(this);
String principal = (String)indexes.get(FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME);
this.originalPrincipalName = principal;
if (principal != null) {
String principalRedisKey = RedisIndexedSessionRepository.this.getPrincipalKey(principal);
RedisIndexedSessionRepository.this.sessionRedisOperations.boundSetOps(principalRedisKey).add(new Object[]{sessionId});
}
}
this.delta = new HashMap(this.delta.size());
Long originalExpiration = this.originalLastAccessTime != null ? this.originalLastAccessTime.plus(this.getMaxInactiveInterval()).toEpochMilli() : null;
RedisIndexedSessionRepository.this.expirationPolicy.onExpirationUpdated(originalExpiration, this);
}
}
단순히 코드를 통해 추측은 가능했지만, 정말 런타임시에도 우리가 예상하는 방향으로 진행이 되는지 확인이 필요했습니다.
필요한 지점에 BreakPoint
를 걸어서 통해 확인한 결과 spring:session:index:org.springframework.session.FindByIndexNameSessionRepos.PRINCIPAL_NAME_INDEX_NAME:user
에 sessionId
를 저장하는 것을 확인할 수 있었습니다.
생성이 언제 되는지 확인이 되었으면, 반대로 제거가 언제 되는지 확인이 필요했습니다. 만약 제거되는 코드가 없다면 직접 만들어서 해결하면 되었고, 그게 아니였다면 무엇이 문제인지 파악해서 해결해야 했습니다.
상수인 PRINCIPAL_NAME_INDEX_NAME
를 통해서 생성되는 것을 확인했으니, 반대로 PRINCIPAL_NAME_INDEX_NAME
를 통해 삭제되는 부분을 찾으면 되었습니다. 결국 같은 java
안에 cleanupPrincipalIndex
를 통해 삭제가 되는 것을 확인할 수 있었습니다.
private void cleanupPrincipalIndex(RedisIndexedSessionRepository.RedisSession session) {
String sessionId = session.getId();
Map<String, String> indexes = this.indexResolver.resolveIndexesFor(session);
String principal = (String)indexes.get(PRINCIPAL_NAME_INDEX_NAME);
if (principal != null) {
this.sessionRedisOperations.boundSetOps(this.getPrincipalKey(principal)).remove(new Object[]{sessionId});
}
}
그렇다면 해당 함수를 호출하는 부분만 찾으면, 언제 삭제가 되는지 파악할 수 있었습니다. 해당 함수를 호출하는 부분을 찾아가 보면 onMessage
라는 함수를 통해서 삭제되는 것을 확인할 수 있고, 어떠한 KEY
가 만료되거나, 삭제되었을 때 문제가 되는 PRINCIPAL_NAME_INDEX_NAME:{userId}
안의 sessionId
가 삭제 되는 것을 확인했습니다.
public void onMessage(Message message, byte[] pattern) {
byte[] messageChannel = message.getChannel();
if (ByteUtils.startsWith(messageChannel, this.sessionCreatedChannelPrefixBytes)) {
Map<Object, Object> loaded = (Map)this.defaultSerializer.deserialize(message.getBody());
this.handleCreated(loaded, new String(messageChannel));
} else {
byte[] messageBody = message.getBody();
if (ByteUtils.startsWith(messageBody, this.expiredKeyPrefixBytes)) {
boolean isDeleted = Arrays.equals(messageChannel, this.sessionDeletedChannelBytes);
if (isDeleted || Arrays.equals(messageChannel, this.sessionExpiredChannelBytes)) {
String body = new String(messageBody);
int beginIndex = body.lastIndexOf(":") + 1;
int endIndex = body.length();
String sessionId = body.substring(beginIndex, endIndex);
RedisIndexedSessionRepository.RedisSession session = this.getSession(sessionId, true);
if (session == null) {
logger.warn("Unable to publish SessionDestroyedEvent for session " + sessionId);
return;
}
if (logger.isDebugEnabled()) {
logger.debug("Publishing SessionDestroyedEvent for session " + sessionId);
}
this.cleanupPrincipalIndex(session);
if (isDeleted) {
this.handleDeleted(session);
} else {
this.handleExpired(session);
}
}
}
}
}
그렇다면 어떤 KEY
가 만료/삭제되었을 때 문제가 되는 KEY
의 sessionId
도 삭제할지 궁금했습니다. 필요한 지점에 BreakPoint
를걸어서 확인한 결과 spring:session:sessions:expires:{sessionId}
가 Redis
에서 제공하는 TTL
기능을 통해 Expired
가 되면 onMessage
함수를 호출한다는 것을 확인할 수 있었습니다.
어느 부분이 문제가 되는지, 생성과 삭제가 언제 이뤄지는지 확인했습니다. 그렇다면 정상적으로 Redis
의 Event
를 Listen
을 해서 삭제가 되는 코드가 분명히 있는데, 어떤 이유로 sessionId
는 삭제가 안 되는 건지 궁금해집니다.
문제를 해결하기 위해서는 Redis Event
에 대해서 알아보면 더 이해하기 쉬울 것 같습니다. Redis
에서는 특정 이벤트가 발생할 수 있는 여러 조건이 있습니다. 명령어를 실행하거나, KEY
가 생성 또는 제거되는 등의 행동이 있을 때 이벤트를 발생시킬 수 있습니다. 하지만 이벤트를 발생시키기 위해서는 Redis
의 설정 파일인 redis.conf
에 발생할 이벤트를 정의 해줘야 합니다.
https://redis.io/docs/manual/keyspace-notifications/#configuration
테스트를 위해 Local
에 환경을 만들었을 때는 정상적으로 이벤트가 발생되어서 onMessage
가 실행된 것을 확인할 수 있었습니다. 그렇다면 왜 ElastiCache
에서는 동작하지 않았을까요?
ElastiCache
에서는 파라미터 그룹 메뉴를 통해 설정을 할 수 있습니다. 하지만 이벤트와 관련된 옵션인 notify-keyspace-events
은 아무것도 설정이 되어있지 않습니다. 결국 KEY
가 만료가 되어도, 이벤트가 발생하지 않았던 것 입니다.
KEY
가 만료되는 이벤트를 발생시키는 옵션인 x(Expired events (events generated every time a key expires)
가 비활성화 되어있는 것을 확인했습니다. 그렇다면 옵션을 활성화를 하면 정상적으로 삭제가 될 것을 예상합니다.
25%
-> 100%
까지 오르다가, Scale Up
을 통해 48%
까지 내려오고, 이슈 해결 후 1.7%
에서 머물고 있는 것이 확인이 가능합니다,
당황하기 시작하면 오히려 더 큰 상처를 내거나, 잘못된 길을 갈 수 있다고 생각합니다. 그 상황에서 침착하고 Scale Up
을 통해 서비스를 정상적으로 운영을 한 것은 옳은 선택이였다고 생각합니다. Scale Up
을 통해 안정화가 된 다음부터 분석을 시작하여 하나하나 파악해서 수정을 했던 것도 좋은 경험이었습니다. 이번 경험을 통해 앞으로도 잘 알려지지 않은 이슈도 해결할 수 있다는 자신감이 생겼습니다. 예상치 못한 이슈가 발생해도 당황하지 않고, 해결해내는 것 또한 실력이지 않을까 싶습니다.
좋은 글 감사합니다.