킥오프 배치 첫 구현 — 매시 전체 EXPIRED 사고와 Winston 도입

💡 Tip. 바쁜 현대인들을 위한 본문 요약

• 사고: 첫 배치 작업으로 짠 킥오프 배치가 한 회 실행에 모든 ACTIVE 숙제를 EXPIRED 처리했다. 한 회원의 진행 중 숙제(ID 58)가 점심 직전에 사라졌다
• 함정 1: findExpiredAssignments()가 시간 초과를 전혀 체크하지 않고 ACTIVE 전체를 그대로 반환했다
• 함정 2: @Cron(CronExpression.EVERY_HOUR)로 등록돼 매시간 실행, 함정 1과 합쳐져 매시 전체 EXPIRED
• 수정: expiresAt < now 시간 비교 한 줄 + cron을 '0 6 * * *' (매일 06:00 KST) 한 줄로 차단
• 진짜 교훈: 사고가 났는데 로그가 없었다. 콘솔만 쓰던 NestJS 기본 로거를 폐기하고 Winston + winston-daily-rotate-file로 갈아탔다 (app/error 분리, GCP severity 매핑)

---

🌱 왜 배치를 짜야 했나

이전 편에서 지표 누계 시스템을 INSERT 전용 스냅샷으로 굳혔다. 지표가 매 묶음 완료마다 쌓이는 흐름이 됐다.

그 다음 자연스럽게 따라온 게 배치 작업이다. 회원의 하루 호흡은 단순했다.

• 아침에 새 숙제가 발행된다
• 시간 제한(예: 30분) 안에 풀면 COMPLETED
• 시간이 지나면 EXPIRED — 성취도 계산이 들어가고, 연속 POOR이 쌓이면 레벨이 한 단 내려간다

이 EXPIRED 전환이 실시간 핸들러에 구현돼 있지 않았다. 회원이 숙제를 열고 30분 뒤에 닫지 않으면, 그 ACTIVE 행은 “원래 30분 안에 끝났어야 하는데 안 끝난” 상태로 영원히 떠 있는다. 누군가가 시간을 보고 EXPIRED로 바꿔줘야 한다.

그래서 킥오프 배치라는 작업을 만들었다. 매일 한 번 돌면서 세 가지를 한다.

1. Phase 1 — 만료 처리: 시간 초과한 ACTIVE 숙제를 EXPIRED로 굳히고 성취도를 계산
2. Phase 2 — 일일 생성: 오늘 ACTIVE 숙제가 없는 회원에게 새 숙제 1건 발행
3. Phase 3 — 레벨 조정: Phase 1의 성취도를 보고 연속 POOR/EXCELLENT를 정책 임계치와 비교해 레벨 한 단 조정

NestJS 진영에서 배치 작업은 @nestjs/schedule 패키지의 @Cron 데코레이터가 표준이다. 공식 문서가 친절하니 첫 배치도 그쪽으로 갔다.

docs.nestjs.com

문서를 보고 그대로 적용했다.

import { Cron, CronExpression } from '@nestjs/schedule';

@Injectable()
export class BatchProcessApplicationService {
  private readonly logger = new Logger(BatchProcessApplicationService.name);

  @Cron(CronExpression.EVERY_HOUR)
  async runKickoffBatch() {
    this.logger.log('[KickoffBatch] Started');
    // Phase 1: 만료 처리
    const expired = await this.findExpiredAssignments();
    for (const a of expired) {
      await this.processExpiredAssignment(a);
    }
    // Phase 2: 일일 생성
    // ...
  }

  private async findExpiredAssignments() {
    return this.prisma.assignment.findMany({
      where: { status: 'ACTIVE' },
      include: { student: { include: { classStudents: true } } },
    });
  }
}

배포하고 나서 점심을 먹으러 갔다. 12:00 정각, 첫 실행이 돈 시점이었다.

---

🔥 증상 — 한 시간 만에 모든 ACTIVE가 EXPIRED

점심에서 돌아와 운영자 페이지를 열었다. 모니터링 탭의 오늘 진행 중 숙제 카운터가 0이었다.

처음엔 무슨 통계 캐시 문제인 줄 알았다. 한 회원의 상세를 눌러봤다. 오전에 발행된 ACTIVE 숙제(ID 58) 한 건이 분명히 있었는데, 상태가 EXPIRED로 바뀌어 있었다. 성취도는 POOR. completedBundleCount = 0. 그 회원은 점심에 막 숙제 화면을 열어둔 채로 자리를 비웠을 뿐이다.

DB에 직접 들어가 확인했다.

SELECT id, status, started_at, completed_at, achievement_state
FROM assignment
WHERE status = 'EXPIRED'
  AND completed_at >= NOW() - INTERVAL '2 hours'
ORDER BY completed_at DESC;

수십 행이 떴다. 모두 completed_at이 정확히 한 시간 단위로 정렬됐다. 11:00, 12:00 — 시간 정각마다 묶음으로 EXPIRED 처리가 들어가 있었다.

🔍 단서: 시간 정각마다 묶음이 만들어진다는 건, 그 시각에 무언가 자동 트리거가 돌고 있다는 뜻이다. 첫 의심은 cron이어야 한다.

grep -r "@Cron" apps/api/src/. 한 군데 잡혔다. 방금 배포한 킥오프 배치였다.

EVERY_HOUR. 매시간. 모든 ACTIVE.

이걸 깨달은 순간, ID 58은 시작이 아니라 끝이라는 게 보였다. 하루 동안 발행된 모든 진행 중 숙제가 시간 정각마다 한꺼번에 EXPIRED로 굳어가고 있던 거다.

---

🔍 탐색 — 가설 둘과 진짜 범인

가설 1: where 조건이 빠졌나?

처음엔 findExpiredAssignments()에 시간 조건은 분명히 들어 있는데 뭔가 다른 곳에서 덮어쓴 줄 알았다. 코드를 다시 봤다.

private async findExpiredAssignments() {
  return this.prisma.assignment.findMany({
    where: { status: 'ACTIVE' },
    include: { ... },
  });
}

status: 'ACTIVE' 한 줄뿐이었다. 시간 비교가 아예 없다. 만료를 가른다는 함수가 만료 기준을 가지고 있지 않다.

생각해보면 처음 짤 때 “시간 체크는 어디서 하지?” 라고 한 번 멈췄던 기억이 있다. 그때 머릿속에서 processExpiredAssignment() 안에서 한 번 더 거른다고 가정하고 넘어갔다. 그 가정이 그대로 코드가 됐다 — 아무 데서도 안 거른다.

가설 2: cron 표현식이 잘못 들어갔나?

CronExpression.EVERY_HOUR. @nestjs/schedule 공식 enum이다. 잘못된 값이 아니다. 매시간 0분 0초에 실행한다는 정확한 의미를 가진다.

문제는 enum이 잘못된 게 아니라, 이 작업을 매시간 돌릴 이유가 없었다는 점이다. 회원의 숙제 시간 제한은 30분이지만, 만료 처리를 한 시간 단위로 미루는 것과 하루 단위로 미루는 것 사이의 운영 차이는 거의 없다. 매일 아침 한 번이면 충분하다. 매시간은 그냥 “자주 도는 게 좋은 거 아닌가” 라는 막연한 감각으로 골랐을 뿐이었다.

진짜 범인: 두 함정의 곱

함정 둘은 따로 보면 사소했다.

• where: { status: 'ACTIVE' }만 있는 쿼리 — 그 자체로는 그냥 “모든 ACTIVE를 가져오는” 정상 코드다
• @Cron(EVERY_HOUR) — 단순한 cron 표현식, 문법 오류도 아니다

두 함정이 곱해지자 한 시간마다 모든 진행 중 숙제를 EXPIRED 처리하는 폭주가 됐다. 만약 cron이 매일 한 번이었다면 사고는 하루 1회로 제한됐을 거고, where에 시간 조건이 있었다면 cron 빈도와 무관하게 정확한 만료만 굳혔을 거다.

📌 핵심: 배치 코드의 버그는 “한 줄짜리 함정의 곱”으로 폭주한다. 빈도(cron) 와 필터(쿼리) 두 축이 따로 정의돼 있을 때, 어느 한 축에만 결함이 있으면 다른 축이 다치고, 둘 다에 결함이 있으면 데이터가 한 회 실행에 사라진다.

@nestjs/schedule이 문제가 아니다. 공식 문서가 친절하기 때문에 첫 배치를 짤 때 “어떻게 등록하는가”는 명확히 보였는데, “어디서 시간 비교를 하는가” 라는 책임 분담이 코드에 안 잡혀 있었다.

---

🛠️ 해결 — 두 줄 수정과 복구

1) 만료 기준을 함수 안에서 거른다

회원이 속한 클래스의 bundleTimeLimitMinutes (예: 30분) 만큼 지났는지를 startedAt 기준으로 계산해서 거르도록 바꿨다.

// apps/api/src/application/services/batch-process.application.service.ts

private async findExpiredAssignments() {
  const now = new Date();

  const activeAssignments = await this.prisma.assignment.findMany({
    where: {
      status: 'ACTIVE',
      startedAt: { not: null }, // 시작도 안 한 행은 만료 대상 아님
    },
    include: {
      student: {
        include: {
          user: { select: { loginId: true } },
          classStudents: {
            where: { unassignedAt: null },
            include: { class: true },
          },
        },
      },
    },
  });

  const expiredAssignments = activeAssignments.filter((assignment) => {
    const timeLimitMinutes =
      assignment.student?.classStudents?.[0]?.class?.bundleTimeLimitMinutes ?? 30;

    const startedAt = new Date(assignment.startedAt!);
    const expiresAt = new Date(
      startedAt.getTime() + timeLimitMinutes * 60 * 1000,
    );

    return expiresAt < now;
  });

  this.logger.log(
    `[KickoffBatch] Scan - found=${expiredAssignments.length} expired / ${activeAssignments.length} active`,
  );

  return expiredAssignments;
}

세 가지가 같이 들어갔다.

• startedAt: { not: null } — startedAt이 비어 있는 행은 회원이 아직 열어보지 않은 숙제다. 만료 대상이 아니다
• expiresAt < now 필터 — 실제 시간 비교가 함수 안에서 끝난다
• Scan 로그 한 줄 — “스캔 결과 N건 중 M건 만료” 가 매 실행마다 찍힌다. 다음에 비슷한 폭주가 시작되면 한 줄로 잡힌다

⚠️ 주의: startedAt이 null인 행을 그대로 두면 회원이 숙제를 열지도 못한 채 다음 날을 맞이한 경우가 EXPIRED로 굳혀진다. 만료의 기준은 “열고도 시간 지난” 행이지 “발행했지만 안 연” 행이 아니다. 이 두 케이스는 운영 의미가 다르니 쿼리에서 갈라야 한다.

2) cron 표현식을 매일 06:00 KST로

@Cron(CronExpression.EVERY_HOUR)을 @Cron('0 6 * * *')로 바꿨다. NestJS의 타임존은 main.ts에서 process.env.TZ = 'Asia/Seoul';로 강제돼 있어서 별도 옵션 없이 KST로 해석된다.

// 🔻 이전
@Cron(CronExpression.EVERY_HOUR)
async runKickoffBatch() { ... }

// 🔺 이후
@Cron('0 6 * * *') // 매일 06:00 KST
async runKickoffBatch() { ... }

매일 한 번이면 충분하다. 회원의 하루 호흡이 시작되기 직전에 어제 진행 중인 숙제를 정리하고 오늘 숙제를 발행하면, 화면을 열었을 때 깔끔한 상태가 보장된다.

3) 1.5 단계 — 누락 ACTIVE 따라잡기

수정한 함수만으로는 끝이 아니었다. 사고 사이에 정상이었어야 할 ACTIVE 행도 같이 EXPIRED로 굳혀졌기 때문이다. 백필 스크립트 한 번을 돌려 started_at + bundleTimeLimitMinutes가 미래인 행을 다시 ACTIVE로 되돌렸고, 그 다음부터는 Phase 1.5라는 단계를 추가해 scheduledAt < today인 stale ACTIVE를 같이 정리하도록 만들었다.

// Phase 1.5: 어제 이전에 발행됐는데 아직 ACTIVE인 행을 개별 만료
const today = new Date();
today.setHours(0, 0, 0, 0);

const staleAssignments = await this.prisma.assignment.findMany({
  where: { status: 'ACTIVE', scheduledAt: { lt: today } },
  include: { ... },
});

for (const assignment of staleAssignments) {
  await this.processExpiredAssignment(
    assignment, policy, levelNameMap,
    expiredDetails, levelAdjustmentDetails,
    '[Phase 1.5]',
  );
}

원래 findExpiredAssignments()는 “오늘 시간 초과”만 본다. 만약 무언가 사유로 어제 ACTIVE가 그대로 남아 있으면 영원히 안 잡힌다. Phase 1.5는 그 안전망이다. 하루 단위로 잔류한 ACTIVE는 무조건 정리.

4) 컨트롤러 분리 — 외부 호출 가능하게

배치 함수가 데코레이터 하나만 가지고 있으면 사고 났을 때 손쓸 방법이 없다. cron 다음 실행을 기다리거나, 코드를 고쳐서 다시 배포해야 한다. 그래서 같은 함수를 호출하는 컨트롤러 두 벌을 추가했다.

// 1) 운영자 수동 실행용 (Swagger 노출)
@ApiTags('admin-system')
@ApiBearerAuth('JWT')
@UseGuards(JwtAuthGuard, RolesGuard)
@Roles('PLATFORM_ADMIN')
@Controller('admin/batch')
export class BatchProcessController {
  @Post('kickoff')
  @HttpCode(HttpStatus.OK)
  @ApiOperation({
    summary: '킥오프 배치 수동 실행',
    description:
      '시간 초과된 ACTIVE 숙제를 EXPIRED로 처리하는 배치를 수동으로 실행합니다. ' +
      '일반적으로 매일 오전 6시(KST)에 자동 실행됩니다. 테스트/디버깅 목적으로 사용하세요.',
  })
  async runKickoffBatch() {
    return this.batchProcessService.runKickoffBatchManually();
  }
}

// 2) Cloud Scheduler용 (Swagger 비노출)
@ApiExcludeController()
@Controller('internal/batch')
@UseGuards(CloudSchedulerGuard)
export class InternalBatchController {
  @Post('kickoff')
  @HttpCode(200)
  async runKickoff() {
    return this.batchService.runKickoffBatch();
  }
}

운영자가 Swagger에서 Try it out 한 방으로 돌릴 수 있는 경로(/admin/batch/kickoff)와, 이후 Cloud Scheduler가 OIDC 토큰으로 때릴 내부 경로(/internal/batch/kickoff)를 갈랐다. 인증 가드도 다르다 — 운영자 경로는 JWT + RBAC, 내부 경로는 x-cloudscheduler 헤더 + Cloud Run의 OIDC 검증.

CloudSchedulerGuard는 단순하다.

@Injectable()
export class CloudSchedulerGuard implements CanActivate {
  canActivate(context: ExecutionContext): boolean {
    const request = context.switchToHttp().getRequest();
    const isScheduler = request.headers['x-cloudscheduler'] === 'true';
    const isDev = process.env.NODE_ENV !== 'production';
    return isScheduler || isDev;
  }
}

이렇게 분리해 두면 @Cron을 떼내고 외부 스케줄러로 옮겨가는 길도 열린다. 실제로 이후 호흡에서 @nestjs/schedule을 떼고 Cloud Scheduler HTTP 트리거로 전부 옮겨갔다 — 이유는 인스턴스 1개 이상으로 늘어났을 때 cron이 중복 발화되는 위험과, 배포 시점에 cron이 끊기는 문제가 컸기 때문이다. 두 컨트롤러로 갈라 두지 않았다면 그 이관도 코드 수술이 훨씬 컸을 거다.

📌 핵심: 배치 함수는 트리거(데코레이터/cron)와 본체(서비스 메서드)를 분리하고, 본체는 두 종류의 HTTP 컨트롤러로 노출하라. 외부 호출만 가능해도 사고 복구의 도구가 생기고, 이후 스케줄러를 갈아끼울 때 본체를 안 건드릴 수 있다.

---

🧩 진짜 사고 — 사고가 났는데 흔적이 없었다

두 줄짜리 수정으로 코드 사고는 끝났다. 정작 더 컸던 게 따로 있었다.

사후에 운영자 페이지의 잘못 EXPIRED된 행 목록을 보면서 “이게 정확히 몇 시 몇 분에 일어났는지” 를 찾으려고 했는데, 로그가 없었다.

NestJS의 기본 Logger는 콘솔에 색깔 입혀서 흘려보낸다. Cloud Run에 배포된 상태였으니 stdout이 journalctl처럼 어디엔가는 흘러갔겠지만, 그걸 시간 단위로 검색해서 보려면 콘솔에서 grep을 하든지 GCP Cloud Logging UI를 들어가야 한다. 사고 처음 한 시간은 그 둘 다 안 했다 — 그냥 콘솔 탭을 새로고침하면서 “지금부터 보이는 새 로그만” 봤다.

ID 58의 EXPIRED 전환이 언제 일어났는지 정확히 알려면 다음 중 하나가 있어야 했다.

• 사고 시점의 로그가 파일로 남아 있음 — 디스크에서 다시 읽을 수 있음
• 사고 시점의 로그가 GCP Cloud Logging에 구조화된 JSON으로 들어가 있음 — severity, jsonPayload로 검색 가능

둘 다 없었다. 콘솔 텍스트가 흘러간 게 전부였다.

이 시점에 결정이 갈렸다. 두 가지 선택지가 있었다.

후자로 갔다. NestJS 생태계에서 가장 보편적인 조합은 nest-winston + winston + winston-daily-rotate-file 이다.

github.com

---

🛡️ 예방 — Winston 도입과 설정

1) 패키지 설치

pnpm add winston nest-winston winston-daily-rotate-file

세 패키지가 한 묶음이다.

• winston — 본체 로거
• nest-winston — NestJS의 Logger 인터페이스를 winston으로 갈아끼울 어댑터
• winston-daily-rotate-file — 일별 파일 회전 transport (오늘은 app-2026-01-23.log, 내일은 app-2026-01-24.log)

2) winston 설정 — 환경별 출력 분기

apps/api/src/common/logger/winston.config.ts 한 파일로 끝낸다. 핵심은 로컬과 프로덕션의 콘솔 포맷이 다르다는 점이다.

// apps/api/src/common/logger/winston.config.ts
import { WinstonModuleOptions } from 'nest-winston';
import * as winston from 'winston';
import 'winston-daily-rotate-file';

const isProduction = process.env.NODE_ENV === 'production';

/** GCP Cloud Logging severity 매핑 */
function levelToSeverity(level: string): string {
  const map: Record<string, string> = {
    error: 'ERROR',
    warn: 'WARNING',
    info: 'INFO',
    log: 'INFO',
    debug: 'DEBUG',
    verbose: 'DEBUG',
  };
  return map[level] || 'DEFAULT';
}

/** 콘솔 transport: 프로덕션=JSON(GCP 파싱), 로컬=컬러 텍스트 */
const consoleTransport = isProduction
  ? new winston.transports.Console({
      format: winston.format.combine(
        winston.format.timestamp({ format: 'YYYY-MM-DDTHH:mm:ss.SSSZ' }),
        winston.format((info) => {
          info.severity = levelToSeverity(info.level);
          return info;
        })(),
        winston.format.json(),
      ),
    })
  : new winston.transports.Console({
      format: winston.format.combine(
        winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
        winston.format.colorize(),
        winston.format.printf(({ timestamp, level, message, context }) => {
          return `[${timestamp}] [${level}] [${context || 'App'}] ${message}`;
        }),
      ),
    });

const logLevel = process.env.LOG_LEVEL || (isProduction ? 'info' : 'debug');

export const winstonConfig: WinstonModuleOptions = {
  level: logLevel,
  transports: [
    consoleTransport,
    // 파일 출력 (일별 로테이션)
    new winston.transports.DailyRotateFile({
      dirname: 'logs',
      filename: 'app-%DATE%.log',
      datePattern: 'YYYY-MM-DD',
      maxSize: '20m',
      maxFiles: '14d',
      format: winston.format.combine(
        winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
        winston.format.printf(({ timestamp, level, message, context }) => {
          return `[${timestamp}] [${level.toUpperCase()}] [${context || 'App'}] ${message}`;
        }),
      ),
    }),
    // 에러 전용 파일
    new winston.transports.DailyRotateFile({
      dirname: 'logs',
      filename: 'error-%DATE%.log',
      datePattern: 'YYYY-MM-DD',
      level: 'error',
      maxSize: '20m',
      maxFiles: '30d',
      format: winston.format.combine(
        winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
        winston.format.json(),
      ),
    }),
  ],
};

핵심 결정 다섯 가지를 적용했다.

3) main.ts에서 winston을 NestJS 기본 로거로 교체

NestFactory.create()에 logger 옵션을 넘긴다. 이걸로 앱 전체의 this.logger.log() 호출이 전부 winston을 탄다.

// apps/api/src/main.ts
process.env.TZ = 'Asia/Seoul'; // 모든 import 전에

import { WinstonModule } from 'nest-winston';
import { winstonConfig } from './common/logger/winston.config';

async function bootstrap() {
  const app = await NestFactory.create(AppModule, {
    logger: WinstonModule.createLogger(winstonConfig),
  });
  // ...
}

WinstonModule.createLogger()는 NestJS의 LoggerService 인터페이스를 구현한 인스턴스를 만들어준다. NestJS 부트스트랩 단계의 로그([Nest] LOG ...)부터 전부 winston을 거치게 된다.

🔍 단서: process.env.TZ는 모든 import 전에 설정돼야 한다. import 구문은 호이스팅돼서 위로 올라가는 것처럼 보이지만, 실제로 Date() 생성자가 호출되기 전에 TZ가 잡혀 있으면 된다. winston의 timestamp 포맷도 결국 new Date()를 쓰니 영향을 받는다. KST가 아닌 시간이 찍히는 사고를 피하려면 이 한 줄을 가장 위에 두는 게 안전하다.

4) 배치 함수에 구조화된 로그 박기

수정한 runKickoffBatch()에는 실행의 시작·스캔·각 단계·완료 요약을 전부 로그로 찍었다.

async runKickoffBatch(): Promise<KickoffBatchResultDto> {
  const startTime = Date.now();
  this.logger.log('[KickoffBatch] Started');

  // ...

  this.logger.log(
    `[KickoffBatch] ════════════════════════════════════════\n` +
      `[KickoffBatch] 완료 - 소요 ${(durationMs / 1000).toFixed(1)}초\n` +
      `[KickoffBatch] 만료: ${expiredDetails.length}건 | 일괄만료: ${staleAssignments.length}건\n` +
      `[KickoffBatch] 생성: ${createdDetails.length}건\n` +
      `[KickoffBatch] 레벨조정: ${levelAdjustmentDetails.length}건 ` +
      `(⬇️${downCount} ⬆️${upCount} 🔄${restoreCount})\n` +
      `[KickoffBatch] 정책: excellent≥${policy.excellentThreshold}% ` +
      `poor<${policy.poorThreshold}% 연속일=${policy.levelDownConsecutiveDays}\n` +
      `[KickoffBatch] ════════════════════════════════════════`,
  );

  // ...
}

회원별 만료·레벨 조정도 한 줄씩 따로 찍는다.

this.logger.log(
  `[Flow] student=${loginId}(${assignment.studentId}) | 숙제 만료(${phaseLabel}) | ` +
    `assignmentId=${assignment.id} | bundles=${completedBundles}/${totalBundles} | ` +
    `avgAccuracy=${avgAccuracy?.toFixed(1) ?? 'N/A'}% | achievement=${achievementState} | ` +
    `levelAdj=${adjustmentInfo.adjusted ? adjustmentInfo.reason : 'none'}`,
);

[KickoffBatch] ... 접두사로 실행 단위 로그, [Flow] student=... | ... 접두사로 회원 단위 로그를 갈랐다. 사고가 다시 나면 두 가지 grep 한 방으로 잡힌다.

# 실행 단위
grep '\[KickoffBatch\]' logs/app-2026-01-23.log | head

# 회원 단위
grep 'student=loginId123' logs/app-2026-01-23.log

5) 자동 테스트 — 사고 재발 방지

코드 수정은 했지만 다음번에 또 누군가 where: { status: 'ACTIVE' } 한 줄짜리 쿼리로 되돌릴 수도 있다. 그래서 findExpiredAssignments에 대한 단위 테스트 두 개를 추가했다.

// apps/api/src/application/controllers/__tests__/batch-process.controller.spec.ts
describe('runKickoffBatch', () => {
  it('startedAt + bundleTimeLimitMinutes 가 미래면 만료 대상이 아니다', async () => {
    // given: 5분 전에 시작, 30분 시간 제한
    const fiveMinutesAgo = new Date(Date.now() - 5 * 60 * 1000);
    await prisma.assignment.create({
      data: { status: 'ACTIVE', startedAt: fiveMinutesAgo, ... },
    });

    // when
    await service.runKickoffBatch();

    // then: 그대로 ACTIVE
    const after = await prisma.assignment.findFirst({ where: { id: ... } });
    expect(after.status).toBe('ACTIVE');
  });

  it('startedAt + bundleTimeLimitMinutes 가 과거면 EXPIRED 처리된다', async () => {
    // given: 1시간 전에 시작, 30분 시간 제한
    const oneHourAgo = new Date(Date.now() - 60 * 60 * 1000);
    await prisma.assignment.create({
      data: { status: 'ACTIVE', startedAt: oneHourAgo, ... },
    });

    // when
    await service.runKickoffBatch();

    // then: EXPIRED
    const after = await prisma.assignment.findFirst({ where: { id: ... } });
    expect(after.status).toBe('EXPIRED');
  });
});

startedAt이 미래(=시간 제한 안 지남)일 때 그대로 ACTIVE, 과거(=시간 제한 지남)일 때 EXPIRED. 둘이 갈리는 임계가 깨지면 즉시 빨간 줄이 뜬다. CI가 실패하면 머지가 막힌다.

---

✅ 검증

사고 후 첫 실행

cron을 매일 06:00 KST로 바꾸고, where에 시간 비교를 추가한 다음, 다음 날 아침 첫 실행 로그를 봤다.

[2026-01-24 06:00:00.012] [INFO] [BatchProcessApplicationService] [KickoffBatch] Started
[2026-01-24 06:00:00.345] [INFO] [BatchProcessApplicationService] [KickoffBatch] Scan - found=3 expired / 17 active
[2026-01-24 06:00:01.012] [INFO] [BatchProcessApplicationService] [Flow] student=loginId001(stu_abc) | 숙제 만료([Phase 1]) | assignmentId=58 | bundles=4/5 | avgAccuracy=72.3% | achievement=NORMAL | levelAdj=none
...
[2026-01-24 06:00:08.456] [INFO] [BatchProcessApplicationService] [KickoffBatch] 완료 - 소요 8.4초
[2026-01-24 06:00:08.456] [INFO] [BatchProcessApplicationService] [KickoffBatch] 만료: 3건 | 일괄만료: 0건
[2026-01-24 06:00:08.456] [INFO] [BatchProcessApplicationService] [KickoffBatch] 생성: 14건
[2026-01-24 06:00:08.456] [INFO] [BatchProcessApplicationService] [KickoffBatch] 레벨조정: 1건 (⬇️1 ⬆️0 🔄0)

Scan - found=3 expired / 17 active. 한 줄이지만 이 줄 하나가 폭주 차단의 가장 큰 안전망이다. 다음 실행에서 갑자기 found=14 / 17이 찍히면 즉시 알람을 걸 수 있다.

파일 로그 grep

같은 시각 logs/app-2026-01-24.log 파일에도 동일 내용이 박혔다.

$ wc -l logs/app-2026-01-24.log
   1248 logs/app-2026-01-24.log

$ grep '\[KickoffBatch\]' logs/app-2026-01-24.log | head
[2026-01-24 06:00:00.012] [INFO] [BatchProcessApplicationService] [KickoffBatch] Started
[2026-01-24 06:00:00.345] [INFO] [BatchProcessApplicationService] [KickoffBatch] Scan - found=3 expired / 17 active
[2026-01-24 06:00:08.456] [INFO] [BatchProcessApplicationService] [KickoffBatch] 완료 - 소요 8.4초

$ grep -c '\[Flow\]' logs/app-2026-01-24.log
17

회원 단위 로그 17건 (만료 대상 3건 + 생성 14건). 실행 요약과 회원별 흐름이 동시에 잡힌다.

에러 전용 파일

logs/error-2026-01-24.log는 비어 있어야 정상이다. 비어 있으면 한 줄도 없다.

$ ls -la logs/error-2026-01-24.log
ls: logs/error-2026-01-24.log: No such file or directory

DailyRotateFile은 로그가 1건이라도 찍힐 때까지 파일을 만들지 않는다. 에러가 0건이면 파일 자체가 없다. 운영자가 매일 한 번 “에러 파일이 있나?” 만 봐도 되는 단순한 체크가 만들어진다.

GCP Cloud Logging severity 필터

프로덕션 콘솔 transport는 JSON 출력 + severity 필드를 같이 내보낸다. GCP Cloud Logging UI에서 다음 필터 한 줄로 ERROR만 본다.

severity >= ERROR
resource.type = "cloud_run_revision"

이전엔 텍스트 grep으로 ERROR를 찾았다. 메시지 본문에 우연히 ERROR가 들어간 INFO 로그(예: “user input contains the word ERROR”)까지 같이 잡혔다. severity 필드가 분리된 다음부터는 false positive가 0건이다.

---

📋 정리 — 핵심 요약

---

🛡️ 첫 배치 작업 8개 체크리스트

배치 작업을 처음 짤 때 이 여덟 가지만 챙겨 두어도 첫 사고는 거의 막힌다.

1. 빈도와 필터를 같이 정한다 — 둘 중 하나만 결함이 있어도 데이터가 한 회 실행에 사라질 수 있다. cron 표현식을 정할 때 “이 함수가 한 번에 처리하는 행 수가 평소의 100배가 돼도 괜찮은가” 를 물어보라
2. 만료/삭제 기준은 함수 안에서 거른다 — 호출하는 쪽이 따로 거를 거라는 가정은 거의 깨진다
3. 스캔 결과를 한 줄 로그로 남겨라 — [Batch] Scan - found=N / M total 한 줄이 가장 싸고 가장 강한 폭주 감지기다
4. 실행 단위 + 항목 단위 로그를 분리하라 — [Batch] ...와 [Flow] entity=... | ... 두 접두사로 갈라야 grep이 쉬워진다
5. 트리거(데코레이터)와 본체(서비스)를 분리하라 — 두 컨트롤러(운영자 수동 + 외부 스케줄러)로 노출해야 사고 복구의 도구가 생긴다
6. 로그를 파일로 남겨라 — 콘솔만 의존하면 사고 시점 흔적이 흘러간다. winston-daily-rotate-file이 표준
7. 프로덕션 콘솔은 JSON + severity 필드를 출력한다 — GCP/AWS의 구조화된 로깅이 그제서야 의미 있는 검색이 된다
8. 임계 케이스 단위 테스트 두 개를 추가하라 — “기준 직전” / “기준 직후” 두 케이스만 있어도 다음 누군가가 필터를 한 줄로 되돌리는 사고가 막힌다

📌 핵심: 배치 작업의 첫 사고는 거의 빈도 × 필터 × 가시성 세 축의 곱이다. 한 축에라도 결함이 있으면 다른 축이 다친다. 셋이 동시에 결함이면 운영자 페이지가 점심 직후에 0으로 떨어진다.

---

다음 편은 이번 글의 회고에서 미뤘던 운영 테이블 분리 — 누계 RAW 값과 표시용 점수를 다른 테이블로 갈라 0~9500 스케일·로그스케일·95% 하드캡을 굳히는 member_metric_display 도입 — 이다. 같은 사고 직후 며칠에 짠 작업이라 호흡이 이어진다.