환상(장)의 (ElastiCache + Spring Session + Spring Security) Memory Leak

안녕하세요! 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가 줄어드는 것이 확인할 수 있었습니다.

의심 1. Redis SET

데이터를 가져오는 API중 어떤 데이터는 항상 DB에서 가져와야 할 것이지만, 꼭 그렇지 않은 데이터도 있습니다. 문제가 된다고 생각한 데이터는 항상 최신의 데이터가 필요했던 것은 아니었고, 요구사항을 생각해보면 Redis에서 제공하는 기능을 이용하는 것이 낫다고 판단하여 Redis에 저장하고 있었습니다. 이 데이터의 개수는 100,000건이 넘었고, 각각의 용량은 매우 적었습니다. 하지만 이 데이터 때문에 Memory가 부족할 수도 있지 않을까? 라는 작은 의심을 하고 있었습니다. 결국 데이터가 사용하고 있는 Memory의 총합은 100MB도 안되었고, 데이터를 한번 저장하면 늘어나거나, 줄어드는 일이 전혀 없었기에 큰 문제가 되지 않았습니다.

의심 2. Pub/Sub

한 서버에서 발생한 메시지는 모든 서버에 전파가 되어야 하는 요구사항이 있었기에 Redis의 Pub/Sub을 사용하고 있었습니다. 발행되는 메시지는 사용자의 행동으로 발행이 되었고, 결국 사용자가 늘어나면 더 많은 메시지가 발행이 되는 구조였습니다. 만약 메시지가 발행이 되고, 삭제가 안 된다면 당연히 Memory Leak으로 연결될 것이 였습니다. 다른 Redis의 자료구조는 Memory를 사용하여 저장하고 있지만, Pub/Sub은 다른 구조라고 생각이 들어서 어떻게 동작하는지 확인이 필요했습니다. 여러 문서를 찾아본 결과 Pub/Sub의 메시지는 Memory에 저장하지 않고, 사라지는 구조였습니다. 어느 정도 확신했지만, 결국 Pub/Sub문제는 아니었습니다.

https://redis.com/redis-best-practices/communication-patterns/pub-sub/

의심 3. Session Clustering

문제를 파악하기 위해 그래프를 분석하기 시작했고, 특정 시간대에 Memory가 급격히 줄어드는 패턴을 보이기 시작했습니다. 특정 시간대는 사용자의 활동이 가장 많은 시간대였고, 결국 SET, Pub/Sub도 아닌 상황에서 사용자의 활동과 가장 관련이 있던 부분은 여러 서버에서 로그인 정보 공유를 위한 Session Clustering라고 확신을 갖기 시작했습니다. 하지만 어느 문서를 찾아봐도 Session Clustering의 문제로 Memory Leak이 되었다는 문서를 찾지 못했지만, 확신이 생기기 시작했습니다.

원인 파악

가장 확신이 있던 Session Clustering에 대해서 깊게 분석할 필요가 있었습니다.

DBSIZE

로그인하면 유의미하게 KEY개수가 변화하는지 확인이 필요했습니다. 확인을 위해서 Redis의 DBSIZE명령어를 사용했고, 5일 정도 모니터링을 진행했습니다. 하지만 유의미하게 KEY의 개수는 늘어나거나 줄어들지는 않았고, Memory의 사용량은 지속해서 늘어나고 있었습니다. 결국 KEY가 늘어나서 Memory가 부족했던 것은 아니고, 어떤 KEY가 시간이 지날수록 더 많은 Memory를 사용하고 있다는 것을 확신했습니다.

MEMORY USAGE

어떤 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가 문제인지 알게 되었습니다.

TTL

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

PRINCIPAL_NAME_INDEX_NAME?

문제를 해결하기 위한 단순한 방법으로 배치를 이용하여 KEY를 주기적으로 삭제해줘도 충분했지만, KEY의 생명 주기와 사용하는 이유가 매우 궁금해졌습니다. 운영 환경에서는 테스트 시 어떤 문제가 발생할지 모르니, Local에 같은 환경 세팅을 하여 분석하기 시작했습니다.

무슨 KEY 일까?

사용자에게 할당된 모든 sessionId를 얻으려면 매우 복잡할 것 입니다. 하지만 PRINCIPAL_NAME_INDEX_NAME:{userId}를 이용하면 사용자에게 할당된 모든 sessionId를 얻어올 수 있습니다. 이 sessionId를 통해 역으로 session을 추적할 수 있고, 필요에 따라 세션을 제거할 수 있게 됩니다.
예를 들어 사용자가 비밀번호를 변경하면 다른 기기에서는 로그아웃이 되어야 한다는 정책이 있다고 생각해봅니다. 그러면 사용자에게 할당된 모든 sessionId를 찾아서 삭제해줘야 합니다. 이때 PRINCIPAL_NAME_INDEX_NAME:{userId}를 통해 사용자의 모든 sessionId를 제거해서 로그아웃시킬 수 있게 됩니다.

언제 생성이 되는가? (Deep Dive)

1. SessionRepositoryFilter

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이기 때문에, 어떤 구현체를 사용하는지에 따라 원인 생성이 되는 시점 확인이 가능해 보였습니다.

RedisIndexedSessionRepository

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를 저장하는 것을 확인할 수 있었습니다.

언제 제거가 되는가?

생성이 언제 되는지 확인이 되었으면, 반대로 제거가 언제 되는지 확인이 필요했습니다. 만약 제거되는 코드가 없다면 직접 만들어서 해결하면 되었고, 그게 아니였다면 무엇이 문제인지 파악해서 해결해야 했습니다.

onMessage

상수인 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 Event에 대해서 알아보면 더 이해하기 쉬울 것 같습니다. Redis에서는 특정 이벤트가 발생할 수 있는 여러 조건이 있습니다. 명령어를 실행하거나, KEY가 생성 또는 제거되는 등의 행동이 있을 때 이벤트를 발생시킬 수 있습니다. 하지만 이벤트를 발생시키기 위해서는 Redis의 설정 파일인 redis.conf에 발생할 이벤트를 정의 해줘야 합니다.

https://redis.io/docs/manual/keyspace-notifications/#configuration

ElastiCache Option

테스트를 위해 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을 통해 안정화가 된 다음부터 분석을 시작하여 하나하나 파악해서 수정을 했던 것도 좋은 경험이었습니다. 이번 경험을 통해 앞으로도 잘 알려지지 않은 이슈도 해결할 수 있다는 자신감이 생겼습니다. 예상치 못한 이슈가 발생해도 당황하지 않고, 해결해내는 것 또한 실력이지 않을까 싶습니다.