승인 시각이 승인한 때가 아니었다

표준데이터 신청 상세에는 처리 이력 타임라인이 있습니다. 제출·검토·승인·반려 같은 전이 사실과 심사 의견을 한 줄기 시간순으로 세워 보여 주는 화면이에요.

여기 찍힌 승인 시각이 실제로 승인한 때보다 이릅니다. 정확히는 한 단계 전, 그러니까 직전 전이가 일어난 시각이 찍혀 있었습니다.

대기 행은 미리 깔린다

심사 액션은 RequestAction 행으로 관리합니다. 이 행은 처리할 때 만들어지는 게 아니라, 앞 단계가 끝나는 순간 다음 단계의 대기 행으로 미리 깔립니다. 신청이 시작될 때 초기 액션을 만들고, 전이가 일어날 때마다 다음 전이의 액션 행을 채워 넣어요.

RequestAction.objects.create(
    request=self.request,
    transition=ta.transition,
    action=ta.action,
    is_active=True,
    is_complete=False,
)

그리고 시각 칸은 이렇게 생겼습니다.

timestamp = models.DateTimeField(default=timezone.now, null=True, blank=True)

default 는 행이 만들어질 때 한 번 평가됩니다. 위 코드에서 is_complete=False 인 대기 행이 깔리는 그 순간이에요. 그 뒤 실제로 누군가 승인 버튼을 누르면 완료 처리가 도는데, 그 코드가 이랬습니다.

RequestAction.objects.select_related(...).filter(
    ...
).update(is_active=False, is_complete=True)

is_active 와 is_complete 만 바꿉니다. timestamp 는 그대로예요. 그러니까 이력에 남는 시각은 "이 일이 일어난 때"가 아니라 "이 일을 기다리는 줄이 만들어진 때" 였습니다. 대기 줄은 직전 전이 때 깔리니까, 결과적으로 한 단계 전 시각이 찍힙니다.

같은 모델 파일에 RequestData 도 똑같이 default=timezone.now 를 씁니다. 그런데 이쪽은 맞아요. 심사 의견 행은 심사자가 의견을 쓰는 순간 만들어지고, 만드는 함수가 timestamp=timezone.now()를 직접 넘기기도 합니다. 행 생성 시각과 사건 시각이 같은 자리예요. 같은 한 줄이 한쪽에서는 맞고 한쪽에서는 틀린 겁니다. 둘이 같은 값이 아닐 때 default 는 사건 시각이 못 됩니다.

시각이 틀리면 순서도 틀린다

이게 표시만의 문제가 아닌 이유가 있습니다. 타임라인 매크로가 전이 사실과 심사 의견을 합친 뒤 이 값으로 정렬해요.

{% set tl.items = tl.items | sort(attribute="time") %}

전이 쪽 시각은 한 단계 전으로 밀려 있고 심사 의견 쪽 시각은 정확합니다. 그러면 승인 항목이 그 승인을 낳은 심사 의견보다 위에 설 수 있습니다. 의견을 쓰기도 전에 승인한 것처럼 보이는 이력이에요. 심사 이력은 "누가 언제 무엇을 했나"를 남기려고 있는 자린데, 시각이 틀리면 그 자리의 존재 이유가 없어집니다.

`auto_now` 는 애초에 답이 아니었다

시각 칸이 갱신되지 않는다는 말을 들으면 auto_now=True 가 먼저 떠오릅니다. 여기서는 안 됩니다.

완료 처리가 쿼리셋 update() 라서요. update() 와 bulk_update() 는 SQL을 직접 쏘기 때문에 모델의 save() 를 안 거치고, 그래서 시그널도 auto_now 도 건너뜁니다. 필드를 auto_now=True 로 바꿔도 이 경로에서는 값이 그대로 남아요. 고친 것 같은 착각만 남습니다.

성격으로 봐도 맞지 않습니다. auto_now 는 "무슨 저장이든 무조건 현재 시각"이라 나중에 다른 이유로 이 행을 건드리기만 해도 심사 이력의 시각이 바뀝니다. 이력은 그러면 안 되는 값이에요.

그래서 갱신을 명시적으로 넣었습니다(dc9b08ef).

# 해당 액션 완료 처리. timestamp 는 대기 행을 만든 시각이라 여기서 안 찍으면
# 처리 이력의 승인·반려 시각이 한 단계 전(이전 전이 시각)으로 밀린다.
).update(is_active=False, is_complete=True, timestamp=timezone.now())

한 인자를 더한 게 전부입니다. 대신 왜 여기서 찍어야 하는지를 주석으로 남겼어요. 이 줄만 보면 timestamp 를 왜 굳이 다시 쓰는지 알 수 없고, 모르면 다음에 정리하다 지웁니다.

검증

대기 행을 한 시간 전으로 밀어 두고 처리한 뒤, 찍힌 시각이 밀어 둔 값이 아니라 지금에 가까운지 봅니다.

def test_완료된_액션의_시각은_처리한_때다(self):
    """대기 행은 이전 전이 때 미리 깔리므로, 완료할 때 시각을 다시 찍어야
    처리 이력의 승인 시각이 한 단계 앞으로 밀리지 않는다."""
    request_obj = self._new_request(self.record)
    stale = timezone.now() - timedelta(hours=1)
    RequestAction.objects.filter(request=request_obj).update(timestamp=stale)

    self._run(request_obj, self.submit_tr)

    done = RequestAction.objects.get(
        request=request_obj, action=self.submit_tr[1], is_complete=True
    )
    self.assertGreater(done.timestamp, stale + timedelta(minutes=50))

assertGreater 의 기준을 stale 이 아니라 stale + 50분 으로 잡은 이유가 있습니다. stale 보다 크기만 하면 되는 조건은 너무 헐거워요. 갱신이 아예 안 되더라도 다른 이유로 값이 1초만 움직이면 통과합니다. 한 시간을 밀어 두고 50분 뒤보다 뒤인지를 보면, 통과하려면 실제로 현재 시각이 찍히는 수밖에 없습니다. timezone.now() 와 정확히 비교하지 않은 건 테스트가 도는 사이에 시각이 흐르기 때문이고요.

남은 것 · 한계

이미 쌓인 이력은 그대로입니다. 이 커밋 이전에 처리된 신청의 승인·반려 시각은 여전히 한 단계 전 값이에요. 어긋난 폭이 전이마다 다르고, 다음 대기 행의 생성 시각으로 되짚을 수는 있어도 마지막 단계는 그 근거마저 없어서 소급 보정 대신 그냥 두기로 했습니다. 지금 화면에는 옛 이력과 새 이력이 같은 모양으로 섞여 있고, 둘을 구분해 주는 표시가 없습니다.
같은 함정이 남아 있을 수 있습니다. 이번에 고친 건 표준데이터·OID 심사 액션 한 곳입니다. default=timezone.now 로 잡힌 칸을 미리 만들어 두고 나중에 완료 표시만 하는 구조가 다른 데 또 있는지는 전수로 훑지 않았어요. 판별 기준은 하나입니다. 행이 생기는 때와 일이 일어나는 때가 같은가.
정렬 뒤섞임은 테스트로 안 잡았습니다. 붙인 테스트는 값이 갱신되는지만 봅니다. 전이와 심사 의견을 섞었을 때 타임라인 순서가 맞는지는 여전히 화면을 열어 봐야 알아요. 시각 하나로 두 가지(표시·정렬)를 쓰는 구조라 정작 더 아픈 쪽이 안 잠겨 있습니다.
이력 표시 형식 자체는 이 시점에 아직 화면마다 제각각이었습니다. 그건 엿새 뒤에 따로 정리했습니다.

승인 시각이 승인한 때가 아니었다

대기 행은 미리 깔린다

시각이 틀리면 순서도 틀린다

auto_now 는 애초에 답이 아니었다

검증

남은 것 · 한계

`auto_now` 는 애초에 답이 아니었다