[Trouble Shooting] 종료하지 않은 Transaction을 Connection Pool로 반환

kukjunLEE·2024년 4월 1일

TROUBLESHOOTING

Trouble Shooting

목록 보기

5/5

문제

해당 문제가 발생하는 상황을 Sequence Diagram으로 표현해보면, 다음과 같습니다.

문제 상황

해당 현상에 대해서 더 설명하면 다음과 같습니다.

서버 재부팅 이후 2~30분 동안은 나타나지 않음.
문제가 발생하고 실제 데이터베이스에서 조회 해보면, 변경되지 않은 값이 조회 됨.
업데이트 한 값이 바로 조회될 때도 있고, 바로 조회 안될 때도 있음.
3-1. 조회 되지 않을 때, 서버를 재부팅하거나 더 시간이 지나게 되면 이전 값이 다시 조회됨.

외부의 문제 확인

DataBase
1. DB는 RDBMS, MariaDB의 latest 버전을 쓰고 있었고, 해당 버전에서 관련된 취약점을 찾을 수 없었습니다.
2. DB는 해당 Application과 DataGrip 외에는 Connection을 가지고 있지 않았습니다.

Cache
1. 이전 값 조회라는 키워드가 사실 캐시랑 연관이 될 수 있는데, 먼저 Radis와 같은 캐싱 데이터베이스를 사용하지 않았습니다.
2. 해당 문제와 관련해서 Nestjs Typeorm에서 캐시를 설정할 수 있다고 해서, 확인하고 캐싱 기능을 꺼 두었지만 문제가 해결되지 않았습니다.

해당 문제는 Application 내부에서 문제가 있다고 판단했고,
똑같은 호출에도 값이 변경되는 경우와, 변경된 것 처럼 보이지만 일정 시간 뒤에 다시 돌아오는 현상이 무분별하게 섞여 있어서 문제해결을 위해 깊게 파보기로 결정했습니다.

과정 및 해결

먼저 문제가 발생할 수 있는 부분을 생각해보면 다음과 같습니다.
1. 상품 A의 수정에 대해 DB 지연 입력 - 지연되는 동안 Connection 간 자원 공유가 되지 않음
2. 특정 Connection에 문제가 생겨 다른 Connection들과는 다른 값을 조회 함
3. Connection Pool 이상 및 TypeORM Issue (사용하는 TypeORM 버전 이상에서 해당 Issue가 있음)

과정

Application Log 추가
값을 수정하고, 조회하는 부분에 Log를 추가했습니다. Log를 살펴보니 Database에서 값을 가져올 때, 동일한 시점에 A요청은 변경된 값을 가져오고, B요청은 변경되지 않은 값을 가져오는 것을 확인할 수 있었습니다.
그리고 재부팅 하면 변경된 값이 반영이 안되고, 일정 시간이 지나도 변경된 값이 반영이 안되는 사실을 확인했습니다.

이를 Sequence Diagram으로 표현하면 다음과 같습니다.
Application Log

그리고 해당 현상이 발생한뒤 일정 시간이 지나거나 서버를 다시 띄워보면 다음과 같은 상황이 발생합니다.

Application Log 2

Application Log를 살펴보고 나면, 1번으로 말했던 상품 A의 수정에 대한 DB 지연 입력은 아니라고 판단됩니다. 판단 이유는 지연 입력이라고 하면, 기다린 후 지연 입력된 다음부터는 변경된 값으로 조회해야 합니다. 하지만 이전 값을 조회하고 있습니다.

DB SQL Log
이후에는 문제 상황을 로컬 환경에 구축하고, DB SQL Log를 활성화 시켜서 확인해보았습니다.

Log 활성화 결과, Connection 중 한개의 Connection이 RollBack 없이 StartTransaction을 수행하고 있었습니다.

해당 위치를 찾아본 결과 Cron으로 동작하는 부분에서 명시적 트랜잭션 선언을 사용하고 있었고, 중간에 return을 할때, Rollback을 해주고 있지 않았습니다. 간단하게 코드로 표현해보면 다음과 같습니다.

goodCode() {
  try {
	const connection = getConnection();
    connection.startTransaction();
    // 비지니스 로직
    connection.commitTransaction();
    return dto;
  } catch(e) {
  	// 예외 처리
    connection.rollback();
  } finally {
    connection.release();
  }
}

위와 같은 내용으로 작성하는 것이 일반적인데, 제 경우에는 다음과 같이 작성되어 있었습니다.

badCode() {
  try {
	const connection = getConnection();
    connection.startTransaction();
    // 비지니스 로직
    if(A === true) {
      return A;
    }
    connection.commitTransaction();
    return dto;
  } catch(e) {
  	// 예외 처리
    connection.rollback();
  } finally {
    connection.release();
  }
}

명시적 트랜잭션 선언을 해 놓고, return 하는 시점에 Rollback, Commit을 다 하지 않아서, 그대로 ConnectionPool로 트랜잭션이 닫히지 않은 상태로 넘어가게 되었습니다.

만약 해당 커넥션이 트랜잭션 없이 생성이나, 수정을 하는 내부 로직과 결합된다면 다음과 같은 문제가 발생할 수 있습니다.

Connection Issue 1

~~그림은 제가 손수 그렸습니다. 잘 그렸죠?~~

닫히지 않은 Connection을 가지고 트랜잭션 선언 없이 수정 API를 쓰게 되면, 지금과 같이, 수정되고, 닫히지 않은 Connection이 그대로 돌아가게 됩니다.

Connection Issue 2
이 때, 닫힌 Connection과 닫히지 않은 Connection은 서로 다른 값을 조회하게 됩니다. (이 값은, 고립 정책에 따라 달라질 수 있습니다.)

그리고 만약 트랜잭션을 사용하는 로직을 만나면 다음과 같은 현상이 발생합니다.

Connection Issue 3

Start Transaction을 한번 더 하면 Rollback으로 간주한다는 것은 공식 문서에 나와 있습니다.

결론

해당 내용으로 미루어볼 때, 문제는 Connection을 닫지 않은 상태로, Pool에 돌려주는 것 때문으로 판단됩니다. (2번 Issue)

해결

해결 방법은 명시적 트랜잭션을 선언하는 부분에서, 누락되어 있는 Rollback, Commit 처리를 해주면 됩니다.

해당 작업 이후 Log를 살펴보니 중간에 종료되는 경우에 트랜잭션 Rollback이 정상적으로 일어나고 있었습니다. 로컬환경과 개발서버에서 모니터링을 하고, 충분히 테스트를 거친후 문제가 해겨되었다고 판단해서, Hotfix로 배포해서 문제를 해결하였습니다.

고찰

해당 문제를 해결하는 과정에서 더 고민해본 점들은 다음과 같습니다.

1. 운영환경과 스테이징 환경에서 발생하는 예외 처리 방법 고안

스테이징 환경에서 테스트 도중 발견한 이슈였습니다. 스테이징, 운영환경에서는 SQL Log를 기록해두지 않았고, Application에서도 Log를 만들어 보관하지 않았는데, 이로 인해서 금방 발견할 수 있었던 문제를 약 2일 정도 잡고 있었습니다.

운영환겨과 스테이징 환경에서, 각각 환경에 맞게 Log Level을 설정하고 보관하는 정책을 정하고 실행함을 통해서 문제를 빠르게 찾고 해결할 수 있습니다.

로그는 Winston을 사용하면 Console에 찍어서 확인하는 방식에 비해 확실한 이점을 얻을 수 있습니다.

Inpa님 블로그 - Winston 모듈 사용법 - 서버 로그 관리

2. 트랜잭션 사용시, 실수가 발생할 수 있음.

이번 이슈는 Entity Manager에서 트랜잭션을 시작하고 커밋과 롤백없이 그대로 반환되었을때, 발생할 수 있는 문제를 파악할 수 있었던 기회가 되어 좋았지만 근본적인 문제는 로직마다 커넥션을 받아서 트랜잭션을 사용하고 반환하는 부분을 직접 작성하는 부분에 있었습니다.

트랜잭션이 시작되면, Rollback과 Commit이 되지 않은 상태로 방출될 수 없도록 해야 한다. 라는 명제를 만족시키지 못하면, 휴먼에러가 발생할 여지가 있습니다.

먼저 이러한 해결을 손쉽게 하는 방법은 트랜잭션 처리 방식에 대해서 추상화를 해서, AOP로 적용시키는 방법이 있습니다. typeorm-transaction을 이용해서 트랜잭션을 추상화해서 데코레이터를 적용하므로 해결할 수 있습니다.

3. 메서드 내에서 나누어진 실행흐름

badCode() {
  try {
	const connection = getConnection();
    connection.startTransaction();
    // 비지니스 로직
    ...
    // 실행 흐름이 나누어짐
    if (A === true) {
      return A;
    }
    connection.commitTransaction();
    return dto;
  } catch(e) {
  	// 예외 처리
    connection.rollback();
  } finally {
    connection.release();
  }
}

트랜잭션 내부에서 실행 흐름이 나누어 지는게 문제가 됩니다.
코드의 흐름을 보면 try 내부 정상 실행 시, 마지막 Commit으로 해당 내용을 데이터베이스에 반영하고 dto를 반환하는 한편, 예외가 발생하는 경우 Rollback하도록 만들었습니다.

하지만 중간에 있는 A반환으로 인해 BadCode에서는 메서드의 역할을 정확하게 알 수 없어졌습니다.

해당 내용은 조회 후 값이 A인 경우는 그대로 반환하고, 아닌 경우에는 변경한 후 그 값을 반환 한다는 요구사항에 대한 해결책이라고 가정하면 내용을 조금 변경해서 문제를 해결할 수 있습니다.

// 변경

// 조회
betterGoodCode() {
  try {
	const connection = getConnection();
    connection.startTransaction();
    // 비지니스 로직
    ...
    // 실행 흐름이 나누어짐
    let dto;
    if (A === true) {
      dto = await handleA(connection);
    } else {
      dto = await handleNonA(connection);
    }
    connection.commitTransaction();
    return dto;
  } catch(e) {
  	// 예외 처리
    connection.rollback();
  } finally {
    connection.release();
  }
}

4. 장애 대응 절차의 수립

이번엔 운영환경에서 발생한 문제는 아니었지만, 스테이징에서 해당하는 문제를 해결하지 못했다면, 운영환경에서 해당하는 문제가 발생할수도 있었습니다.

스테이징 환경에서의 장애 대응책을 수립하고, 운영환경에서는 어떻게 장애를 대응할지 고민해보는 시간이 필요하다는 생각에 여러 게시글을 읽어보았는데, 좋은 글이 있어서 소개하고자 합니다.

LINE 기술블로그 - LINE 플랫폼 서버의 장애 대응 프로세스와 문화

구름 공식 블로그 - 장애 대응 '이것'부터 시작하세요

5. 결론

제가 위에서 발생한 현상에 대해서 적었는데,

서버 재부팅 이후 2~30분 동안은 나타나지 않음.
문제가 발생하고 실제 데이터베이스에서 조회 해보면, 변경되지 않은 값이 조회 됨.
업데이트 한 값이 바로 조회될 때도 있고, 바로 조회 안될 때도 있음.
3-1. 조회 되지 않을 때, 서버를 재부팅하거나 더 시간이 지나게 되면 이전 값이 다시 조회됨.

이러한 값이 나오게 된 이유로 열린 트랜잭션과 예기치 못한 Rollback으로 인한 문제라고 이야기 했습니다.

위 세가지 현상은 트랜잭션 동작과정을 잘 이해해야 해당하는 원인까지 도달할 수 있습니다.
아래 Inpa님 블로그에서 트랜잭션 동작방식을 잘 설명해주고 있습니다.

Inpa님 블로그 - 트랜잭션(Transaction) 개념 & 사용 💯 완벽 정리