search

fluxcd / source-controller

The GitOps Toolkit source management component
https://fluxcd.io
Apache License 2.0
238 stars 188 forks source link

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

Closed kingdonb closed 2 years ago

kingdonb commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

hiddeco commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

kingdonb commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

{"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 commented 2 years ago

@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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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.