반응형
쿠버네티스 환경에선 Action Controller Runner (이하 ARC) 를 이용해서 파드를 Self Hosted Runner 로 사용할 수 있습니다.
ARC 구조는 위와 같습니다. Self Hosted Runner 로 사용할 파드를 RunnerDeployment 또는 RunnerSet 으로 배포할 수 있죠.
RunnerDeployment 는 쿠버네티스에서 Deployment 와 동일하게 동작하고, RunnerSet 은 StatefulSet 과 동일하게 동작합니다.
또한 배포하게 되면 파드 안에 2가지 컨테이너 동작하게 되는데, 하나는 Github Action Job 을 처리하는 Runner 컨테이너, 또 하나는 Docker 관련 일을 처리하는 Docker 컨테이너입니다.
옵션을 통해 Runner 컨테이너만 실행되게끔 할 수 있지만, 그리 추천되는 방법은 아닙니다.
아무튼 저는 ARC 를 이용해서 Self Hosted Runner 를 RunnerDeployment 로 여러 개 띄어놓았고, Github Action 이벤트가 발생하면 RunnerDeployment 중 하나를 가져다 사용하도록 구현했습니다.
이번 글에서는 ARC 를 사용하면서 발생 한 에러 중 "RUNNER_TOKEN must be set" 에 대한 트러블 슈팅을 공유하고자 합니다.
꽤나 직관적인 에러 메시지 였지만, 저에게 있어 지금까지 가장 힘들게 했던 에러 였습니다.
마치.. 타노스를 상대하는 어벤져스 처럼요 !
우선 RUNNER_TOKEN 가 뭘까?
ARC 를 사용해서 Self Hosted Runner 를 지정하려면 Github 에서 제공한 TOKEN 이 필요한데 바로 이 토큰이 RUNNER_TOKEN 입니다.
에러 메시지만 보면 이 RUNNER_TOKEN 을 지정하면 될 것처럼 보이지만.. printenv 를 한 결과 분명 RUNNER_TOKEN 값은 지정되어 있었습니다.
printenv RUNNER_TOKEN
# RUNNER_TOKEN="XXXX"
분명이 있음에도 불구하고, Action 을 동작해보면 아래와 같은 에러가 발생하죠.
본격적인 트러블 슈팅 시작 🔥
Github Action 에서는 아래와 같이 2가지 방법으로 action 를 사용할 수 있습니다.
로컬에 있는 action 을 사용하는 방법 하나
jobs:
steps:
- name: use custom action
uses: ./.github/actions/custom-action
github Repo 에 존재하는 action 을 사용하는 방법 하나
jobs:
steps:
- name: use custom action
uses: kingbj940429/gitops/actions/custom-action@v1.0
이 중 전자로 했을 경우 성공적으로 action 이 수행되나, 후자로 하면 RUNNER_TOKEN must be set 에러가 발생한다.
차라리 둘 다 발생했으면 더 나을 걸..
이해가 정말 안간다.. 로컬에 있는 action 코드랑 Repo 에 따로 있는 action 코드는 완전히 동일하고, ARC 에서 실행되는 것도 동일하다.
차이점이라면 로컬이랑 Repo 밖에 없다.. 우선 이걸로는 실마리를 찾기가 힘들 거 같아 구글에 관련 에러를 검색했고, 관련 검색 결과가 딱 하나가 나왔다. 부푼 기대감을 안고 클릭했다.
정확히 일치하지는 않으나 핵심 에러인 RUNNER 환경 변수가 Set 되지 않았다는 맥락은 비슷해서 쭉 읽어보았다. (Issued)
ARC 를 Helm 이용해서 배포할 때 위와 같은 옵션을 주라고 한다. 될 것 같다라는 느낌은 전혀 받지 않았지만.. 선택권이 없었기에 한번 시도해봤다.
정말 특이하게 트러블 슈팅 하면서 "안될거 같은데.." 같은 느낌을 받으면 정말 100% 안된다.. 이번에도 마찬가지다. 안된다 🤦
혹시나 해서 ARC TroubleShooting 문서도 쭉 살펴봤다.
관련된 이슈는 없다... 옆으로 보고, 위로 보고, 아래로 봐도 없다..
그럼 한번 ARC 관련 로그를 찍어볼까?
먼저 Action Controller 부터 확인해보자
k logs action-controller2023-02-13T06:07:36Z DEBUG runnerreplicaset Created replica(s) {"runnerreplicaset": "actions-runner-system/xxxxxxx", "lastSyncTime": null, "effectiveTime": "<nil>", "templateHashDesired": "54cb5b687f", "replicasDesired": 1, "replicasPending": 0, "replicasRunning": 0, "replicasMaybeRunning": 0, "templateHashObserved": [], "created": 1}
2023-02-13T06:07:36Z DEBUG runnerreplicaset Skipped reconcilation because owner is not synced yet {"runnerreplicaset": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f", "owner": "actions-runner-system/xxxxxxxx", "pods": null}
2023-02-13T06:07:36Z INFO runner Removed finalizer {"runner": "actions-runner-system/xxxxxxxx"}
2023-02-13T06:07:36Z DEBUG runnerreplicaset Skipped reconcilation because owner is not synced yet {"runnerreplicaset": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f", "owner": "actions-runner-system/xxxxxxxx", "pods": null}
2023-02-13T06:07:36Z DEBUG controller-runtime.webhook.webhooks received request {"webhook": "/mutate-actions-summerwind-dev-v1alpha1-runner", "UID": "ba4c43bb-cbba-45b0-8565-144b6323ee18", "kind": "actions.summerwind.dev/v1alpha1, Kind=Runner", "resource": {"group":"actions.summerwind.dev","version":"v1alpha1","resource":"runners"}}
2023-02-13T06:07:36Z DEBUG controller-runtime.webhook.webhooks wrote response {"webhook": "/mutate-actions-summerwind-dev-v1alpha1-runner", "code": 200, "reason": "", "UID": "ba4c43bb-cbba-45b0-8565-144b6323ee18", "allowed": true}
2023-02-13T06:07:36Z DEBUG controller-runtime.webhook.webhooks received request {"webhook": "/validate-actions-summerwind-dev-v1alpha1-runner", "UID": "e1f2936f-bc5a-4636-a475-747ea6292189", "kind": "actions.summerwind.dev/v1alpha1, Kind=Runner", "resource": {"group":"actions.summerwind.dev","version":"v1alpha1","resource":"runners"}}
2023-02-13T06:07:36Z INFO runner-resource validate resource to be updated {"name": "xxxxxxx-self-hosted-runner-q546f-rgpfq"}
2023-02-13T06:07:36Z DEBUG controller-runtime.webhook.webhooks wrote response {"webhook": "/validate-actions-summerwind-dev-v1alpha1-runner", "code": 200, "reason": "", "UID": "e1f2936f-bc5a-4636-a475-747ea6292189", "allowed": true}
2023-02-13T06:07:36Z DEBUG runnerreplicaset Skipped reconcilation because owner is not synced yet {"runnerreplicaset": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f", "owner": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f-rgpfq", "pods": null}
2023-02-13T06:07:36Z DEBUG runnerreplicaset Skipped reconcilation because owner is not synced yet {"runnerreplicaset": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f", "owner": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f-rgpfq", "pods": null}
2023-02-13T06:07:36Z INFO runner Updated registration token {"runner": "xxxxxxx-self-hosted-runner-q546f-rgpfq", "repository": ""}
2023-02-13T06:07:36Z DEBUG events Successfully update registration token {"type": "Normal", "object": {"kind":"Runner","namespace":"actions-runner-system","name":"xxxxxxx-self-hosted-runner-q546f-rgpfq","uid":"8c123ea1-026e-4125-b9cf-9a284bd13c75","apiVersion":"actions.summerwind.dev/v1alpha1","resourceVersion":"45228693"}, "reason": "RegistrationTokenUpdated"}
2023-02-13T06:07:36Z INFO runnerpod Runner pod has been stopped with a successful status. {"runnerpod": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f-rbd2t"}
2023-02-13T06:07:36Z DEBUG controller-runtime.webhook.webhooks received request {"webhook": "/mutate-runner-set-pod", "UID": "0b9a608b-5d3d-4551-9a44-022faf166b5d", "kind": "/v1, Kind=Pod", "resource": {"group":"","version":"v1","resource":"pods"}}
2023-02-13T06:07:36Z DEBUG controller-runtime.webhook.webhooks wrote response {"webhook": "/mutate-runner-set-pod", "code": 200, "reason": "", "UID": "0b9a608b-5d3d-4551-9a44-022faf166b5d", "allowed": true}
2023-02-13T06:07:36Z INFO runner Created runner pod {"runner": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f-rgpfq", "repository": ""}
2023-02-13T06:07:36Z DEBUG events Created pod 'xxxxxxx-self-hosted-runner-q546f-rgpfq' {"type": "Normal", "object": {"kind":"Runner","namespace":"actions-runner-system","name":"xxxxxxx-self-hosted-runner-q546f-rgpfq","uid":"8c123ea1-026e-4125-b9cf-9a284bd13c75","apiVersion":"actions.summerwind.dev/v1alpha1","resourceVersion":"45228695"}, "reason": "PodCreated"}
2023-02-13T06:07:41Z DEBUG runner Runner appears to have been registered and running. {"runner": "actions-runner-system/xxxxxxx-self-hosted-runner-q546f-rgpfq", "podCreationTimestamp": "2023-02-13 06:07:36 +0000 UTC"}
WARN 레벨 이상의 로그는 보이지 않는다.
그럼 Runner Container 와 Docker Container 는 어떨까?
k logs -f xxxxxx -c runner2023-02-13 06:06:46.371 DEBUG --- Docker enabled runner detected and Docker daemon wait is enabled
2023-02-13 06:06:46.373 DEBUG --- Waiting until Docker is available or the timeout of 120 seconds is reached
}CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
2023-02-13 06:06:49.305 NOTICE --- WARNING LATEST TAG HAS BEEN DEPRECATED. SEE GITHUB ISSUE FOR DETAILS:
2023-02-13 06:06:49.307 NOTICE --- https://github.com/actions/actions-runner-controller/issues/2056
√ Connected to GitHub
Current runner version: '2.301.1'
2023-02-13 06:06:52Z: Listening for Jobs
2023-02-13 06:07:22Z: Running job: preview
2023-02-13 06:07:34Z: Job preview completed with result: Succeeded
√ Removed .credentials
Does not exist. Skipping Removing .runner
Runner listener exit with 0 return code, stop the service, no retry needed.
Exiting runner...
2023-02-13 06:07:35.818 NOTICE --- Runner init exited. Exiting this process with code 0 so that the container and the pod is GC'ed Kubernetes soon.
k logs -f xxxxxx -c dockertime="2023-02-13T06:06:46.144961961Z" level=info msg="[core] [Channel #4] Channel switches to new LB policy \"pick_first\"" module=grpc
time="2023-02-13T06:06:46.145019956Z" level=info msg="[core] [Channel #4 SubChannel #5] Subchannel created" module=grpc
time="2023-02-13T06:06:46.145056389Z" level=info msg="[core] [Channel #4 SubChannel #5] Subchannel Connectivity change to CONNECTING" module=grpc
time="2023-02-13T06:06:46.145159337Z" level=info msg="[core] [Channel #4 SubChannel #5] Subchannel picks a new address \"/var/run/docker/containerd/containerd.sock\" to connect" module=grpc
time="2023-02-13T06:06:46.145464937Z" level=info msg="[core] [Channel #4] Channel Connectivity change to CONNECTING" module=grpc
time="2023-02-13T06:06:46.145548880Z" level=info msg="[core] [Channel #4 SubChannel #5] Subchannel Connectivity change to READY" module=grpc
time="2023-02-13T06:06:46.145713463Z" level=info msg="[core] [Channel #4] Channel Connectivity change to READY" module=grpc
time="2023-02-13T06:06:46.147228733Z" level=info msg="[core] [Channel #7] Channel created" module=grpc
time="2023-02-13T06:06:46.147381111Z" level=info msg="[core] [Channel #7] original dial target is: \"unix:///var/run/docker/containerd/containerd.sock\"" module=grpc
time="2023-02-13T06:06:46.147519765Z" level=info msg="[core] [Channel #7] parsed dial target is: {Scheme:unix Authority: Endpoint:var/run/docker/containerd/containerd.sock URL:{Scheme:unix Opaque: User: Host: Path:/var/run/docker/containerd/containerd.sock RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}" module=grpc
time="2023-02-13T06:06:46.147559630Z" level=info msg="[core] [Channel #7] Channel authority set to \"localhost\"" module=grpc
time="2023-02-13T06:06:46.147609375Z" level=info msg="[core] [Channel #7] Resolver state updated: {\n \"Addresses\": [\n {\n \"Addr\": \"/var/run/docker/containerd/containerd.sock\",\n \"ServerName\": \"\",\n \"Attributes\": {},\n \"BalancerAttributes\": null,\n \"Type\": 0,\n \"Metadata\": null\n }\n ],\n \"ServiceConfig\": null,\n \"Attributes\": null\n} (resolver returned new addresses)" module=grpc
time="2023-02-13T06:06:46.147724629Z" level=info msg="[core] [Channel #7] Channel switches to new LB policy \"pick_first\"" module=grpc
time="2023-02-13T06:06:46.147772673Z" level=info msg="[core] [Channel #7 SubChannel #8] Subchannel created" module=grpc
time="2023-02-13T06:06:46.147955997Z" level=info msg="[core] [Channel #7 SubChannel #8] Subchannel Connectivity change to CONNECTING" module=grpc
time="2023-02-13T06:06:46.148195188Z" level=info msg="[core] [Channel #7 SubChannel #8] Subchannel picks a new address \"/var/run/docker/containerd/containerd.sock\" to connect" module=grpc
time="2023-02-13T06:06:46.148546236Z" level=info msg="[core] [Channel #7] Channel Connectivity change to CONNECTING" module=grpc
time="2023-02-13T06:06:46.148761854Z" level=info msg="[core] [Channel #7 SubChannel #8] Subchannel Connectivity change to READY" module=grpc
time="2023-02-13T06:06:46.148830249Z" level=info msg="[core] [Channel #7] Channel Connectivity change to READY" module=grpc
time="2023-02-13T06:06:49.090273681Z" level=info msg="Loading containers: start."
time="2023-02-13T06:06:49.156210525Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
time="2023-02-13T06:06:49.195090470Z" level=info msg="Loading containers: done."
time="2023-02-13T06:06:49.204421258Z" level=info msg="Docker daemon" commit=d7573ab graphdriver=overlay2 version=23.0.0
time="2023-02-13T06:06:49.204556037Z" level=info msg="Daemon has completed initialization"
time="2023-02-13T06:06:49.244085304Z" level=info msg="[core] [Server #10] Server created" module=grpc
time="2023-02-13T06:06:49.250054597Z" level=info msg="API listen on [::]:2376"
2023/02/13 06:06:49 http: TLS handshake error from 127.0.0.1:51708: EOF
time="2023-02-13T06:06:49.284558088Z" level=info msg="API listen on /var/run/docker.sock"
Prestop hook started
Waiting for dockerd to start
1
Prestop hook stopped
time="2023-02-13T06:07:37.836693870Z" level=info msg="Processing signal 'terminated'"
time="2023-02-13T06:07:37.837730502Z" level=info msg="[core] [Channel #4] Channel Connectivity change to SHUTDOWN" module=grpc
time="2023-02-13T06:07:37.837793352Z" level=info msg="[core] [Channel #4 SubChannel #5] Subchannel Connectivity change to SHUTDOWN" module=grpc
time="2023-02-13T06:07:37.837816003Z" level=info msg="[core] [Channel #4 SubChannel #5] Subchannel deleted" module=grpc
time="2023-02-13T06:07:37.837825169Z" level=info msg="[core] [Channel #4] Channel deleted" module=grpc
time="2023-02-13T06:07:37.837917878Z" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
time="2023-02-13T06:07:37.838376482Z" level=info msg="Daemon shutdown complete"
역시나 둘 다 WARN 레벨 이상의 로그는 보이지 않는다.
나는 그렇게 갈 길을 잃었고, 포기하려고 했다.
분명 RUNNER_TOKEN 은 파드 내에서 Set 되어있고, 관련 내용도 찾을 수 없으니 더 이상 실마리를 찾기가 어려웠다.
그러던 중 혹시나 해서 runner container 에 접속해서 무슨 프로세스나 띄어져 있는지 보려고 했다.
k exec -it xxxxxx -c runner -- bash
ps aux
#USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
#runner 1 0.0 0.0 4112 3060 ? Ss 03:51 0:00 /bin/bash /usr/bin/entrypoint.sh
#runner 7 0.0 0.0 220 4 ? S 03:51 0:00 dumb-init bash
#runner 9 0.0 0.0 3980 2872 ? Ss 03:51 0:00 bash
#runner 11 0.0 0.0 3980 2944 ? S 03:51 0:00 /bin/bash ./run.sh
#runner 103 0.0 0.0 3980 3024 ? S 03:51 0:00 /bin/bash /runner/run-helper.sh
#runner 107 0.4 2.1 3458056 88332 ? Sl 03:51 0:02 /runner/bin/Runner.Listener run
#runner 151 0.0 0.0 4244 3420 pts/0 Ss 03:59 0:00 bash
#runner 158 0.0 0.0 5896 2784 pts/0 R+ 03:59 0:00 ps aux
출력값을 보고 갑자기 문뜩 떠올랐다 !!
custom action 에서 sh 을 실행시켜주는 sh 파일 이름은 entrypoint.sh 이다. 그리고 PATH 에 경로를 등록해서 사용한다.
그런데!! runner container 의 PID 1 도 entrypoint.sh 다.
아하! 원인을 찾은거 같다!
그래도 뭐하는 녀석인지 궁금해서 바로 코드를 까봤다.
#!/bin/bash
source logger.sh
source graceful-stop.sh
trap graceful_stop TERM
dumb-init bash <<'SCRIPT' &
source logger.sh
startup.sh
SCRIPT
RUNNER_INIT_PID=$!
log.notice "Runner init started with pid $RUNNER_INIT_PID"
wait $RUNNER_INIT_PID
log.notice "Runner init exited. Exiting this process with code 0 so that the container and the pod is GC'ed Kubernetes soon."
if [ -f /runner/.runner ]; then
# If the runner failed with the following error:
# √ Connected to GitHub
# Failed to create a session. The runner registration has been deleted from the server, please re-configure.
# Runner listener exit with terminated error, stop the service, no retry needed.
# Exiting runner...
# It might have failed to delete the .runner file.
# We use the existence of the .runner file as the indicator that the runner agent has not stopped yet.
# Remove it by ourselves now, so that the dockerd sidecar prestop won't hang waiting for the .runner file to appear.
echo "Removing the .runner file"
rm -f /runner/.runner
fi
trap - TERM
코드는 이게 다인데 아마 중간에 있는 startup.sh 가 핵심 파일인 거 같다. 바로 까보자!
...
if [ -z "${RUNNER_TOKEN}" ]; then
log.error 'RUNNER_TOKEN must be set'
exit 1
fi
...
찾았다.. 관련 에러 메시지..!!
내가 작성한 custom action 의 entrypoint.sh 와 runner 를 실행시켜주는 entrypoint.sh 둘 다 PATH 에 등록되어 있고, runner 의 entrypoint.sh 가 앞서 등록되었기 때문에 custom action 의 entrypoint.sh 은 계속 무시되었던 것이였다.
runner 의 entrypoint.sh 만 2번 실행되었던 것이다.
따라서 custom action 의 entrypoint.sh 이름을 변경하거나 절대 경로를 이용해서 entrypoint.sh 를 실행시켜주면 이 문제는 깔끔히 해결된다.
마무리
entrypoint.sh 의 이름이 중복되서 발생한 문제였다. 해결 방법은 매우 간단했으나, 이를 찾기까지가 정말 정말 정말 힘들었던 이번 에러였다.
ps aux 를 해보지 않았다면 아마 지금도 해결하지 못했을 것이다.
아무튼 이번 에러도 무사히 해결했다 👍
반응형
'트러블 빵야' 카테고리의 다른 글
| [Kubernetes] 친한 듯, 안 친한 Pod 와 Goofys (2) | 2023.02.12 |
|---|---|
| [Kubernetes] aws_auth 를 찾을 수 없습니다.. (0) | 2022.12.23 |
