2. ebpf 활용 이슈 해결

굳이 적는이유

태어나서 잡은 원인중에 진짜 레전드로 어려워서 안적으면 서러워서.......

 

eBPF 활용 시스템콜 추적 및 원인규명

---

0. 본 문서의 역할

포렌식 보고서 가 답한 것: "무엇이 깨졌는가" (재현 가능한 코드 버그, 3-region 패턴, sparse hole 존재).

본 문서가 답하는 것: "어떻게 깨졌는가" — 어떤 syscall 이 호출됐고, 언제, 왜 호출됐는지를 커널 레벨에서 실시간 관측 한 결과.

핵심 결론 한 줄:

두 개의 fd 가 같은 파일(inode)을 동시에 가리키는 race 가 있었고, 두 번째 open 의 O_TRUNC 가 기존 파일을 날린 직후 첫 번째 fd 의 stale offset 으로 write 가 들어가면서 sparse hole 이 생성됨.

---

1. 왜 eBPF 를 썼나

1-1. 일반 도구의 한계

포렌식 단계까지 확정된 사실:

• sparse hole 이 존재하려면 특정 syscall (lseek / ftruncate / fallocate / pwrite) 이 호출되거나, stale fd 에 write 가 일어나야 한다.
• 코드에는 그런 syscall 호출이 직접적으로 없다.
• 그렇다면 간접 경로 (klauspost/compress 내부, os runtime, OS 상호작용) 에서 호출되는 것이어야 함.

이걸 확인하려면 실행 중인 프로세스의 syscall 을 실시간으로 관측 해야 한다.

 

선택지는 보통 레이어 내려가서 디버깅 하려면 뭐..... 저거 4개로 해야한다.

 

strace	🔴 매우 높음 (ptrace)	❌ 타이밍이 바뀌어 race 재현 안 될 위험	⚠️ 1차 탐색용만
bpftrace (eBPF)	🟢 거의 제로 (커널 필터)	✅ 실제 타이밍 유지	⭐ 최우선
perf trace	🟡 중간	🟡	차선
Go 내부 로깅	🟢 낮음	✅	⭐ bpftrace 와 병행

 

race 를 디버깅할 때 ptrace 기반 strace 는 사실상 쓸 수 없다.

 

프로세스마다 context switch 오버헤드가 5~20 배 수준이라 타이밍이 크게 바뀌어 race 가 숨어버린다. eBPF 는 커널 내부에서 이벤트를 훅 걸어 user space 에 전달만 하는 구조라 오버헤드가 미미하다.

1-2. eBPF 한 줄 설명

커널에 작은 관찰 스크립트를 주입해두고, 특정 이벤트(e.g. syscall entry)가 발생할 때마다 거의 공짜에 가까운 비용으로 실행시키는 메커니즘.

비유:

• strace = 프로세스를 따라다니며 일일이 받아적기 (느림, 본인도 지침)
• bpftrace = 커널 안에 CCTV 를 설치 (원본 프로세스는 아무것도 모름)

bpftrace 는 그 eBPF 를 awk 스타일 문법으로 쓸 수 있게 해주는 frontend. kernel 5.14 / Rocky Linux 9.6 에 이미 설치돼 있어서 추가 빌드 없이 바로 사용 가능했다.

---

2. 트레이싱 파이프라인 설계

2-1. 전체 구조

 

두 개의 관찰자가 병렬로 동작:

• bpftrace: 커널 syscall 레벨 (무엇이 호출됐는지)
• stat-polling watcher: 파일시스템 레벨 (파일이 언제 sparse 상태로 전이했는지)

두 로그의 timestamp 를 시계열로 correlation 하면 "어떤 syscall 이 어느 순간 sparse hole 을 만들었는가" 를 직접 볼 수 있다.

2-2. bpftrace 스크립트 설계 

트레이스 포인트 , 시스템콜 종류이다.

 

파일 open	openat (enter + exit)
일반 write	write, writev
오프셋 지정 write	pwrite64, pwritev, pwritev2
오프셋 이동	lseek
파일 확장/축소	ftruncate, truncate, fallocate
fd 복제	dup, dup2, dup3, fcntl
파일명 변경	renameat2, unlinkat
파일 close	close

 

각 이벤트에 기록하는 것:

• time("%H:%M:%S ") — 벽시계 시각
• nsecs — 나노초 단위 monotonic clock (race 순서 판정용)
• tid — 스레드 ID (어느 goroutine 이 어느 OS 스레드를 썼는지)
• fd, path, flags, mode (openat), wbytes/wcount (write 집계)

필터링:

• pid == @target — 대상 agent 프로세스만
• @fd[pid, args->fd] != "" — openat 에서 이미 추적 시작한 fd 만 (노이즈 제거)

write 는 이벤트가 너무 많아서 개별 출력 대신 fd 별 집계:

• @wcount[pid, fd] — write 호출 횟수
• @wbytes[pid, fd] — 누적 바이트
• @first_ns[pid, fd], @last_ns[pid, fd] — 첫 write / 마지막 write 의 nanosecond timestamp

close 시 해당 fd 의 집계를 전부 dump:

이 한 줄에 "해당 fd 의 생애 동안 write 가 언제 시작했고 언제 끝났는지" 가 들어간다. 이후 다른 fd 의 open ns 와 대조하면 race 순서를 ms 단위 정확도로 판정 가능.

2-3. Stat 기반 watcher (hcap-watch.sh)

500 ms 마다 stat --printf='%s|%b|%Y|%n\\n' 로 temp 디렉토리의 모든 hcap 파일 상태 기록:

blocks * 512 / size 비율이 0.9 미만 으로 떨어지면 SPARSE 라벨. 이게 정확히 sparse hole 이 생긴 시점 을 초 단위 이하로 포착.

---

3. 선수 지식 — Linux 의 fd / struct file / inode 계층

이 절은 본 보고서 전체에서 가장 중요한 개념 조각 이다. 앞으로 나올 관측 해석 (특히 "fd 가 두 개인데 같은 파일")이 이 지식 없이는 혼란스럽다.

3-1. 헷갈리지말아야되는 포인트

흔한 직관:

"fd=6 과 fd=7 은 다른 fd 번호니까 서로 다른 파일 아니야?"

결론부터: 아니다. 같은 fd 번호 ≠ 같은 파일이고, 다른 fd 번호 ≠ 다른 파일이다. fd 는 파일 자체가 아니라 "파일을 가리키는 참조의 참조" 다.

3-2. 3 단계 계층

핵심:

• struct file 은 "이 파일에 접근하는 나만의 관점" (offset 등) 을 담는 per-open 구조체
• inode 는 "파일 자체" — 디스크 상 데이터와 크기/블록 정보
• 여러 struct file 이 같은 inode 를 공유 가능

3-3. 같은 경로를 두 번 open() 했을 때

이때 일어나는 일:

• 프로세스에 새 fd 가 하나 더 할당 (fd=7)
• 커널 내부에 새 struct file B 가 생성 (offset=0, 고유 flags)
• VFS 가 path lookup 을 수행해 같은 inode I 를 찾음
• fd=6 (struct file A) 와 fd=7 (struct file B) 는 서로 독립적인 offset 을 가지지만, 같은 inode 에 쓰고 읽는다

예:

• fd=6 에 write(fd=6, "hello", 5) → struct file A 의 offset 이 0 → 5, inode I 의 data 가 "hello"
• fd=7 에 write(fd=7, "X", 1) → struct file B 의 offset 이 0 → 1, inode I 의 data 가 "Xello" (offset 0 위치 덮어씀)
• fd=7 이 offset 을 0 으로 유지하는 건 자기 struct file B 안의 offset 만 이고, fd=6 의 offset (5) 은 건드리지 않음

3-4. O_TRUNC 는 어느 레벨에 작용하나

 

결정적 포인트:

• O_TRUNC 는 inode 레벨 에 작용한다. size 를 0 으로 만들고 blocks 를 해제.
• 다른 struct file (다른 fd) 의 offset 은 건드리지 않는다. struct file 은 각자 독립.

그래서 만약 fd=6 이 offset 19 MB 를 가지고 있는 상태에서 다른 프로세스(또는 같은 프로세스의 다른 goroutine)가 같은 path 를 O_TRUNC 로 open 해서 fd=7 을 받으면:

• inode 는 size=0 으로 잘림 (내용 전부 해제)
• fd=6 의 struct file 은 그대로 offset 19 MB
• fd=6 이 다음 write 를 하면 offset 19 MB 에 쓰려고 함
• 커널: "이 inode 의 size 는 0 인데 offset 19 MB 에 쓴다고?"
• → sparse file 로 확장: inode size 를 19 MB + n 으로 키우고, [0, 19 MB) 는 hole 로 마크, [19 MB, 19 MB + n) 만 실제 블록 할당

이게 우리가 본 3-region 패턴의 직접적 생성 메커니즘이다.

3-5. "fd 가 다르면 다른 파일" 이 맞는 경우

만약 다음 시퀀스가 있다면 fd 가 다른 파일을 가리키는 게 맞다:

이 경우 fd=6 과 fd=7 은 진짜로 다른 파일 (다른 inode). 하지만 fd=6 과 fd=7 모두 유효한 read/write 가 가능 (fd=6 은 orphan inode I₁ 에 계속 쓸 수 있음, 닫히면 I₁ 삭제).

우리 run2 에서는 중간에 unlinkat syscall 이 관측되지 않았다. 그러니 fd=6 과 fd=7 은 같은 inode 를 공유하는 관계. 이 사실이 이후 모든 추론의 기반이다.

---

4. Run 1 — 첫 관측

4-1. 세팅

hcap-trace.bt (v1) 로 2026-04-11 17:01~17:07 UTC 세션 진행. 재현 스크립트: robust_v2_tps.sh trace_run small 300 120.

v1 스크립트의 한계:

• Open flags 미기록
• nanosecond timestamp 없음 (초 단위 wall clock 만)

그래도 "무엇이 open/close 됐는가" 는 충분히 드러남.

4-2. 재현 결과

• ..._20260411_1703.hcap.gz — 18.08 MB size / 2.34 MB allocated (87% sparse)
• ..._20260411_1704.hcap.gz — 9.40 MB size / ~9.5 MB allocated (정상)

4-3. 핵심 관측 — 같은 파일의 두 번 OPEN

로그를 봐보면 fd 값 6 에서 7이 다른 프로세스로 인해 열린다. 즉 파일 오염이 진행된다는 뜻.

17:03:00	OPEN	6792	6	—
17:03:54	OPEN	6792	7 ★	— (같은 1703 파일 재오픈!)
17:03:54	CLOSE fd=6	6791	6	18,955,097
17:04:00	CLOSE fd=7	6791	7	2,444,992

 

관찰:

• 같은 파일명 (1703.hcap.gz) 에 대해 두 번의 OPEN
• fd=6 의 wbytes (18.9 MB) ≈ 파일 크기 (18.9 MB)
• fd=7 의 wbytes (2.4 MB) ≈ 파일 실제 allocated blocks (2.3 MB)

이 시점까지의 가설:

"두 fd 가 동일 파일을 동시에 가리켰고, 두 번째 open 이 O_TRUNC 로 파일을 날렸을 가능성이 높다. 하지만 open flags 를 모르고 timing 도 초 단위라 확정 불가."

→ v2 트레이서로 재도전 결정.

4-4. Run1 의 부산물 — 정상 rotation 의 관측

같은 trace log 의 17:02 → 17:03 minute boundary 이벤트도 잡힘:

이건 정상 rotation 이다:

• 이전 파일이 close 됨
• 새 파일이 open 됨
• 파일명이 다름 → 같은 inode 공유 아님 → 문제없음

이 사실이 나중에 중요해진다. goroutine race 자체는 분마다 일어나지만, 대부분 무해 라는 관측의 근거가 이 이벤트.

---

5. Run 2 — smoking gun 확보

5-1. v2 트레이서 개선점

hcap-trace-v2.bt 로 업그레이드:

• openat flags + mode 기록 (O_TRUNC 포함 여부 확정)
• nanosecond timestamp (nsecs) 기록 (race 순서 정밀 판정)
• write first_ns / last_ns 집계 (fd 별 write 기간 추적)
• pid 필터 를 각 probe 의 filter 절에 명시 (v1 에선 -p 만으로는 필터 안 됐음)
• writev/pwritev/pwritev2/dup/fcntl/renameat2/unlinkat 추가 커버

5-2. 재현 결과

• ..._20260411_1720.gz — 19,053,425 bytes size / 217,088 bytes allocated (98.9% sparse) — 극단적 손상
• ..._20260411_1721.gz — 8.2 MB, 정상

Run1 대비 sparse 비율이 훨씬 극단적 (87% → 99%). race window 가 조금 다른 양상이지만 같은 패턴.

5-3. 나노초 상관분석

세 가지 순간을 ns 로 비교 해본 순서:

1. fd=7 OPEN (17:20:58.691601)
2. fd=6 의 마지막 write 25.7 μs 뒤 (17:20:58.691626)
3. fd=6 CLOSE 3.2 μs 뒤 (17:20:58.691629)

즉 fd=7 이 open 된 후에도 fd=6 이 write 를 한 번 더 했다.

이는 3-3 절에서 설명한 메커니즘의 직접 증거.

5-5. 메커니즘 재구성 (fd/inode 관점)

간단하게 말하면 특정 fd 으로 인해서 파일을 open하고 파악하고 write하는 부분이 있을텐데 다른 fd로 똑같이 open해서 제어권을 가져가면 O_TRUNC로 다시 같은 파일을 들어왔을때 사이에 000000 와 같은 빈 버퍼공간이 들어가게된다고 보면 된다.

 

결과:

• inode I₁ 의 size ≈ 19 MB
• inode I₁ 의 할당 블록 = [0, 211 KB) + [19 MB, 19 MB + n)
• 중간 [211 KB, 19 MB) = 모두 sparse hole

5-6. 파일의 최종 상태와 산수

stat 결과:

산수 검증:

• fd=7 wbytes = 211,499 bytes → [0, 211 KB) 영역, 할당 ≈ 211 KB ✓
• 총 할당 217,088 bytes — fd=7 영역 211,499 bytes = 5,589 bytes 잔여
• 5,589 bytes ≈ 5.5 KB, 이건 Region C (fd=6 의 post-truncate write) 크기와 일치 ✓
• 파일 size 19,053,425 bytes = fd=6 wbytes 정확히 ✓

산수가 단위까지 맞는다는 건 분석 중에 가설을 세웠던 부분이 완벽히 설명된다. 는 뜻. 우연으로 설명하기엔 수치가 너무 정확.

5-7. Run 1 의 fd 수치 일치성

같은 공식을 run1 에도 적용:

• _1703.hcap.gz: size=18,955,097 / blocks=4,784 × 512 = 2,449,408
• fd=7 wbytes = 2,444,992 ≈ allocated blocks (2,449,408 bytes) ✓
• fd=6 wbytes = 18,955,097 ≈ 파일 size (18,955,097 bytes) ✓

두 run 이 모두 같은 공식에 맞아떨어짐 → 메커니즘 재현성 확인.

---

6. Sparse hole 생성 경로 기각 목록

3-3 에서 언급한 대로 sparse hole 을 만들 수 있는 커널 경로는 5 가지:

 

관측시

 

1	lseek + write	bpftrace 에서 lseek 0 건
2	ftruncate(fd, X>EOF)	ftruncate 0 건
3	fallocate(FALLOC_FL_KEEP_SIZE)	fallocate 0 건
4	fallocate(FALLOC_FL_PUNCH_HOLE)	fallocate 0 건
5	stale fd 로 write (struct file offset > 현재 inode size)	★ 직접 관측됨

 

1~4 는 bpftrace 의 syscall tracepoint 에서 0 건. tracepoint 는 syscall entry 에서 무조건 걸리는 훅이라 "안 보였다 = 호출되지 않았다" 로 봐도 된다 (bpftrace stderr 깨끗, Lost events 경고 0 건).

5 번 메커니즘만 남고, 그것이 실제로 trace 에서 직접 관측됨 → root cause 확정.

---

7. 개같이 고민한 다른 대안 가설 기각

7-1. "XFS 의 비동기 block allocation 때문에 blocks 가 나중에 잡히는 것"

❌ XFS buffered write 는 write 시점에 iomap 을 통해 blocks 를 할당한다. Delayed allocation 은 있지만 그건 block 번호 확정만 delayed 이지 할당 자체는 발생한 상태. 게다가 reference-healthy 파일은 같은 XFS 에서 blocks*512 ≈ size 로 정상. 파일시스템 특성이 아님.

7-2. "OS page cache eviction"

❌ Page cache 는 memory 레벨이고 on-disk block allocation 과 무관.

7-3. "XFS speculative preallocation"

❌ Speculative preallocation 은 더 많이 할당한다. 반대 방향.

7-4. "write 가 EFAULT 로 실패해서 wbytes 집계가 잘못됨"

❌ bpftrace 는 sys_enter_write 에서 요청 바이트만 기록. 전수 실패라면 파일에 아무것도 없어야 함.

7-5. "bpftrace 가 이벤트를 드롭했을 가능성"

⚠️ 이론적으로 가능하지만 bpftrace 의 Lost events: N 경고 0 건. Stderr 깨끗. 확률 극소.

7-6. "외부 프로세스가 파일을 만짐"

❌ 우리 bpftrace 는 pid=6614 필터. 하지만 watcher 는 필터 없이 모든 파일을 polling. Watcher log 의 sparse 전이 시각이 agent 이벤트와 정확히 동기화 — 외부 개입 흔적 없음.

7-7. "Go runtime 의 buffered write"

❌ os.File.Write 는 바로 write(2) 로 전달. gzip.Writer 의 compression block buffer 는 user-space 지만 block 내용은 결국 write(2) 로 커널에 전달됨.

7-8. "klauspost/compress parallel mode 의 내부 goroutine"

❌ gzip.NewWriterLevel() 로 생성한 writer 는 single-goroutine 모드. SetConcurrency() 호출 없으면 parallel 아님. 소스 코드 확인 (grep -r SetConcurrency = 0 건).

8 개 대안 모두 기각. 5 번 (stale fd + O_TRUNC race) 만 관측에 부합.

---

8. 쓰레드 원인이 아니다

반론 중 쓰레드나 이벤트로 인해서 비동기적으로 파일에 대한 처리 때문에 그런 것은 아닐까? -> 아니었음

8-1. 관찰: 같은 race 가 17:20:00 에도 있었지만 무해했다

이것도 정확히 동일한 쓰레드 race 다. (rotateLocked() 의 go func() { oldGz.Close(); oldFile.Close() } + 바로 이어지는 새 OpenFile). 하지만 결과는 정상.

왜? 파일명이 다르기 때문에:

• fd=7 이 close 하는 것은 inode I (_1719)
• fd=6 이 open 하는 것은 inode J (_1720)
• 두 fd 는 다른 inode 를 가리킨다 → offset / size / blocks 가 독립적
• 어느 순서로 실행되든 서로 간섭 없음

8-2. 17:20:58 event 와의 본질적 차이

17:20:58 에서는:

• 첫 번째 open 이 inode I 생성
• 두 번째 open 이 같은 inode I 를 가리킴 (같은 path 이므로 VFS lookup 결과 동일)
• 두 fd 가 같은 inode 에 동시 접근 → race 조건 성립

즉 문제는 race 자체의 존재 가 아니라 race 가 발생한 대상이 같은 inode 였다 는 것. 파일명이 달랐다면 race 가 있어도 무해했을 것.

 

---

9. 결론

9-1. 확정된 사실

1. 3-region 패턴의 sparse hole 은 stale fd + O_TRUNC race 로 생성됨 — 5 가지 가능한 커널 경로 중 4 가지를 bpftrace 로 직접 기각, 5 번만 실측에서 직접 관측.
2. Race 의 직접 증거: Run2 의 fd=7 OPEN (17:20:58.691601) 후 25.7 μs 뒤 fd=6 의 마지막 write. 둘 다 같은 path, 같은 O_TRUNC flag, 같은 inode.
3. 산수 검증 완벽: file size (19 MB) = fd=6 wbytes, allocated blocks (212 KB) ≈ fd=7 wbytes + fd=6 post-truncate write (5.5 KB Region C).
4. 재현율 100%: Run1, Run2 두 세션 모두 동일 패턴.