RUNNER_TOKEN must be set

kingbj940429 commented 1 year ago

Checks

[X] I've already read https://github.com/actions/actions-runner-controller/blob/master/TROUBLESHOOTING.md and I'm sure my issue is not covered in the troubleshooting guide.
[X] I'm not using a custom entrypoint in my runner image

Controller Version

0.27.0

Helm Chart Version

0.27.0

CertManager Version

1.10

Deployment Method

Helm

cert-manager installation

yes
yes

Checks

[X] This isn't a question or user support case (For Q&A and community support, go to Discussions. It might also be a good idea to contract with any of contributors and maintainers if your business is so critical and therefore you need priority support
[X] I've read releasenotes before submitting this issue and I'm sure it's not due to any recently-introduced backward-incompatible changes
[X] My actions-runner-controller version (v0.x.y) does support the feature
[X] I've already upgraded ARC (including the CRDs, see charts/actions-runner-controller/docs/UPGRADING.md for details) to the latest and it didn't fix the issue
[X] I've migrated to the workflow job webhook event (if you using webhook driven scaling)

Resource Definitions

apiVersion: actions.summerwind.dev/v1alpha1
kind: RunnerDeployment
metadata:
  name: self-hosted-runner
  namespace: actions-runner-system
spec:
  replicas: 1
  template:
    spec:
      serviceAccountName: xxx
      organization: xxxx
      ephemeral: true
      dockerEnabled: true
      dockerRegistryMirror: xxxx
      workDir: /runner/_work
      labels:
        - al2_x86_64
        - platform
      resources:
        requests:
          cpu: "1"
          memory: "3Gi"
      nodeSelector:
        Purpose: self-hosted-runner
        Architecture: al2_x86_64
      tolerations:
        - key: "self-hosted-runner"
          value: "true"
          operator: "Equal"
          effect: "NoExecute"

To Reproduce

1. create custom action
2. run custom action in action repo (ex. custom-action@v1.0.0)
3. I can see "RUNNER_TOKEN must be set"

Describe the bug

when I use arc, I can see under log.

2023-02-13 05:15:32.972  NOTICE --- Runner init started with pid 282
2023-02-13 05:15:32.977  DEBUG --- Github endpoint URL https://github.com/
2023-02-13 05:15:32.979  ERROR --- RUNNER_TOKEN must be set
2023-02-13 05:15:32.981  NOTICE --- Runner init exited. Exiting this process with code 0 so that the container and the pod is GC'ed Kubernetes soon.
Removing the .runner file

so I tried this way to solve issue-1305 but It didn't work..

      - name: preview-front
        uses: ./.github/actions/custom-action
        with:
          git-token: ${{ secrets.GIT_TOKEN }}

this action works.

but under action didn't work. show "RUNNER_TOKEN must be set"

      - name: preview-front
        uses: kingbj940429/custom-action@v1.0.0
        with:
          git-token: ${{ secrets.GIT_TOKEN }}

please help me..

Describe the expected behavior

I wan't see RUNNER_TOKEN must be set

Whole Controller Logs

2023-02-13T06:07:36Z    DEBUG   runnerreplicaset    Created replica(s)  {"runnerreplicaset": "actions-runner-system/csg-sd-gitops-self-hosted-runner-q546f", "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/csg-sd-gitops-self-hosted-runner-q546f", "owner": "actions-runner-system/csg-sd-gitops-self-hosted-runner-q546f-rgpfq", "pods": null}
2023-02-13T06:07:36Z    INFO    runner  Removed finalizer   {"runner": "actions-runner-system/csg-sd-gitops-self-hosted-runner-q546f-rbd2t"}
2023-02-13T06:07:36Z    DEBUG   runnerreplicaset    Skipped reconcilation because owner is not synced yet   {"runnerreplicaset": "actions-runner-system/csg-sd-gitops-self-hosted-runner-q546f", "owner": "actions-runner-system/csg-sd-gitops-self-hosted-runner-q546f-rgpfq", "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": "csg-sd-gitops-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/csg-sd-gitops-self-hosted-runner-q546f", "owner": "actions-runner-system/csg-sd-gitops-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/csg-sd-gitops-self-hosted-runner-q546f", "owner": "actions-runner-system/csg-sd-gitops-self-hosted-runner-q546f-rgpfq", "pods": null}
2023-02-13T06:07:36Z    INFO    runner  Updated registration token  {"runner": "csg-sd-gitops-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":"csg-sd-gitops-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/csg-sd-gitops-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/csg-sd-gitops-self-hosted-runner-q546f-rgpfq", "repository": ""}
2023-02-13T06:07:36Z    DEBUG   events  Created pod 'csg-sd-gitops-self-hosted-runner-q546f-rgpfq'  {"type": "Normal", "object": {"kind":"Runner","namespace":"actions-runner-system","name":"csg-sd-gitops-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/csg-sd-gitops-self-hosted-runner-q546f-rgpfq", "podCreationTimestamp": "2023-02-13 06:07:36 +0000 UTC"}

Whole Runner Pod Logs

docker container

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"

<br>

runner container
```text
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.



### Additional Context

_No response_

github-actions[bot] commented 1 year ago

Hello! Thank you for filing an issue.

The maintainers will triage your issue shortly.

In the meantime, please take a look at the troubleshooting guide for bug reports.

If this is a feature request, please review our contribution guidelines.

kingbj940429 commented 1 year ago

I solved

Btijmen commented 1 year ago

@kingbj940429 how did you solve it? Other people (like me) might be able to benefit from your solution

kingbj940429 commented 1 year ago

@Btijmen on the action controller runner pod, command ps aux. then, you can find /bin/bash /usr/bin/entrypoint.sh command at the first line.

this entrypoint.sh is owned by action runner

Otherwise, In my custom action, I was using same /usr/bin/entrypoint.sh shell script name.

name: 'Hello World'
description: 'Greet someone'
inputs:
  who-to-greet:  # id of input
    description: 'Who to greet'
    required: true
    default: 'World'
outputs:
  random-number:
    description: "Random number"
    value: ${{ steps.random-number-generator.outputs.random-number }}
runs:
  using: "composite"
  steps:
    - run: /usr/bin/entrypoint.sh # this is mean local entrypoint.sh I wrote, not action controller
      shell: bash

both entrypoint.sh in my custom action and in action runner were registered with $PATH.

that means other one is overwritten.

eventually, only runner's entrypoint.sh was run twice.

If you want to find 'RUNNER_TOKEN must be set' log at runner file, run vim /usr/bin/entrypoint.sh you can find startup.sh.

and If run vim startup.sh, you cant find RUNNER_TOKEN must be set

this is a blog post I wrote about the issue, but it's in Korean, so you'll need a translator.

In conclustion, CHANGE custom action entrypoint.sh name

anyway If you didn't set RUNNER_TOKEN, this error occurs as you can see in startup.sh provided by action runner.

I hope it helps.

Btijmen commented 1 year ago

Thanks a lot for the extensive answer!

actions / actions-runner-controller