Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HelmCharts red herring when k3s cluster supplies CRD first name conflict #831

Closed
kingdonb opened this issue Jul 13, 2022 · 19 comments
Closed

Comments

@kingdonb
Copy link
Member

I was testing an OCI Chart Repository:

apiVersion: source.toolkit.fluxcd.io/v1beta2
kind: HelmRepository
metadata:
  name: podinfo
  namespace: podinfo
spec:
  interval: 30s
  timeout: 60s
  type: oci
  url: oci://ghcr.io/kingdonb/podinfo/helm

and noticed I forgot to make it public. The errors were confusing:

$ flux get hr -n podinfo
NAME   	REVISION	SUSPENDED	READY	MESSAGE
podinfo	        	False    	False	HelmChart 'podinfo/podinfo-podinfo' is not ready

There is no indication that there was an auth failure until I check the logs of source-controller:

{"level":"error","ts":"2022-07-13T13:47:47.998Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET \"https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET \"https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}

OK, there's the error. (An aside: I think this should be reported somewhere as a condition)

I made the chart public, and I'm explaining this in the sequence of events that I tested because I am not certain what will be important to reproduce the error

{"level":"info","ts":"2022-07-13T13:53:49.380Z","logger":"controller.helmchart","msg":"pulled 'podinfo' chart with version '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"96c30552-3a25-4f16-bafd-05edd3fd85c6"}
{"level":"info","ts":"2022-07-13T13:54:49.391Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"ca9eaf9d-b4a0-4ede-86a1-0af6dcb43790"}
{"level":"info","ts":"2022-07-13T13:54:49.600Z","logger":"controller.helmchart","msg":"artifact up-to-date with remote revision: '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"ca9eaf9d-b4a0-4ede-86a1-0af6dcb43790"}

The release succeeded, but I was waiting to see HelmChart get created and never did observe it. The garbage collector has deleted it already. Not sure why, it seems a bug!

$ k get helmchart -A
No resources found

$ k get helmrelease
NAME      AGE     READY   STATUS
podinfo   8m25s   True    Release reconciliation succeeded

The chart does work but it has been garbage collected apparently in error. Subsequent log messages do not show the chart being recreated and garbage collected again, but it is remembered by the source controller apparently:

{"level":"info","ts":"2022-07-13T13:56:49.947Z","logger":"controller.helmchart","msg":"artifact up-to-date with remote revision: '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"820fe10e-059c-4206-86e7-4e03fa1b3701"}
{"level":"info","ts":"2022-07-13T13:57:50.112Z","logger":"controller.helmchart","msg":"artifact up-to-date with remote revision: '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"bed4bd43-a507-4554-8bc6-5c5bf1c1fda7"}
{"level":"info","ts":"2022-07-13T13:58:50.282Z","logger":"controller.helmchart","msg":"artifact up-to-date with remote revision: '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"24418ba2-5114-4ab5-b64a-ac33f9d3d363"}
{"level":"info","ts":"2022-07-13T13:59:50.466Z","logger":"controller.helmchart","msg":"artifact up-to-date with remote revision: '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"b4b32138-0cc9-45fc-b98f-dfa60f723a4e"}
@stefanprodan
Copy link
Member

stefanprodan commented Jul 13, 2022

I'm really confused about what these logs mean:

{"level":"info","ts":"2022-07-11T13:22:01.784Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"test-flux","namespace":"podinfo","reconcileID":"c7150a72-383e-4d17-971d-625ba7b1a1ab"}
{"level":"info","ts":"2022-07-11T13:22:02.027Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"msdemo","namespace":"msdemo","reconcileID":"3360a361-4257-4054-acdd-8897bf6c65a6"}
{"level":"info","ts":"2022-07-11T13:22:03.516Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"c0323191-9167-4f16-a489-d0bbcf3b18e1"}
{"level":"info","ts":"2022-07-11T13:26:02.494Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"podinfo","namespace":"default","reconcileID":"eb4ae989-82af-43fd-9e89-debd87f46ac6"}
{"level":"info","ts":"2022-07-11T13:28:10.203Z","logger":"controller.gitrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"cf0a5ab5-fa65-42c4-95a5-3cbea33f22c5"}
{"level":"info","ts":"2022-07-11T13:28:13.809Z","logger":"controller.ocirepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","name":"podinfo-oci","namespace":"flux-system","reconcileID":"c82a4080-eb65-4072-a16f-b51e8f139779"}
{"level":"info","ts":"2022-07-11T13:51:03.602Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"9e58bca1-5048-42e9-9cc4-a0e7516bb9a6"}
{"level":"info","ts":"2022-07-11T14:21:01.120Z","logger":"controller.helmrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"linkerd2-stable","namespace":"linkerd","reconcileID":"812551ac-cbfe-40ae-a0b6-088fa0dff563"}
{"level":"info","ts":"2022-07-11T14:21:01.315Z","logger":"controller.helmrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"headlamp","namespace":"monitoring","reconcileID":"29ae57c5-01ed-4e1e-8dc7-305ed63d83fc"}
{"level":"info","ts":"2022-07-11T14:21:01.510Z","logger":"controller.helmrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"kubernetes-dashboard","namespace":"monitoring","reconcileID":"b645e3c0-1bb9-440a-92a5-dc0bd4306ed3"}
{"level":"info","ts":"2022-07-11T14:21:01.726Z","logger":"controller.helmrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"grafana-charts","namespace":"monitoring","reconcileID":"addb4140-a112-443a-b242-67421af32d12"}
{"level":"info","ts":"2022-07-11T14:21:02.573Z","logger":"controller.helmrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"prometheus-community","namespace":"monitoring","reconcileID":"8df742ec-e183-4d9f-90ed-ecbc7f8e783c"}
{"level":"info","ts":"2022-07-11T14:21:03.125Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"linkerd-linkerd-viz","namespace":"linkerd","reconcileID":"b6375a9f-f24d-4618-8d9a-d83d9a9061ee"}
{"level":"info","ts":"2022-07-11T14:21:03.364Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"linkerd-linkerd2","namespace":"linkerd","reconcileID":"67ac3001-af44-4588-8faa-09623f203074"}
{"level":"info","ts":"2022-07-11T14:21:04.324Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"monitoring-headlamp","namespace":"monitoring","reconcileID":"9ad9d944-6301-4c9c-8cff-32ea9ec945c1"}
{"level":"info","ts":"2022-07-11T14:21:04.334Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"monitoring-kube-prometheus-stack","namespace":"monitoring","reconcileID":"b4bb17bb-0b87-4133-8297-5f6c8564749e"}
{"level":"info","ts":"2022-07-11T14:21:04.714Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"monitoring-kubernetes-dashboard","namespace":"monitoring","reconcileID":"b3db22c0-1180-4af2-8853-f7ec295ad5f1"}
{"level":"info","ts":"2022-07-11T14:21:04.856Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"monitoring-loki-stack","namespace":"monitoring","reconcileID":"70852bfc-2ae2-4520-b82d-5e3afa964654"}
{"level":"info","ts":"2022-07-11T14:26:02.491Z","logger":"controller.helmchart","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"flux-system-weave-gitops","namespace":"flux-system","reconcileID":"d098a6bf-c0fb-4352-8f19-9bd2811e24a1"}
{"level":"info","ts":"2022-07-11T14:55:14.805Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"9afbbe28-12a5-4db1-a921-0e2cde5b5358"}
{"level":"info","ts":"2022-07-11T14:55:28.654Z","logger":"controller.gitrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"8ad70c53-7ad2-4499-8aff-b2cfa1b92c8b"}
{"level":"info","ts":"2022-07-11T14:56:29.553Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"3da4fd8e-dfa7-493a-9ec6-e8e6a421a7da"}
{"level":"info","ts":"2022-07-11T15:01:34.112Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"bbcfec23-29b1-4132-ab35-32a26d83c449"}
{"level":"info","ts":"2022-07-11T15:02:35.033Z","logger":"controller.gitrepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","name":"flux-system","namespace":"flux-system","reconcileID":"2a5170b7-4ccd-4ace-a2e0-4b4bf91da1b9"}
{"level":"info","ts":"2022-07-11T17:21:02.069Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"grafana-charts","namespace":"monitoring","reconcileID":"e5b9cd1d-889d-428d-b369-d9299e1f7fba"}
{"level":"info","ts":"2022-07-12T11:21:04.428Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"prometheus-community","namespace":"monitoring","reconcileID":"e2ecb548-15b4-4414-9c93-cb65e07df589"}
{"level":"info","ts":"2022-07-12T12:21:04.865Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"prometheus-community","namespace":"monitoring","reconcileID":"34559f9a-a234-4ad8-b322-b7484582d05e"}
{"level":"info","ts":"2022-07-12T19:21:05.677Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"prometheus-community","namespace":"monitoring","reconcileID":"9e627094-6ead-423b-a9c0-e8406e99da3c"}
{"level":"info","ts":"2022-07-12T23:21:03.945Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"grafana-charts","namespace":"monitoring","reconcileID":"909f436d-e1a6-46d1-ac77-d27f510fe022"}
{"level":"info","ts":"2022-07-13T09:21:06.915Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"prometheus-community","namespace":"monitoring","reconcileID":"2ff54082-05de-4cb1-a156-3a28c5f1ebe7"}
{"level":"info","ts":"2022-07-13T10:20:57.469Z","logger":"controller.ocirepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","name":"podinfo-oci","namespace":"flux-system","reconcileID":"9dbfc75e-6703-4eb6-831d-1e29f59dd054"}
{"level":"info","ts":"2022-07-13T11:10:52.381Z","logger":"controller.ocirepository","msg":"garbage collected 1 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","name":"thrfg","namespace":"flux-system","reconcileID":"a4688e61-5c30-4b9c-962b-80e482f421d2"}
{"level":"info","ts":"2022-07-13T11:21:07.465Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"prometheus-community","namespace":"monitoring","reconcileID":"a19d8194-b118-4309-bf19-679c15986733"}
{"level":"info","ts":"2022-07-13T13:21:04.964Z","logger":"controller.helmrepository","msg":"garbage collected 2 artifacts","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"grafana-charts","namespace":"monitoring","reconcileID":"9b347d69-2c9d-4332-8134-d14f38dfc258"}

Why are 2 artifacts deleted for some charts?

@hiddeco
Copy link
Member

hiddeco commented Jul 13, 2022

I do not think this is a source-controller issue, but possibly an issue with the helm-controller controlling the life-cycle of the chart.

Can you provide a precise step-by-step instruction of the changes in combination with the changes to the HelmRelease (chart spec)?

@stefanprodan
Copy link
Member

OK, there's the error. (An aside: I think this should be reported somewhere as a condition)

It is reported, on the HelmChart conditions that users are unaware of. Hence all users need to learn how to debug HelmReleases https://fluxcd.io/docs/cheatsheets/troubleshooting/#how-to-debug-not-ready-errors

@kingdonb
Copy link
Member Author

kingdonb commented Jul 13, 2022

So I could find the condition, if I had access to a HelmChart but it either hasn't been created or was garbage collected on either side of the error, making it impossible to read the conditions:

apiVersion: source.toolkit.fluxcd.io/v1beta2
kind: HelmRepository
metadata:
  name: podinfo
  namespace: podinfo
spec:
  interval: 30s
  timeout: 60s
  type: oci
  url: oci://ghcr.io/kingdonb/podinfo/helm

helmrelease:

---
apiVersion: helm.toolkit.fluxcd.io/v2beta1
kind: HelmRelease
metadata:
  name: podinfo
  namespace: podinfo
spec:
  chart:
    spec:
      chart: podinfo
      reconcileStrategy: ChartVersion
      sourceRef:
        kind: HelmRepository
        name: podinfo
  interval: 1m0s

This reproduces instantly without the "private repo step" on Flux 0.31.3+ oci dev work, Helm controller is at:

► ghcr.io/fluxcd/helm-controller:v0.22.1
► ghcr.io/fluxcd/source-controller:oci-09a9ef44

@kingdonb
Copy link
Member Author

kingdonb commented Jul 13, 2022

After installing those two resources on the cluster, first the helmrepository then the helmrelease, with a separate terminal running kubectl get helmchart -w, I actually never see the HelmChart resource created as it is apparently instantly garbage collected. If users are expected to monitor HelmChart resources for their conditions to determine the failure reason for a HelmRelease, this is not an acceptable lifecycle for the chart resource.

@stefanprodan
Copy link
Member

SC does not delete HelmCharts, this is a helm-controller bug. I'll let @hiddeco move this issue if that's the case.

@hiddeco
Copy link
Member

hiddeco commented Jul 13, 2022

What are the helm-controller logs telling you? I find it unlikely the chart is instantly garbage collected, but rather think it is not created at all from some reason (which may have to do with source-controller being an RC?).

@stefanprodan
Copy link
Member

stefanprodan commented Jul 13, 2022

I can't reproduce this with the latest SC OCI build

apiVersion: source.toolkit.fluxcd.io/v1beta2
kind: HelmRepository
metadata:
  name: podinfo
  namespace: helm-oci
spec:
  interval: 30s
  timeout: 60s
  type: oci
  url: oci://ghcr.io/kingdonb/podinfo/helm
---
apiVersion: helm.toolkit.fluxcd.io/v2beta1
kind: HelmRelease
metadata:
  name: podinfo
  namespace: helm-oci
spec:
  chart:
    spec:
      chart: podinfo
      reconcileStrategy: ChartVersion
      sourceRef:
        kind: HelmRepository
        name: podinfo
  interval: 1m0s
---
apiVersion: v1
kind: Namespace
metadata:
  name: helm-oci

The cluster was boostraped with the latest CLI from the OCI branch using make build-dev:

$ k -n helm-oci get hr
NAME      AGE   READY   STATUS
podinfo   11s   True    Release reconciliation succeeded

$ k -n helm-oci get helmchart
NAME               CHART     VERSION   SOURCE KIND      SOURCE NAME   AGE   READY   STATUS
helm-oci-podinfo   podinfo   *         HelmRepository   podinfo       21s   True    pulled 'podinfo' chart with version '6.1.14'

$ flux version
flux: v0.0.0-oci-09e7d00-1657707162
helm-controller: v0.22.1
image-automation-controller: v0.23.4
image-reflector-controller: v0.19.2
kustomize-controller: oci-7681bda9
notification-controller: v0.24.0
source-controller: oci-102e9a94

@kingdonb
Copy link
Member Author

It seems to be an issue on k3s only, I'm not sure what causes this but I am using vcluster with host k8s at v1.21.14 and k3s at v1.21.12+k3s1 – if this affects only k3s, do we want to pursue it?

I can file it upstream with k3s if I can isolate it well enough to explain it in an issue for them, but it seems likely to be related to either k3s or the specific version of k3s that I'm using. I'll try some different permutations.

@hiddeco
Copy link
Member

hiddeco commented Jul 13, 2022

I think it would be good to know what precisely appears to (not) happen in both controllers versus the others. The helm-controller logs would probably tell more, did you e.g. see a reconciliation error at the end of the HelmRelease reconciliation related to the chart?

@souleb
Copy link
Member

souleb commented Jul 13, 2022

k3s has it's own helm-controller. Maybe it's interfering.

@kingdonb
Copy link
Member Author

kingdonb commented Jul 13, 2022

This is a bare k3s (vcluster) with no services other than coredns

I've captured a clean set of logs with the full history when the OCI Repository is private:

helm-controller:

{"level":"info","ts":"2022-07-13T15:49:34.732Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-07-13T15:49:34.733Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-07-13T15:49:34.733Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-07-13T15:49:34.733Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I0713 15:49:34.834559       7 leaderelection.go:248] attempting to acquire leader lease flux-system/helm-controller-leader-election...
I0713 15:49:34.849495       7 leaderelection.go:258] successfully acquired lease flux-system/helm-controller-leader-election
{"level":"info","ts":"2022-07-13T15:49:34.849Z","logger":"controller.helmrelease","msg":"Starting EventSource","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","source":"kind source: *v2beta1.HelmRelease"}
{"level":"info","ts":"2022-07-13T15:49:34.849Z","logger":"controller.helmrelease","msg":"Starting EventSource","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","source":"kind source: *v1beta2.HelmChart"}
{"level":"info","ts":"2022-07-13T15:49:34.849Z","logger":"controller.helmrelease","msg":"Starting Controller","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease"}
{"level":"info","ts":"2022-07-13T15:49:34.950Z","logger":"controller.helmrelease","msg":"Starting workers","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","worker count":4}
{"level":"info","ts":"2022-07-13T15:49:48.623Z","logger":"controller.helmrelease","msg":"HelmChart 'podinfo/podinfo-podinfo' is not ready","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","name":"podinfo","namespace":"podinfo"}
{"level":"info","ts":"2022-07-13T15:49:48.627Z","logger":"controller.helmrelease","msg":"reconcilation finished in 17.897844ms, next run in 1m0s","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","name":"podinfo","namespace":"podinfo"}

source-controller:

{"level":"info","ts":"2022-07-13T15:49:34.944Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-07-13T15:49:34.945Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-07-13T15:49:34.945Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
{"level":"info","ts":"2022-07-13T15:49:34.945Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
I0713 15:49:35.046449       1 leaderelection.go:248] attempting to acquire leader lease flux-system/source-controller-leader-election...
I0713 15:49:35.061325       1 leaderelection.go:258] successfully acquired lease flux-system/source-controller-leader-election
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.gitrepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"setup","msg":"starting file server"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.gitrepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmrepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","source":"kind source: *v1beta2.HelmRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmrepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","source":"kind source: *v1beta2.HelmRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmrepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmrepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.HelmChart"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.HelmRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.Bucket"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.ocirepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","source":"kind source: *v1beta2.OCIRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.ocirepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.bucket","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"Bucket","source":"kind source: *v1beta2.Bucket"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.helmchart","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart"}
{"level":"info","ts":"2022-07-13T15:49:35.061Z","logger":"controller.bucket","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"Bucket"}
{"level":"info","ts":"2022-07-13T15:49:35.162Z","logger":"controller.bucket","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"Bucket","worker count":2}
{"level":"info","ts":"2022-07-13T15:49:35.162Z","logger":"controller.gitrepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:49:35.162Z","logger":"controller.helmrepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:49:35.162Z","logger":"controller.helmrepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:49:35.162Z","logger":"controller.ocirepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:49:35.162Z","logger":"controller.helmchart","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","worker count":2}
{"level":"info","ts":"2022-07-13T15:49:45.863Z","logger":"controller.helmrepository","msg":"Helm repository is ready","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"podinfo","namespace":"podinfo","reconcileID":"520b059e-82a1-41c1-bf1f-f194e89abea9"}
{"level":"error","ts":"2022-07-13T15:49:49.599Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET \"https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET \"https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}
{"level":"error","ts":"2022-07-13T15:49:51.197Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET \"https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET \"https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}
{"level":"error","ts":"2022-07-13T15:49:54.296Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET \"https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET \"https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}
{"level":"error","ts":"2022-07-13T15:50:00.512Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET \"https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET \"https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}
{"level":"error","ts":"2022-07-13T15:50:12.621Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET \"https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET \"https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}

and I'll attach another set of clean logs based on when the chart OCI repo is public (next comment) – the state with the missing helmchart when reconciliation fails:

(⎈ |demo-cluster-1:podinfo):~/projects/podinfo/deploy/overlays/experiment (master *+|u+19)$ k get -A helmchart
No resources found

(⎈ |demo-cluster-1:podinfo):~/projects/podinfo/deploy/overlays/experiment (master *+|u+19)$ k get -A helmrelease
NAMESPACE   NAME      AGE    READY   STATUS
podinfo     podinfo   101s   False   HelmChart 'podinfo/podinfo-podinfo' is not ready

(⎈ |demo-cluster-1:podinfo):~/projects/podinfo/deploy/overlays/experiment (master *+|u+19)$ k get -A helmrepository
NAMESPACE   NAME      URL                                   AGE    READY   STATUS
podinfo     podinfo   oci://ghcr.io/kingdonb/podinfo/helm   107s   True    Helm repository is ready

@kingdonb
Copy link
Member Author

When the repository is public, this is the log:

helm-controller:

{"level":"info","ts":"2022-07-13T15:53:54.065Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-07-13T15:53:54.066Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-07-13T15:53:54.066Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-07-13T15:53:54.066Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I0713 15:53:54.167689       7 leaderelection.go:248] attempting to acquire leader lease flux-system/helm-controller-leader-election...
I0713 15:53:54.181873       7 leaderelection.go:258] successfully acquired lease flux-system/helm-controller-leader-election
{"level":"info","ts":"2022-07-13T15:53:54.182Z","logger":"controller.helmrelease","msg":"Starting EventSource","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","source":"kind source: *v2beta1.HelmRelease"}
{"level":"info","ts":"2022-07-13T15:53:54.182Z","logger":"controller.helmrelease","msg":"Starting EventSource","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","source":"kind source: *v1beta2.HelmChart"}
{"level":"info","ts":"2022-07-13T15:53:54.182Z","logger":"controller.helmrelease","msg":"Starting Controller","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease"}
{"level":"info","ts":"2022-07-13T15:53:54.283Z","logger":"controller.helmrelease","msg":"Starting workers","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","worker count":4}
{"level":"info","ts":"2022-07-13T15:54:06.622Z","logger":"controller.helmrelease","msg":"HelmChart 'podinfo/podinfo-podinfo' is not ready","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","name":"podinfo","namespace":"podinfo"}
{"level":"info","ts":"2022-07-13T15:54:06.626Z","logger":"controller.helmrelease","msg":"reconcilation finished in 18.181713ms, next run in 1m0s","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","name":"podinfo","namespace":"podinfo"}
{"level":"info","ts":"2022-07-13T15:54:08.485Z","logger":"controller.helmrelease","msg":"reconcilation finished in 237.374715ms, next run in 1m0s","reconciler group":"helm.toolkit.fluxcd.io","reconciler kind":"HelmRelease","name":"podinfo","namespace":"podinfo"}

source-controller:

{"level":"info","ts":"2022-07-13T15:53:53.971Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-07-13T15:53:53.972Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-07-13T15:53:53.973Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-07-13T15:53:53.973Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I0713 15:53:54.074539       1 leaderelection.go:248] attempting to acquire leader lease flux-system/source-controller-leader-election...
I0713 15:53:54.090660       1 leaderelection.go:258] successfully acquired lease flux-system/source-controller-leader-election
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.gitrepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"setup","msg":"starting file server"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.bucket","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"Bucket","source":"kind source: *v1beta2.Bucket"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.bucket","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"Bucket"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmrepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","source":"kind source: *v1beta2.HelmRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.ocirepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","source":"kind source: *v1beta2.OCIRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.gitrepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.ocirepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmrepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmrepository","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","source":"kind source: *v1beta2.HelmRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmrepository","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.HelmChart"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.HelmRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmchart","msg":"Starting EventSource","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","source":"kind source: *v1beta2.Bucket"}
{"level":"info","ts":"2022-07-13T15:53:54.090Z","logger":"controller.helmchart","msg":"Starting Controller","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart"}
{"level":"info","ts":"2022-07-13T15:53:54.191Z","logger":"controller.gitrepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"GitRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:53:54.191Z","logger":"controller.ocirepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"OCIRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:53:54.191Z","logger":"controller.helmrepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:53:54.191Z","logger":"controller.helmrepository","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","worker count":2}
{"level":"info","ts":"2022-07-13T15:53:54.191Z","logger":"controller.helmchart","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","worker count":2}
{"level":"info","ts":"2022-07-13T15:53:54.191Z","logger":"controller.bucket","msg":"Starting workers","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"Bucket","worker count":2}
{"level":"info","ts":"2022-07-13T15:54:02.359Z","logger":"controller.helmrepository","msg":"Helm repository is ready","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmRepository","name":"podinfo","namespace":"podinfo","reconcileID":"6a512055-55de-4b29-8756-239f356dbc9d"}
{"level":"info","ts":"2022-07-13T15:54:08.237Z","logger":"controller.helmchart","msg":"pulled 'podinfo' chart with version '6.1.14'","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","reconcileID":"e2c54e19-4ae5-45ee-9209-1ac75fce3be3"}

In neither case (public or private, success or failure) do I actually see any HelmChart resources created on the cluster

@kingdonb
Copy link
Member Author

Just a note after reviewing these logs, this time the notice about garbage collecting was not posted. (But the HelmChart resources are still not shown as created on the cluster.)

@souleb
Copy link
Member

souleb commented Jul 13, 2022

{"level":"error","ts":"2022-07-13T15:50:12.621Z","logger":"controller.helmchart","msg":"Reconciler error","reconciler group":"source.toolkit.fluxcd.io","reconciler kind":"HelmChart","name":"podinfo-podinfo","namespace":"podinfo","error":"chart pull error: chart pull error: failed to get chart version for remote reference: GET "https://ghcr.io/v2/kingdonb/podinfo/helm/podinfo/tags/list\": GET "https://ghcr.io/token?scope=repository%3Akingdonb%2Fpodinfo%2Fhelm%2Fpodinfo%3Apull&service=ghcr.io\": unexpected status code 401: unauthorized: authentication required"}

It did not get any tag, so not having a chart make sense. But then the helmrepository is fine, with the same token? What version of SC are you running?

@somtochiama
Copy link
Member

@kingdonb Could it be something with kubectl

It is kinda weird that you never see the HelmChart even before any garbage collection is done. It should be present at least when the repository is private and it has the error. Could something else be deleting the helm chart?

@kingdonb
Copy link
Member Author

It did not get any tag, so not having a chart make sense

The normal behavior is to populate a HelmChart resource with the reason for failure in its conditions. This is the behavior on a regular kind cluster, it's different for some reason on this k3s cluster.

If the HelmChart is not created then the user cannot read failed conditions on it. There is no token, this is a repo that was accidentally private. It works when marked public, but again the HelmChart is not created on the cluster for some reason.

This is a build from the oci branch and with the source controller at source-controller: oci-102e9a94 – I can revert to the latest release for testing if that would help, but I don't think it's an issue with Flux at this point, but likely some misbehavior of k3s – I'd suggest that I test against a newer k3s before we spend too much more collective effort trying to understand.

@kingdonb
Copy link
Member Author

Sorry to waste so much time on this, there is no issue:

helmcharts.helm.cattle.io            helmcharts.source.toolkit.fluxcd.io

@souleb @somtochiama you had it right, this is a conflict with the helm controller provided by k3s, they have installed some CRDs on my vcluster that I didn't ask for, and when I kubectl get helmcharts I am reaching the wrong helmchart crd.

Sorry for the noise everyone.

@hiddeco
Copy link
Member

hiddeco commented Jul 13, 2022

Might still be good to have this noted somewhere as a K3s specific gotcha around kubectl get helmchart, as I think there are more people going to be running into this.

kingdonb pushed a commit to fluxcd/website that referenced this issue Jul 14, 2022
Follow-up to cover common likely issue noticed while attempting to debug
a red-herring issue in fluxcd/source-controller#831

Signed-off-by: Kingdon Barrett <kingdon@weave.works>
kingdonb pushed a commit to fluxcd/website that referenced this issue Jul 14, 2022
Follow-up to cover common likely issue noticed while attempting to debug
a red-herring issue in fluxcd/source-controller#831

Signed-off-by: Kingdon Barrett <kingdon@weave.works>
kingdonb pushed a commit to fluxcd/website that referenced this issue Jul 14, 2022
Follow-up to cover common likely issue noticed while attempting to debug
a red-herring issue in fluxcd/source-controller#831

Signed-off-by: Kingdon Barrett <kingdon@weave.works>
@kingdonb kingdonb changed the title OCI HelmChart is garbage collected erroneously out of sequence HelmCharts red herring when k3s cluster supplies CRD first name conflict Jul 14, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants