개발 기록 2026-10-20 docs/devlog/2026-10-20-6-M2-통합-테스트.md GitHub에서 보기

M2 통합 테스트

작성일: 2026-10-20
작성: 워커 W5 (Codex gpt-6.1-sol, effort max), 브랜치 feature/m2-wrapup, WBS 2.4, 2.6
기준 커밋: 7cd594d
관련 문서: 시스템 구조와 데이터 모델 (2.1, 4.1-4.2, 5.1-5.4, 6, 12.2), 분개테스트 룰과 감사 용어 (2.9, 7.6), WBS와 마일스톤, 라운드 4 계약과 통합, Testing 실행 경로, 라운드 3 통합

목표

M2의 남은 레이블 전체 경로 시험과 S2 시작 동작 시험을 마친다. 기존 Engagements, Ledger, Runner의 모든 감사 이벤트가 커밋 뒤 AuditTrail.broadcast_appended/1로 전달되게 하고, DuplicateEntry의 간헐적인 15초 DB 타임아웃을 실행 계획으로 조사한다.

완료 조건은 MIX_TEST_PARTITION=6 mix precommit 통과, mix.lock 무변경, 소유 파일만 수정, devlog와 코드 커밋이다.

한 일

파일	변경
engagements.ex	Multi 성공 결과의 이벤트로 `engagement.created`, `engagement.member_added` 방송
ledger.ex	등록, 성공, 실패 Multi의 이벤트를 커밋 뒤 방송. 업로드와 합성 GL이 같은 등록 경로 사용
runner.ex	시작 이벤트 방송, 룰 실패와 실행 마감 이벤트를 트랜잭션 결과로 반환한 뒤 방송
engagements_test.exs, ledger_test.exs, runner_test.exs	각 action의 실제 seq와 메시지 필드, 실패 시 미방송, 재시도 시 중복 미방송, 롤백, 메시지 순서 검증
duplicate_entry.ex, duplicate_entry_test.exs	상관 하위 쿼리를 헤더와 라인의 조인으로 대체. 제외한 source의 전표가 선행 전표로 선택되지 않는 회귀 시험
runner_label_test.exs	시드 20251231, 7에 대해 실제 ingest와 rules 큐를 실행하고 rule_results와 findings를 정답과 비교
engagement_live_test.exs	기존 테스트 수정 없이 S2 시작, S4 이동, 동시 실행 충돌, 미적재, 실패, 검토자 경로 5개 추가

레이블 전체 경로는 generate_sample_import/3 -> Oban.drain_queue(queue: :ingest) -> Testing.start_test_run/3 -> Oban.drain_queue(queue: :rules)다. 실행한 8개 룰이 모두 성공했는지 확인하고, 모든 전표의 실제 룰 집합이 expected_rules와 같은지 검사한다. finding의 점수, 적중 개수, rule_ids도 저장된 값으로 비교한다. clean 전표는 finding이 없어야 한다.

triage 대상은 finding의 실제 점수와 실행에 저장된 임계값으로 고른 뒤 expected_triage 집합과 비교한다. 기본 시드는 8,341전표, 19,804라인, finding 265개, triage 52개, 경미 적중 213개다. 레이블 CSV는 테스트가 파일에서만 읽으며 DB나 룰 실행 경로에 넣지 않는다.

결정과 트레이드오프

상태 메시지를 먼저, 감사 메시지를 마지막에 보낸다. Ledger는 import_updated -> audit_appended, Runner 시작은 test_run_updated -> audit_appended다. 룰 마감은 rule_progress -> test_run_updated -> run_completed(마지막 룰일 때만) -> audit_appended 순서다. 한 마감에서 실패와 완료 이벤트가 함께 생기면 seq 순서로 보낸다. 기존 상태 메시지 순서를 유지하면서 감사 방송을 덧붙였다. Engagements에는 별도 상태 메시지가 없으므로 감사 이벤트만 보낸다.
Runner의 record_event/3는 이벤트 구조체를 반환한다. record/1 안에서 방송하는 대안은 상위 트랜잭션이 나중에 실패해도 메시지가 남는다. close_rule/5의 결과에 이벤트 목록을 담고 Repo.transact/1이 성공한 뒤에만 방송한다. 실패 이벤트 삽입 뒤 finding 유일 제약 충돌을 일으키는 테스트에서 이벤트와 룰 상태가 함께 롤백되고 메시지가 없는지 검증했다.
룰 집계 전에 헤더와 개별 라인을 조인한다. import, source, 거래처 필터는 헤더에 적용하고 라인은 journal_entry_id FK로 찾는다. Importer가 라인과 헤더를 함께 적재하는 기존 불변식을 따른다. 라인의 import 조건을 중복 적용하면 통계 오차에서 BitmapAnd가 적재 전체를 반복해서 읽을 수 있어 제거했다. 금액은 계속 라인의 합으로 계산하며 헤더의 캐시된 합계로 대체하지 않는다. 계정과 차대 집합, 날짜 경계, FIFO 선행 전표 선택은 유지한다.
인덱스나 시간 제한을 바꾸지 않았다. 기존 전표 PK와 라인의 (journal_entry_id, line_number) 인덱스로 충분했다. 추가 마이그레이션과 :slow 태그는 필요하지 않았다.
테스트 준비 helper는 파일 안에 둔다. 기존 RulesLabelTest와 공통 부분은 작고 test/support/*는 메인 소유다. 공유 파일을 바꾸지 않고 각 파일에서 레이블 읽기와 파일 정리를 수행한다. Application env도 바꾸지 않았다.
S2의 미적재와 실패 상태는 시작 버튼이 숨겨진다. 현재 구현은 disabled 버튼을 그리지 않는다. 이 동작을 그대로 고정했고, 실패 GL에 직접 이벤트를 보내도 실행이 생기지 않고 고정된 한국어 flash가 나오는지 확인했다. 실행 중 충돌은 화면이 열린 뒤 다른 요청이 run을 만든 상황으로 재현한다.

DuplicateEntry 느린 쿼리 조사

계측 조건

MIX_ENV=test MIX_TEST_PARTITION=6 mix run -e ...에서 SQL sandbox를 체크아웃하고 합성 GL을 실제 적재했다. Repo query telemetry에서 Ecto가 만든 SQL과 바인딩 파라미터를 받아 EXPLAIN (ANALYZE, BUFFERS)에 전달했다. 이전 쿼리는 기준 커밋의 Ecto 쿼리를 같은 프로세스에서 구성했다. 데이터와 파일은 sandbox checkin과 파일 삭제로 정리했다. 운영 DB나 다른 워커 partition은 사용하지 않았다.

평상시 계획과 반복 조회

동일한 기본 시드와 연결에서 비교한 출력의 관련 줄이다.

original_plan
GroupAggregate ... (actual time=35.728..38.116 rows=16 loops=1)
  Buffers: shared hit=70490
  ...
  SubPlan 1
    Index Scan using journal_entries_pkey ... (actual time=0.000..0.000 rows=1 loops=7509)
  SubPlan 2
    Index Scan using journal_entries_pkey ... (actual time=0.000..0.001 rows=1 loops=7933)
  SubPlan 3
    Index Scan using journal_entries_pkey ... (actual time=0.000..0.000 rows=1 loops=7933)
Execution Time: 38.138 ms

출력용 거래처 하위 쿼리가 바깥의 NULL/빈 문자열 필터에도 펼쳐져 총 23,375번 실행됐다. 이때는 PK를 골라 빨랐지만, 같은 헤더 조회에 id와 ledger_import_id 조건을 함께 둔 것이 다른 통계 상태에서 위험했다.

15초 타임아웃 재현

한 전표씩 가진 작은 import 100개를 schema fixture로 만들고 ANALYZE journal_entries, ANALYZE journal_lines를 실행한 뒤 기본 GL을 추가했다. 기존 통계는 import별 전표를 적게 추정한다. 이 상태에서 이전 쿼리의 계획은 다음과 같았다. 아래는 추정 계획에서 관련 줄만 발췌했다.

SubPlan 1
  Index Scan using journal_entries_ledger_import_id_posting_date_index on journal_entries ssj0
    (cost=0.28..8.31 rows=1 width=516)
    Filter: (((source)::text = ANY ('{manual,system}'::text[])) AND (id = sj0.journal_entry_id))
SubPlan 2
  Index Scan using journal_entries_ledger_import_id_posting_date_index on journal_entries ssj0_1
SubPlan 3
  Index Scan using journal_entries_ledger_import_id_posting_date_index on journal_entries ssj0_2

전표 ID는 Index Cond가 아닌 Filter가 됐고, import의 8,341전표를 매 하위 쿼리에서 훑는다. 이어서 실행한 EXPLAIN ANALYZE도 기존 15초 제한에서 취소됐다.

client ... timed out because it queued and checked out the connection for longer than 15000ms
** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request

같은 데이터와 통계에서 먼저 실행한 수정 룰은 rule_us=34377 hits=15 entries=8341 lines=19804였다. 과거 실패 당시의 DB 상태를 보존한 것은 아니므로 당시 계획과 완전히 같았다고 단정하지 않는다. 이번에 재현한 원인은 통계 오차로 잘못 고른 import 인덱스와, 이를 증폭하는 반복 상관 하위 쿼리다.

검토 후 버린 조인 대안

헤더와 라인을 먼저 조인하되 두 테이블 모두에 import 조건을 남긴 대안도 계측했다. 라인에서 import 인덱스와 전표 인덱스를 BitmapAnd로 합쳤다. import 전체 bitmap을 7,701번 다시 만들어 1.63초가 걸렸다.

Bitmap Index Scan on journal_lines_ledger_import_id_account_code_index
  (actual time=0.203..0.203 rows=19804 loops=7701)
Buffers: shared hit=239558
Execution Time: 1630.096 ms

그래서 최종 구현은 헤더로 import를 제한하고 FK로 라인을 찾는다. 라인 집계를 만든 뒤 헤더에 조인하는 대안도 이전 라운드에서 집계 반복 문제가 관찰됐으므로 선택하지 않았다.

최종 계획

revised_plan
GroupAggregate ... (actual time=30.000..32.292 rows=16 loops=1)
  Buffers: shared hit=23481
  ...
  Bitmap Index Scan on journal_entries_ledger_import_id_posting_date_index
    (actual time=0.080..0.080 rows=8341 loops=1)
  Bitmap Index Scan on journal_lines_journal_entry_id_line_number_index
    (actual time=0.000..0.000 rows=2 loops=7701)
    Index Cond: (journal_entry_id = sj1.id)
Execution Time: 32.316 ms

import 헤더를 한 번 고르고, 각 전표의 라인만 기존 인덱스로 찾는다. 동일 연결 비교에서 shared hit는 70,490에서 23,481로 줄었다. 그룹 후보는 수정 전후 모두 16개였고, 날짜 구간 적용 후 결과는 15 hits였다. 두 시드의 룰 직접 호출과 Runner 전체 경로에서도 모든 레이블이 같았다. 성능 수치는 로컬 합성 데이터 측정이며 운영 규모 성능 보장은 아니다.

막힌 점과 해결

평상시 단독 테스트에서는 타임아웃이 재현되지 않았다. 작은 적재들의 통계와 분석 전 대량 적재를 조합해 인덱스 오선택을 재현했다. 제한 시간을 늘려 실패를 숨기지 않았다.
메시지 순서 테스트의 첫 구현은 계정 fixture가 보낸 Swoosh 테스트 메일까지 받아 실패했다. 도메인 메시지 종류만 선택하고, 감사 메시지는 먼저 도착한 것부터 꺼내 seq를 비교하도록 고쳤다. 수정 후 전체 검증을 다시 통과했다.
생성 이벤트는 함수 안에서 새 engagement ID가 생겨 미리 구독할 수 없었다. 해당 테스트 프로세스의 engagement INSERT telemetry에서 UUID 파라미터의 토픽을 구독한다. SQL 파라미터 위치에는 의존하지 않으며 handler는 on_exit에서 해제한다. 앱의 이벤트 생성 방식은 바꾸지 않았다.

검증

모든 mix 테스트 명령에 MIX_TEST_PARTITION=6을 지정했다.

검증	실제 결과
수정 전 RulesLabelTest, 두 시드	`Result: 2 passed`, 2.1초
Engagements, Ledger, DuplicateEntry 묶음 (추가 source 시험 전)	`Result: 50 passed`, 2.1초
Runner, RunnerLabel, EngagementLive 묶음	`Result: 53 passed`, 2.7초
RulesLabel, RunnerLabel, DuplicateEntry 묶음 (추가 source 시험 전)	`Result: 12 passed`, 2.3초
`MIX_TEST_PARTITION=6 mix precommit`	`Result: 400 passed`, 5.7초
감사 메시지 순서 단언 보강 뒤 같은 precommit	`Result: 400 passed`, 6.3초
devlog 작성 뒤 최종 precommit	`Result: 400 passed`, 14.9초
`git diff --check`	출력 없음, 종료 코드 0
`mix.lock`	변경 없음. 시작과 검증 후 blob 해시 일치

마지막 코드 검증의 실제 마지막 줄:

Finished in 14.9 seconds (14.2s async, 0.7s sync)

Result: 400 passed

precommit의 경고를 오류로 처리하는 컴파일, 미사용 의존성 검사, 포맷, 전체 테스트가 통과했다. @tag :slow나 테스트 시간 제한 변경은 없다. rules_label_test.exs, audit_trail.ex, testing.ex, 마이그레이션과 공유 설정은 수정하지 않았다.

Elixir 학습 포인트

Ecto.Multi의 성공 결과에는 이름을 붙인 각 단계의 결과가 들어 있다. %{audit_event: event}를 패턴 매칭해 꺼내면 저장과 방송 시점을 명확히 나눌 수 있다.
Repo.transact(fn -> ... end) 안에서 호출한 AuditTrail.record/1도 같은 DB 트랜잭션에 속한다. 함수가 이벤트를 반환한다고 커밋된 것이 아니므로 결과를 바깥으로 돌려준 뒤 방송해야 한다.
assert_receive는 패턴과 맞는 메시지를 찾고 앞선 다른 메시지는 건너뛴다. 순서 검증에서는 도메인 메시지를 도착 순으로 꺼내야 한다. Swoosh 메일처럼 관계없는 메시지는 가드로 제외한다.
Oban.drain_queue/2는 실제 Worker를 실행하므로 컨텍스트 호출만 검증할 때 빠지기 쉬운 job args, 저장된 룰 파라미터, 결과 저장과 마지막 룰 집계를 함께 확인한다.
Ecto 쿼리의 논리적 모양이 같아 보여도 PostgreSQL 통계에 따라 인덱스 선택과 반복 횟수가 바뀐다. actual rows, loops, Index Cond와 Filter를 함께 읽어야 한다.

다음 할 일

메인이 워커 브랜치를 통합하고 partition 1에서 전체 검증 및 브라우저 확인을 수행한다.
WBS 2.4와 2.6의 테스트 완료 상태와 docs 색인을 메인 소유 문서에 반영한다.
다른 환경에서도 같은 느린 쿼리가 보이면 행 수와 최신 통계를 함께 기록하고 실제 계획을 비교한다.

남은 이슈와 변경 요청

계약과 스키마 변경 요청: 없음. 추가 인덱스도 필요하지 않다.
메인 소유 S2 변경 요청: 코드 검토에서 handle_event("start_run", ...)가 현재 화면의 engagement와 조회한 import의 engagement_id를 비교하지 않는 것을 발견했다. 사용자가 양쪽 engagement 멤버라면 다른 대상 import ID로 실행을 만들고 현재 engagement의 S4 URL로 이동할 수 있다. show.ex에서 두 ID의 일치를 검사하도록 검토를 요청했다. 이 워커는 해당 파일을 수정하지 않았고 이 경로의 자동 재현 테스트도 추가하지 않았다.
메인 소유 문서 요청: docs 색인에 이 devlog 한 줄을 추가한다.
구현과 로컬 자동 검증을 마쳤다. 브라우저 확인, 메인 브랜치 통합, 배포는 이 워커의 범위 밖이다.