Random `Operation Cancelled` Runner Decommissions

[jbkc85]

Describe the bug

In the current deployment of actions-runner-controller, whenever a GitHub runner has an action cancelled (via GitHub UI) or has an action that fails (like a unit test), it seems to cause a cascading effect that triggers other random cancellations of actions running on other runners in the system. Furthermore, there is a high chance that at the end of a GitHub workflow that one of the last remaining runners (IE: a runner that survives until a scale down is triggered via reconciling) is cancelled while 'busy' with a Workflow Job/Step.

Checks

• we are not using ephemeral runners at this time - though ephemeral runners appear to have the same issue
• we are on vsummerwind/actions-runner-controller:v0.20.1 and use the the provided GitHub-runner with our own custom OpenJDK installation
• controller is installed via Helm:

syncPeriod: 5m
githubAPICacheDuration: 5m
nodeSelector:
  environment: ops
  purpose: infrastructure

• AWS EKS w/ Cluster Autoscaling and Spot Instances (confirmed spot instances aren't causing a shutdown issue)

To Reproduce
Steps to reproduce the behavior (though is more random than not):

1. Setup GitHub-action-controller with the above Helm deployment and the following spec:

apiVersion: actions.summerwind.dev/v1alpha1
kind: RunnerDeployment
metadata:
  namespace: default
  name: org-runners
spec:
  template:
    metadata:
      annotations:
        cluster-autoscaler.kubernetes.io/safe-to-evict: "true"
    spec:
      dockerdWithinRunnerContainer: true
      organization: <Github Org>
      nodeSelector:
        capacity-type: SPOT
        purpose: github-runners
        environment: ops
      labels:
        - java
        - linux
        - eks
        - self-hosted
      image: <GitHub-runner image here>
      resources:
        requests:
          cpu: "1.0"
          memory: "10Gi"
---
apiVersion: actions.summerwind.dev/v1alpha1
kind: HorizontalRunnerAutoscaler
metadata:
  namespace: default
  name: runners-autoscaler
spec:
  scaleTargetRef:
    name: org-runners
  scaleDownDelaySecondsAfterScaleOut: 3600
  minReplicas: 1
  maxReplicas: 150
  metrics:
  - type: TotalNumberOfQueuedAndInProgressWorkflowRuns
    repositoryNames:
    - <your repository here>

2. Run a large set (32-64 jobs) workflow and cancel one or two of the jobs.

Expected behavior
The expectation is that the jobs continue - regardless of success/failure and the workflow succeeds in finishing the appointed jobs/tasks.

Screenshots
No screenshots, but the lines simply output Error: The Operation was canceled.

Environment (please complete the following information):

• Controller Version: v0.20.1
• Deployment Method: Helm
• Helm Chart Version: v0.13.1

Additional context
The workflow is extremely active and can have anywhere between 32-64 running jobs. Each job takes between 6 and 20 minutes, depending on the test it is deploying. What I have seen is that it appears that the logs for 'unregistered' runners have an impact once those runners are to be reconciled. I see a lot of:

2021-10-26T05:41:39.576Z	DEBUG	actions-runner-controller.runnerreplicaset	Failed to check if runner is busy. Either this runner has never been successfully registered to GitHub or it still needs more time.	{"runnerreplicaset": "default/org-runners-749hr", "runnerName": "org-runners-749hr-gr85x"}
2021-10-26T05:41:40.172Z	INFO	actions-runner-controller.runner	Skipped registration check because it's deferred until 2021-10-26 05:42:30 +0000 UTC. Retrying in 48.827500109s at latest	{"runner": "default/org-runners-749hr-w9ll4", "lastRegistrationCheckTime": "2021-10-26 05:41:30 +0000 UTC", "registrationCheckInterval": "1m0s"}

and based on the behavior, I wonder if what's happening is that the reconciler takes a registration timeout of a previous pod and applies it to these as they are trying to catch up - thus resulting in a runner being marked for deletion even though it is only a minute or two into its registration check interval.

With that being said I was hoping to increase these intervals and have more of a grace period between the controller just shutting things down where it doesn't 'know' if the runner is busy or not, but honestly I can't tell if thats what is happening.

Any insight would be helpful - and let me know if there is anything else I can provide!

[mumoshu]

@jbkc85 Hey! Have you already tried the new ephemeral runners that can be enabled via RUNNER_FEATURE_FLAG_EPHEMERAL as documented in https://github.com/actions-runner-controller/actions-runner-controller#ephemeral-runners?

Also- which flavor of GitHub are you using, GitHub Enterprise Server, or GitHub Cloud?

[jbkc85]

@jbkc85 Hey! Have you already tried the new ephemeral runners that can be enabled via RUNNER_FEATURE_FLAG_EPHEMERAL as documented in https://github.com/actions-runner-controller/actions-runner-controller#ephemeral-runners?

Also- which flavor of GitHub are you using, GitHub Enterprise Server, or GitHub Cloud?

Normal GitHub (thats cloud? Def not enterprise) mixed in with AWS EKS deployed runners.

I have tried ephemeral and to no luck. Generally what happens is that during a scale up event, when the reconciler starts to run through its scaling down, it picks new pods not yet registered (because they haven't had a chance to be registered) and marks them for deletion. I might try Ephemeral again to see what we can do, as maybe we just didn't catch the issue earlier. I will get back to you!

[antodoms]

@jbkc85 We are also experiencing the same issue. have you found a solution to this?

i am currently using stateful RunnerSet and webhook terminates wrong pod during a scale-down web-hook event.

Was this working on versions before 0.20.1 ??

[jbkc85]

@jbkc85 We are also experiencing the same issue. have you found a solution to this?

i am currently using stateful RunnerSet and webhook terminates wrong pod during a scale-down web-hook event.

Was this working on versions before 0.20.1 ??

I am not sure it was ever 'working' depending on your workload. The fact is the reconciler reconciles nodes that have not yet 'registered', and when you are spinning up (and down) a ton of nodes, the registration falls behind due to API limits or otherwise, making some of your runners eventually reconciled prematurely. I am trying to pinpoint the exact cause of this in the code but I haven't had as much luck as I wished.

One way to eliminate SOME of these issues is to set your scaleDownDelaySecondsAfterScaleOut in the HoriziontalRunnerAutoscaler higher (I set mine to 3600), but its a temporary fix. If you are constantly churning through runners, eventually you don't scale out anymore in which case the delay times out (as its not reset per a scale up) and you run into the same issue.

[mumoshu]

@jbkc85 Thanks for the info!
I was reviewing everything you've provided in this issue and I'm not sure what's happening yet.

the reconciler takes a registration timeout of a previous pod and applies it to these as they are trying to catch up - thus resulting in a runner being marked for deletion even though it is only a minute or two into its registration check interval.

I've read code but AFAIK this shouldn't happen as we use runner's CreationTimestamp for registration check timeout and it's reset by deleting/recreating the runner on scale-down/up.

https://github.com/actions-runner-controller/actions-runner-controller/blob/b6c33cee3276da76993c550c68fe6c9278b20464/controllers/runnerreplicaset_controller.go#L227

With that being said I was hoping to increase these intervals and have more of a grace period between the controller just shutting things down where it doesn't 'know' if the runner is busy or not

I think this one is hard-coded today:

https://github.com/actions-runner-controller/actions-runner-controller/blob/b6c33cee3276da76993c550c68fe6c9278b20464/controllers/runnerreplicaset_controller.go#L225

Would you mind changing it and building a custom actions-runner-controller image using our makefile to see making it longer works for you?

the reconciler starts to run through its scaling down, it picks new pods not yet registered (because they haven't had a chance to be registered) and marks them for deletion

I was thinking that we already guard against that case in

https://github.com/actions-runner-controller/actions-runner-controller/blob/b6c33cee3276da76993c550c68fe6c9278b20464/controllers/runnerreplicaset_controller.go#L196-L249

In nutshell we log Failed to check if runner is busy. Either this runner has never been successfully registered to GitHub or it still needs more time and delete the runner only when we are sure that your runner isn't available according to GitHub API. If the runner isn't available, it shouldn't be running any workflow job. It needs to register itself to GitHub before running any workflow job.

I have tried ephemeral and to no luck

What was your runner image tag in image: <GitHub-runner image here> and how your RunnerDeployment looked like when you tried ephemeral runners?

[mumoshu]

@antodoms Hey! Thanks for reporting. I think yours is a completely different issue. Would you mind creating another issue for it, so that we can better differentiate it and avoid other folks bringing similar but different issue reports here which is confusing?

Anyway, I'm doubting if you're being affected by a potential bug in RunnerSet implementation. It's implemented separately from RunnerDeployment. RunnerDeployment has some logic to prevent busy runners from being terminated.

I might have missed implementing simiilar logic for RunnerSet.

[mumoshu]

@antodoms Hey! Have you used RUNNER_FEATURE_FLAG_EPHEMERAL to enable the new runners?

I reviewed both actions-runner-controller and actions/runner's (C#) code and I got to think that the use of ephemeral runners would solve your issue for RunnerSet.

[mumoshu]

@jbkc85 Hey! Which runner image did you use, btw? I still think the use of new ephemeral runners would resolve your issue. So I was wondering if you used some outdated runner image that doesn't yet support RUNNER_FEATURE_FLAG_EPHEMERAL, or your RunnerDeployment spec was somehow wrong? 🤔

If you could share the exact RunnerDeployment manifest you used to test RUNNER_FEATURE_FLAG_EPHEMERAL, i'd greatly appreciate it! Thanks.

[antodoms]

@mumoshu, basically i want to share the docker cache like images between multiple github runner pods, for which i thought RunnerSet is best, but now that i know RunnerSet uses StatefulSet i think it will create a new volume for each pod instead of sharing the volume between pod, so i am currently changing my runners to use RunnerDeployment with PersistentVolumeClaim using EFS.

The only thing i am not able to do so far is reusing the existing images on the next pod, not sure if i am targetting the volume correctly.

this is my current config

apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: "{{ .Values.runnerName }}"
spec:
  accessModes:
    - ReadWriteMany
  storageClassName: efs-sc
  resources:
    requests:
      storage: 100Gi
---
apiVersion: actions.summerwind.dev/v1alpha1
kind: RunnerDeployment
metadata:
  name: "{{ .Values.runnerName }}"
  namespace: {{ .Release.Namespace }}
spec:
  replicas: {{ .Values.desiredReplica }}
  template:
    metadata:
      labels:
        app: "{{ .Values.runnerName }}"
        namespace: {{ .Release.Namespace }}
    spec:
      ephemeral: false
{{ if eq .Values.dockerWithinDocker true }} 
      image: {{ .Values.runnerImageDind }}
      dockerdWithinRunnerContainer: true
{{ else }}
      image: {{ .Values.runnerImage }}
{{ end }}
      repository: {{ .Values.repository }}
      labels:
        {{ toYaml .Values.labels | indent 4 }}
      volumes:
        - name: "{{ .Values.runnerName }}"
          emptyDir: {}
      volumeMounts:
        - name: "{{ .Values.runnerName }}"
          mountPath: /var/lib/docker
---
apiVersion: actions.summerwind.dev/v1alpha1
kind: HorizontalRunnerAutoscaler
metadata:
  name: "{{ .Values.runnerName }}"
  namespace: {{ .Release.Namespace }}
spec:
  scaleDownDelaySecondsAfterScaleOut: {{ .Values.scaleDownDelaySecondsAfterScaleOut }}
  scaleTargetRef:
    name: "{{ .Values.runnerName }}"
{{ if eq .Values.statefulRunners true }}
    kind: "RunnerSet"
{{ end }}
  minReplicas: {{ .Values.minReplica }}
  maxReplicas: {{ .Values.maxReplica }}
  scaleUpTriggers:
  - githubEvent: {}
    duration: {{ .Values.coolDownDuration }}
    amount: {{ .Values.scaleCountPerWorkflow }}
---

[mumoshu]

@antodoms Thanks! But, AFAIK, dockerd isn't designed to share/var/lib/docker across multiple dockerd processes.

Some adventurous folks have tried to bind-mount /var/lib/docker from the host into the Docker-in-Docker container. Sometimes they share /var/lib/docker with multiple containers.
The Docker daemon was explicitly designed to have exclusive access to /var/lib/docker. Nothing else should touch, poke, or tickle any of the Docker files hidden there.
https://jpetazzo.github.io/2015/09/03/do-not-use-docker-in-docker-for-ci/

So, all you could do would be to have a single persistent volume per pod and ensure RUNNER_FEATURE_FLAG_EPHEMERAL is set. That's basically RunnerSet + RUNNER_FEATURE_FLAG_EPHEMERAL.

[jbkc85]

@jbkc85 Hey! Which runner image did you use, btw? I still think the use of new ephemeral runners would resolve your issue. So I was wondering if you used some outdated runner image that doesn't yet support RUNNER_FEATURE_FLAG_EPHEMERAL, or your RunnerDeployment spec was somehow wrong? 🤔

If you could share the exact RunnerDeployment manifest you used to test RUNNER_FEATURE_FLAG_EPHEMERAL, i'd greatly appreciate it! Thanks.

@mumoshu I am so sorry, ive been out sick for the last ... well, pretty much week. I am going to try out a few of these things this week and see what happens. I do know that we used the ephemeral flag at one point, but believe we saw the same issues....I can try it again this week when I get back into action and see what happens!

Thank you again for all the responses. I do apologize for leaving things high and dry w/ my absence.

[jbkc85]

@mumoshu now I remember. We had Ephemeral on, but due to the constant checking of check-ins we actually ran ourselves out of GitHub API calls constantly. We are talking about a scaling from 1 to 130 nodes relatively quickly...so yea, the ephemeral runners hurt us there.

I will still give this a shot whenever I get a chance. I do appreciate your communication and effort on this project!

[mumoshu]

@jbkc85 Hey! Thanks for the response. Yeah. you mentioned that it might be due to API rate limit. But seeing runner and the controller's implementation/code, I'd say API rate limit shouldn't affect runner availability.

#911 (comment)

It would be great if you could provide us more complete evidence of API rate limit affecting runner availability, or easy steps to reproduce your issue on anyone's environment, if possible, so that we can leverage our collective human resource to further debug it together!

Anyway, API rate limit issue will mostly disappear once we managed to make #920. Thanks for suggesting that, too!

[gmambro]

Hello, I am experiencing something quite similar to what @jbkc85 described.
Looking at the logs I can see a sequence of events like this one.

• At 17:01:16.922 controller logs Created runner pod {"runner": "runners-ns/runner-5nzbv-nsns2...
• 0.3 seconds later the controller logs Runner pod exists but we failed to check if runner is busy
• Then it logs Rechecking the runner registration in 1m10.104479734s and
• Skipped registration check because it's deferred until 2021-11-22 17:02:17 +0000 UTC. Retrying in 58.735154414s at latest
• 17:01:17.863 the pod starts with --ephemeral
• 17:01:20.489 pod/runner logs √ Runner successfully added
• 17:01:21.413 pod/runner logs √ Runner connection is good
• 17:01:21.503 pod/runner logs Starting Runner listener with startup type: service
• 17:01:24:377 pod/docker logs "Daemon has completed initialization"
• 17:01:27:495 pod/runner logs Running job: ...
• the jobs goes without problems
• 17:11:35.185 controller logs Already existing GitHub runner still appears offline . Recreating the pod to see if it resolves the issue. CAUTION: If you see this a lot, you should investigate the root cause. and then Deleted runner pod
• 17:11:35.895 pod/runner shutting down the listener

Please let me know if you have any suggestions of things we could try or other info you need to better understand it. Thank you!