← 목록
gcloud IAP fd 경합 추적기

장애 분석 · 2026-09-17 ~ 2026-09-26

gcloud IAP tunnel은 왜 자기 설정 DB에 TLS 메시지를 써 넣었나

운영 중인 Spring Boot 앱이 간헐적으로 PostgreSQL에 연결하지 못했다. 원인은 DB도 네트워크도 아니었다. DB 앞단의 gcloud compute start-iap-tunnel이 이미 닫은 파일 디스크립터(fd) 번호로 계속 읽고 쓰다가, 그 번호를 새로 받은 자신의 SQLite 설정 파일에 TLS alert 24 bytes를 써 넣고 있었다. 이 페이지는 증상에서 syscall 한 줄까지 범위를 좁혀 간 과정과 그 증거를 담았다.

Google Cloud SDK 582.0.0 bundled Python 3.14.7 bundled OpenSSL 3.5.7 (정적 링크) Linux 6.12 (Oracle Linux 9 UEK) ✔ syscall 수준 확증

한눈에 보기

증상

Spring이 ConnectionFactoryImpl.enableSSL()에서 Read timed out. 이후 새 DB 연결이 전부 실패. 그런데 gcloud process와 :15432 listener는 살아 있었다.

근본 원인

gcloud IAP tunnel의 fd use-after-close race. 연결 종료 thread가 SSL socket을 닫는 동안 수신 thread는 OpenSSL 안에서 같은 원시 fd 번호로 계속 읽고 쓴다.

트리거

클라이언트(Hikari pool)가 연결을 닫고 곧바로 새 연결을 연다. 새 연결이 default_configs.db를 열 때 방금 반납된 fd 번호를 받는다.

영향

default_configs.db offset 29에 17 03 03 00 13 + 19 bytes가 들어가 손상. 이후 모든 새 tunnel 연결과 같은 설정을 쓰는 모든 gcloud 명령이 database disk image is malformed로 실패.

배제된 것

PostgreSQL 서버, GCP VM, IAP 서비스, 네트워크 경로, system OpenSSL 혼용, proxy/LD 환경변수. gcloud 583~586 릴리스 노트에 관련 수정 없음.

아직 추정인 것 1건

같은 race가 DB 파일이 아니라 다른 연결의 socket에 걸리는 변형. 초기의 간헐적 Read timed out을 설명할 수 있지만 syscall로 잡지는 못했다.

결정적 한 줄 · 2026-09-26 19:31:20, 수신 thread 1421083이 fd 7로 read(29)를 해서 SQLite 헤더를 읽은 뒤, 같은 fd 7로 write(24)를 했다. 그 24 bytes(17 03 03 00 13 aa 23 cb …)가 손상된 DB의 offset 29 내용과 byte 단위로 일치한다. fd 7은 140ms 전에 다른 thread가 닫은 WebSocket socket 번호였다. → 확증 타임라인
English summary. A long-running gcloud compute start-iap-tunnel (SDK 582.0.0, lightweight WebSocket path) intermittently broke all new tunnel connections while the process and its listener stayed up. We traced it to an fd use-after-close race: the per-connection handler thread closes the WebSocket's SSL socket without synchronizing with the receive thread, which is still inside OpenSSL's SSL_read holding the raw integer fd from SSL_set_fd. When a new connection opens default_configs.db and receives the same fd number, the stale reader reads 29 bytes of the SQLite header, fails to decrypt them, and writes a 24-byte TLS 1.3 alert record (17 03 03 00 13…) into the database at offset 29. bpftrace captured the full close(7) → openat(db)=7 → read(7,29) → write(7,24) chain in production, and the written bytes match the corrupted file exactly.

조사 여정: 범위를 좁혀 간 16단계

각 단계는 가설 → 한 일 → 관측 → 결론 순서로 적었다. 오른쪽 막대는 그 시점에 "gcloud 내부 fd race"라는 최종 결론에 대해 가졌던 확신 정도다.

가설 트리

노드를 누르면 판정 근거가 나온다. 표시: ✕ 기각 △ 약화·보류 ◎ 지지 ✔ 확정 ? 추정

    확증: 2026-09-26 19:31:20의 syscall 타임라인

    production gcloud process에 붙여 둔 bpftrace가 기록한 이벤트 중, 관련된 thread 3개와 fd 7만 추렸다. 기준점 t0는 연결 [93]의 처리 thread가 WebSocket socket(fd 7)을 close()한 순간이다. 위쪽 띠는 그 시점에 fd 7 번호가 무엇을 가리켰는지를 보여 준다.

    thread 3개의 fd 7 관련 syscall 타임라인
    fd 7 = WebSocket SSL socket fd 7 = 다른 설정 파일(active_config) fd 7 = default_configs.db ● read · ■ write · ✕ close · ▲ open · ◆ 손상

    무엇이 일어났나

    1. 1421083(연결 [93]의 수신 thread)은 95초 전부터 fd 7에서 다음 TLS record를 기다리며 read() 안에 잠들어 있었다.
    2. 1421118(연결 [93]의 처리 thread)이 local EOF를 받고 WebSocket Close를 보낸 뒤 fd 7을 닫았다.
    3. 4.9ms 뒤 1431669(새 연결 [94])가 설정 파일들을 열었고, 커널은 가장 낮은 빈 번호인 7을 줬다.
    4. 140ms 뒤 서버 frame이 도착해 1421083이 깨어났다. 잠들어 있던 read()는 옛 socket에서 record header를 받았고, OpenSSL은 본문 29 bytes를 더 읽으려고 read(7, 29)를 다시 불렀다. 이때 7은 이미 DB 파일이었다.
    5. SQLite 헤더를 복호화할 수 없으니 OpenSSL은 fatal alert를 보냈다. write(7, 24)가 파일 위치 29, 즉 방금 29 bytes를 읽은 바로 그 자리에 떨어졌다.

    왜 이것이 확증인가

    • DB에 쓴 주체와 syscall, 파일 위치, bytes가 모두 기록에 있다. 이제 "구조가 닮았다"는 추론이 아니다.
    • trace의 write payload와 손상 파일의 offset 29 bytes가 일치한다. Hex 뷰어에서 나란히 비교할 수 있다.
    • offset 29라는 이상한 위치가 직전 read 29 bytes로 정확히 설명된다. 4번의 손상이 모두 offset 29였다.
    • 쓴 thread의 이름은 Thread-275 (_ReceiveFromWebSocket)이고, user stack은 __write ← 정적 OpenSSL ← _ssl ← Python이다.

    Hex 뷰어: 손상된 default_configs.db

    관측한 손상 파일 4개의 앞 96 bytes다. 노란 칸이 덮어써진 24 bytes(offset 29~52)이고, 빨간 테두리는 TLS record header 5 bytes다. 칸에 마우스를 올리거나 탭하면 그 위치의 SQLite 헤더 필드가 나온다.

    칸을 가리키면 SQLite 헤더 필드 설명이 표시됩니다.

    덮어쓴 24 bytes의 구조 (TLS 1.3 record)

    trace에 기록된 write payload (19:31:20)

    손상 파일 offset 29~44 (같은 날짜 파일)

    19 = 2 + 1 + 16. TLS 1.3에서는 alert도 암호화된 application-data record(type 0x17)로 나간다. 본문은 alert 2 bytes, 실제 content type 1 byte, AEAD 인증 태그 16 bytes를 합쳐 19 bytes(0x13)다. 연결마다 키가 다르므로 header 5 bytes는 매번 같고 뒤 19 bytes는 매번 다르다. 4개 파일이 정확히 그랬다.
    DB가 "malformed"가 된 이유. offset 28~31은 SQLite의 database size in pages다. 원래 00 00 00 03(3 pages)이어야 할 값이 00 17 03 03, 즉 1,508,099 pages가 됐다. 이어서 freelist 정보, schema cookie, schema format(offset 32~52)까지 덮였다.

    코드 경로: 동기화 없는 두 thread

    gcloud는 tunnel로 들어오는 TCP 연결 하나마다 thread 두 개를 쓴다. 둘은 같은 SSL socket을 공유하지만, 닫는 쪽은 읽는 쪽이 끝나기를 기다리지 않는다.

    닫는 쪽 · RunReceiveLocalData thread
    1. conn.recv()가 빈 값 → local EOF
    2. finally: conn.close() (trace: shutdown(6), close(6))
    3. IapTunnelWebSocket.Close() → helper.SendClose() (write(7))
    4. helper.Close() → IapLightWeightWebsocket.close()
    5. if self.connected and self.sock: → self.sock.close()
      fd 7 반납. 수신 thread를 join하지 않고 lock도 없다
    읽는 쪽 · _ReceiveFromWebSocket thread
    1. run_forever() 루프: while self.connected:
    2. self.recv() → recv_frame() → _recv_bytes()
    3. self.sock.recv_into() (Python SSLSocket)
    4. _ssl C 모듈 → OpenSSL SSL_read()
      GIL을 놓고 실행. fd는 SSL_set_fd 때 받은 정수 7
    5. OpenSSL 내부에서 read(7) / 실패 시 alert write(7)
      Python의 fd=-1 보호를 거치지 않는다
    소스 발췌 보기Apache 2.0 · SDK 582.0.0
    # Google Cloud SDK 582.0.0 (Apache License 2.0) — 발췌. "..."는 생략 표시.

## lib/googlecloudsdk/command_lib/compute/iap_tunnel.py — RunReceiveLocalData (닫는 쪽 thread)
  def RunReceiveLocalData(self, conn, socket_address, user_agent, conn_id=0):
    websocket_conn = None
    try:
      websocket_conn = self._InitiateConnection(conn, ...)
      while not self._shutdown:
        data = conn.recv(utils.SUBPROTOCOL_MAX_DATA_FRAME_SIZE)
        if not data:
          websocket_conn.LocalEOF()
          log.debug('[%d] Received local EOF, closing connection', conn_id)
          if not websocket_conn.WaitForAllSent():
            ...
          break
        websocket_conn.Send(data)
    except (Exception, exceptions.Error) as e:
      log.exception('[%d] Error during local connection to [%s]: %s', ...)
    finally:
      ...
      try:
        conn.close()                      # client 쪽 socket (trace: shutdown(6), close(6))
      except EnvironmentError:
        pass
      try:
        if websocket_conn:
          websocket_conn.Close()          # → WebSocket SSL socket close (trace: write(7) x2, close(7))
      except (EnvironmentError, exceptions.Error):
        pass

## lib/googlecloudsdk/api_lib/compute/iap_tunnel_websocket.py — IapTunnelWebSocket.Close
  def Close(self):
    """Close down local connection and WebSocket connection."""
    self._stopping = True
    self._unsent_data.put(StoppingError)
    ...
    if self._websocket_helper:
      if not self._close_message_sent:
        self._websocket_helper.SendClose()
        self._close_message_sent = True
      self._websocket_helper.Close()     # receive thread 를 join 하지 않음

## lib/googlecloudsdk/api_lib/compute/iap_tunnel_websocket_helper.py
  def Close(self, msg=''):
    """Close the WebSocket."""
    if not self._is_closed:
      self._is_closed = True
      try:
        self._websocket.close()
      except:  # pylint: disable=bare-except
        pass
  ...
  def _ReceiveFromWebSocket(self):       # 별도 daemon thread (receive thread)
    """Receive data from WebSocket connection."""
    try:
      ...
        self._websocket.run_forever(origin=TUNNEL_CLOUDPROXY_ORIGIN, sslopt=self._sslopt)
    except:  # pylint: disable=bare-except
      ...
    try:
      self.Close()
    ...

## lib/googlecloudsdk/api_lib/compute/iap_tunnel_lightweight_websocket.py
  def close(self, close_code=CLOSE_STATUS_NORMAL, close_message=six.b("")):
    """Closes the connection."""
    if self.connected and self.sock:     # lock 없는 check-then-act
      try:
        self.send_close(close_code, close_message)
        self.sock.close()                # ← fd 번호 반납. 다른 thread 는 아직 SSL_read 중일 수 있음
        self.sock = None
        self.connected = False
      except (websocket_exceptions.WebSocketConnectionClosedException, socket.error) as e:
        ...

  def run_forever(self, sslopt, **options):
    """Main method that will stay running while the connection is open."""
    try:
      ...
      self._connect(sslopt, **options)
      while self.connected:
        if self.sock.fileno() == -1:
          raise websocket_exceptions.WebSocketConnectionClosedException(...)
        self._wait_for_socket_to_ready(timeout=WEBSOCKET_RETRY_TIMEOUT_SECS)
        frame = self.recv()               # → recv_frame → _recv_bytes
        if frame.opcode == websocket_frame_utils.ABNF.OPCODE_CLOSE:
          close_args = self._get_close_args(frame.data)
          self.close()
          self.on_close(*close_args)
        else:
          self.on_data(frame.data, frame.opcode)
    ...

  def _recv_bytes(self, buffersize):
    ...
        while total_bytes_read < buffersize:
          bytes_received = self.sock.recv_into(view[total_bytes_read:],
                                               buffersize - total_bytes_read)
          # SSLSocket.recv_into → _ssl → OpenSSL SSL_read → read(<SSL_set_fd 로 받은 원시 fd>)
    ...

## lib/googlecloudsdk/command_lib/compute/iap_tunnel.py — _CleanDeadClientConnections (accept loop)
  def _CleanDeadClientConnections(self):
    """Erase reference to dead connections so they can be garbage collected."""
    ...
      for client_thread, conn in self._connections:
        if not client_thread.is_alive():
          dead_connections += 1
          try:
            conn.close()
          ...
      if dead_connections:
        log.debug('Cleaned [%d] dead connection(s).' % dead_connections)
        self._connections = conn_still_alive
      gc.collect(2)
      log.debug('connections alive: [%d]' % len(self._connections))

# 옛 eBPF 감시 (trace-default-config.bt) 의 필터 — 결함
    if ($inode->i_ino == 20396383 &&
        $inode->i_sb->s_dev == 0xfc00) {          # ← 사용자 공간 표기(stat %D) 값

# 같은 파일시스템에서 실측
    stat -c %D <file>            → fc00          (new_encode_dev: major 252, minor 0)
    bpftrace: f_inode->i_sb->s_dev → 0xfc00000   (커널 MKDEV: 252 << 20)
    → 필터가 한 번도 참이 된 적 없음 → "TARGET WRITE 없음" 은 증거가 아니었음

    왜 Python의 보호가 통하지 않았나

    Python socket 객체는 close()하면 자기 fd를 -1로 바꾼다. 그래서 Python 코드가 닫힌 socket을 다시 써도 fd=-1로 syscall이 나가 EBADF로 안전하게 실패한다. 문제는 TLS 읽기와 쓰기를 실제로 하는 OpenSSL이 이 값을 보지 않는다는 점이다.

    구분syscall대상 fd실험실 1,500연결의미
    Python 수준 재사용sendto-168안전 닫힌 socket 객체가 -1로 막힘
    Python 수준 재사용recvfrom-119안전 위와 같음
    OpenSSL 원시 fdread실제 번호 (7, 8, 11, 12, 17, 23)6위험 번호가 재사용됐으면 남의 파일이나 socket을 읽음

    원시 fd read()가 close 뒤 얼마 만에 일어났나

    close 이후 stale read 까지의 간격(ms, 로그 축)

    실험실 6건은 close 후 0.07~110.68ms 사이였다. production near-miss는 89.46ms, 확증 사건은 139.97ms였다. 이 사이에 다른 thread가 파일을 열면 번호가 겹친다.

    실험실 재현: 전제 조건은 흔했지만 손상은 재현되지 않았다

    운영 tunnel은 건드리지 않고, 설정 디렉터리를 복사해 별도 :15433 tunnel을 띄웠다. 그 process에만 필터를 건 bpftrace로 fd 생성과 close, 모든 I/O, EBADF를 기록했다.

    부하연결 수관측손상
    무작위 (full / abrupt / RST 혼합), 동시 6300socket close 1,780건 중 다른 thread가 닫은 경우 597건. 그렇게 닫힌 번호를 200ms 안에 default_configs.db가 다시 받은 경우 197건 (최단 0.03ms, 중앙값 4.2ms)0
    무작위, 동시 101,500EBADF 93건. 그중 원시 fd read() 6건0
    순차 (종료 후 0~300ms 뒤 다음 연결), 동시 3, 12라운드6,000원시 fd use-after-close 0건0
    표적 쌍 (A 종료 직후 −2~+8ms에 B 연결)1,000쌍B 응답 1,000/1,000 'S'0
    pgjdbc 흉내 (TLS handshake → Terminate → 즉시 close → B)~100쌍production 관측으로 전환하면서 중단0
    왜 실험실에서는 안 났나 (추정). 실험실 연결은 'S'만 주고받은 조용한 연결이라, 닫힌 뒤 도착하는 서버 frame이 WebSocket Close 하나뿐이었다. 수신 thread는 그것을 받고 곧바로 종료한다. production 연결은 실제 PostgreSQL TLS 세션이라 종료 때 frame이 여러 개 온다. 그래서 첫 frame을 처리한 뒤 두 번째 read()를 하게 되고, 그 위험 구간이 약 90~140ms로 길다. 그래서 운영 환경에 관측 장치를 붙이는 쪽으로 전환했다.

    production 사건 비교

    gcloud 로그(초 단위 timestamp는 로그를 읽은 시각)와 DB 파일 mtime을 나란히 놓았다. 세 번 모두 순서가 같다: 이전 연결 종료 → 새 연결 → DB가 덮어써짐 → 이전 연결의 수신 thread가 아직 동작 → 새 연결 실패.

    사건이전 연결 CLOSE새 연결 시작DB mtime이전 연결 WS Close 수신새 연결 malformed
    09-24 05:44 ([518]→[519])01.61401.62301.720601.72601.838
    09-25 10:32 ([9]→[10])43.01543.13943.134743.20443.242
    09-26 19:31 ([93]→[94]) · trace 확보19.98420.02320.101820.10820.204

    09-17 08:05에도 같은 형태(offset 29, 17 03 03 00 13)의 손상 파일이 있었다. 당시에는 timestamp 기록이 없어 순서를 비교할 수 없다.

    손상 이후: 실패 로그 폭증 (09-24, 시간당 gcloud 로그 줄 수)

    2026-09-24 시간당 gcloud stderr 줄 수

    near-miss: production에서 본 "번호가 재사용되지 않은" 경우

    2026-09-25 13:44, 앱 재시작 중 처리 thread 784443이 fd 7에 write 2회 후 close(7). 89.46ms 뒤 약 43.8초 동안 read(7)에서 대기하던 수신 thread 784460이 다시 read(7)를 했고 EBADF가 났다. 이번에는 그 사이 7번을 연 파일이 없었다. 같은 순간 DB가 열렸다면 손상이었다.

    수정 제안 (gcloud 쪽)

    1. 닫는 순서를 바꾼다

    sock.shutdown(SHUT_RDWR)로 수신 thread의 read를 깨우고, 그 thread를 join()한 뒤에만 close()한다. 아니면 socket 소유권을 수신 thread에 주고 닫기도 그쪽에서 하게 한다.

    2. close와 I/O를 같은 lock으로

    IapLightWeightWebsocket.close()는 lock 없는 check-then-act다. send에서 쓰는 lock을 close와 수신 경로에도 적용하고, close가 시작되면 run_forever가 더 읽지 않게 한다.

    의사 코드
    def close(self):
    with self._lock:
        if not self.connected:
            return
        self.connected = False            # run_forever 루프가 더 읽지 않게
        try:
            self.send_close()
        finally:
            self.sock.shutdown(socket.SHUT_RDWR)   # 블로킹 read 를 깨움 (fd 는 아직 살아 있음)
    if threading.current_thread() is not self._receiver:
        self._receiver.join(timeout=5)     # 수신 thread 가 OpenSSL 밖으로 나온 뒤
    self.sock.close()                      # 그때 비로소 번호 반납

    운영 교훈

    listener가 살아 있어도 end-to-end가 정상인 것은 아니다

    TCP connect 성공은 tunnel이 건강하다는 뜻이 아니다. PostgreSQL SSLRequest(00 00 00 08 04 d2 16 2f)를 보내 'S'/'N'를 받는 probe가 필요하다. A/B 시험에서 :15432는 connect 0.1ms에 성공하고 SSLRequest에서 reset됐다.

    독립 경로 대조군이 가장 빨리 범위를 줄인다

    같은 목적지로 가는 다른 호스트의 tunnel이 같은 시각에 'S'를 받았다. 이 한 번의 비교로 원격 전체(PG, VM, IAP, 네트워크)가 빠졌다.

    감시 도구도 검증해야 한다

    eBPF 필터가 s_dev == 0xfc00(사용자 공간 표기)였다. 커널 값은 0xfc00000(MKDEV)라 필터가 한 번도 참이 되지 않았다. "기록 없음"을 "사건 없음"으로 믿었다가 철회했다. 필터는 알려진 이벤트로 먼저 시험해야 한다.

    1차 원인과 2차 증폭을 분리한다

    앱 전체가 멈춘 직접 원인은 Slack 알림 코드였다. timeout 없는 동기 호출, .body(sendSlack(...)) 이중 호출, 컨테이너에 없던 webhook URL(기본값이 자기 자신)이 겹쳐 self-deadlock이 났다. 고치지 않았다면 DB 원인을 찾아도 장애 규모는 그대로였을 것이다.

    숫자의 모양이 가설을 준다

    24 bytes, 0x13 = 19 = 2 + 1 + 16, 그리고 항상 offset 29. 이 크기와 위치가 "암호화된 TLS alert가 파일에 쓰였다", 이어서 "fd 번호가 섞였다"는 가설을 곧바로 가리켰다.

    재현이 안 되면 관측을 옮긴다

    실험실 약 10,000연결로도 손상은 재현되지 않았다. 대신 운영 process에 PID를 따라가는 tracer와 손상 즉시 증거를 보존하는 supervisor를 붙였고, 다음 자연 발생에서 전체 syscall 사슬을 얻었다.

    증거 부록

    원본은 운영 서버의 /var/oled/diary-forensics/ 아래에 있다. 공개를 위해 IP, 프로젝트, 계정, invocation-id 등을 가렸다(<CLIENT_IP>, <ID> 등).

    E1 A/B 진단 결과 (2026-09-25 08:34)root-cause-20260925T083457Z/
    ### ROOT-CAUSE-CLASSIFICATION.txt
Captured: 2026-09-25T08:35:21.325Z

OLD_RESULT=3
OLD_SECOND_RESULT=3
FRESH_RESULT=99

CLASSIFICATION=CONTROL_TUNNEL_NOT_AVAILABLE

The fresh :15433 control could not be created.
Inspect fresh tunnel logs before drawing a conclusion.
### probe-old.txt
[OLD-15432] target=127.0.0.1:15432
[OLD-15432] start=1790325310314511163
[OLD-15432] TCP_CONNECT=OK
[OLD-15432] TCP_TIME=0.000137s
[OLD-15432] PG_SSL_RESPONSE=TIMEOUT_OR_ERROR
[OLD-15432] PG_SSL_TIME=0.201741s
[OLD-15432] ERROR=ConnectionResetError(104, 'Connection reset by peer')
### probe-old-second.txt
[OLD-15432-SECOND] target=127.0.0.1:15432
[OLD-15432-SECOND] start=1790325316783490690
[OLD-15432-SECOND] TCP_CONNECT=OK
[OLD-15432-SECOND] TCP_TIME=0.000136s
[OLD-15432-SECOND] PG_SSL_RESPONSE=TIMEOUT_OR_ERROR
[OLD-15432-SECOND] PG_SSL_TIME=4.027823s
[OLD-15432-SECOND] ERROR=ConnectionResetError(104, 'Connection reset by peer')
### probe-fresh.txt
FRESH_RESULT=NOT_AVAILABLE
### fresh-15433.stderr.log (tail)
sqlite3.DatabaseError: database disk image is malformed
ERROR: gcloud crashed (DatabaseError): database disk image is malformed

If you would like to report this issue, please run the following command:
  gcloud feedback

To check gcloud for common problems, please run the following command:
  gcloud info --run-diagnostics
    E2 09-24 05:44 손상 전후 gcloud 로그와 시간당 줄 수iap-timestamp/stderr-timestamped.log
    ### hourly line counts
    359 2026-09-24T01
    262 2026-09-24T02
    261 2026-09-24T03
    376 2026-09-24T04
   3322 2026-09-24T05
  10799 2026-09-24T06
  10799 2026-09-24T07
  10800 2026-09-24T08
### 05:44 sequence
2026-09-24T05:41:54.222Z DEBUG: [518] ENQUEUED data_len [44] bytes_to_send[:20] [b"\x17\x03\x03\x00'\x14!\xf3\xae\x02(KK\xfe\x1a\x86?\x02Z~"]
2026-09-24T05:41:54.225Z DEBUG: [518] SEND data_len [50] send_data[:20] b"\x00\x04\x00\x00\x00,\x17\x03\x03\x00'\x14!\xf3\xae\x02(KK\xfe"
2026-09-24T05:41:54.345Z DEBUG: [518] RECV opcode [2] data_len [10] binary_data[:20] [b'\x00\x07\x00\x00\x00\x00\x00\x00\x06:']
2026-09-24T05:41:54.347Z DEBUG: [518] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1c*h\x1c\x8e\x9a\xdbiS;']
2026-09-24T05:41:56.223Z DEBUG: [518] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\t\xee'
2026-09-24T05:43:52.020Z DEBUG: [518] ENQUEUED data_len [44] bytes_to_send[:20] [b"\x17\x03\x03\x00'\x0f\x12\x8e\xe9\x96'%(\x8d\xc9\xe5II\xef\x90"]
2026-09-24T05:43:52.022Z DEBUG: [518] SEND data_len [50] send_data[:20] b"\x00\x04\x00\x00\x00,\x17\x03\x03\x00'\x0f\x12\x8e\xe9\x96'%(\x8d"
2026-09-24T05:43:52.142Z DEBUG: [518] RECV opcode [2] data_len [10] binary_data[:20] [b'\x00\x07\x00\x00\x00\x00\x00\x00\x06f']
2026-09-24T05:43:52.144Z DEBUG: [518] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1c\x8c\x9af\xd9Sc\xd3v#']
2026-09-24T05:43:54.021Z DEBUG: [518] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\n\x0f'
2026-09-24T05:44:01.601Z DEBUG: [518] ENQUEUED data_len [43] bytes_to_send[:20] [b'\x17\x03\x03\x00&D5>\\V\x1fc\xf9\x10\x8aKQ(\x83q']
2026-09-24T05:44:01.604Z DEBUG: [518] ENQUEUED data_len [80] bytes_to_send[:20] [b'\x17\x03\x03\x00#\xd0pG\x87\xc7\x99{\x10\x8a\x03\x98\xed\xdf\xc2\xbb']
2026-09-24T05:44:01.606Z DEBUG: [518] Received local EOF, closing connection
2026-09-24T05:44:01.609Z DEBUG: [518] SEND data_len [49] send_data[:20] b'\x00\x04\x00\x00\x00+\x17\x03\x03\x00&D5>\\V\x1fc\xf9\x10'
2026-09-24T05:44:01.611Z DEBUG: [518] SEND data_len [86] send_data[:20] b'\x00\x04\x00\x00\x00P\x17\x03\x03\x00#\xd0pG\x87\xc7\x99{\x10\x8a'
2026-09-24T05:44:01.614Z DEBUG: [518] CLOSE
2026-09-24T05:44:01.617Z INFO: [518] Client closed connection from [('<CLIENT_IP>', 47348)].
2026-09-24T05:44:01.620Z DEBUG: On GCE from memory cache: False
2026-09-24T05:44:01.623Z DEBUG: [519] user-agent [gcloud/582.0.0 command/gcloud.compute.start-iap-tunnel invocation-id/<ID> environment/None environment-version/None client-os/LINUX client-os-ver/6.12.0 client-pltf-arch/x86_64 interactive/False from-script/False python/3.14.7 term/  (Linux 6.12.0-204.92.4.4.3.el9uek.x86_64)]
2026-09-24T05:44:01.626Z DEBUG: Cleaned [1] dead connection(s).
2026-09-24T05:44:01.629Z DEBUG: credentials type for _GetAccessTokenCallback is [<googlecloudsdk.core.credentials.google_auth_credentials.Credentials object at 0x7ff68dd14ad0>].
2026-09-24T05:44:01.721Z DEBUG: connections alive: [1]
2026-09-24T05:44:01.724Z DEBUG: On GCE from memory cache: False
2026-09-24T05:44:01.726Z INFO: [518] Received WebSocket Close message [1: 1].
2026-09-24T05:44:01.838Z ERROR: [519] Error during local connection to [('<CLIENT_IP>', 33692)]: database disk image is malformed
2026-09-24T05:44:01.840Z Traceback (most recent call last):
2026-09-24T05:44:01.843Z   File "/home/opc/google-cloud-sdk/lib/googlecloudsdk/command_lib/compute/iap_tunnel.py", line 805, in RunReceiveLocalData
2026-09-24T05:44:01.850Z     websocket_conn = self._InitiateConnection(
### 05:44 malformed first
38429:2026-09-24T05:44:01.838Z ERROR: [519] Error during local connection to [('<CLIENT_IP>', 33692)]: database disk image is malformed
    E3 09-25 10:32 손상 전후 gcloud 로그prod-corruption-20260925T103243Z/
    2026-09-25T10:28:55.548Z DEBUG: [9] ENQUEUED data_len [44] bytes_to_send[:20] [b"\x17\x03\x03\x00'hJ\x8f\x86\x87#\xb5\xd7\x97L\xa7_\xefv\x0e"]
2026-09-25T10:28:55.550Z DEBUG: [9] SEND data_len [50] send_data[:20] b"\x00\x04\x00\x00\x00,\x17\x03\x03\x00'hJ\x8f\x86\x87#\xb5\xd7\x97"
2026-09-25T10:28:55.675Z DEBUG: [9] RECV opcode [2] data_len [10] binary_data[:20] [b'\x00\x07\x00\x00\x00\x00\x00\x00\x06f']
2026-09-25T10:28:55.677Z DEBUG: [9] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1cx\x96\x11\x0f\xa9\xf2 t\xaa']
2026-09-25T10:28:57.549Z DEBUG: [9] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\n\x0f'
2026-09-25T10:30:46.382Z DEBUG: [9] ENQUEUED data_len [44] bytes_to_send[:20] [b'\x17\x03\x03\x00\'\x1ar"\xca\xaf\x1d9\x16I\xef\xb5"\xa0\xc5\x04']
2026-09-25T10:30:46.384Z DEBUG: [9] SEND data_len [50] send_data[:20] b'\x00\x04\x00\x00\x00,\x17\x03\x03\x00\'\x1ar"\xca\xaf\x1d9\x16I'
2026-09-25T10:30:46.509Z DEBUG: [9] RECV opcode [2] data_len [10] binary_data[:20] [b'\x00\x07\x00\x00\x00\x00\x00\x00\x06\x92']
2026-09-25T10:30:46.512Z DEBUG: [9] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1c\xad\xc9Xvh\\\x8e\x05\t']
2026-09-25T10:30:48.383Z DEBUG: [9] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\n0'
2026-09-25T10:32:37.216Z DEBUG: [9] ENQUEUED data_len [44] bytes_to_send[:20] [b"\x17\x03\x03\x00'\xa0Yt\x82\x92\rG\xaf\x86\x1aQI\x99N\xcc"]
2026-09-25T10:32:37.219Z DEBUG: [9] SEND data_len [50] send_data[:20] b"\x00\x04\x00\x00\x00,\x17\x03\x03\x00'\xa0Yt\x82\x92\rG\xaf\x86"
2026-09-25T10:32:37.343Z DEBUG: [9] RECV opcode [2] data_len [10] binary_data[:20] [b'\x00\x07\x00\x00\x00\x00\x00\x00\x06\xbe']
2026-09-25T10:32:37.345Z DEBUG: [9] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1c\xf6\xf3\xfb\x02gu\xe3\xa0x']
2026-09-25T10:32:39.217Z DEBUG: [9] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\nQ'
2026-09-25T10:32:43.008Z DEBUG: [9] ENQUEUED data_len [123] bytes_to_send[:20] [b'\x17\x03\x03\x00&\xf2\xec\xc6&\xde\xd2~\x9c\x94K\xe1\xdc\xa9\x8e\xa5']
2026-09-25T10:32:43.012Z DEBUG: [9] SEND data_len [129] send_data[:20] b'\x00\x04\x00\x00\x00{\x17\x03\x03\x00&\xf2\xec\xc6&\xde\xd2~\x9c\x94'
2026-09-25T10:32:43.015Z DEBUG: [9] CLOSE
2026-09-25T10:32:43.017Z DEBUG: [9] Received local EOF, closing connection
2026-09-25T10:32:43.020Z INFO: [9] Client closed connection from [('<CLIENT_IP>', 50996)].
2026-09-25T10:32:43.022Z DEBUG: Cleaned [1] dead connection(s).
2026-09-25T10:32:43.131Z DEBUG: connections alive: [1]
2026-09-25T10:32:43.135Z DEBUG: On GCE from memory cache: False
2026-09-25T10:32:43.139Z DEBUG: [10] user-agent [gcloud/582.0.0 command/gcloud.compute.start-iap-tunnel invocation-id/<ID> environment/None environment-version/None client-os/LINUX client-os-ver/6.12.0 client-pltf-arch/x86_64 interactive/False from-script/False python/3.14.7 term/  (Linux 6.12.0-204.92.4.4.3.el9uek.x86_64)]
2026-09-25T10:32:43.142Z DEBUG: credentials type for _GetAccessTokenCallback is [<googlecloudsdk.core.credentials.google_auth_credentials.Credentials object at 0x7f9534c60cd0>].
2026-09-25T10:32:43.204Z INFO: [9] Received WebSocket Close message [1: 1].
2026-09-25T10:32:43.242Z ERROR: [10] Error during local connection to [('<CLIENT_IP>', 56058)]: database disk image is malformed
2026-09-25T10:32:43.244Z Traceback (most recent call last):
2026-09-25T10:32:43.247Z   File "/home/opc/google-cloud-sdk/lib/googlecloudsdk/command_lib/compute/iap_tunnel.py", line 805, in RunReceiveLocalData
2026-09-25T10:32:43.249Z     websocket_conn = self._InitiateConnection(
2026-09-25T10:32:43.252Z         conn,
2026-09-25T10:32:43.302Z     ...<4 lines>...
    E4 확증 사건 bpftrace 발췌 (19:31:20)prod-corruption-20260926T193120Z/fdrace.log
    # bpftrace excerpt, gcloud start-iap-tunnel pid 784375 (nsecs = CLOCK_MONOTONIC)
# tid 1421083 = _ReceiveFromWebSocket thread of conn [93]; tid 1421118 = RunReceiveLocalData thread of conn [93]; tid 1431669 = handler thread of conn [94]
1782994483758112 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1782994484310035 IO     tid=1421083 fd=6 tracepoint:syscalls:sys_enter_sendto
1782996355584267 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1782997486670764 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1783112618900675 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1783112744694864 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1783112746043553 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1783112746076144 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1783112746408372 IO     tid=1421083 fd=6 tracepoint:syscalls:sys_enter_sendto
1783114619712111 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1783115748224655 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1783210794447320 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1783210794813040 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1783210794881670 SHUTDN tid=1421118 fd=6 how=2
1783210794934250 CLOSE  tid=1421118 fd=6
1783210795261518 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1783210795334326 IO     tid=1421118 fd=7 tracepoint:syscalls:sys_enter_write
1783210795370684 CLOSE  tid=1421118 fd=7
1783210800071097 OPEN   tid=1431669 fd=7 /home/opc/.config/gcloud-diary-iap/active_config
1783210800137653 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_read
1783210800146870 FREAD  tid=1431669 fd=7 ino=20396382 pos=0 len=8
1783210800153333 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_read
1783210800154636 FREAD  tid=1431669 fd=7 ino=20396382 pos=7 len=1
1783210800174753 CLOSE  tid=1431669 fd=7
1783210800281204 OPEN   tid=1431669 fd=7 /home/opc/.config/gcloud-diary-iap/default_configs.db
1783210800312674 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800314698 FREAD  tid=1431669 fd=7 ino=23194204 pos=0 len=100
1783210800492314 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800617059 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800632419 FREAD  tid=1431669 fd=7 ino=23194204 pos=24 len=16
1783210800672694 CLOSE  tid=1431669 fd=7
1783210800736124 OPEN   tid=1431669 fd=7 /home/opc/.config/gcloud-diary-iap/default_configs.db
1783210800757786 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800759549 FREAD  tid=1431669 fd=7 ino=23194204 pos=0 len=100
1783210800881228 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800962192 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800963985 FREAD  tid=1431669 fd=7 ino=23194204 pos=24 len=16
1783210800975998 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210800983442 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210801044016 CLOSE  tid=1431669 fd=7
1783210875242833 OPEN   tid=1431669 fd=7 /home/opc/.config/gcloud-diary-iap/active_config
1783210875296264 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_read
1783210875298508 FREAD  tid=1431669 fd=7 ino=20396382 pos=0 len=8
1783210875305011 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_read
1783210875306433 FREAD  tid=1431669 fd=7 ino=20396382 pos=7 len=1
1783210875324368 CLOSE  tid=1431669 fd=7
1783210875422643 OPEN   tid=1431669 fd=7 /home/opc/.config/gcloud-diary-iap/default_configs.db
1783210875438032 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210875439976 FREAD  tid=1431669 fd=7 ino=23194204 pos=0 len=100
1783210875611861 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210875719143 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210875721067 FREAD  tid=1431669 fd=7 ino=23194204 pos=24 len=16
1783210875757235 CLOSE  tid=1431669 fd=7
1783210875818321 OPEN   tid=1431669 fd=7 /home/opc/.config/gcloud-diary-iap/default_configs.db
1783210875829722 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210875831436 FREAD  tid=1431669 fd=7 ino=23194204 pos=0 len=100
1783210875949419 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210935320369 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210935337711 FREAD  tid=1431669 fd=7 ino=23194204 pos=24 len=16
1783210935339094 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_read
1783210935341608 FREAD  tid=1421083 fd=7 ino=23194204 pos=0 len=29
1783210935360444 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210935369572 IO     tid=1431669 fd=7 tracepoint:syscalls:sys_enter_pread64
1783210935394108 IO     tid=1421083 fd=7 tracepoint:syscalls:sys_enter_write
1783210935397805 FWRITE tid=1421083 fd=7 ino=23194204 pos=29 len=24 head=\x17\x03\x03\x00\x13\xaa#\xcb\xc9\x02r\xa9\x82\xf1=\xde
!!! TLS-LOOKING WRITE TO REGULAR FILE !!! tid=1421083 comm=Thread-275 (_Re
!!! TLS-LOOKING WRITE TO REGULAR FILE !!! tid=1421083 comm=Thread-275 (_Re
ustack:
        __write+79
        0x5627de228a30
        0x5627de113346
        0x5627de113227
        0x5627de5e0a63
        0x5627de5943be
        0x5627de5eeb03
        0x5627de5da308
        0x5627de5da5b4
        0x5627de592fcb
        0x5627de59f3d9
        0x5627ddfdda94
        0x5627ddd38995
        PyObject_Vectorcall+85
        0x5627dde67cdf
        _PyEval_EvalFrameDefault+254
        0x5627dde57653
        0x5627ddd2cf9f
        0x5627dde5ca42
        _PyEval_EvalFrameDefault+254
        0x5627dde57653
        0x5627ddd2cf9f
        0x5627dde878f8
        0x5627dde67499
        _PyEval_EvalFrameDefault+254
        0x5627dde57653
        0x5627ddd2cf9f
        0x5627de06e801
        0x5627ddeead19
        start_thread+825
    E5 확증 사건 gcloud 로그와 손상 DB 헤더prod-corruption-20260926T193120Z/
    2026-09-26T19:27:43.653Z DEBUG: [93] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1c\xfe\xf5_\xae-K\xec\x95\xdc']
2026-09-26T19:27:45.524Z DEBUG: [93] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\x14\xda'
2026-09-26T19:29:41.788Z DEBUG: [93] ENQUEUED data_len [44] bytes_to_send[:20] [b"\x17\x03\x03\x00'\xcaQ\r\x80,\xe9D\xc3\x15\x14\xe5k$\xe3\xce"]
2026-09-26T19:29:41.791Z DEBUG: [93] SEND data_len [50] send_data[:20] b"\x00\x04\x00\x00\x00,\x17\x03\x03\x00'\xcaQ\r\x80,\xe9D\xc3\x15"
2026-09-26T19:29:41.914Z DEBUG: [93] RECV opcode [2] data_len [10] binary_data[:20] [b'\x00\x07\x00\x00\x00\x00\x00\x00\x08\x1d']
2026-09-26T19:29:41.916Z DEBUG: [93] RECV opcode [2] data_len [39] binary_data[:20] [b'\x00\x04\x00\x00\x00!\x17\x03\x03\x00\x1c\xa8\xc4\x8c!\x95\xbf\xb4\xe8\xdc']
2026-09-26T19:29:43.788Z DEBUG: [93] SEND data_len [10] send_data[:20] b'\x00\x07\x00\x00\x00\x00\x00\x00\x14\xfb'
2026-09-26T19:31:19.964Z DEBUG: [93] ENQUEUED data_len [43] bytes_to_send[:20] [b'\x17\x03\x03\x00&\xa5\xd8\xe6\x02We\xf1\xcd\xa0\xed\xb6}\xd3\xe8\x95']
2026-09-26T19:31:19.967Z DEBUG: [93] ENQUEUED data_len [80] bytes_to_send[:20] [b'\x17\x03\x03\x00#vQz\x9ec\x995\xa3n\xa6\x17\x0ci.F']
2026-09-26T19:31:19.974Z DEBUG: [93] Received local EOF, closing connection
2026-09-26T19:31:19.978Z DEBUG: [93] SEND data_len [49] send_data[:20] b'\x00\x04\x00\x00\x00+\x17\x03\x03\x00&\xa5\xd8\xe6\x02We\xf1\xcd\xa0'
2026-09-26T19:31:19.981Z DEBUG: [93] SEND data_len [86] send_data[:20] b'\x00\x04\x00\x00\x00P\x17\x03\x03\x00#vQz\x9ec\x995\xa3n'
2026-09-26T19:31:19.984Z DEBUG: [93] CLOSE
2026-09-26T19:31:20.016Z INFO: [93] Client closed connection from [('<CLIENT_IP>', 35734)].
2026-09-26T19:31:20.019Z DEBUG: On GCE from memory cache: False
2026-09-26T19:31:20.023Z DEBUG: [94] user-agent [gcloud/582.0.0 command/gcloud.compute.start-iap-tunnel invocation-id/<ID> environment/None environment-version/None client-os/LINUX client-os-v
2026-09-26T19:31:20.027Z DEBUG: Cleaned [1] dead connection(s).
2026-09-26T19:31:20.030Z DEBUG: credentials type for _GetAccessTokenCallback is [<googlecloudsdk.core.credentials.google_auth_credentials.Credentials object at 0x7f3970558cd0>].
2026-09-26T19:31:20.043Z DEBUG: connections alive: [1]
2026-09-26T19:31:20.105Z DEBUG: On GCE from memory cache: False
2026-09-26T19:31:20.108Z INFO: [93] Received WebSocket Close message [1: 1].
2026-09-26T19:31:20.204Z ERROR: [94] Error during local connection to [('<CLIENT_IP>', 56440)]: database disk image is malformed
2026-09-26T19:31:20.206Z Traceback (most recent call last):
2026-09-26T19:31:20.209Z   File "/home/opc/google-cloud-sdk/lib/googlecloudsdk/command_lib/compute/iap_tunnel.py", line 805, in RunReceiveLocalData
2026-09-26T19:31:20.211Z     websocket_conn = self._InitiateConnection(
2026-09-26T19:31:20.213Z         conn,
2026-09-26T19:31:20.216Z     ...<4 lines>...
2026-09-26T19:31:20.220Z         conn_id=conn_id,
2026-09-26T19:31:20.227Z     )
2026-09-26T19:31:20.302Z   File "/home/opc/google-cloud-sdk/lib/googlecloudsdk/command_lib/compute/iap_tunnel.py", line 771, in _InitiateConnection
2026-09-26T19:31:20.305Z     new_websocket.InitiateConnection()

== hexdump of corrupted default_configs.db (first 64 bytes)
00000000: 5351 4c69 7465 2066 6f72 6d61 7420 3300  SQLite format 3.
00000010: 1000 0101 0040 2020 0000 0003 0017 0303  .....@  ........
00000020: 0013 aa23 cbc9 0272 a982 f13d dea7 0fbe  ...#...r...=....
00000030: 1559 2993 ea00 0000 0000 0001 0000 0000  .Y).............
    E6 production near-miss (09-25 13:44)prod-trace/fdrace-pid*.log
    ### near-miss (fdrace-pid784375-20260925T134124Z.log line 292)
1675931699860192 IO     tid=784460 fd=7 tracepoint:syscalls:sys_enter_read
1675931701473721 IO     tid=784460 fd=7 tracepoint:syscalls:sys_enter_read
1675931701490703 IO     tid=784460 fd=7 tracepoint:syscalls:sys_enter_read
1675934704522372 IO     tid=784460 fd=7 tracepoint:syscalls:sys_enter_read
1675978445696236 IO     tid=784443 fd=7 tracepoint:syscalls:sys_enter_write
1675978445830710 IO     tid=784443 fd=7 tracepoint:syscalls:sys_enter_write
1675978445870755 CLOSE  tid=784443 fd=7
1675978535335496 IO     tid=784460 fd=7 tracepoint:syscalls:sys_enter_read
1675978535348952 EBADF  tid=784460 fd=7 tracepoint:syscalls:sys_exit_read
!!! RAW-FD USE-AFTER-CLOSE !!! tid=784460 fd=7
ustack:
        __GI_read+76
    E7 실험실 재현 통계repro-20260925T090534Z/
    ### analyze fdrace2 (1500 conc10)
events: {'ACCEPT': 1500, 'OPEN': 7492, 'IO': 189646, 'FREAD': 9000, 'CLOSE': 16393, 'SOCKET': 7407, 'SHUTDN': 3000, 'EBADF': 93}
HIT (non-sqlite read/write on DB fd): 0
STALE (old socket user touching new file generation): 0
EBADF (use of already-closed fd): 93
     68 tracepoint:syscalls:sys_exit_sendto
     19 tracepoint:syscalls:sys_exit_recvfrom
      6 tracepoint:syscalls:sys_exit_read
### hunt.log
09:26:41 round=1 corrupt_dbs=0 hit=0 raw_uaf=15 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 135), (('full', 'S'), 244), (('rst', 'S'), 121)]
09:29:38 round=2 corrupt_dbs=0 hit=0 raw_uaf=28 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 119), (('full', 'S'), 274), (('rst', 'S'), 107)]
09:32:32 round=3 corrupt_dbs=0 hit=0 raw_uaf=45 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 132), (('full', 'S'), 244), (('rst', 'S'), 124)]
09:35:22 round=4 corrupt_dbs=0 hit=0 raw_uaf=61 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 146), (('full', 'S'), 250), (('rst', 'S'), 104)]
09:38:16 round=5 corrupt_dbs=0 hit=0 raw_uaf=70 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 134), (('full', 'S'), 259), (('rst', 'S'), 107)]
09:41:17 round=6 corrupt_dbs=0 hit=0 raw_uaf=89 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 135), (('full', 'S'), 252), (('rst', 'S'), 113)]
09:44:16 round=7 corrupt_dbs=0 hit=0 raw_uaf=101 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 124), (('full', 'S'), 226), (('rst', 'S'), 150)]
09:47:13 round=8 corrupt_dbs=0 hit=0 raw_uaf=112 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 136), (('full', 'S'), 255), (('rst', 'S'), 109)]
09:50:07 round=9 corrupt_dbs=0 hit=0 raw_uaf=125 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 122), (('full', 'S'), 255), (('rst', 'S'), 123)]
09:53:06 round=10 corrupt_dbs=0 hit=0 raw_uaf=146 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 125), (('full', 'S'), 235), (('rst', 'S'), 140)]
09:56:07 round=11 corrupt_dbs=0 hit=0 raw_uaf=161 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 122), (('full', 'S'), 255), (('rst', 'S'), 123)]
09:59:11 round=12 corrupt_dbs=0 hit=0 raw_uaf=171 tls_file_writes=0 SUMMARY [(('abrupt', 'SENT'), 122), (('full', 'S'), 271), (('rst', 'S'), 107)]
no reproduction after 12 rounds
### pair summary
SUMMARY {'S': 1000}
10:21:57 #950 ok {'S': 950}
10:23:04 #1000 ok {'S': 1000}
### pair2
13:34:38 #50 ok {'S': 50}
13:36:32 #100 ok {'S': 100}
### load-summary
SUMMARY [(('abrupt', 'SENT'), 69), (('full', 'S'), 139), (('rst', 'S'), 92)]
SUMMARY [(('abrupt', 'SENT'), 357), (('full', 'S'), 759), (('full', 'TIMEOUT'), 1), (('rst', 'S'), 383)]
SUMMARY [(('abrupt', 'SENT'), 135), (('full', 'S'), 244), (('rst', 'S'), 121)]
SUMMARY [(('abrupt', 'SENT'), 119), (('full', 'S'), 274), (('rst', 'S'), 107)]
SUMMARY [(('abrupt', 'SENT'), 132), (('full', 'S'), 244), (('rst', 'S'), 124)]
SUMMARY [(('abrupt', 'SENT'), 146), (('full', 'S'), 250), (('rst', 'S'), 104)]
SUMMARY [(('abrupt', 'SENT'), 134), (('full', 'S'), 259), (('rst', 'S'), 107)]
SUMMARY [(('abrupt', 'SENT'), 135), (('full', 'S'), 252), (('rst', 'S'), 113)]
SUMMARY [(('abrupt', 'SENT'), 124), (('full', 'S'), 226), (('rst', 'S'), 150)]
SUMMARY [(('abrupt', 'SENT'), 136), (('full', 'S'), 255), (('rst', 'S'), 109)]
SUMMARY [(('abrupt', 'SENT'), 122), (('full', 'S'), 255), (('rst', 'S'), 123)]
SUMMARY [(('abrupt', 'SENT'), 125), (('full', 'S'), 235), (('rst', 'S'), 140)]
SUMMARY [(('abrupt', 'SENT'), 122), (('full', 'S'), 255), (('rst', 'S'), 123)]
SUMMARY [(('abrupt', 'SENT'), 122), (('full', 'S'), 271), (('rst', 'S'), 107)]
### lab300: same-thread 1183 cross-thread 597 db-reuse<200ms 197 min_ms 0.03 median_ms 4.2
### raw-fd EBADF detail (fdrace2)
read fd=17 reader_tid=502660 closer_tid=502798 gap_ms=0.18
read fd=23 reader_tid=505835 closer_tid=505975 gap_ms=0.26
read fd=17 reader_tid=510398 closer_tid=510317 gap_ms=0.07
read fd=12 reader_tid=512090 closer_tid=512252 gap_ms=0.35
read fd=11 reader_tid=520126 closer_tid=520250 gap_ms=3.79
read fd=8 reader_tid=523681 closer_tid=523635 gap_ms=110.68
    E8 손상 DB 4개의 hexdump각 사건 폴더
    ### /var/oled/diary-forensics/root-cause-20260925T083457Z/default_configs.db.corrupt.20260924T054401Z
size=12288 mtime=2026-09-24 05:44:01.720654520 +0000
00000000: 5351 4c69 7465 2066 6f72 6d61 7420 3300  SQLite format 3.
00000010: 1000 0101 0040 2020 0000 0003 0017 0303  .....@  ........
00000020: 0013 c98c 9768 fcee 268e 8137 ba38 7ac3  .....h..&..7.8z.
00000030: 7ed5 64c0 5a00 0000 0000 0001 0000 0000  ~.d.Z...........
00000040: 0000 0000 0000 0000 0000 0000 0000 0000  ................
00000050: 0000 0000 0000 0000 0000 0000 0000 0003  ................
### /var/oled/diary-forensics/prod-corruption-20260925T103243Z/default_configs.db.corrupt
size=12288 mtime=2026-09-25 10:32:43.134759753 +0000
00000000: 5351 4c69 7465 2066 6f72 6d61 7420 3300  SQLite format 3.
00000010: 1000 0101 0040 2020 0000 0003 0017 0303  .....@  ........
00000020: 0013 1205 4a46 10a2 aa88 9d1a 074e 5d57  ....JF.......N]W
00000030: 7b17 6a5f b700 0000 0000 0001 0000 0000  {.j_............
00000040: 0000 0000 0000 0000 0000 0000 0000 0000  ................
00000050: 0000 0000 0000 0000 0000 0000 0000 0003  ................
### /var/oled/diary-forensics/prod-corruption-20260926T193120Z/default_configs.db.corrupt
size=12288 mtime=2026-09-26 19:31:20.101826250 +0000
00000000: 5351 4c69 7465 2066 6f72 6d61 7420 3300  SQLite format 3.
00000010: 1000 0101 0040 2020 0000 0003 0017 0303  .....@  ........
00000020: 0013 aa23 cbc9 0272 a982 f13d dea7 0fbe  ...#...r...=....
00000030: 1559 2993 ea00 0000 0000 0001 0000 0000  .Y).............
00000040: 0000 0000 0000 0000 0000 0000 0000 0000  ................
00000050: 0000 0000 0000 0000 0000 0000 0000 0003  ................
### /var/oled/diary-forensics/iap-ebpf/default_configs.db.corrupt.20260917T131711Z
size=12288 mtime=2026-09-17 08:05:24.605798898 +0000
00000000: 5351 4c69 7465 2066 6f72 6d61 7420 3300  SQLite format 3.
00000010: 1000 0101 0040 2020 0000 0003 0017 0303  .....@  ........
00000020: 0013 c10b f5c1 a02d 6581 8e43 e6b7 068f  .......-e..C....
00000030: 920f 5f78 ee00 0000 0000 0001 0000 0000  .._x............
00000040: 0000 0000 0000 0000 0000 0000 0000 0000  ................
00000050: 0000 0000 0000 0000 0000 0000 0000 0003  ................
    E9 gcloud stderr의 TLS 오류 누적 (09-25 복구 전까지)pre-recovery-20260925T091158Z/
    ### /var/oled/diary-forensics/pre-recovery-20260925T091158Z/iap-stderr.log
 159429 malformed
    284 SSL: WRONG_VERSION_NUMBER
    139 SSL: RECORD_LAYER_FAILURE
     88 SSL: UNEXPECTED_MESSAGE
      6 SSL: EXCESSIVE_MESSAGE_SIZE
--- sample UNEXPECTED_MESSAGE context
17906-  File "/home/opc/google-cloud-sdk/platform/bundledpythonunix/lib/python3.14/ssl.py", line 1088, in _create
17907-    self.do_handshake()
17908-    ~~~~~~~~~~~~~~~~~^^
17909-  File "/home/opc/google-cloud-sdk/platform/bundledpythonunix/lib/python3.14/ssl.py", line 1384, in do_handshake
17910-    self._sslobj.do_handshake()
17911-    ~~~~~~~~~~~~~~~~~~~~~~~~~^^
17912:ssl.SSLError: [SSL: UNEXPECTED_MESSAGE] unexpected message (_ssl.c:1082)
    E10 사용한 bpftrace 프로그램prod-fdrace.bt
    // PROD: diary-db-iap-tunnel gcloud process fd lifecycle / file I/O / raw-fd use-after-close tracer (tgid = $1)
// 목적: "close된 socket fd 번호가 sqlite 파일로 재사용되고, 그 fd에 TLS record가 써지는가"를
// syscall 단위로 기록한다.
config = { max_strlen = 128 }

BEGIN { printf("=== fdrace tracer started, target pid=%d ===\n", $1); }

// ---- fd 생성 ----
tracepoint:syscalls:sys_enter_openat /pid == $1/ { @fn[tid] = str(args.filename); }
tracepoint:syscalls:sys_exit_openat /pid == $1 && has_key(@fn, tid)/ {
  printf("%lu OPEN   tid=%d fd=%d %s\n", nsecs, tid, args.ret, @fn[tid]);
  delete(@fn, tid);
}
tracepoint:syscalls:sys_exit_socket /pid == $1/ { printf("%lu SOCKET tid=%d fd=%d\n", nsecs, tid, args.ret); }
tracepoint:syscalls:sys_exit_accept4 /pid == $1/ { printf("%lu ACCEPT tid=%d fd=%d\n", nsecs, tid, args.ret); }
tracepoint:syscalls:sys_exit_accept /pid == $1/ { printf("%lu ACCEPT tid=%d fd=%d\n", nsecs, tid, args.ret); }
tracepoint:syscalls:sys_exit_dup /pid == $1/ { printf("%lu DUP    tid=%d fd=%d\n", nsecs, tid, args.ret); }

// ---- fd 해제 ----
tracepoint:syscalls:sys_enter_close /pid == $1/ { printf("%lu CLOSE  tid=%d fd=%d\n", nsecs, tid, args.fd); }
tracepoint:syscalls:sys_enter_shutdown /pid == $1/ { printf("%lu SHUTDN tid=%d fd=%d how=%d\n", nsecs, tid, args.fd, args.how); }

// ---- write/read syscall 진입 시 fd 기록 (vfs_* 에는 fd가 없으므로 tid로 연결) ----
tracepoint:syscalls:sys_enter_write   /pid == $1/ { @wfd[tid] = args.fd; }
tracepoint:syscalls:sys_enter_pwrite64 /pid == $1/ { @wfd[tid] = args.fd; }
tracepoint:syscalls:sys_exit_write    /pid == $1/ { delete(@wfd, tid); }
tracepoint:syscalls:sys_exit_pwrite64 /pid == $1/ { delete(@wfd, tid); }
tracepoint:syscalls:sys_enter_read    /pid == $1/ { @rfd[tid] = args.fd; }
tracepoint:syscalls:sys_enter_pread64 /pid == $1/ { @rfd[tid] = args.fd; }
tracepoint:syscalls:sys_exit_read     /pid == $1/ { delete(@rfd, tid); }
tracepoint:syscalls:sys_exit_pread64  /pid == $1/ { delete(@rfd, tid); }

// ---- 일반 파일(S_IFREG)에 대한 write: sqlite 정상 write + 이상 write 모두 ----
kprobe:vfs_write /pid == $1/ {
  $f = (struct file *)arg0;
  if (($f->f_inode->i_mode & 0xF000) == 0x8000) {
    $h0 = *(uint8 *)uptr(arg1);
    printf("%lu FWRITE tid=%d fd=%d ino=%lu pos=%ld len=%lu head=%r\n",
           nsecs, tid, @wfd[tid], $f->f_inode->i_ino, *(int64 *)arg3, arg2,
           buf(uptr(arg1), arg2 < 16 ? arg2 : 16));
    if ($h0 == 0x17 || $h0 == 0x15 || $h0 == 0x16) {
      printf("!!! TLS-LOOKING WRITE TO REGULAR FILE !!! tid=%d comm=%s\nustack:%s\nkstack:%s\n",
             tid, comm, ustack(30), kstack(15));
    }
  }
}

// ---- 일반 파일 read (OpenSSL이 TLS header 5 bytes를 파일에서 읽는지 확인) ----
kprobe:vfs_read /pid == $1/ {
  $f = (struct file *)arg0;
  if (($f->f_inode->i_mode & 0xF000) == 0x8000 && arg2 < 4096) {
    printf("%lu FREAD  tid=%d fd=%d ino=%lu pos=%ld len=%lu\n",
           nsecs, tid, @rfd[tid], $f->f_inode->i_ino, *(int64 *)arg3, arg2);
    if (arg2 == 5) {
      printf("!!! 5-BYTE READ FROM REGULAR FILE (TLS record header size) !!! tid=%d\nustack:%s\n",
             tid, ustack(30));
    }
  }
}

// fdrace.bt 보강: 모든 fd I/O의 (tid, fd)와 EBADF(닫힌 fd 사용)를 기록한다.
// 분석: DB 파일 generation의 fd를 opener가 아닌 thread가 I/O 하면 = race 적중.
tracepoint:syscalls:sys_enter_read,
tracepoint:syscalls:sys_enter_write,
tracepoint:syscalls:sys_enter_recvfrom,
tracepoint:syscalls:sys_enter_sendto,
tracepoint:syscalls:sys_enter_recvmsg,
tracepoint:syscalls:sys_enter_sendmsg,
tracepoint:syscalls:sys_enter_pread64,
tracepoint:syscalls:sys_enter_pwrite64
/pid == $1/ { printf("%lu IO     tid=%d fd=%d %s\n", nsecs, tid, args.fd, probe); @iofd[tid] = args.fd; }

tracepoint:syscalls:sys_exit_read,
tracepoint:syscalls:sys_exit_write,
tracepoint:syscalls:sys_exit_recvfrom,
tracepoint:syscalls:sys_exit_sendto,
tracepoint:syscalls:sys_exit_recvmsg,
tracepoint:syscalls:sys_exit_sendmsg,
tracepoint:syscalls:sys_exit_pread64,
tracepoint:syscalls:sys_exit_pwrite64
/pid == $1/ {
  if (args.ret == -9) {
    printf("%lu EBADF  tid=%d fd=%d %s\n", nsecs, tid, @iofd[tid], probe);
    if ((int64)@iofd[tid] >= 0) { printf("!!! RAW-FD USE-AFTER-CLOSE !!! tid=%d fd=%d\nustack:%s\n", tid, @iofd[tid], ustack(40)); }
  }
  delete(@iofd, tid);
}
END { clear(@fn); clear(@wfd); clear(@rfd); clear(@iofd); }

    용어집

    fd (file descriptor)
    process가 연 파일이나 socket을 가리키는 작은 정수. Linux는 새로 열 때 비어 있는 가장 작은 번호를 준다.
    use-after-close
    이미 close()한 fd 번호를 계속 쓰는 버그. 번호가 재사용되면 전혀 다른 파일이나 socket에 읽고 쓰게 된다.
    race (경합)
    두 thread의 실행 순서에 따라 결과가 달라지는 상태. 여기서는 "닫기"와 "읽기"의 순서.
    TLS record
    TLS가 데이터를 나르는 단위. header 5 bytes(type 1, version 2, length 2) 뒤에 본문이 온다. TLS 1.3에서는 alert도 0x17로 암호화되어 나간다.
    AEAD tag
    암호문에 붙는 16 bytes 인증 태그. 이것이 맞지 않으면 복호화 실패로 연결을 끊고 alert를 보낸다.
    SSL_set_fd
    OpenSSL에 socket의 정수 fd를 넘겨주는 함수. OpenSSL은 이후 이 번호로 직접 read()/write()를 한다.
    EBADF
    "잘못된 fd" 오류. 닫힌 번호를 쓰면 나지만, 번호가 이미 재사용됐다면 나지 않고 남의 대상에 조용히 쓴다.
    bpftrace
    커널 eBPF로 syscall과 커널 함수를 추적하는 도구. 여기서는 gcloud PID 하나만 골라 fd 수명과 I/O를 기록했다.
    SSLRequest
    PostgreSQL 클라이언트가 TLS를 쓰겠다고 알리는 8 bytes 요청. 서버는 1 byte('S' 또는 'N')로 답한다.
    IAP TCP forwarding
    Google Cloud의 Identity-Aware Proxy가 외부 IP 없는 VM으로 TCP를 중계하는 기능. 클라이언트 쪽은 gcloud compute start-iap-tunnel이 WebSocket over TLS로 연결한다.