Kubernetes의 CronJob에서 스케줄을 업데이트한 뒤 의도치 않게 다시 한번 스케줄링되는 문제를 발견했다. 처음에는 아무런 힌트가 없어서 왜 크론잡이 실행되었는지 이해하지 못했으나 동료들과 오랫동안 살펴보다 보니 어느 정도 원인을 알 수 있었고 똑같이 재현해 낼 수도 있게 되었다.
다른 분이 알려주셔서 Updating a cronjob causes jobs to be scheduled retroactively와 같은 문제라는 것을 알게 되었는데 크론잡의 스케줄을 업데이트한 뒤에 스케줄링이 소급 적용된 것이다. 다시 말하면 오늘 3시에 스케줄을 설정한 크론잡이 3시에 실행된 이후 5시에 내일은 4시부터 실행되길 바라고 4시로 변경했지만 실제로는 소급 적용되어서 오늘 4시 스케줄링도 실행될 수 있다는 의미이다.
상황을 재현할 수 있게는 되었지만, 조건을 잘 알지 못했기에 동작이 궁금해서 더 테스트해보았다. Kubernetes는 워낙 복잡한 시스템이기 때문에 여전히 모든 것을 알지는 못하지만, 대충의 동작 방식은 이해하게 되었다. 이 글은 그 찾아가게 된 과정을 정리한 글이다.
CronJob
먼저 크론잡을 간단히 살펴보면 크론잡은 Kubernetes 1.21에서 GA가 되었으므로 batch/v1 그룹 버전을 사용한다. 그리고 Kubernetes 1.20부터 성능이 크게 개선된 CronJob 컨트롤러 v2가 도입되어 1.21부터는 v2 컨트롤러를 기본으로 사용한다. 여기서도 v2 컨트롤러만 사용해서 트러블슈팅을 했다.
v1 컨트롤러에서는 10초마다 폴링해서 크론잡을 실행하도록 구현이 되어서 API 부하도 일으키고 크론잡이 많은 경우 지연시간도 커지는 문제가 있었지만, v2부터는 다른 컨트롤러처럼 sahred informer를 통해 특정 리소스에 대한 추가, 수정, 삭제 알림을 받을 수 있게 되어서 컨트롤러는 큐에서 이벤트를 가져와서 일관되게 처리하게 되었다. 물론 여전히 크론잡 컨트롤러는 10초마다 실행된다.
이미지 출처: Kubernetes 1.21: CronJob Reaches GA
크론잡이 변경되거나 잡과 관련된 변경이 일어날 때마다 해당 크론잡을 나타내는 키를 큐에 푸시한다. 핸들러는 이 키를 큐에서 가져와서 크론잡을 처리한 뒤 완료되면 다음 스케줄 시간을 위해 다시 큐에 키를 푸시한다.
CronJob 실행해보기
먼저 크론잡의 동작을 살펴보기 위해 일단 간단한 크론잡을 만들어 보자.
apiVersion: batch/v1
kind: CronJob
metadata:
name: cron-test
spec:
schedule: "5 13 * * *"
jobTemplate:
spec:
template:
spec:
containers:
- name: cron-test
image: busybox:1.28
imagePullPolicy: IfNotPresent
command:
- /bin/sh
- -c
- date; echo Hello from the Kubernetes cluster
restartPolicy: OnFailure
이 크론잡을 다음과 같이 클러스터에 적용한다. schedule은 등록하고 바로 실행되도록 가까운 시간으로 설정했다.
$ kubectl -n cron-test apply -f cron.yaml
잠시 뒤 스케줄링 한 시간이 되면 잡이 실행된 것을 확인할 수 있다.
$ kubectl -n cron-test get all
NAME READY STATUS RESTARTS AGE
pod/cron-test-27991364-56v87 0/1 Completed 0 50s
NAME SCHEDULE SUSPEND ACTIVE LAST SCHEDULE AGE
cronjob.batch/cron-test 5 13 * * * False 0 50s 81s
NAME COMPLETIONS DURATION AGE
job.batch/cron-test-27991364 1/1 8s 50s
이제 크론잡의 정보를 kubectl -n cron-test get cronjob.batch/cron-test -o yaml로 다시 확인해 보자.
apiVersion: batch/v1
kind: CronJob
metadata:
creationTimestamp: "2023-03-22T13:01:51Z"
generation: 1
name: cron-test
namespace: cron-test
spec:
# 중략
schedule: 5 13 * * *
status:
lastScheduleTime: "2023-03-22T13:05:00Z"
lastSuccessfulTime: "2023-03-22T13:05:08Z"
lastScheduleTime를 보면 스케줄링한 시간인 13시 5분에 스케줄링 되어 13시 5분 8초에 성공적으로 완료된 것을 볼 수 있다.
CronJob 스케줄 업데이트하기
매일 13시 5분에 실행되는 크론잡이었지만 내일부터는 13시 10분에 실행되기를 원한다고 해보자. 그래서 13시 10분이 지난 13시 15분경에 스케줄을 13시 10분으로 업데이트한다.
apiVersion: batch/v1
kind: CronJob
metadata:
creationTimestamp: "2023-03-22T13:01:51Z"
generation: 2
name: cron-test
namespace: cron-test
spec:
# 중략
schedule: 10 13 * * *
status:
lastScheduleTime: "2023-03-22T13:05:00Z"
lastSuccessfulTime: "2023-03-22T13:05:08Z"
스케줄이 10 13 * * *로 변경되었고 generation이 2로 바뀌었다. 당연히 status는 그대로이다. 글이라서 표현하기가 쉽지 않은데 현재 시각은 13시 15분경이다.
$ kubectl -n cron-test get all
NAME READY STATUS RESTARTS AGE
pod/cron-test-27991364-56v87 0/1 Completed 0 10m34s
NAME SCHEDULE SUSPEND ACTIVE LAST SCHEDULE AGE
cronjob.batch/cron-test 10 13 * * * False 0 10m34s 13m45s
NAME COMPLETIONS DURATION AGE
job.batch/cron-test-27991364 1/1 8s 10m34s
아까 13시 5분에 실행되었던 job과 pod이 남아있는데 이를 삭제해보자.
$ kubectl -n cron-test delete job.batch/cron-test-27991364
job.batch "cron-test-27991364" deleted
잡을 삭제한 뒤에 다시 확인해 보면 새로운 잡이 바로 다시 실행된 것을 볼 수 있다. AGE 보면 새로 생겼다는 것을 알 수 있다.
$ kubectl -n cron-test get all
NAME READY STATUS RESTARTS AGE
pod/cron-test-27991330-rnwvs 0/1 Completed 0 2s
NAME SCHEDULE SUSPEND ACTIVE LAST SCHEDULE AGE
cronjob.batch/cron-test 10 10 * * * False 1 6m4s 14m15s
NAME COMPLETIONS DURATION AGE
job.batch/cron-test-27991330 0/1 2s 2s
크론잡을 다시 확인해 보자.
apiVersion: batch/v1
kind: CronJob
metadata:
creationTimestamp: "2023-03-22T13:01:51Z"
generation: 2
name: cron-test
namespace: cron-test
spec:
# 중략
schedule: 10 13 * * *
status:
lastScheduleTime: "2023-03-22T13:10:00Z"
lastSuccessfulTime: "2023-03-22T13:16:12Z"
잡이 새로 생성되면서 lastScheduleTime가 바뀌었는데 새로 업데이트한 스케줄 시간인 13시 10분으로 바뀌었고 실제로 잡이 생성된 시간은 13시 16분 정도였기 때문에 lastSuccessfulTime은 13시 16분 12초로 기록되었다. 이 결과만 보면 마치 10분에 시작되어 16분 12초에 끝난 것처럼 보이지만 실제로 위 시나리오에서 보듯이 16분에 시작되어 아까처럼 몇초 만에 끝났지만, 스케줄링 시간만 저렇게 업데이트된 것이다.
다시 한번 설명하지만 매일 13시 5분에 실행되도록 설정된 크론잡을 오늘 실행된 이후 13시 15분쯤 내일부터는 13시 10분에 실행되기를 바라고 13시 10분으로 스케줄을 업데이트했지만 실제로는 소급 적용이 되어서 오늘 13시 10분 스케줄이 또 실행되었다.
이 상황을 이해하기 위해 소급 적용이 되기 전에 스케줄만 업데이트된 상황을 다시 한번 보자.
spec:
schedule: 10 13 * * *
status:
lastScheduleTime: "2023-03-22T13:05:00Z"
lastSuccessfulTime: "2023-03-22T13:05:08Z"
앞에서 보았듯이 크론잡에는 생성된 시간은 있지만 업데이트된 시간은 존재하지 않는다. 그래서 위 상황만 보면 이 크론잡은 매일 13시 10분에 실행되는 크론잡이지만 마지막 스케줄은 13시 5분이었다. 다시 말하면 크론잡 입장에서는 13시 10분에 실행되어야 할 스케줄이 실행되지 않았다는 것을 의미한다. 이는 CronJob 컨트롤러에 장애가 있었는지 혹은 다른 문제가 있었는지 모르지만 위 상태 정보로 판단할 때 놓친 스케줄이 있다고 판단할 수밖에 없다.
크론잡의 세부 동작 살펴보기
크론잡의 스케줄을 업데이트했을 때 소급 적용이 된다는 것도 왜 그렇게 판단하는지는 이해할 수 있었지만 언제 그런 일이, 혹은 왜 발생하는지는 알 수가 없었다. 예를 들어 앞에서는 크론잡의 스케줄을 업데이트한 뒤에 Job을 제거했는데 미리 Job을 제거한 뒤에 스케줄을 업데이트하면 소급 적용이 되지 않는다. 여기서는 Job을 삭제하면서 의도적으로 상황을 만들었지만, 실제 클러스터에서는 훨씬 복잡한 설정과 함께 예상치 못한 시간이 이런 일이 발생했다. 결국 크론잡의 실행은 크론잡 컨트롤러가 관리할 때니 크론잡 컨트롤러가 어떻게 동작하는지 좀 더 알고 싶어서 다양하게 시도했다. 결과적으로 위에서 소급 적용된다는 것 외에 대단한 것을 알아낸 것은 아니지만 크론잡 컨트롤러의 동작은 어느 정도 이해하게 되었다.
로그 레벨
테스트가 쉽도록 로컬에서 Kind로 로그레벨을 수정해서 CronJob Controller가 포함된 kube-controller-manager
의 상세한 로그를 살펴봤다.
기본 kind 클러스터 기준으로 kube-controller-manager의 로그에서 cron 관련만 필터링해서 보니까 크론잡 관련 동작을 추적해 볼 수 있었다. 위 테스트에서 네임스페이스와 크론잡의 이름에도 cron이 들어있기 때문에 크론잡 컨트롤러가 아니어도 로그를 확인할 수 있다.
$ kubectl kube-system logs pod/kube-controller-manager-kind-control-plane -f | grep cron
I0322 13:01:07.847630 1 graph_builder.go:632] GraphBuilder process object: batch/v1/CronJob, namespace cron-test, name cron-test, uid 4ca03342-9c56-45b0-8387-b50f4244b386, event type add, virtual=false
I0322 13:01:07.847916 1 cronjob_controllerv2.go:531] "No unmet start times" cronjob="cron-test/cron-test"
I0322 13:01:07.847944 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="3m52.252242287s"
이 로깅 규칙은 Kubernetes의 문서 보면 알 수 있는데 다음과 같은 형식으로 되어 있다.
Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg...
각 부분을 좀 더 설명하면 다음과 같다.
L은 로그 레벨을 나타내므로 위에서I는 Info를 뜻한다.(에러나 워닝 등이 있는듯하고 1,2,3,4,5로 구분되는 로그 레벨은 나오지 않는다.)mmdd는 월/일을 의미하므로 위는 3월 22일이다.hh:mm:ss.uuuuuu는 시간이다.threadid는GetTID()가 반환하는 스레드 ID이다.file:line]는 컨트롤러의 파일명과 라인이다. 로그를 찍는 파일과 라인 수가 찍혀서 해당 코드를 찾아보기 쉽다.msg는 실제 로그 메시지이다.
klog.V(4).InfoS("Re-queuing cronjob", "cronjob", klog.KRef(cronJob.GetNamespace(), cronJob.GetName()), "requeueAfter", requeueAfter)와 같이 했을 때 뒷부분이 메시지와 추가 키/값이 함께msg` 부분에 출력된다.
kube-apiserver의 로그도 켜서 봤는데 모든 동작을 다 볼 수 있긴 하지만 내가 kubectl로 확인하는 로그도 다 나와서 보기가 쉽지 않았다.(나중을 위해서 apiserver의 로그를 쉽게 확인하는 방법을 찾아놔야겠다고 생각했다.)
Kubernetes 소스 코드
Kuberentes는 오픈소스이므로 당연히 코드를 확인할 수 있다. Kubernetes 1.24.10 기준으로 보고 있기 때문에 해당 태그로 코드를 확인했는데 cronjob_controllerv2.go의 코드를 확인할 수 있고 일부 유틸리티 함수 외에는 크론잡 컨트롤러 코드는 cronjob_controllerv2.go안에 있다.
컨트롤러 자체도 아주 긴 코드는 아니지만 주요 흐름을 따라가 보자. 아래 코드는 해당 함수의 전체 코드는 아니고 주요 흐름을 따라갈 수 있는 부분만 남긴 것이다.
func NewControllerV2() {
jobInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
AddFunc: jm.addJob,
UpdateFunc: jm.updateJob,
DeleteFunc: jm.deleteJob,
})
cronJobsInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
AddFunc: func(obj interface{}) {jm.enqueueController(obj) },
UpdateFunc: jm.updateCronJob,
DeleteFunc: func(obj interface{}) {jm.enqueueController(obj) },
})
}
NewControllerV2에서 informer에 이벤트 핸들러를 등록한다. informer는 특정 리소스의 변화가 생겼을 때 이를 컨트롤러에 알려주는 역할을 한다.
func (jm *ControllerV2) Run(ctx context.Context, workers int) {
klog.InfoS("Starting cronjob controller v2")
defer klog.InfoS("Shutting down cronjob controller v2")
for i := 0; i < workers; i++ {
go wait.UntilWithContext(ctx, jm.worker, time.Second)
}
<-ctx.Done()
}
Run은 크론잡 컨트롤러를 시작하는 함수이다. 클러스터를 띄우면 컨트롤러 시작 로그가 남는데 kube-controller-manager가 이를 시작해 주는 것으로 생각한다. 여기서는 워커 수만큼 워커를 실행한다.
func (jm *ControllerV2) worker(ctx context.Context) {
for jm.processNextWorkItem(ctx) {
}
}
워커는 단순히 processNextWorkItem를 반복해서 실행한다. 코드를 보면 마치 processNextWorkItem가 무한루프로 실행될 것 같지만 그렇지는 않고 이후 로그를 보면 작업 큐에 이벤트가 등록될 때 processNextWorkItem가 호출된다.
func (jm *ControllerV2) processNextWorkItem() bool {
key, quit := jm.queue.Get()
requeueAfter, err := jm.sync(ctx, key.(string))
}
processNextWorkItem에서는 작업 큐에서 아이템을 가져와서 sync()함수를 호출한 뒤에 다시 큐에 넣는 등의 행동을 한다.
func (jm *ControllerV2) sync(ctx context.Context, cronJobKey string) (*time.Duration, error) {
cronJob, err := jm.cronJobLister.CronJobs(ns).Get(name)
jobsToBeReconciled, err := jm.getJobsToBeReconciled(cronJob)
cronJobCopy, requeueAfter, updateStatus, err := jm.syncCronJob(ctx, cronJob, jobsToBeReconciled)
}
sync에서는 크론잡을 가져와서 syncCronJob을 호출한다.
func (jm *ControllerV2) syncCronJob() {
scheduledTime, err := getNextScheduleTime(*cronJob, now, sched, jm.recorder)
if scheduledTime == nil {
klog.V(4).InfoS("No unmet start times", "cronjob", klog.KRef(cronJob.GetNamespace(), cronJob.GetName()))
t := nextScheduledTimeDuration(sched, now)
return cronJob, t, updateStatus, nil
}
jobResp, err := jm.jobControl.CreateJob(cronJob.Namespace, jobReq)
t := nextScheduledTimeDuration(sched, now)
return cronJob, t, updateStatus, nil
}
syncCronJob이 크론잡을 처리하는 주요 로직이 있는 함수이고 여기서 스케줄 할 게 있는지 등을 검사해서 잡을 생성하고 다음 스케줄을 계산한다. 여기서 크론잡의 다른 옵션등의 대한 동작도 처리하고 있다. 예제 컨트롤러인 sample-controller도 거의 비슷한 구조로 되어 있다.
작업 큐를 이용한 Controller의 동작을 이해하려면 다음 그림이 도움이 된다.
이미지 출처: client-go under the hood
이전에 Programming Kubernetes를 공부하면서 Kubernetes 내부 구조에 대해서 어느 정도 배웠지만 당시에 잘 이해 못했는데 그때 더 열심히 공부할 것이라는 생각이 많이 들었다.(지금 다시 보면 더 많이 이해되려나...)
추가로 cronjob_controllerv2_test.go에 테스트 코드가 잘 되어 있어서 이를 통해서 syncCronJob에 원하는 시간 값을 넣어서 테스트해볼 수 있었다. 앞에서처럼 스케줄이 업데이트되어 lastScheduleTime과 현재 스케줄이 다른 경우에서 syncCronJob를 실행했을 때 numberOfMissedSchedules가 1로 나오는 것도 확인할 수 있었다.
사실 Go 언어를 할 줄 모르지만, 코드를 보면서 Kubernetes 같은 거대한 프로젝트를 이렇게 컨트롤러 단위로 실행해보고 테스트해볼 수 있다는 점에 꽤 놀랐다. 큐를 기반으로 모듈화가 잘 되어 있다는 것을 느낄 수 있었고 컨트롤러가 정말 컨트롤러의 관심사에만 관여하고 있다는 것을 알 수 있었다.
추가 로깅
코드까지 보았지만, Kubernetes 클러스터 내에서 동작하는 컨트롤러가 다른 컴포넌트와 어떻게 동작하는지는 알 수가 없었고 이 부분이 정말 전부 다인지 다른 관여 부분이 있는지 알 수가 없었다. 결국 가장 좋은 것은 Kuberentes 클러스터에서 직접 보는 것이었으므로 Kuberentes 소스 코드에서 이미지를 빌드해서 Kind로 띄우는 방법을 찾아서 직접 빌드했다. 직접 빌드할 수 있다는 것을 확인한 뒤로는 cronjob_controllerv2.go에 필요한 부분마다 추가 로그를 남기면서 앞에서 크론잡을 실행하고 스케줄을 업데이트할 때 어떻게 동작하는지 무슨 값이 들어오는지를 살펴볼 수 있었다.
로그는 klog.V(5).InfoS("sync()") 식으로 메시지를 남기거나 다른 변수의 값도 확인하고 싶으면 klog.V(5).InfoS("processNextWorkItem()", "key", key, "quit", quit)처럼 남겨서 각 동작을 확인했다. 이 로그는 다음과 같이 출력된다.
I0322 13:04:07.847690 1 cronjob_controllerv2.go:179] "sync()"
I0322 13:04:07.847686 1 cronjob_controllerv2.go:159] "processNextWorkItem()" key="cron-test/cron-test" quit=false
CronJob이 소급 적용될 때의 CronJob Controller 동작 확인하기
여기서부터는 앞에서 소급적용 되도록 CronJob을 업데이틑 하는 과정에서 내가 이해한 동작이랑 코드를 따라가 보는 내용이다. 글로 적기가 쉽진 않으므로 궁금하다면 코드를 같이 열어보면서 보면 더 좋을 것 같다.
CronJob 생성
처음 cron-test이란 CronJob을 생성하면 다음과 같은 로그가 남는다.
I0321 13:01:07.847630 1 graph_builder.go:632] GraphBuilder process object: batch/v1/CronJob, namespace cron-test, name cron-test, uid 4ca03342-9c56-45b0-8387-b50f4244b386, event type add, virtual=false
I0321 13:01:07.847916 1 cronjob_controllerv2.go:531] "No unmet start times" cronjob="cron-test/cron-test"
I0321 13:01:07.847944 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="3m52.252242287s"
내부 동작을 추적해 보면 Informer의 AddFunc를 통해서 enqueueController()가 호출되면서 작업 큐에 키 cron-test/cron-test가 등록된다. 작업 큐에 등록되었으니 processNextWorkItem()가 호출되고 다시 sync()가 호출되면서 syncCronJob()까지 이어진다.
syncCronJob() 안에서는 getNextScheduleTime()를 호출하는데 이는 utils.go의 getNextScheduleTime()을 호출한다. 처음 생성되었으므로 earliestTime는 크론잡이 생성된 시간이 되는데 이 값으로 getMostRecentScheduleTime를 호출하면 t의 값은 panic이 된다.
scheduledTime == nil 조건에 걸리면서 위에서 본 No unmet start times 로그를 찍고 다음 타임 스케줄(크론잡을 생성하고 첫 스케줄까지 남은 시간)인 3m52.252242287s를 반환하면서 끝나고 processNextWorkItem()는 이를 다시 큐에 추가한다.
첫 스케줄에 CronJob 트리거
13시 5분이 되어 첫 크론잡이 트리거 되면 다음과 같이 많은 로그가 남는다. 참고로 로그를 많이 봤는데 워커도 여러 개이고 잡업 큐를 통해서 실행되기 때문에 로그 순서가 반드시 실행순서는 아니고 종종 뒤바뀌기도 한다.
I0321 13:05:00.130230 1 graph_builder.go:632] GraphBuilder process object: batch/v1/Job, namespace cron-test, name cron-test-27990062, uid 7422a0d1-3c8f-45d3-8466-309a47691a60, event type add, virtual=false
I0321 13:05:00.130362 1 ttlafterfinished_controller.go:125] Adding job cron-test/cron-test-27990062
I0321 13:05:00.130415 1 job_controller.go:498] enqueueing job cron-test/cron-test-27990062
I0321 13:05:00.130493 1 controller_utils.go:206] Controller cron-test/cron-test-27990062 either never recorded expectations, or the ttl expired.
I0321 13:05:00.130634 1 controller_utils.go:223] Setting expectations &controller.ControlleeExpectations{add:1, del:0, key:"cron-test/cron-test-27990062", timestamp:time.Time{wall:0xc0fe889207c943e5, ext:205528780887, loc:(*time.Location)(0x38024e0)}}
I0321 13:05:00.130698 1 job_controller.go:1375] Too few pods running job "cron-test/cron-test-27990062", need 1, creating 1
I0321 13:05:00.131173 1 cronjob_controllerv2.go:613] "Created Job" job="cron-test/cron-test-27990062" cronjob="cron-test/cron-test"
I0321 13:05:00.131594 1 event.go:294] "Event occurred" object="cron-test/cron-test" fieldPath="" kind="CronJob" apiVersion="batch/v1" type="Normal" reason="SuccessfulCreate" message="Created job cron-test-27990062"
I0321 13:05:00.133797 1 graph_builder.go:632] GraphBuilder process object: batch/v1/CronJob, namespace cron-test, name cron-test, uid 4ca03342-9c56-45b0-8387-b50f4244b386, event type update, virtual=false
I0321 13:05:00.134186 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="23h59m59.998917329s"
I0321 13:05:00.134367 1 cronjob_controllerv2.go:531] "No unmet start times" cronjob="cron-test/cron-test"
I0321 13:05:00.134383 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="23h59m59.965746537s"
...중략...
I0321 13:05:00.143634 1 job_controller.go:657] Finished syncing job "cron-test/cron-test-27990062" (13.164084ms)
I0321 13:05:00.144169 1 controller_utils.go:189] Controller expectations fulfilled &controller.ControlleeExpectations{add:0, del:0, key:"cron-test/cron-test-27990062", timestamp:time.Time{wall:0xc0fe889207c943e5, ext:205528780887, loc:(*time.Location)(0x38024e0)}}
I0321 13:05:00.143610 1 cronjob_controllerv2.go:531] "No unmet start times" cronjob="cron-test/cron-test"
I0321 13:05:00.144257 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="23h59m59.956432454s"
이번에도 마찬가지로 processNextWorkItem() -> sync() -> syncCronJob 순으로 실행이 된다. 아까 큐에 남은 시간을 기록해서 넣어놓은 것 때문에 실행된 것으로 예상하는데 이 부분은 Informer를 더 공부해야 동작을 알 수 있을것 같다. 이번에 syncJob()에서 getNextScheduleTime()를 호출할 때는 getMostRecentScheduleTime()에서 numberOfMissedSchedules가 1이 나오면서 scheduledTime이 2023-03-22 13:05:00 +0000 UTC가 된다. scheduledTime이 나왔으므로 로직을 계속 타서 CreateJob()을 호출하면서 잡이 생성되고 Created Job 로그를 출력한다.
위에서 비슷한 로그가 여러 개 보이는데 이는 잡을 생성하고 또 작업 큐에 넣고 syncCronJob()이 돌고 다시 큐에 넣고 하는 등의 작업이 반복된다. 이 과정에서 잡이 완료된 것을 확인하고 status를 업데이트하는등의 작업이 이루어진다. 작업이 다 끝나면 처음에 작업 큐에 넣었던 것처럼 다음 스케줄을 위해 requeueAfter="23h59m59.965746537s로 작업 큐에 다시 키를 등록한다.
CronJob 스케줄 업데이트
CronJob의 스케줄을 업데이트(스케줄 5 13 * * *을 13시 15분에 10 13 * * *으로 업데이트)할 때는 다음과 같이 업데이트 이벤트만 로그에 남는다.
I0322 13:15:37.058356 1 graph_builder.go:632] GraphBuilder process object: batch/v1/CronJob, namespace cron-test, name cron-test, uid b84821f2-c2ff-4863-9fc7-94062ed1360c, event type update, virtual=false
이때는 processNextWorkItem()에서 시작하지 않고 바로 updateCronJob()이 호출된다. 여기서 당연히 oldCJ.Spec.Schedule는 5 13 * * *이고 newCJ.Spec.Schedule는 10 13 * * *가 된다.
// 스케줄 변경으로 인해 다음 작업 큐가 기존에 있던 것보다 더 빨라져야 한다면 작업 큐에 의해 여기서 처리될 것이다.
// 다음 작업 큐가 이전 스케줄보다 늦어진다면 sync loop가 기존 스케줄을 가지고 이미 큐에 추가된 키에 대해서는 아무 작업도 하지 않을 것이다.
if oldCJ.Spec.Schedule != newCJ.Spec.Schedule || (timeZoneEnabled && !pointer.StringEqual(oldCJ.Spec.TimeZone, newCJ.Spec.TimeZone)) {
// 스케줄 변경, 큐 시간 변경, recorder에 nil을 전달하여 syncCronJob이 모든 경고를 출력할 것이다.
sched, err := cron.ParseStandard(formatSchedule(timeZoneEnabled, newCJ, nil))
if err != nil {
// this is likely a user error in defining the spec value
// we should log the error and not reconcile this cronjob until an update to spec
klog.V(2).InfoS("Unparseable schedule for cronjob", "cronjob", klog.KRef(newCJ.GetNamespace(), newCJ.GetName()), "schedule", newCJ.Spec.Schedule, "err", err)
jm.recorder.Eventf(newCJ, corev1.EventTypeWarning, "UnParseableCronJobSchedule", "unparseable schedule for cronjob: %s", newCJ.Spec.Schedule)
return
}
now := jm.now()
t := nextScheduledTimeDuration(sched, now)
jm.enqueueControllerAfter(curr, *t)
return
}
updateCronJob() 코드를 보면 스케줄이 달라진 경우 스케줄을 다시 계산해서 작업 큐에 넣는 것을 볼 수 있는데 여기서는 놓친 스케줄을 확인하는 것이 아니라 nextScheduledTimeDuration()에서 계산만 하므로 다시 큐에 넣을 때 내일까지 남은 시간인 "23h54m23.041279538s"(다음날 13시 10분까지 남은 시간)로 큐에 넣는다. 다시 말하면 여기서 소급 적용을 위한 작업 큐를 추가하는 것은 아니다.
기존 트리거된 Job의 삭제
kubectl로 기존 완료된 잡을 수동으로 지웠을 때이다. Job이 삭제되었으니 당연히 Job이 삭제되는 로그가 남는다.
I0322 13:16:39.686726 1 graph_builder.go:632] GraphBuilder process object: batch/v1/Job, namespace cron-test, name cron-test-27991325, uid e3cd8d95-4325-439b-8069-b60846fe0b41, event type delete, virtual=false
I0322 13:16:39.686775 1 garbagecollector.go:496] "Processing object" object="cron-test/cron-test-27991325-2nxrx" objectUID=7bfbd327-ce7b-45f2-b84b-bac2a8227c45 kind="Pod" virtual=false
I0322 13:16:39.686877 1 resource_quota_monitor.go:359] QuotaMonitor process object: batch/v1, Resource=jobs, namespace cron-test, name cron-test-27991325, uid e3cd8d95-4325-439b-8069-b60846fe0b41, event type delete
I0322 13:16:39.686995 1 job_controller.go:674] Job has been deleted: cron-test/cron-test-27991325
I0322 13:16:39.687346 1 job_controller.go:661] Finished syncing job "cron-test/cron-test-27991325" (360.375µs)
Job이 삭제되자마자 바로 새로운 잡을 생성하는 로그가 남으면서 아까 최초 크론잡이 트리거 될 때처럼 Job을 생성하고 이를 기록하고 업데이트하는 로그가 남게 된다.
I0322 17:24:09.097406 1 cronjob_controllerv2.go:613] "Created Job" job="cron-test/cron-test-27991759" cronjob="cron-test/cron-test"
I0322 17:24:09.097547 1 event.go:294] "Event occurred" object="cron-test/cron-test" fieldPath="" kind="CronJob" apiVersion="batch/v1" type="Normal" reason="SuccessfulCreate" message="Created job cron-test-27991759"
I0322 17:24:09.097672 1 graph_builder.go:632] GraphBuilder process object: batch/v1/Job, namespace cron-test, name cron-test-27991759, uid 670ffadd-718a-41f6-9975-59969db5efb4, event type add, virtual=false
I0322 17:24:09.097671 1 job_controller.go:498] enqueueing job cron-test/cron-test-27991759
I0322 17:24:09.097733 1 controller_utils.go:206] Controller cron-test/cron-test-27991759 either never recorded expectations, or the ttl expired.
I0322 17:24:09.097782 1 controller_utils.go:223] Setting expectations &controller.ControlleeExpectations{add:1, del:0, key:"cron-test/cron-test-27991759", timestamp:time.Time{wall:0xc0feec4e45d4043c, ext:842095804135, loc:(*time.Location)(0x38024e0)}}
I0322 17:24:09.097811 1 job_controller.go:1375] Too few pods running job "cron-test/cron-test-27991759", need 1, creating 1
I0322 17:24:09.097679 1 ttlafterfinished_controller.go:125] Adding job cron-test/cron-test-27991759
I0322 17:24:09.100026 1 garbagecollector.go:623] adding [v1/Pod, namespace: cron-test, name: cron-test-27991754-46xc4, uid: 470fcf4d-9dfa-47a3-b466-7e5b010e9236] to attemptToDelete, because its owner [batch/v1/Job, namespace: cron-test, name: cron-test-27991754, uid: a64c478f-1a68-4cec-834a-c0586ca45fb2] is deletingDependents
I0322 17:24:09.100112 1 graph_builder.go:632] GraphBuilder process object: batch/v1/CronJob, namespace cron-test, name cron-test, uid 4d23a067-094a-4312-9ed0-c1b1f5d12135, event type update, virtual=false
I0322 17:24:09.100619 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="23h54m51.006225537s"
I0322 17:24:09.100697 1 cronjob_controllerv2.go:531] "No unmet start times" cronjob="cron-test/cron-test"
I0322 17:24:09.100713 1 cronjob_controllerv2.go:220] "Re-queuing cronjob" cronjob="cron-test/cron-test" requeueAfter="23h54m50.999321037s"
이를 내부적으로 보면 deleteJob()에서 enqueueController()로 작업 큐에 추가하고 다시 cron-test/cron-test키로 processNextWorkItem() -> sync() -> syncCronJob()이 실행된다.
syncCronJob()에서 getNextScheduleTime()를 호출하는데 getNextScheduleTime()에서 earliestTime이 lastScheduleTime인 2023-03-22 13:05:00 +0000 UTC가 되면서 numberOfMissedSchedules는 1이 되고 getNextScheduleTime()이 다음 스케줄 시간으로 2023-03-22 13:10:00 +0000 UTC을 반환하게 되고 syncCronJob()에서 scheduledTime이 있으므로 CreateJob()을 호출하게 된다.
지금까지 본 과정이 크론잡 스케줄이 소급 적용되는 과정이다.
정리
위 과정에서 보았듯이 결국 모든 작업의 시작은 작업 큐에 이벤트가 들어가면서 processNextWorkItem() -> sync() -> syncCronJob()순으로 호출되는 것이다. Informer에 대한 지식이 부족해서 작업 큐에 이벤트가 추가되는 모든 상황에 대해서 알지는 못하지만, Informer는 결국 관찰하는 리소스의 변경을 추적하는 것이므로 CronJob(연관된 Job 포함)의 변경이 되었을 때 작업큐가 추가되고 syncCronJob()이 호출되면서 놓친 스케줄을 잡아내든 다음 스케줄을 조정하든 작업이 진행되는 것이다. 예를 들어 Job에 ttlSecondsAfterFinished을 추가해서 Job이 지워진다고 하더라도 앞에서 본 시나리오와 똑같이 소급 적용이 발생한다. 어떤 식으로든 CronJob 리소스에 변경이 발생해서 syncCronJob()이 호출된다면 소급 적용이 발생할 수 있는 걸로 보인다.
가장 확실한 방법은 스케줄을 업데이트할 때 그냥 업데이트하는 것이 아니라 기존 크론잡을 삭제하고 다시 생성하는 것이다. Kubernetes에 올라온 이슈에도 이를 강제하기 위해 스케줄을 불변으로 만들어서 업데이트할 수 없게 만들자는 얘기도 있지만 현실적이지 않다고 대답한 걸로 보아 이렇게 바꾸진 않을 것으로 보인다. 복잡한 문제를 피하려면 스케줄 업데이트는 항상 기존 CronJob을 삭제하고 새로운 CronJob을 만드는 것으로 보인다.
또 다른 방법은 CronJob에 startingDeadlineSeconds를 설정하는 것이다. Kubernetes 문서를 보면 다음과 같이 나와 있다.
It is important to note that if the startingDeadlineSeconds field is set (not nil), the controller counts how many missed jobs occurred from the value of startingDeadlineSeconds until now rather than from the last scheduled time until now.
startingDeadlineSeconds필드를nil이 아닌 값으로 설정했다면 컨트롤러는 마지막 스케줄 시간부터 지금까지가 아닌startingDeadlineSeconds부터 지금까지의 놓친 Job의 수를 계산한다.
그러므로 CronJob의 변경한 스케줄의 시간이 startingDeadlineSeconds보다 더 이전이라면 소급 적용되지 않는다.
Comments