Loading...

Type: Bug
Resolution: Unresolved
Priority: Minor
Fix Version/s: None
Affects Version/s: 4.13, 4.15
Component/s: Machine Config Operator
Labels:
- mco-triaged

Activity Type:
Quality / Stability / Reliability
Blocked:
False
Blocked Reason:

Hide

None

Show
None
Story Points:
None
Severity:
Low
Regression:
No

Target Backport Versions:
None
Target Version:
None
Release Blocker:
None
Sprint:
MCO Sprint 247, MCO Sprint 248, MCO Sprint 249, MCO Sprint 250, MCO Sprint 255
sprint_count:
5

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

PX Impact Score:

Release Note Status:
None
Release Note Type:
None
Release Note Text:
None

Escape Reason:
None
Escape Impact:
None
Corrective Measures:
None
SDLC stage when should've been found:
None

Description of problem:

A 4.15.0-ec.2 aws-ovn-serial run has:

$ curl -s https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-nightly-4.15-e2e-aws-ovn-serial/1724489687197814784/artifacts/e2e-aws-ovn-serial/gather-extra/artifacts/pods/openshift-machine-config-operator_machine-config-controller-9b68b8bc6-crqxn_machine-config-controller.log | grep 'Re-syncing ControllerConfig due to secret pull-secret change'
I1114 18:26:44.585262       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change
I1114 18:51:10.023414       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change
I1114 19:15:35.460686       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change
I1114 19:40:00.902110       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change
I1114 20:04:26.339691       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change
I1114 20:28:51.777106       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change
I1114 20:53:17.214710       1 template_controller.go:134] Re-syncing ControllerConfig due to secret pull-secret change

despite the pull secret not changing during that run. This is distracting noise, and it would be easier to understand what the MCC was up to if it only logged this on actual pull-secret changes.

Version-Release number of selected component (if applicable):

Seen in 4.13.15, and found again in the first 4.15 CI run I looked at, so likely many recent 4.y. I haven't dug into history to know which 4.y added the log line, but I would not be surprised if every release that can log this line has this noise issue.

How reproducible:

Seen in two of two clusters I've looked at, so likely very reproducible, although the sample size is still small.

Steps to Reproduce:

1. Install a cluster, without messing with the pull-secret Secret.
2. oc -n openshift-machine-config-operator logs -l k8s-app=machine-config-controller -c machine-config-controller --tail -1 | grep -c 'Re-syncing ControllerConfig due to secret pull-secret change'

Actual results:

For the 4.15 CI run, the grep returns 7:

$ curl -s https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-nightly-4.15-e2e-aws-ovn-serial/1724489687197814784/artifacts/e2e-aws-ovn-serial/gather-extra/artifacts/pods/openshift-machine-config-operator_machine-config-controller-9b68b8bc6-crqxn_machine-config-controller.log | grep -c 'Re-syncing ControllerConfig due to secret pull-secret change'
7

Expected results:

The grep returns 0, unless actual changes have been made to the pull-secret Secret.

Additional info:

Audit logs for the 4.15 CI run:

$ curl -s https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-nightly-4.15-e2e-aws-ovn-serial/1724489687197814784/artifacts/e2e-aws-ovn-serial/gather-audit-logs/artifacts/audit-logs.tar | tar -xz --strip-components=2
$ zgrep -h '"resource":"secrets","namespace":"openshift-config"' kube-apiserver/*.log.gz | jq -r '.verb' | sort | uniq -c
      7 create
    689 get
     17 list
      3 update
    764 watch
$ zgrep -h '"resource":"secrets","namespace":"openshift-config"' kube-apiserver/*.log.gz | jq -c 'select(.verb == "create" or .verb == "update") | {stageTimestamp, verb, responseCode: .responseStatus.code, objectRef, username: .user.username}' | sort
{"stageTimestamp":"2023-11-14T18:29:33.305090Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"default-token-rq2wh","apiVersion":"v1"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:29:34.567647Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"deployer-token-hd4r2","apiVersion":"v1"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:29:34.589124Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"builder-token-xnqcm","apiVersion":"v1"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:29:35.612229Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"default-dockercfg-f96rb","apiVersion":"v1"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:29:38.439031Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"deployer-dockercfg-fr6kc","apiVersion":"v1"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:29:38.472701Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"builder-dockercfg-sbw6b","apiVersion":"v1"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:32:29.253258Z","verb":"update","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"deployer-dockercfg-fr6kc","uid":"53b82fbb-ef0e-40d8-a469-d5fdbe019dfc","apiVersion":"v1","resourceVersion":"16062"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:32:29.654553Z","verb":"update","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"builder-dockercfg-sbw6b","uid":"8aae4eea-6117-40e0-9cbc-3cf67cf3af6f","apiVersion":"v1","resourceVersion":"16069"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:32:30.086273Z","verb":"update","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"default-dockercfg-f96rb","uid":"f96d706d-70ad-42b5-a7f6-80090eb0e304","apiVersion":"v1","resourceVersion":"15319"},"username":"system:serviceaccount:openshift-infra:serviceaccount-pull-secrets-controller"}
{"stageTimestamp":"2023-11-14T18:43:47.855805Z","verb":"create","responseCode":201,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"support","apiVersion":"v1"},"username":"system:admin"}

But there's nothing in there that correlates with the 20:53:17 Re-syncing ControllerConfig due to secret pull-secret change log line I quoted earlier in the description. It's possible that the logged lines are due to watch interruptions, or the informer's resyncPeriod.

$ zgrep -h '"resource":"secrets","namespace":"openshift-config"' kube-apiserver/*.log.gz | jq -c 'select(.user.username == "system:serviceaccount:openshift-machine-config-operator:machine-config-controller") | {stageTimestamp, verb, responseCode: .responseStatus.code, objectRef}' | sort | grep -4 20:53:17
{"stageTimestamp":"2023-11-14T20:45:11.689051Z","verb":"get","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"pull-secret","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T20:45:12.214469Z","verb":"get","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"pull-secret","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T20:46:27.329313Z","verb":"watch","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T20:46:27.330610Z","verb":"watch","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T20:53:17.219796Z","verb":"get","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","name":"pull-secret","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T20:54:04.330809Z","verb":"watch","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T20:54:04.332720Z","verb":"watch","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T21:03:32.333049Z","verb":"watch","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","apiVersion":"v1"}}
{"stageTimestamp":"2023-11-14T21:03:32.333972Z","verb":"watch","responseCode":200,"objectRef":{"resource":"secrets","namespace":"openshift-config","apiVersion":"v1"}}

So that 2023-11-14T20:53:17.219796 get is a few milliseconds after the 20:53:17.214710 logged line, and there's nothing obvious as a trigger for why the MCC picked that time to wonder if pull-secret had changed.

is related to

MCO-1016 Remove logs about non-existent changes in the machine-config-controller

Code Review

Details

Description

Description of problem:

Version-Release number of selected component (if applicable):

How reproducible:

Steps to Reproduce:

Actual results:

Expected results:

Additional info:

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates