Actions-runner-controller: Runner container does not restart even if the job ends normally

Created on 30 Jul 2020 · 15Comments · Source: summerwind/actions-runner-controller

Hai ! Thank you always for your Kubernetes operator !!

I have a question.
Even if the action job finishes successfully, only certain pods get stuck without performing a runner container restart...

runnerDeployment’s manifest:

```runnerDeployment.yaml
apiVersion: actions.summerwind.dev/v1alpha1
kind: RunnerDeployment
metadata:
name: runner
namespace: runner
spec:
replicas: 3
template:
spec:
affinity:
nodeAffinity:
requiredDuringSchedulingIgnoredDuringExecution:
nodeSelectorTerms:
- matchExpressions:
- key: beta.kubernetes.io/instance-type
operator: In
values:
- c4.2xlarge
- c5.2xlarge
envFrom:
- configMapRef:
name: ro-actions-runner
- secretRef:
name: ro-actions-runner
image: .dkr.ecr.ap-northeast-1.amazonaws.com/custom-runner:1.15
labels:
- ro
repository:

runner's status:

😀 ❯❯❯ k get pod -n runner
NAME READY STATUS RESTARTS AGE
ro-runner-52zmh-4tcrt 2/2 Running 0 47m
ro-runner-52zmh-vjb2f 2/2 Running 0 136m
ro-runner-52zmh-wxt6k 1/2 Running 0 124m <<< this runner pod

😀 ❯❯❯ k describe pod -n runner ro-runner-52zmh-wxt6k
Name: ro-runner-52zmh-wxt6k
Namespace: runner
Priority: 0
Node: ip-10-0-56-65.ap-northeast-1.compute.internal/10.0.56.65
Start Time: Thu, 30 Jul 2020 16:44:09 +0900
Labels: runner-template-hash=847bc54779
Annotations: kubernetes.io/psp: eks.privileged
Status: Running
IP: 10.0.59.171
Controlled By: Runner/ro-runner-52zmh-wxt6k
Containers:
runner:
Container ID: docker://19080ec1adc8822bfaf916c43797e7171a1c5ff5b1666b0df2485cd9c19db976
Image: .dkr.ecr.ap-northeast-1.amazonaws.com/custom-runner:1.15
Image ID: docker-pullable://.dkr.ecr.ap-northeast-1.amazonaws.com/custom-runner@sha256:bb88570bc0bedc6c8b8321887e9b6e693c0fb6542aba83e3a839949338f99b73
Port:
Host Port:
State: Terminated
Reason: Completed <<< normally finish
Exit Code: 0 <<< exit status 0
Started: Thu, 30 Jul 2020 16:44:10 +0900
Finished: Thu, 30 Jul 2020 17:05:52 +0900
Ready: False

I’m thinking that the runner container will be restarted when the actions jobs normally finish running by the following processing.
Is my perception correct?

https://github.com/summerwind/actions-runner-controller/blob/ba8f61141b30268a00387795a66abdd72b60c78c/controllers/runner_controller.go#L194-L196

runner's status

😱 ❯❯❯ k get pod -n runner ro-runner-52zmh-wxt6k -o json | jq -r ".status.containerStatuses[].state"
{
"running": {
"startedAt": "2020-07-30T07:44:10Z"
}
}
{
"terminated": {
"containerID": "docker://19080ec1adc8822bfaf916c43797e7171a1c5ff5b1666b0df2485cd9c19db976",
"exitCode": 0,
"finishedAt": "2020-07-30T08:05:52Z",
"reason": "Completed",
"startedAt": "2020-07-30T07:44:10Z"
}
}
```

Thank you!

Source

naka-gawa

👍1

Most helpful comment

The error is here: https://github.com/summerwind/actions-runner-controller/blob/ee8fb5a3886ef5a75df5c126bcd3c846e13c801e/github/github.go#L87

The token does not get refreshed for a 10 minute interval. The old token is returned and the reconcile function returns with Requeue: true - after the token update function is called. If you reduce this 10 minute interval - this should repair this problem. @mumoshu

Since token expiration is not a huge deal - the runner can still make calls even if the registration token has expired, I suggest we change this function to:

    if ok && rt.GetExpiresAt().After(time.Now()) {
        return rt, nil
    }

ZacharyBenamram on 25 Nov 2020

👍2

All 15 comments

Perhaps it is related to the issue below?
https://github.com/summerwind/actions-runner-controller/issues/62

naka-gawa on 30 Jul 2020

kaykhancheckpoint on 23 Sep 2020

This appears to be tied to when jobs land in a failed state

2020-11-17 00:16:18Z: Listening for Jobs
2020-11-17 00:27:53Z: Running job: ci_tests
2020-11-17 00:30:07Z: Job ci_tests completed with result: Failed
Runner listener exited with error code 0
Runner listener exit with 0 return code, stop the service, no retry needed.

ZacharyBenamram on 17 Nov 2020

@ZacharyBenamram Thanks for raising another point to see!

@ahmad-hamade has submitted a detailed report related to this in #198, and it seems this happens even when the job succeeded.

mumoshu on 17 Nov 2020

As the stopped runner eventually removed and recreated, this might be due to that any of our controllers doesn't detect the stopped container until the next resync period?

Generally speaking, any controller that creates pods should "watch" events from the pod, and enqueue a reconciliation on the parent "runner" resource on every pod event. Maybe our runner-controller isn't working like that?

mumoshu on 17 Nov 2020

👀1

Today I faced the same problem again and my job completed with the result succeeded.

Here are the logs:

Starting Runner listener with startup type: service
Started listener process
Started running service

√ Connected to GitHub

2020-11-17 11:21:16Z: Listening for Jobs
2020-11-17 11:38:53Z: Running job: Plan Changes (self-hosted, xxxxxxx, non-prod, account-resources)
2020-11-17 11:39:08Z: Job Plan Changes (self-hosted, xxxxxxx, non-prod, account-resources) completed with result: Succeeded
Runner listener exited with error code 0
Runner listener exit with 0 return code, stop the service, no retry needed.

>> k get po -n runner-infra                                
NAME                       READY   STATUS      RESTARTS   AGE
runner-infra-4kcrh-46487   0/1     Completed   0          21m

>> k get runnerdeployments.actions.summerwind.dev -A
NAMESPACE      NAME           DESIRED   CURRENT   READY
runner-infra   runner-infra   1                   

>> k get runner -A                                  
NAMESPACE      NAME                       ORGANIZATION   REPOSITORY               LABELS                                         STATUS
runner-infra   runner-infra-4kcrh-46487                  org_dummy_1/somerepo     [runner-infra xxxxxxxxxxxx fs-test-eks test]   Running

>> k get po -n runner-infra
NAME                       READY   STATUS      RESTARTS   AGE
runner-infra-4kcrh-46487   0/1     Completed   0          22m

ahmad-hamade on 17 Nov 2020

@ahmad-hamade / @naka-gawa - do you see the job running and completing within a similar time window by either an "Updated registration token" event or a "the object has been modified; please apply your changes to the latest version and try again" error?