수동 실행이 예약 실행으로 오판된 버그 - systemd 활성화 메타데이터가 생각보다 오래 남았다
한 달 전에 고쳤다고 믿은 버그가, 완전히 다른 원인으로 다시 터졌습니다
제 자동매매 시스템은 하루 중 정해진 시각에 자동으로 매매 라운드를 돕니다. 그런데 종종 제가 직접 라운드를 한 번 더 돌려야 하는 상황이 생깁니다.
안전장치가 발동해서 한동안 매수가 막혀 있다가, 그 장치를 풀고 수동으로 거래를 재개해야 하는 경우가 그렇습니다. 이 안전장치와 수동 개입 절차는 종목을 고르는 판단 로직이 아니라 주문 실행·안전장치 계층에 속합니다. 전체 설계는 실전 계좌 적용편(새 창)에 정리해 뒀습니다.
코드는 "이번 실행이 예약된 자동 라운드인지, 제가 수동으로 돌린 건지"를 매번 구분해야 합니다. 자동 라운드에만 적용되는 지각 가드가 있기 때문입니다.
예약된 시각보다 한참 늦게 시작된 자동 라운드는 타이밍이 깨졌다는 신호라 발주를 막는 게 맞습니다. 하지만 제가 지금 막 수동으로 돌린 라운드라면 "지각"이라는 판정 자체가 의미가 없습니다.
무슨 일이 있었나
안전장치 때문에 매수가 막힌 걸 풀고, 수동으로 라운드를 돌렸습니다. 그런데 시스템이 이 실행을 예약된 라운드로 인식하고, 지각 가드를 적용해 발주를 차단했습니다.
판정 근거를 보니 "원래 정해진 시각보다 한참 지각했다"는 이유였습니다. 지금 막 수동으로 돌린 실행에 "지각"이라는 말 자체가 성립하지 않는 상황이었습니다.
처음엔 뭐라고 생각했나
이 판별 로직은 한 달쯘 전에도 같은 증상으로 한 번 고친 적이 있었습니다. 그때는 자동화 유닛 설정 파일에 "이건 예약 실행"이라는 값을 아예 박아둔 게 원인이었습니다.
유닛 설정에 값을 박아두면, 제가 수동으로 그 유닛을 실행시켜도 같은 값이 그대로 따라옵니다. 그래서 그때는 그 하드코딩을 걷어내고, 대신 운영체제가 실행 시점에 넣어주는 표시로 판별하도록 바꿨습니다. 자동화 스케줄러가 타이머로 깨울 때만 붙는 환경변수였습니다.
문서에도 "제가 수동으로 실행하면 이 표시가 비어 있다"고 적어뒀습니다. 그래서 이번에도 같은 쪽을 의심했습니다. 그 환경변수가 또 어딘가에 잘못 박혀 있는 게 아닐까 하고 설정 파일을 뒤졌습니다.
설정 파일에는 문제가 없었습니다. 환경변수 주입 방식도 문서에 적힌 그대로였습니다. 뭔가 다른 원인이 있었습니다.
진짜 원인
실제로 들여다보니, 그 환경변수 자체가 "매번 새로 세팅된다"는 전제가 틀려 있었습니다.
운영체제 서비스 관리자가 하는 일이었습니다. 타이머가 하루 중 처음으로 어떤 작업을 깨우면, 그 작업에 "너를 깨운 건 이 타이머야"라는 표시를 붙입니다.
문제는 이 표시가 작업이 끝나고 비활성 상태로 돌아간 뒤에도 지워지지 않는다는 점이었습니다. 그리고 같은 날 두 번째, 세 번째로 같은 타이머가 다시 깨워도 이 표시는 덮어써지지 않았습니다.
그러니 그날 아침 자동 라운드가 한 번 돌고 난 뒤, 오후에 제가 같은 작업을 수동으로 실행시키면, 아침에 붙었던 "타이머가 깨웠다"는 표시가 그대로 상속됐습니다. 코드는 이 표시만 보고 "이건 타이머가 깨운 예약 실행"이라고 결론 내렸습니다.
한 달 전 사고와 이번 사고는 증상이 똑같았습니다. 수동 실행이 예약 실행으로 오판된 것입니다. 하지만 원인은 완전히 달랐습니다.
한 달 전엔 "표시를 누가 박아뒀는가"의 문제였고, 이번엔 "표시가 예상보다 훨씬 오래 산다"는 운영체제 동작 자체의 문제였습니다. 지난번 수선은 표시를 누가 세팅하는지만 고쳤을 뿐, 그 표시의 수명이 얼마나 긴지는 검증한 적이 없었습니다.
어떻게 고쳤나
처음 떠올린 방법은 그 표시가 얼마나 오래된 값인지를 재서, 너무 오래됐으면 상속된 낡은 표시로 보고 버리는 것이었습니다. 운영체제가 표시와 함께 "이 표시가 만들어진 시각"도 함께 넘겨주기 때문에 가능할 것 같았습니다.
구현하면서 실제 로그를 찍어보니 이 방법은 쓸 수 없었습니다. 그 "만들어진 시각" 값도 하루 중 첫 번째 발화 시각에 고정된 채, 이후 발화에서 전혀 갱신되지 않았습니다.
이 값으로 나이를 재면, 그날 진짜로 타이머가 정상적으로 깨운 두 번째·세 번째 라운드까지 "낡은 표시니까 수동 실행"으로 잘못 떨어질 뻔했습니다. 관찰된 사례 하나(그날 첫 발화)에만 맞춘 수정이 다른 정상 사례를 깨뜨릴 뻔한 겁니다. 배포 전에 실측으로 걸러냈습니다.
최종적으로는 비교 대상을 바꿨습니다. 타이머 쪽에는 "마지막으로 발화한 시각"이 매 발화마다 갱신되는 별도의 값이 있었습니다.
이 값과, 서비스가 실제로 지금 막 활성화된 시각을 대조했습니다. 두 시각의 간격이 짧으면 방금 그 타이머가 깨운 것이고, 간격이 크게 벌어져 있으면 예전 표시가 상속된 수동 실행으로 판정했습니다.
둘 중 어느 쪽도 조회나 해석이 안 되는 경우를 대비해 방향도 하나로 정해뒀습니다. 판별이 애매하면 "예약 실행(지각 가드 적용)" 쪽으로 기울이게 했습니다. 자동 라운드를 수동으로 잘못 보고 보호장치를 빼먹는 쪽보다, 수동 라운드를 예약으로 잘못 보고 한 번 막히는 쪽이 훨씬 안전하기 때문입니다.
막히는 쪽으로 fail-safe를 잡아도 빠져나갈 길은 남겨뒀습니다. 판별 로직과 별개로, 제가 명시적으로 "이건 수동이다/예약이다"라고 선언할 수 있는 값이 있어서, 이 값이 있으면 어떤 추론도 무시하고 그걸 그대로 따릅니다.
마지막으로 판정에 쓰인 근거(발화와 시작 사이 간격, 재시작 횟수 등)를 실행 기록 한 줄에 같이 남겼습니다. 다음에 같은 종류의 오판이 또 생기면, 로그를 뒤지지 않고 이 한 줄만 보고 원인을 바로 알 수 있게 하기 위해서였습니다.
일반화하면
"이 실행이 자동인지 수동인지"를 주변 메타데이터로 추론하려 한다면, 그 메타데이터의 수명을 직접 확인해야 합니다. 환경변수든 타임스탬프든, "매번 새로 세팅된다"는 전제는 문서나 직관이 아니라 실측으로 검증해야 합니다.
이번 사건의 첫 번째 수선도 "사람이 수동으로 실행하면 이 표시가 비어 있다"는, 검증 없이 적어둔 문장이 틀린 전제였습니다.
같은 증상이 재발했다고 해서 같은 원인이라고 단정하면 안 됩니다. 겉보기엔 완전히 같은 버그(수동 실행이 예약으로 오판됨)였지만, 원인 계층이 전혀 달랐습니다.
전에 고친 지점만 다시 들여다봤다면 시간을 허비했을 겁니다.
외부 시스템의 동작은 문서가 아니라 실측으로 확인해야 합니다. 운영체제나 프레임워크가 내부적으로 뭘 하는지는 개발자가 통제할 수 없는 영역입니다.
"당연히 이럴 것"이라는 가정 대신, 실제 로그를 찍어서 확인하는 쪽이 결국 더 쌉니다.
관찰된 사례 하나에 맞춘 수정은 다른 사례를 깨뜨릴 수 있습니다. 첫 번째 고침 아이디어는 하루 중 첫 번째 발화라는 사례 하나만 보고 설계됐습니다.
실제로 그대로 적용했다면 같은 날 두 번째·세 번째 발화를 오판했을 겁니다. 배포 전에 여러 사례로 실측해 본 게 이걸 막았습니다.
판별이 애매할 때 어느 쪽으로 기울일지는 미리 정해야 합니다. 두 가지 오판 중 하나가 다른 하나보다 덜 위험하다면, 애매한 경우엔 그 안전한 쪽으로 기울여야 합니다.
그리고 그 fail-safe 때문에 막히는 정당한 경우를 위해, 추론을 무시하고 바로 꽂을 수 있는 명시적 탈출구도 같이 만들어야 합니다.
이 사건 이후로는 "환경변수나 타임스탬프가 매번 새로 세팅되는가"를 가정하는 코드를 새로 짤 때마다, 그 가정을 실제로 한 번은 눈으로 확인하고 넘어가는 습관이 생겼습니다.