Firebase와 JVM crash 문제

봄도둑·2024년 1월 12일
JavaSpring
0

Spring 개인 노트

목록 보기
14/17

1. 개발 환경

먼저 firebase와 JVM crash 문제를 살펴보기 전 개발 환경을 먼저 보겠습니다.

  • local backend : java 17(OpenJDK)
  • 배포 환경 backend : AWS Corretto 17
  • build : maven

2. 에러 발생

가상 성형앱 프로젝트에 채팅 및 푸시 기능을 위해 firebase를 도입했습니다. firebase를 사용하면 FCM이라는 푸시 메세징 처리와 firestore라는 NoSQL DB를 통해 채팅 기능을 구현했습니다.

이 과정에서 백엔드는 firebase는 firebase의 admin sdk의 dependency를 사용하게 됩니다. 아래는 firebase 사용을 위해 주입한 firebase의 dependency입니다.

<!-- firebase-admin -->
<dependency>
    <groupId>com.google.firebase</groupId>
    <artifactId>firebase-admin</artifactId>
    <version>9.2.0</version>
</dependency>

아래의 코드는 firebase를 사용한 채팅을 보내는 service입니다. 코드 자체의 의미보다는 채팅방을 생성하고 메세지를 보낼 때 firebase를 사용한다 라고 보시면 됩니다. (firebase의 상세한 사용은 추후 다룰 예정이니 조금만 기다려주세요!)

@Slf4j
@Service
@RequiredArgsConstructor
public class FirestoreService {

    private final ChattingMapper chattingMapper;

    private final PushService pushService;

    Logger logger = LogManager.getLogger(this.getClass());

    public long createChat(long userId, long targetUserId) {
        Firestore firestore = FirestoreClient.getFirestore();
        List<Long> users = List.of(userId, targetUserId);
        ChatDTO chatDTO = ChatDTO.from(new LastMessageDTO(), users);
        Long chatSeq = chattingMapper.increaseChattingSeq();
        ApiFuture<WriteResult> apiFuture = firestore
            .collection(FirestoreCollection.CHAT.getCollectionName())
            .document(chatSeq.toString())
            .set(chatDTO);

        return chatSeq;
    }

    public LastMessageDTO insertChatMessage(long chatId, long userId, String message) {
        validateBlocked(String.valueOf(chatId), userId);
        updateConnect(String.valueOf(chatId), userId);
        Firestore firestore = FirestoreClient.getFirestore();
        DocumentReference docRef = firestore.collection(FirestoreCollection.CHAT.getCollectionName()).document(String.valueOf(chatId));
        InsertMessageDTO insertMessageDTO = InsertMessageDTO.of(message, userId);
        LastMessageDTO insertLastMessageDTO = LastMessageDTO.of(message, userId);
        ApiFuture<WriteResult> apiFuture = docRef.update("lastMessage", insertLastMessageDTO);
        ApiFuture<DocumentReference> apiFutureMessage = docRef.collection(FirestoreCollection.MESSAGES.getCollectionName()).document().getParent().add(insertMessageDTO);

        if (isConnect(String.valueOf(chatId), userId)) {
            ChatDTO chatDTO = getChatDTO(String.valueOf(chatId));
            pushService.sendChatPush(chatDTO.getOtherUserId(userId), userId, chatId, message);
        }

        return insertLastMessageDTO;
    }
}

해당 코드를 local 환경(OpenJDK 17)에서 테스트를 진행했고, 정상적으로 동작하고 있음을 확인했습니다. 실제 개발계 환경에서 정상적으로 동작하는지 확인을 하기 위해 배포를 진행했습니다. 배포 역시 성공해 개발계 파드가 재기동 없이 정상적으로 동작하고 있음을 확인하고 API 호출을 했습니다.

그런데…. 채팅방을 생성하는 API를 호출할 때, 정상적인 실패 에러에 대한 응답이 아니라 502 bad gateway 에러가 떨어지고 있었습니다.

혹시 백엔드를 제대로 호출하지 못한 문제인가 싶어 pod의 상태를 확인했습니다.

위의 이미지는 현재 배포한 pod로 백엔드 pod는 backend-main 파드를 보시면 됩니다. 해당 파드는 재기동을 1회 한 것으로 보입니다. 이 경우 생각할 수 있는 포인트는 크게 2가지였습니다.

  1. 빌드를 실패해서 반복 재기동 중이다.
  2. pod가 비정상적으로 종료된 후 재기동 중이다.

1번 케이스는 발생할 수 없다고 판단한 것이 채팅방을 생성하려면 토큰을 받아오는 로그인 동작이 필요합니다. 로그인 API 호출 후 받은 토큰을 통해 채팅방을 생성하는 API를 호출하는 순서를 가지기 때문에 빌드 실패에 의한 재기동 가능성은 없다고 봐야 합니다.

일반적으로 자바는 처리가 불가능한 에러 상황이 발생하면 에러가 발생했던 지점과 원인을 명시합니다. 아래의 이미지처럼 발생한 에러는 NullPointerException, 발생 원인은 null 값에서는 length() 함수를 호출할 수 없음을, 에러가 발생한 코드 지점을 명시합니다.

즉, 에러가 발생했다고 해서 백엔드 어플리케이션이 비정상적으로 종료되지는 않습니다. 이번에 발생한 에러는 그동안은 겪어보지 못했던 생소한 에러입니다. 어떠한 문제로 발생했는지, 원인과 발생 지점을 명확하게 파악하기 힘든 에러였습니다.

그 결과, 제가 도달한 방법은 다음과 같았습니다. 결국 어플리케이션이 비정상적으로 종료된다면, 종료되는 시점에 무언가 힌트를 남기지 않을까라고 생각해 어플리케이션이 죽어버리는 시점의 로그를 확인하기로 했습니다.

A fatal error has been detected by the Java Runtime Environment:

SIGSEGV (0xb) at pc=0x00000000000207d6, pid=1, tid=49

JRE version: OpenJDK Runtime Environment (17.0+14) (build 17-ea+14)
Java VM: OpenJDK 64-Bit Server VM (17-ea+14, mixed mode, sharing, tiered, compressed oops, compressed class ptrs, serial gc, linux-amd64)
Problematic frame:
C  0x00000000000207d6

Core dump will be written. Default location: //core.1

An error report file with more information is saved as:
//hs_err_pid1.log

If you would like to submit a bug report, please visit:
https://bugreport.java.com/bugreport/crash.jsp
The crash happened outside the Java Virtual Machine in native code.
See problematic frame for where to report the bug.

잠복 근무 끝에 어플리케이션이 죽는 시점에 에러를 캐치했습니다. 그런데, 위의 NullPointerException과는 달리 처음 보는 에러 화면이었습니다. 해당 로그를 끝으로 파드는 재실행되며 새롭게 뜨게 됩니다.

도대체 무슨 에러인지 함께 알아봅시다.

위에서 확인한 현상은 모든 프로그램에 존재하는 버그입니다. 쉽게 설명하자면 JVM의 버그가 제대로 처리되지 못하고 JVM crash 문제를 일으킨 현상입니다. 일반적으로 JVM은 정상적으로 처리할 수 없는 에러가 발생하면 명령을 호출한 사용자에게 발생한 예외 상황을 전달하지만, 위의 상황은 JVM 이 에러를 처리하지 못하고 crash된 상황입니다.

그렇다면, 이와 같은 상황에서 우리는 전혀 디버깅을 할 수 없는 것일까요?

그렇지 않습니다. 위의 로그는 JVM이 crash로 인해 종료되기 전 남긴 내용으로 JVM crash에 대한 원인을 전달합니다. 항목별로 상세하게 살펴보겠습니다.

3. JVM Crash 원인 파악

SIGSEGV (0xb) at pc=0x00000000000207d6, pid=1, tid=49

위의 로그는 JVM crash 발생 시 발생 원인을 의미합니다. SIGSEGV는 Segmentation fault를 의미하며 메모리의 잘못된 참조 혹은 JVM의 패키지에 의한 버그, 호환되지 않는 의존성에 따른 에러가 주요 원인으로 발생합니다.

이 외에 자주 발생하는 JVM crash의 원인으로는 SIGBUS가 있습니다. 주로 자바를 빌드한 기기의 SWAP 공간이 충분하지 않거나 JVM이 jar 파일을 사용하고 있을 때 jar 파일의 수정이 일어났을 때 발생합니다.

4. 발생 지점

JRE version: OpenJDK Runtime Environment (17.0+14) (build 17-ea+14)
Java VM: OpenJDK 64-Bit Server VM (17-ea+14, mixed mode, sharing, tiered, compressed oops, compressed class ptrs, serial gc, linux-amd64)
Problematic frame:
C  0x00000000000207d6

위의 로그는 Java의 환경 및 발생 지점을 나타냅니다. 자바 17버전, OpenJDK 17버전에서 문제가 발생했으며 문제가 발생한 위치는 0x00000000000207d6을 의미합니다.

어느 스레드에서 JVM Crash가 발생했는지 명확하게 확인이 필요할 경우가 있습니다. 그럴 상황을 대비해서 JVM은 Crash 발생 시 작업했던 내용을 임시 디렉토리에 로그로 남겨 저장합니다. 남긴 로그의 파일명은 아래처럼 확인할 수 있습니다.

An error report file with more information is saved as:
//hs_err_pid1.log

이렇게 확인한 로그 파일은 직접 분석해도 되지만 https://fastthread.io/에 상기의 로그 파일을 업로드 해 스레드 덤프를 생성해서 상세한 원인을 분석할 수 있습니다.

5. 문제 해결

이번 문제 해결 케이스는 위처럼 JVM의 임시 로그를 보거나 Problematic frame 에서 명시한 정보를 분석해 정확하게 원인을 파악해 해결하지는 못했습니다. google에 해당 에러를 검색한 후 동일하게 반복되는 키워드를 조합, 대강의 원인을 추측한 후에 수정 작업을 진행했습니다.

먼저 Problematic frame에서 명시한 위치 정보 C 0x00000000000207d6 와 에러의 발생 원인인 SIGSEGV 를 조합해 구글링을 했고, 여러 개의 결과에서 공통적으로 보이는 부분은 grpc와 google cloud의 내용이었습니다. 주된 내용은 google cloud의 버전을 올렸더니 호환성에서 문제가 발생했다는 내용이었고, 이전에 작업했던 프로젝트에서 사용한 firebase-admin sdk의 버전과 현재 이슈가 발생한 프로젝트의 버전을 비교했습니다.

그 결과 정상적으로 동작한 프로젝트의 버전이 더 낮음을 확인했고 firebase-admin SDK의 버전을 낮춰 보기로 했습니다. 기존의 9.2.0 버전에서 8.1.0 버전으로 낮추는 과정을 진행했습니다. 

<dependency>
  <groupId>com.google.firebase</groupId>
  <artifactId>firebase-admin</artifactId>
  <version>8.1.0</version>
</dependency>

버전을 낮춘 다음 문제는 해결되었습니다. jvm crash의 정확한 문제는 firebase SDK 내의 grpc-netty 가 JVM과 충돌을 일으켜 세그먼트 폴을 일으키게 됩니다. 문제는 다른 로컬에서 사용한 openJDK 17과는 충돌이 이미 최신 버전에서 수정되었고 AWS의 corretto에서는 여전히 발생하고 있다는 것입니다.

때문에 배포 환경의 java가 AWS의 corretto를 사용하고 있다면 firebase 버전을 8점대 버전으로 낮춰서 개발하기를 권장합니다.

*Reference

profile
봄도둑
Java Spring 백엔드 개발자입니다. java 외에도 다양하고 흥미로운 언어와 프레임워크를 학습하는 것을 좋아합니다.
이전 포스트

사내 프로젝트 Readme(Readme 작성연습)

다음 포스트

자바 Overloading a method: both methods have same erasure 정리

0개의 댓글