Controller not back filling even though number of pods is less than minimum.

[jgreat]

Our runs get stuck sometime because the controller isn't back filling pods after completion. I'm sure I have some settings wrong, but can't figure out why the controller delays reconciliation and refills the pods. Any insights would be amazing.

• controller version: 0.23.0
• helm chart: 0.18.0

Helm values.yaml

githubWebhookServer:
  enabled: true
  imagePullSecrets:
  - name: docker-credentials
  ingress:
    annotations:
      cert-manager.io/cluster-issuer: letsencrypt-production-http
      haproxy.org/server-ssl: "false"
    enabled: true
    hosts:
    - host: ****
      paths:
      - path: /
        pathType: Prefix
    tls:
    - hosts:
      - ***
      secretName: ***-tls
  secret:
    enabled: true
imagePullSecrets:
- name: docker-credentials
metrics:
  serviceMonitor: true
scope:
  singleNamespace: true
  watchNamespace: actions-runner-***
syncPeriod: 1m

manifests for "small" runners

apiVersion: actions.summerwind.dev/v1alpha1
kind: RunnerDeployment
metadata:
  name: gha-runner-org-small
spec:
  template:
    spec:
      # RunnerConfig
      organization: {{ .Values.organization }}
      labels:
      - small
      - self-hosted
      - Linux
      - X64
      dockerdWithinRunnerContainer: true
      dockerMTU: 1350
      ephemeral: true
      # customized dind to support mtu
      image: ***/github-actions-runner-dind:latest

      # RunnerPodSpec
      env:
      - name: DISABLE_RUNNER_UPDATE
        value: "true"
      imagePullSecrets:
      - name: docker-credentials
      resources:
        limits:
          cpu: '2'
          memory: 4Gi
        requests:
          cpu: '2'
          memory: 4Gi
      tolerations:
      - effect: NoSchedule
        key: builder
        operator: Exists
      nodeSelector:
        builder-node: 'true'
---
apiVersion: actions.summerwind.dev/v1alpha1
kind: HorizontalRunnerAutoscaler
metadata:
  name: gha-runner-org-small
spec:
  scaleTargetRef:
    name: gha-runner-org-small
  minReplicas: 5
  maxReplicas: 30
  scaleDownDelaySecondsAfterScaleUp: 30
  scaleUpTriggers:
  - githubEvent:
      workflowJob: {}
    amount: 1
    duration: 1m

Controller logs:

--- Restarted controller after 15 min of no jobs being backfilled ---

I0520 16:53:48.462109       1 request.go:665] Waited for 1.041287959s due to client-side throttling, not priority and fairness, request: GET:https://10.43.0.1:443/apis/apiextensions.k8s.io/v1beta1?timeout=32s
2022-05-20T16:53:48Z	INFO	controller-runtime.metrics	Metrics server is starting to listen	{"addr": "127.0.0.1:8080"}
2022-05-20T16:53:48Z	INFO	actions-runner-controller	Initializing actions-runner-controller	{"github-api-cache-duration": "50s", "default-scale-down-delay": "10m0s", "sync-period": "1m0s", "runner-image": "summerwind/actions-runner:latest", "docker-image": "docker:dind", "common-runnner-labels": null, "watch-namespace": "actions-runner-***"}
2022-05-20T16:53:48Z	INFO	controller-runtime.builder	Registering a mutating webhook	{"GVK": "actions.summerwind.dev/v1alpha1, Kind=Runner", "path": "/mutate-actions-summerwind-dev-v1alpha1-runner"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/mutate-actions-summerwind-dev-v1alpha1-runner"}
2022-05-20T16:53:48Z	INFO	controller-runtime.builder	Registering a validating webhook	{"GVK": "actions.summerwind.dev/v1alpha1, Kind=Runner", "path": "/validate-actions-summerwind-dev-v1alpha1-runner"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/validate-actions-summerwind-dev-v1alpha1-runner"}
2022-05-20T16:53:48Z	INFO	controller-runtime.builder	Registering a mutating webhook	{"GVK": "actions.summerwind.dev/v1alpha1, Kind=RunnerDeployment", "path": "/mutate-actions-summerwind-dev-v1alpha1-runnerdeployment"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/mutate-actions-summerwind-dev-v1alpha1-runnerdeployment"}
2022-05-20T16:53:48Z	INFO	controller-runtime.builder	Registering a validating webhook	{"GVK": "actions.summerwind.dev/v1alpha1, Kind=RunnerDeployment", "path": "/validate-actions-summerwind-dev-v1alpha1-runnerdeployment"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/validate-actions-summerwind-dev-v1alpha1-runnerdeployment"}
2022-05-20T16:53:48Z	INFO	controller-runtime.builder	Registering a mutating webhook	{"GVK": "actions.summerwind.dev/v1alpha1, Kind=RunnerReplicaSet", "path": "/mutate-actions-summerwind-dev-v1alpha1-runnerreplicaset"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/mutate-actions-summerwind-dev-v1alpha1-runnerreplicaset"}
2022-05-20T16:53:48Z	INFO	controller-runtime.builder	Registering a validating webhook	{"GVK": "actions.summerwind.dev/v1alpha1, Kind=RunnerReplicaSet", "path": "/validate-actions-summerwind-dev-v1alpha1-runnerreplicaset"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/validate-actions-summerwind-dev-v1alpha1-runnerreplicaset"}
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Registering webhook	{"path": "/mutate-runner-set-pod"}
2022-05-20T16:53:48Z	INFO	actions-runner-controller	starting manager
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook.webhooks	Starting webhook server
2022-05-20T16:53:48Z	INFO	Starting server	{"path": "/metrics", "kind": "metrics", "addr": "127.0.0.1:8080"}
2022-05-20T16:53:48Z	INFO	controller-runtime.certwatcher	Updated current TLS certificate
2022-05-20T16:53:48Z	INFO	controller-runtime.webhook	Serving webhook server	{"host": "", "port": 9443}
2022-05-20T16:53:48Z	INFO	controller-runtime.certwatcher	Starting certificate watcher
I0520 16:53:48.970388       1 leaderelection.go:248] attempting to acquire leader lease actions-runner-***/actions-runner-controller...
I0520 16:54:06.549777       1 leaderelection.go:258] successfully acquired lease actions-runner-***/actions-runner-controller
2022-05-20T16:54:06Z	DEBUG	events	Normal	{"object": {"kind":"ConfigMap","namespace":"actions-runner-***","name":"actions-runner-controller","uid":"84322ee1-39dd-48c7-ad3f-6ca612429745","apiVersion":"v1","resourceVersion":"330874948"}, "reason": "LeaderElection", "message": "mcf-actions-runner-controller-8dd59cfbd-zncqv_db75a4a4-2827-4799-b902-a895a0e61e71 became leader"}
2022-05-20T16:54:06Z	DEBUG	events	Normal	{"object": {"kind":"Lease","namespace":"actions-runner-***","name":"actions-runner-controller","uid":"5842dcb6-6389-4ac5-98ef-9f56a9b268e4","apiVersion":"coordination.k8s.io/v1","resourceVersion":"330874949"}, "reason": "LeaderElection", "message": "mcf-actions-runner-controller-8dd59cfbd-zncqv_db75a4a4-2827-4799-b902-a895a0e61e71 became leader"}
2022-05-20T16:54:06Z	INFO	controller.runner-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "Runner", "source": "kind source: *v1alpha1.Runner"}
2022-05-20T16:54:06Z	INFO	controller.runnerdeployment-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerDeployment", "source": "kind source: *v1alpha1.RunnerDeployment"}
2022-05-20T16:54:06Z	INFO	controller.runner-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "Runner", "source": "kind source: *v1.Pod"}
2022-05-20T16:54:06Z	INFO	controller.runner-controller	Starting Controller	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "Runner"}
2022-05-20T16:54:06Z	INFO	controller.runnerdeployment-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerDeployment", "source": "kind source: *v1alpha1.RunnerReplicaSet"}
2022-05-20T16:54:06Z	INFO	controller.runnerdeployment-controller	Starting Controller	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerDeployment"}
2022-05-20T16:54:06Z	INFO	controller.horizontalrunnerautoscaler-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "HorizontalRunnerAutoscaler", "source": "kind source: *v1alpha1.HorizontalRunnerAutoscaler"}
2022-05-20T16:54:06Z	INFO	controller.horizontalrunnerautoscaler-controller	Starting Controller	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "HorizontalRunnerAutoscaler"}
2022-05-20T16:54:06Z	INFO	controller.runnerreplicaset-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerReplicaSet", "source": "kind source: *v1alpha1.RunnerReplicaSet"}
2022-05-20T16:54:06Z	INFO	controller.runnerpod-controller	Starting EventSource	{"reconciler group": "", "reconciler kind": "Pod", "source": "kind source: *v1.Pod"}
2022-05-20T16:54:06Z	INFO	controller.runnerreplicaset-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerReplicaSet", "source": "kind source: *v1alpha1.Runner"}
2022-05-20T16:54:06Z	INFO	controller.runnerreplicaset-controller	Starting Controller	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerReplicaSet"}
2022-05-20T16:54:06Z	INFO	controller.runnerpod-controller	Starting Controller	{"reconciler group": "", "reconciler kind": "Pod"}
2022-05-20T16:54:06Z	INFO	controller.runnerset-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerSet", "source": "kind source: *v1alpha1.RunnerSet"}
2022-05-20T16:54:06Z	INFO	controller.runnerset-controller	Starting EventSource	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerSet", "source": "kind source: *v1.StatefulSet"}
2022-05-20T16:54:06Z	INFO	controller.runnerset-controller	Starting Controller	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerSet"}
2022-05-20T16:54:06Z	INFO	controller.runnerpod-controller	Starting workers	{"reconciler group": "", "reconciler kind": "Pod", "worker count": 1}
2022-05-20T16:54:06Z	INFO	controller.runnerset-controller	Starting workers	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerSet", "worker count": 1}
2022-05-20T16:54:06Z	INFO	controller.runnerdeployment-controller	Starting workers	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerDeployment", "worker count": 1}
2022-05-20T16:54:06Z	INFO	controller.runnerreplicaset-controller	Starting workers	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "RunnerReplicaSet", "worker count": 1}
2022-05-20T16:54:06Z	INFO	controller.horizontalrunnerautoscaler-controller	Starting workers	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "HorizontalRunnerAutoscaler", "worker count": 1}
2022-05-20T16:54:06Z	INFO	actions-runner-controller.runnerpod	Runner pod is annotated to wait for completion	{"runnerpod": "actions-runner-***/gha-runner-org-small-6b28s-bbq9p"}
2022-05-20T16:54:06Z	INFO	controller.runner-controller	Starting workers	{"reconciler group": "actions.summerwind.dev", "reconciler kind": "Runner", "worker count": 1}
2022-05-20T16:54:06Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-large", "suggested": 5, "reserved": 0, "min": 5, "max": 15}
2022-05-20T16:54:06Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-small", "suggested": 5, "reserved": 0, "min": 5, "max": 30}
2022-05-20T16:55:06Z	INFO	actions-runner-controller.runnerpod	Runner pod is annotated to wait for completion	{"runnerpod": "actions-runner-***/gha-runner-org-small-6b28s-bbq9p"}
2022-05-20T16:55:55Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-large", "suggested": 5, "reserved": 0, "min": 5, "max": 15}
2022-05-20T16:55:55Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-small", "suggested": 5, "reserved": 0, "min": 5, "max": 30}
2022-05-20T16:56:03Z	INFO	actions-runner-controller.runnerpod	Runner pod is annotated to wait for completion	{"runnerpod": "actions-runner-***/gha-runner-org-small-6b28s-bbq9p"}
2022-05-20T16:56:06Z	INFO	actions-runner-controller.runnerpod	Runner pod is annotated to wait for completion	{"runnerpod": "actions-runner-***/gha-runner-org-small-6b28s-bbq9p"}
2022-05-20T16:56:49Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-large", "suggested": 5, "reserved": 0, "min": 5, "max": 15}
2022-05-20T16:56:49Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-small", "suggested": 5, "reserved": 0, "min": 5, "max": 30}
2022-05-20T16:57:02Z	INFO	actions-runner-controller.runnerpod	Runner pod is annotated to wait for completion	{"runnerpod": "actions-runner-***/gha-runner-org-small-6b28s-bbq9p"}
2022-05-20T16:57:06Z	INFO	actions-runner-controller.runnerpod	Runner pod is annotated to wait for completion	{"runnerpod": "actions-runner-***/gha-runner-org-small-6b28s-bbq9p"}
2022-05-20T16:57:44Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-large", "suggested": 5, "reserved": 0, "min": 5, "max": 15}
2022-05-20T16:57:44Z	DEBUG	actions-runner-controller.horizontalrunnerautoscaler	Calculated desired replicas of 5	{"horizontalrunnerautoscaler": "actions-runner-***/gha-runner-org-small", "suggested": 5, "reserved": 0, "min": 5, "max": 30}

--- Canceled active jobs and controller finally scaled---

2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Created replica(s)	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "lastSyncTime": "2022-05-20T16:47:42Z", "effectiveTime": "2022-05-20 16:45:25 +0000 UTC", "templateHashDesired": "5465475796", "replicasDesired": 5, "replicasPending": 0, "replicasRunning": 2, "replicasMaybeRunning": 2, "templateHashObserved": ["5465475796"], "created": 3}
2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Skipped reconcilation because owner is not synced yet	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "owner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "pods": null}
2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Skipped reconcilation because owner is not synced yet	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "owner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "pods": null}
2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Skipped reconcilation because owner is not synced yet	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "owner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "pods": null}
2022-05-20T16:57:51Z	INFO	actions-runner-controller.runner	Updated registration token	{"runner": "gha-runner-org-small-6b28s-dzlbp", "repository": ""}
2022-05-20T16:57:51Z	DEBUG	events	Normal	{"object": {"kind":"Runner","namespace":"actions-runner-***","name":"gha-runner-org-small-6b28s-dzlbp","uid":"0d1110f4-d1e8-47b2-9dfd-b7876e3b6336","apiVersion":"actions.summerwind.dev/v1alpha1","resourceVersion":"330878172"}, "reason": "RegistrationTokenUpdated", "message": "Successfully update registration token"}
2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Skipped reconcilation because owner is not synced yet	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "owner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "pods": null}
2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Skipped reconcilation because owner is not synced yet	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "owner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "pods": null}
2022-05-20T16:57:51Z	INFO	actions-runner-controller.runner	Updated registration token	{"runner": "gha-runner-org-small-6b28s-ncxd2", "repository": ""}
2022-05-20T16:57:51Z	DEBUG	events	Normal	{"object": {"kind":"Runner","namespace":"actions-runner-***","name":"gha-runner-org-small-6b28s-ncxd2","uid":"e6f02042-8293-4864-8712-b7f65c2f4a6c","apiVersion":"actions.summerwind.dev/v1alpha1","resourceVersion":"330878177"}, "reason": "RegistrationTokenUpdated", "message": "Successfully update registration token"}
2022-05-20T16:57:51Z	DEBUG	actions-runner-controller.runnerreplicaset	Skipped reconcilation because owner is not synced yet	{"runnerreplicaset": "actions-runner-***/gha-runner-org-small-6b28s", "owner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "pods": null}
2022-05-20T16:57:52Z	INFO	actions-runner-controller.runner	Created runner pod	{"runner": "actions-runner-***/gha-runner-org-small-6b28s-dzlbp", "repository": ""}
2022-05-20T16:57:52Z	DEBUG	events	Normal	{"object": {"kind":"Runner","namespace":"actions-runner-***","name":"gha-runner-org-small-6b28s-dzlbp","uid":"0d1110f4-d1e8-47b2-9dfd-b7876e3b6336","apiVersion":"actions.summerwind.dev/v1alpha1","resourceVersion":"330878189"}, "reason": "PodCreated", "message": "Created pod 'gha-runner-org-small-6b28s-dzlbp'"}
2022-05-20T16:57:52Z	INFO	actions-runner-controller.runner	Updated registration token	{"runner": "gha-runner-org-small-6b28s-dxgf2", "repository": ""}
2022-05-20T16:57:52Z	DEBUG	events	Normal	{"object": {"kind":"Runner","namespace":"actions-runner-***","name":"gha-runner-org-small-6b28s-dxgf2","uid":"d7251a4d-95a5-4e8c-a44c-5afee77a6799","apiVersion":"actions.summerwind.dev/v1alpha1","resourceVersion":"330878191"}, "reason": "RegistrationTokenUpdated", "message": "Successfully update registration token"}

[mumoshu]

@jgreat duration: 1m in your scale trigger setting seems very low. It's the duration that ARC expires the added replica (hence the corresponding runner pod gets deleted), which is intended to be used to not leave dangling runner forever when ARC was unable to receive a webhook event for job completion for whatever reason.

Note that the duration starts when ARC added the replica, not when the runner started running a workflow job.

Are you sure your cluster is responsive enough so that it can create a runner pod and it finishes running the job within 1m after github-webhook-based autoscaler of ARC received the webhook event for a queued job, and that works universally even when you triggered several workflow jobs concurrently? (I think it's not.

[jgreat]

I guess that's where I'm confused on setup. Here's a rundown of what I would like to achieve.

• So we would like the minimum amount of runners to stay around forever and wait for job to come in.
• Runners are set to terminate after a job in complete.
• The webhook should be used to scale up runners on demand. New job comes in, new runner comes online.
• Jobs can take 30 second or an hour to complete.

Where a runner is scheduled it pretty easily comes up with 10 or 15 seconds.

So ARC would kill a pods after duration unless its gets an active job? This doesn't seem to be the case when things are idle, nor would I expect that to be true with the Minimum number of runners.

Shouldn't ARC should try and schedule pods on each reconciliation loop if the runners are below the minimum threshold?

[jault3]

I believe I'm seeing similar behavior to @jgreat where the controller isn't back filling pods after completion. I am not using autoscaling at all in my set up, but I configured it to run 18 replicas at all times. I've started to notice that the controller will spin up 18 pods, all 18 runners will execute a job, then quit (so far so good). However, no new runners will be created until the last one finishes. When I look at the runnerdeployment, I see something like this:

$ kubectl get runnerdeployment
NAME                       DESIRED   CURRENT   UP-TO-DATE   AVAILABLE   AGE
my-runner-deployment   18        3         3            3           44m

So it appears that all future github actions workflows are stuck waiting for these last 3 to finish before ARC creates 18 new ones. Is this intended behavior? If so, could it be changed? Or maybe there's something wrong with how I have things configured? Thanks in advance!

apiVersion: actions.summerwind.dev/v1alpha1
kind: RunnerDeployment
metadata:
  name: my-runner-deployment
spec:
  replicas: 18
  template:
    spec:
      organization: MyOrg
      image: summerwind/actions-runner-dind:latest
      imagePullPolicy: Always
      labels:
      - linux
      - X64
      dockerdWithinRunnerContainer: true
      resources:
        limits:
          cpu: "4"
          memory: 16Gi
        requests:
          cpu: "4"
          memory: 16Gi

[joshgriffith1124]

I'm experiencing the same behavior as @jgreat and @jault3. The runnerdeployment will have X number of desired but current will be well below that for a random period of time. At some point(usually 10-15 minutes) the controller creates all the missing runners.