Bug 1755568

Logs seen (and repeating) for machine-config operator:



$ oc -n openshift-machine-config-operator logs machine-config-controller-bf899d8dd-bcjqw
...
E0925 17:16:37.284573       1 reflector.go:134] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: Failed to list *v1.KubeletConfig: v1.KubeletConfigList.Items: []v1.KubeletConfig: v1.KubeletConfig.Spec: v1.KubeletConfigSpec.MachineConfigPoolSelector: v1.LabelSelector.MatchLabels: ReadString: expects " or n, but found t, error found in #10 byte of ...|kubelet":true}}}}],"|..., bigger context ...|chLabels":{"managed.openshift.io/custom-kubelet":true}}}}],"kind":"KubeletConfigList","metadata":{"c|...

This is not an MCD error, there is an error with KubeleteConfig having a problem parsing and throwing your error: v1.LabelSelector.MatchLabels: ReadString: expects " or n, but found t

please double check that you are tainting correctly:
https://github.com/openshift/openshift-docs/blob/ca69ca64e9b84e24e2514e2d401ba44f6e2af453/modules/cli-administrator-node-management.adoc#taint

Passing this along to Node, to assist.

Can you also please provide the must gather from this cluster for more complete logs to review?

Regarding proper tainting, command being run:

oc adm taint node $NODE node.ocs.openshift.io/storage=true:NoSchedule

Per the supplied doc I have no idea if that's correct.  Is there some documentation on acceptable/standard values for the taint?  Not clear what should be set for "groupName".

Must-gather coming soon.

https://docs.openshift.com/container-platform/4.1/nodes/scheduling/nodes-scheduler-taints-tolerations.html

format:  key=value:effect

Slash is not allowed for key maybe.

"The key is any string, up to 253 characters. The key must begin with a letter or number, and may contain letters, numbers, hyphens, dots, and underscores."

The key containing a slash is incorrect, 'node.ocs.openshift.io/storage', though the documentation does say to do it that way.  Doc fix?

I take that back... Looking into it more.

Upstream issue: https://github.com/kubernetes/kubernetes/issues/82296

There is a problem in the yaml conversion library.

Private comment w/ link to the must-gather data.

I tested from 4.1.16 to 4.1.17 for 4 clusters. 
For 3 of them a worker has taint node.ocs.openshift.io/storage=true:NoSchedule
For 1 a worker has taint node.ocs.openshift.io=storage:NoSchedule (to try without slash)

In all cases the cluster is stuck, workers are not being upgraded.  Log for machine-config-controller pod is consistent with what was shared before.

For a sanity check I have also tried deleting the machine-config-controller pod, to make sure that alone doesn't fix things.  It does not resolve the issue, once it is back online the errors come back.

Based on the upstream issue (comment #8), moving this to api/auth team.

Created attachment 1619491 [details]
oc get kubeletconfig -A -o json

This fixes the node upgrades, machine-config-controller is able to continue almost immediately:

oc patch kubeletconfig custom-kubelet --type=merge -p '{"spec":{"machineConfigPoolSelector":{"matchLabels":{"managed.openshift.io/custom-kubelet":"true"}}}}'

I should have noted, this works for both the taints I was testing with:

- node.ocs.openshift.io/storage=true:NoSchedule
- node.ocs.openshift.io=storage:NoSchedule

I may have spoken too soon.  I saw a node become unscheduled which I thought implied it would upgrade.  It hasn't.  All workers are still on a different version than masters.  The errors previously seen in machine-config-controller are no longer happening.  I'll attached the logs in a moment.

Created attachment 1619560 [details]
machine-config-controller log

$ oc get nodes | grep master
ip-10-0-133-210.ec2.internal   Ready    master   19h   v1.13.4+244797462
ip-10-0-135-58.ec2.internal    Ready    master   19h   v1.13.4+244797462
ip-10-0-138-71.ec2.internal    Ready    master   19h   v1.13.4+244797462

$ oc get nodes | grep worker
ip-10-0-128-188.ec2.internal   Ready    worker   18h   v1.13.4+2f97059c6
ip-10-0-129-39.ec2.internal    Ready    worker   18h   v1.13.4+2f97059c6
ip-10-0-135-0.ec2.internal     Ready    worker   17h   v1.13.4+2f97059c6
ip-10-0-135-143.ec2.internal   Ready    worker   18h   v1.13.4+2f97059c6
ip-10-0-143-163.ec2.internal   Ready    worker   18h   v1.13.4+2f97059c6

Expecting workers to upgrade to v1.13.4+244797462

Naveen:

Can you change your kubelet config's (`oc edit kubeletconfig custom-kubelet`) matchLabel to contain a "true" (string) instead of a boolean `true`?

Likely, this will fix the issue... For 4.3.0, I will add validators for the KubeletConfig object as Stefan suggested.

(In reply to Naveen Malik from comment #19)
> $ oc get nodes | grep master
> ip-10-0-133-210.ec2.internal   Ready    master   19h   v1.13.4+244797462
> ip-10-0-135-58.ec2.internal    Ready    master   19h   v1.13.4+244797462
> ip-10-0-138-71.ec2.internal    Ready    master   19h   v1.13.4+244797462
> 
> $ oc get nodes | grep worker
> ip-10-0-128-188.ec2.internal   Ready    worker   18h   v1.13.4+2f97059c6
> ip-10-0-129-39.ec2.internal    Ready    worker   18h   v1.13.4+2f97059c6
> ip-10-0-135-0.ec2.internal     Ready    worker   17h   v1.13.4+2f97059c6
> ip-10-0-135-143.ec2.internal   Ready    worker   18h   v1.13.4+2f97059c6
> ip-10-0-143-163.ec2.internal   Ready    worker   18h   v1.13.4+2f97059c6
> 
> Expecting workers to upgrade to v1.13.4+244797462

can you re-share must-gather to investigate this as well

@Ryan I did this with the patch posted earlier.  But something has reverted it now that I look again.


@Antonio I will post a link to the updated must-gather in a moment.

(In reply to Naveen Malik from comment #23)
> @Ryan I did this with the patch posted earlier.  But something has reverted
> it now that I look again.
> 
> 
> @Antonio I will post a link to the updated must-gather in a moment.

you're still having a machine-config-controller issue, that's why your workers aren't picking up the new configuration:

```
2019-09-26T14:26:56.798780176Z E0926 14:26:56.798731       1 reflector.go:134] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: Failed to list *v1.KubeletConfig: v1.KubeletConfigList.Items: []v1.KubeletConfig: v1.KubeletConfig.Spec: v1.KubeletConfigSpec.MachineConfigPoolSelector: v1.LabelSelector.MatchLabels: ReadString: expects " or n, but found t, error found in #10 byte of ...|kubelet":true}}},"st|..., bigger context ...|chLabels":{"managed.openshift.io/custom-kubelet":true}}},"status":{"conditions":[{"lastTransitionTim|...
```

The above is in the machine-config-controller logs - assuming you ran the must-gather after the patch command as the name of the archive suggests

As noted after patching kubeletconfig it has been reverted by *something*.  I have not investigated what beyond a cursory glance to see if it's managed directly by cvo, doesn't appear to be.

$ oc -n openshift-cluster-version rsh cluster-version-operator-7ff56c9659-swtm9 
sh-4.2# cd release-manifests/
sh-4.2# grep -i kubeletconfig *
0000_80_machine-config-operator_00_clusterreader_clusterrole.yaml:      - kubeletconfigs


So, I am not sure how to move forward here without understanding what is reverting the spec of the kubeletconfig.

the kubelet config is _managed_ by MCO - and from the must-gather it seems like it's not "reverted", can you provide the output of

oc get -oyaml kubeletconfig custom-kubelet

Created attachment 1619639 [details]
oc get -o json kubeletconfig custom-kubelet

Note value of '.spec.machineConfigPoolSelector.matchLabels["managed.openshift.io/custom-kubelet"]' is `true`.  We expect this to be `"true"` in the json output.

Created attachment 1619640 [details]
oc get -o yaml kubeletconfig custom-kubelet

Created attachment 1619649 [details]
oc patch; oc get kubeletconfig

oc patch kubeletconfig custom-kubelet --type=merge -p '{"spec":{"machineConfigPoolSelector":{"matchLabels":{"managed.openshift.io/custom-kubelet":"true"}}}}'
oc get -o json kubeletconfig custom-kubelet > patched-custom-kubelet.kubeletconfig.json

Note value of '.spec.machineConfigPoolSelector.matchLabels["managed.openshift.io/custom-kubelet"]' after patching is `"true"` in json output.

This patch was done earlier today.  Sounding like machine-config controller is changing the value from `"true"` to `true` if it is what manages this object.

@Antonio output requested along with json output before and after applying patch.  Yaml output always show the value to be `true`, never with quotes.

Naveen: Instead of issuing a patch, can you 'oc edit' the object to be a string? Please report back the json and the yaml after.

I have done an edit as well with the same effect.  I have another cluster I haven't touched that has this same problem (aka fresh upgrade, no changes) and I will do an edit.

What I am seeing though is the KubeletConfig is changed back.  It isn't fast.  The patch I did 40 minutes ago is holding.  The logs do not show the error anymore.  But nodes are not being updated.  I'm doing another must-gather for that cluster.

Setup:
- install version 4.1.16
- taint one worker
- upgrade to 4.1.17

Observe one non-tainted worker is upgraded, machine-config-controller logs spew error:

E0926 18:30:47.525184       1 reflector.go:134] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: Failed to list *v1.KubeletConfig: v1.KubeletConfigList.Items: []v1.KubeletConfig: v1.KubeletConfig.Spec: v1.KubeletConfigSpec.MachineConfigPoolSelector: v1.LabelSelector.MatchLabels: ReadString: expects " or n, but found t, error found in #10 byte of ...|kubelet":true}}},"st|..., bigger context ...|chLabels":{"managed.openshift.io/custom-kubelet":true}}},"status":{"conditions":[{"lastTransitionTim|...


Timeline this afternoon (EST):

1:35PM
- edit kubeconfig to set '.spec.machineConfigPoolSelector.matchLabels["managed.openshift.io/custom-kubelet"]' to `"true"` (from `true`). 
- value is confirmed to be quoted with oc get -o yaml kubeletconfig custom-kubelet
- machine-config-controller pod replaced
- machine-config-operator pod replaced

1:38PM to 1:58PM
- observe all masters node transition to ScheduleDisabled->NotReady and back
- NOTE no workers are updated, they remain on the versions they were on before machine-config-controller errors occurred with the upgrade

1:53PM
- machine-config-controller pod replaced
- machine-config-operator pod replaced

2:30PM
- value of '.spec.machineConfigPoolSelector.matchLabels["managed.openshift.io/custom-kubelet"]' in kubeletconfig is `true`, not the expected `"true"`
- errors in machine-config-controller are observed again:
E0926 18:30:38.507820       1 reflector.go:134] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: Failed to list *v1.KubeletConfig: v1.KubeletConfigList.Items: []v1.KubeletConfig: v1.KubeletConfig.Spec: v1.KubeletConfigSpec.MachineConfigPoolSelector: v1.LabelSelector.MatchLabels: ReadString: expects " or n, but found t, error found in #10 byte of ...|kubelet":true}}},"st|..., bigger context ...|chLabels":{"managed.openshift.io/custom-kubelet":true}}},"status":{"conditions":[{"lastTransitionTim|...

Shot in the dark but do you need to escape the quotes?
Something like:
`\"true\"`

@Kirsten after patching the value is good.

Snippets from -o json for kubeletconfig before and after applying the patch.

Before (https://bugzilla.redhat.com/attachment.cgi?id=1619639):
        "machineConfigPoolSelector": {
            "matchLabels": {
                "managed.openshift.io/custom-kubelet": true
            }
        }

After (https://bugzilla.redhat.com/attachment.cgi?id=1619649):

        "machineConfigPoolSelector": {
            "matchLabels": {
                "managed.openshift.io/custom-kubelet": "true"
            }
        }

But, after 55 minutes it is changed back:
        "machineConfigPoolSelector": {
            "matchLabels": {
                "managed.openshift.io/custom-kubelet": true
            }
        }

are you seeing the same "expects " or n but found t"... errors in mcc?

@Kirsten I have tried using a value of `\"true\"`

  machineConfigPoolSelector:
    matchLabels:
      managed.openshift.io/custom-kubelet: \"true\"


Which is translated to `"\\\"true\\\""` and this shows up all over the kubeletconfig .status.conditions:

            {
                "lastTransitionTime": "2019-09-26T20:46:35Z",
                "message": "Error: invalid label selector: invalid label value: \"\\\\\\\"true\\\\\\\"\": a valid label must be an empty string or consist of alphanumeric characters, '-', '_'
 or '.', and must start and end with an alphanumeric character (e.g. 'MyValue',  or 'my_value',  or '12345', regex used for validation is '(([A-Za-z0-9][-A-Za-z0-9_.]*)?[A-Za-z0-9])?')",
                "status": "False",
                "type": "Failure"
            },

Naveen, could you try labeling your MachineConfigPool with the label as "managed.openshift.io/custom-kubelet" : "regular" and make the necessary adjustment in the KubeletConfig matchLabels selector. Basically removing the "true/false" from the value. Might be a temporary workaround.

i would also try: "managed.openshift.io/custom-kubelet" : ""

The issue I think that you are setting this label's value to true (which I didn't realize was your choice), choosing something else will probably fix this as Ryan said above.

I have a fresh OSD 4.1.16 cluster this morning.  The machine-config controller is logging errors, I have not tainted it.  So this will be a simple test to change the label.

E0927 12:35:13.838001       1 reflector.go:134] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: Failed to list *v1.KubeletConfig: v1.KubeletConfigList.Items: []v1.KubeletConfig: v1.KubeletConfig.Spec: v1.KubeletConfigSpec.MachineConfigPoolSelector: v1.LabelSelector.MatchLabels: ReadString: expects " or n, but found t, error found in #10 byte of ...|kubelet":true}}}}],"|..., bigger context ...|chLabels":{"managed.openshift.io/custom-kubelet":true}}}}],"kind":"KubeletConfigList","metadata":{"c|...


I am going to:
1. change the MachineConfigPool label
2. change the KubeletConfig matchLabels selector
3. wait 1 hour
4. see what happened

Checked back in on the cluster I made the edits on.

Both MachineConfigPool label and KubeletConfig matchLabels selector are changed back to original values.

$ oc get machineconfigpool worker -o yaml | grep custom-kubelet
    managed.openshift.io/custom-kubelet: "true"

$ oc get machineconfigpool worker -o json | jq -r '.metadata.labels["managed.openshift.io/custom-kubelet"]'
true


$ oc get kubeletconfig custom-kubelet -o yaml | grep "managed.openshift.io/custom-kubelet" | tail -n1
      managed.openshift.io/custom-kubelet: true

$ oc get kubeletconfig custom-kubelet -o json | jq -r '.spec.machineConfigPoolSelector.matchLabels["managed.openshift.io/custom-kubelet"]'
true


Straight editing these resources is not working.

Naveen, could you use a different name ("" or "a-real-name") instead of true or false for the test?

I used "regular".  The value of "true" and true came back after a while.

Ran a script that patched the MachineConfigPool and KubeletConfig resources then watched the values we care about in a loop.  After 62 minutes both were changed back.  I will attach files "patch.sh" and "patching.log" with the details.

Created attachment 1620194 [details]
script to patch and watch resources

Created attachment 1620195 [details]
output of patch.sh script on an OSD 4.1.16 cluster

We need to backport a fix for KubeletConfig errors to 4.1. Old keys for KubeletConfigs, which fail validation, get reinjected into the cache queue.

PR: https://github.com/openshift/machine-config-operator/pull/1140

Naveen: If you do the following, it should 'fix' the issue in your cluster without needing to upgrade (for now):

1. Edit the MCP and KubeletConfig again.... I suggest avoiding 'true/false' for the machineLabel for now.
2. Cause the machine-config-controller to restart, or have the MCO create a new one.

@Ryan that is the exact test I just did, I set the values to "regular".  Yes, the controller is restarted (as well as the operator).  As noted, after about an hour the values are set back.  Are you suggesting we hope that the upgrade completes before the values get changed back?

Not exactly:

Let's try this procedure:

Setup:
- install version 4.1.16
- taint one worker

Use this Kubelet Config Label and MCP Label:
  "managed.openshift.io/custom-kubelet" : ""

- upgrade to 4.1.17

@Ryan

I did the recommended steps, though set the value to "regular" for labels.  The upgrade progressed all the way to 4.1.17 without stopping.

I've duplicated this bug to 4.3 (https://bugzilla.redhat.com/show_bug.cgi?id=1757195) in regards to the problem about labels with "true"/"false" values switching types. I suspect we can close this bug as working as 'closed notabug' since upgrades are working.

I redirected the MCO backport (https://github.com/openshift/machine-config-operator/pull/1140) to use (https://bugzilla.redhat.com/show_bug.cgi?id=1757209) since it has already been validated for 4.2.

> I suspect we can close this bug as working as 'closed notabug' since upgrades are working.

Upgrades work if you update two CRs and your upgrade finishes before the CRs are changed back by something in the cluster.  In my testing the window is roughly 1 hour give or take.  That's cutting it pretty close, upgrades are taking longer and longer.  And if there are other issues it may delay progression of the machine-config operator.

To summarize, we have proven in this ticket that:

a) upgrades _do_ work with label values _other_ than true/false
b) label values are problematic with true/false value fields (https://github.com/kubernetes/kubernetes/issues/23251)
c) tainted nodes will upgrade when correct label values are used

We have _not_ proven labels are changing to anything else when they are real strings. Is there a test scenario, not using true/false, that shows labels are changing?

Note: It appears that upstream does not necessarily view true/false value fields in labels as a problem. https://github.com/kubernetes/kubernetes/issues/23251

Some conversation with Ryna on slack and I've found where we are creating this KubeletConfig and understand the path forward to fix this and why I was seeing values change.  Thanks all for looking at this.