ZooKeeper 'Unreasonable length' 예외 발생 원인 및 해결 가이드

문제 현상

ZooKeeper 서버를 시작할 때 다음과 같은 IOException이 발생하며 프로세스가 강제 종료되는 경우가 있습니다.

Exception in thread "main" java.io.IOException: Unreasonable length = 1860320
    at org.apache.jute.BinaryInputArchive.checkLength(BinaryInputArchive.java:127)
    at org.apache.jute.BinaryInputArchive.readBuffer(BinaryInputArchive.java:92)
    ...

근본 원인 분석

ZooKeeper는 구동 시 메모리 데이터를 복원하기 위해 트랜잭션 로그(datalog)와 스냅샷을 로드합니다. 이 과정에서 각 레코드의 크기가 jute.maxbuffer의 제한값(기본적으로 1MB)을 초과하는지 검사합니다.

일반적으로 데이터를 작성(쓰기)할 때도 이 제한값을 검증하기 때문에, 정상적인 상황에서는 1MB를 넘는 단일 노드 데이터가 기록될 수 없습니다. 그렇다면 이러한 비정상적으로 큰 데이터는 어떻게 로그에 기록되었을까요?

원인은 클라이언트 세션이 종료될 때(closeSession) 발생합니다. 클라이언트가 다수의 임시 노드(Ephemeral Nodes)를 생성한 상태에서 세션이 종료되면, ZooKeeper는 해당 세션에 속한 모든 임시 노드를 삭제해야 합니다. 이때 삭제 대상이 되는 모든 임시 노드의 경로(Path)가 하나의 트랜잭션 레코드에 묶여서 기록됩니다.

만약 Apache Dubbo와 같이 레지스트리 데이터를 노드 경로 자체에 매핑하여 사용하는 환경에서 수만 개의 서비스 경로가 등록되어 있다면, 세션 종료 시 생성되는 단일 레코드의 크기가 jute.maxbuffer를 쉽게 초과하게 됩니다.

해결 방안

1. JVM 매개변수 조정

ZooKeeper 서버 시작 스크립트에 JVM 인수를 추가하여 버퍼 크기 제한을 늘립니다.

-Djute.maxbuffer=4194304

위 설정은 버퍼 크기를 4MB로 확장하는 예시입니다. 환경에 따라 적절한 크기로 조정해야 합니다.

2. 손상된 로그 파일 제거

문제를 일으키는 특정 트랜잭션 로그 또는 스냅샷 파일을 물리적으로 삭제합니다. 단, 이 방법을 사용할 경우 메모리에만 존재하고 아직 스냅샷으로 지속화되지 않은 데이터는 유실될 수 있으므로 신중하게 결정해야 합니다.

로그 파일 분석 및 검증

ZooKeeper는 내장된 포매터 클래스를 통해 바이너리 로그를 텍스트 형태로 변환할 수 있습니다.

트랜잭션 로그 분석: org.apache.zookeeper.server.LogFormatter
스냅샷 분석: org.apache.zookeeper.server.SnapshotFormatter

# 트랜잭션 로그 파싱
java -classpath zookeeper-3.4.13.jar:zookeeper-jute-3.4.13.jar:slf4j-api-1.7.6.jar \
org.apache.zookeeper.server.LogFormatter /data/version-2/log.1

# 스냅샷 파싱
java -classpath zookeeper-3.4.13.jar:zookeeper-jute-3.4.13.jar:slf4j-api-1.7.6.jar \
org.apache.zookeeper.server.SnapshotFormatter /data/version-2/snapshot.110005fdc7 > snapshot_dump.log

커스텀 트랜잭션 로그 파서 구현

기본 포매터 대신, 특정 크기 이상의 비정상 레코드를 탐지하고 분리해 내기 위해 LogFormatter의 로직을 참고하여 커스텀 유틸리티를 작성할 수 있습니다. 아래 코드는 트랜잭션 로그를 스트리밍하며 CRC 검증과 크기 필터링을 수행하도록 재구성한 예제입니다.

import org.apache.jute.BinaryInputArchive;
import org.apache.jute.Record;
import org.apache.zookeeper.server.util.SerializeUtils;
import org.apache.zookeeper.txn.TxnHeader;
import org.apache.zookeeper.server.persistence.FileHeader;

import java.io.*;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.zip.Adler32;
import java.util.zip.Checksum;

public class TransactionLogAnalyzer {

    /**
     * 트랜잭션 로그를 분석하여 임계값을 초과하는 대용량 레코드를 추출합니다.
     */
    public static void extractOversizedRecords(String logPath, String outputDir, long thresholdBytes) throws Exception {
        try (FileInputStream fileInputStream = new FileInputStream(logPath);
             BinaryInputArchive archive = BinaryInputArchive.getArchive(fileInputStream)) {
            
            FileHeader header = new FileHeader();
            header.deserialize(archive, "fileheader");

            int transactionCount = 0;
            long totalBytesRead = 0;

            while (true) {
                long expectedCrc = 0;
                byte[] txnData;
                
                try {
                    expectedCrc = archive.readLong("crcvalue");
                    txnData = archive.readBuffer("txnEntry");
                    totalBytesRead += txnData.length;
                } catch (EOFException eof) {
                    System.out.println("Reached EOF after " + transactionCount + " transactions.");
                    break;
                }

                if (txnData.length == 0) {
                    System.out.println("Empty transaction block detected. Total bytes: " + totalBytesRead);
                    break;
                }

                // CRC 무결성 검증
                Checksum checksum = new Adler32();
                checksum.update(txnData, 0, txnData.length);
                if (expectedCrc != checksum.getValue()) {
                    throw new IOException("CRC mismatch detected at transaction " + transactionCount);
                }

                // 임계값 초과 레코드 파일로 저장
                if (txnData.length > thresholdBytes) {
                    String outFileName = outputDir + "/oversized_txn_" + transactionCount + ".dat";
                    Files.write(Paths.get(outFileName), txnData);
                    System.out.println("Extracted oversized record: " + outFileName + " (" + txnData.length + " bytes)");
                }

                TxnHeader txnHeader = new TxnHeader();
                Record txnRecord = SerializeUtils.deserializeTxn(txnData, txnHeader);
                
                // 세션 종료 이벤트(Type -11)이면서 대용량인 경우 상세 로깅
                if (txnHeader.getType() == -11 && txnData.length > thresholdBytes) {
                    SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
                    System.out.printf("[Large CloseSession] Time: %s, Session: 0x%x, Zxid: 0x%x, Size: %d bytes%n",
                            sdf.format(new Date(txnHeader.getTime())),
                            txnHeader.getClientId(),
                            txnHeader.getZxid(),
                            txnData.length);
                }

                if (archive.readByte("EOR") != 'B') {
                    throw new EOFException("Incomplete transaction record at index " + transactionCount);
                }
                transactionCount++;
            }
        }
    }

    public static void main(String[] args) {
        // 버퍼 제한을 임시로 확장하여 파싱 중 오류 방지
        System.setProperty("jute.maxbuffer", "10485760"); // 10MB
        System.setProperty("jute.maxbuffer.extrasize", "10485760");

        String targetLog = "/var/lib/zookeeper/version-2/log.400000001";
        String dumpDirectory = "/tmp/zk-log-dumps";
        long sizeThreshold = 1048576; // 1MB 초과 시 추출

        try {
            new File(dumpDirectory).mkdirs();
            extractOversizedRecords(targetLog, dumpDirectory, sizeThreshold);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

태그: ZooKeeper jute.maxbuffer TransactionLog BinaryInputArchive EphemeralNodes

7월 1일 03:13에 게시됨

괴물 클럽