Helm operator logs full deploy yaml every reconcile cycle even when no changes after upgrading to 1.9 from 1.7

[chlam4]

Bug Report

We have an operator built on the operator-sdk and its helm-operator. After upgrading to sdk 1.9 from 1.7, we are now seeing the operator dumps out the full deployment yaml in the info log at every reconcile cycle, even there are no changes at all. There are no patch requests sent to the kube apiserver. This behavior is new in 1.9; it didn't exist in 1.7.

What did you do?

Follow the procedure here to deploy the operator in a Kubernetes cluster. Tailing the operator log and we will see it dumping out logs of the full deployment yaml every minute. Here is an excerpt of the logging at the beginning of each reconcile cycle, and attached please find the entire log of a full deployment yaml printed out at each cycle.

{"level":"info","ts":1625235104.0440075,"logger":"helm.controller","msg":"Upgraded release","namespace":"turbonomic","name":"xl-release","apiVersion":"charts.helm.k8s.io/v1alpha1","kind":"Xl","release":"xl-release","force":false}
 ---
 # Source: xl/templates/telemetry-secret.yaml
 apiVersion: v1
 kind: Secret
 metadata:
   name: prometheus-datacloud-gateway
   labels:
     app.kubernetes.io/name: xl
     app.kubernetes.io/instance: xl-release
     app.kubernetes.io/managed-by: Helm
 type: Opaque
 data:
...

What did you expect to see?

We expect to see no such logging at the info level when there're no changes in the custom resource of the operator, just like what it was when we built with operator-sdk 1.7. With 1.7, we only see the first line:

{"level":"info","ts":1625235104.0440075,"logger":"helm.controller","msg":"Upgraded release","namespace":"turbonomic","name":"xl-release","apiVersion":"charts.helm.k8s.io/v1alpha1","kind":"Xl","release":"xl-release","force":false}

What did you see instead? Under which circumstances?

We see logging of the full deployment yaml every minute. Attached please find the entire log of a full deployment yaml printed out at each cycle.

Environment

Operator type:
helm operator

Kubernetes cluster type:
vanilla

$ operator-sdk version

operator-sdk version
operator-sdk version: "v1.9.0-6-g2781cf89", commit: "2781cf89a0d51a2783fa979a50ce8fdb22c820a9", kubernetes version: "v1.20.2", go version: "go1.16.3", GOOS: "darwin", GOARCH: "amd64"

$ go version (if language is Go)
N/A

$ kubectl version

Client Version: version.Info{Major:"1", Minor:"21", GitVersion:"v1.21.0", GitCommit:"cb303e613a121a29364f75cc67d3d580833a7479", GitTreeState:"clean", BuildDate:"2021-04-08T21:15:16Z", GoVersion:"go1.16.3", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.10", GitCommit:"62876fc6d93e891aa7fbe19771e6a6c03773b0f7", GitTreeState:"clean", BuildDate:"2020-10-15T01:43:56Z", GoVersion:"go1.13.15", Compiler:"gc", Platform:"linux/amd64"}
WARNING: version difference between client (1.21) and server (1.18) exceeds the supported minor version skew of +/-1

Additional context

We've done some investigation, and were able to isolate the difference was introduced in the following commit. We don't know if it's intentional.
cae12a2

In particular, it is this line of the new code that made the difference:
https://github.com/operator-framework/operator-sdk/blob/master/internal/helm/release/manager.go#L146
It now compares m.chart and deployedRelease.Chart. It used to just compare the deployedRelease.Manifest and candidateRelease.Manifest. That seems intended, but m.chart and
deployedRelease.Chart seem very different, at least in the case of our operator (please see the attached).

[danquah]

Just out of curiosity as I'm tracking down a similar issue. Do you get a new helm release revision for every reconciliation (as in, a "revision" keeps increasing if you do a helm ls -n <namespace>) regardless of any diff?

[danquah]

I'll get back to debugging tomorrow, but just wanted to confirm your experience @chlam4 - I have a small test-setup that creates a simple operator that deploys a single configmap. It's configured with the standard automatic reconciliation every minute, and with v1.7.2 i get the "normal"

2021-07-05T20:43:37.785Z	DEBUG	helm.controller	Reconciling	{"namespace": "loop-install", "name": "loop-sample", "apiVersion": "charts.my.domain/v1alpha1", "kind": "Loop"}

Every minute, but no extra release revision or manifest diff is produced (and importantly for the thing I'm debugging, no post-upgrade helm hooks are run)

Now, when I bump my test-setup to v.1.8.0 I suddenly get a full output of my manifests every minute (it's supposed to be a diff - but as there are no changes, the output just looks like a dump of the configmap) and I get a new helm release revision every minute

2021-07-05T20:47:48.787Z	DEBUG	helm.controller	Reconciling	{"namespace": "loop-install", "name": "loop-sample", "apiVersion": "charts.my.domain/v1alpha1", "kind": "Loop"}
2021-07-05T20:47:49.288Z	DEBUG	predicate	Reconciling due to dependent resource update	{"name": "operator", "namespace": "operator-system", "apiVersion": "v1", "kind": "ConfigMap"}
2021-07-05T20:47:51.487Z	DEBUG	predicate	Reconciling due to dependent resource update	{"name": "operator", "namespace": "operator-system", "apiVersion": "v1", "kind": "ConfigMap"}
 ---
 # Source: loop/templates/config.yaml
 apiVersion: v1
2021-07-05T20:47:51.786Z	INFO	helm.controller	Upgraded release	{"namespace": "loop-install", "name": "loop-sample", "apiVersion": "charts.my.domain/v1alpha1", "kind": "Loop", "release": "loop-sample", "force": false}
2021-07-05T20:47:51.786Z	DEBUG	helm.controller	Config values	{"namespace": "loop-install", "name": "loop-sample", "apiVersion": "charts.my.domain/v1alpha1", "kind": "Loop", "release": "loop-sample", "values": {}}
 kind: ConfigMap
 metadata:
   name: testmap
 data:
   test-key: "test-value"

I'll see if I can clean the test-setup up enough to post it one of these days, but it's quite easy to reproduce. Create any helm-operator (ok, I'm testing with a chart that has a single configmap, maybe it has an effect). Create an instance of the CRD, and wait for a couple of minutes. You should now have multiple revisions of the release.

[chlam4]

@danquah Thanks for confirming a similar behavior. And yes I do also have the revision number incremented every reconcile cycle.

[danquah]

And to put a even finer point on it. Just verified that an operator built with revision b9fe996 (the one before cae12a2) and running on a docker-image with this revision does not have this behaviour. If a do a full rebuild with the subsequent commit (cae12a2) I get the behaviour.

So, next step is to figure out where the bug is. @cndoit18 I believe you where involved in the change - any theories as to what might be wrong?

[ezeriver94]

Hi, I saw differences in the existing release (loaded from helm using the secret stored in K8S) and the release that would be generated (loaded from the manifests in the helm chart rendered with the values); for example, in the first one, the Raw property is not being set because helm package deserializes the secret and, in the Chart object, the Raw property is ignored. On the other hand, in the Load method from Helm, the Raw property is being populated with the manifests that helm would create.
That would generate two different objects and the DeepEqual function would return false.

[cndoit18]

And to put a even finer point on it. Just verified that an operator built with revision b9fe996 (the one before cae12a2) and running on a docker-image with this revision does not have this behaviour. If a do a full rebuild with the subsequent commit (cae12a2) I get the behaviour.

So, next step is to figure out where the bug is. @cndoit18 I believe you where involved in the change - any theories as to what might be wrong?

Sorry, I'll spend some time today fixing this

[cndoit18]

I tried to fix it, can you help to review it? please @ezeriver94 @danquah @chlam4

[danquah]

can you help to review it

I'll love to, thanks for the quick reaction, I'll head over to the issue.

[ezeriver94]

I tried to fix it, can you help to review it? please @ezeriver94 @danquah @chlam4

It's working for me!

[danquah]

Same :)

[chlam4]

Thanks everyone for jumping on this and thanks @cndoit18 for the quick fix. However, it still doesn't seem working for me. It behaves the same as before this change.

As mentioned in the description, the m.chart and deployedRelease.Chart are very different, in the case of our operator (please see the attached).

[cndoit18]

Thanks everyone for jumping on this and thanks @cndoit18 for the quick fix. However, it still doesn't seem working for me. It behaves the same as before this change.

As mentioned in the description, the m.chart and deployedRelease.Chart are very different, in the case of our operator (please see the attached).

I'm very sorry for the impact, I think it has something to do with the release read of the helm

https://github.com/helm/helm/blob/eb99434597d230a2106b22f15ac1e250ca5592f6/pkg/storage/driver/util.go#L56

Can you provide the chart so I can fix this problem?

[danquah]

@chlam4 wird - I'll try the test again. How did you verify ad1f512 ?

[chlam4]

@danquah I checked out your branch, and ran env GOOS=linux make clean build to build, which resulted in the helm-operator binary. I then copied that to my operator and built it.

When it appeared making no difference, I added a log to ensure I did build with your changes. Have you got a chance to look at the m.chart.txt and deployedRelease.Chart.txt? Could they be deemed equal in your new equal function?