[Github Action] 타노스는 이런 느낌일까? RUNNER_TOKEN must be set

 

쿠버네티스 환경에선 Action Controller Runner (이하 ARC) 를 이용해서 파드를 Self Hosted Runner 로 사용할 수 있습니다.

Action Controller Runner - Deployment

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 밖에 없다.. 우선 이걸로는 실마리를 찾기가 힘들 거 같아 구글에 관련 에러를 검색했고, 관련 검색 결과가 딱 하나가 나왔다. 부푼 기대감을 안고 클릭했다.

RunnerSet Runners fail to start with "RUNNER_NAME must be set" after upgrade to 0.22.1 #1305

 

정확히 일치하지는 않으나 핵심 에러인 RUNNER 환경 변수가 Set 되지 않았다는 맥락은 비슷해서 쭉 읽어보았다. (Issued)

 

 

ARC 를 Helm 이용해서 배포할 때 위와 같은 옵션을 주라고 한다. 될 것 같다라는 느낌은 전혀 받지 않았지만.. 선택권이 없었기에 한번 시도해봤다.

 

정말 특이하게 트러블 슈팅 하면서 "안될거 같은데.." 같은 느낌을 받으면 정말 100% 안된다.. 이번에도 마찬가지다. 안된다 🤦

 

혹시나 해서 ARC TroubleShooting 문서도 쭉 살펴봤다.

actions-runner-controller/TROUBLESHOOTING.md

 

관련된 이슈는 없다... 옆으로 보고, 위로 보고, 아래로 봐도 없다..

 

그럼 한번 ARC 관련 로그를 찍어볼까?

 

먼저 Action Controller 부터 확인해보자

k logs action-controller

2023-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 runner

2023-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 docker

time="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 를 해보지 않았다면 아마 지금도 해결하지 못했을 것이다.

 

아무튼 이번 에러도 무사히 해결했다 👍