Skip to content

util: make health-check error message static - #6540

Open
SanjalKatiyar wants to merge 1 commit into
ceph:develfrom
SanjalKatiyar:fix_err_msg
Open

util: make health-check error message static#6540
SanjalKatiyar wants to merge 1 commit into
ceph:develfrom
SanjalKatiyar:fix_err_msg

Conversation

@SanjalKatiyar

@SanjalKatiyar SanjalKatiyar commented Sep 4, 2026

Copy link
Copy Markdown
Contributor

The health-checker reported the duration in its error message, causing the string to change on every poll. The csi-addons sidecar compares consecutive error texts and emits a new Event whenever they defer, resulting in lots of seemingly duplicate volume-condition Events/Logs.

Events:
oc get events -n test-cephfs-bl  --sort-by='.lastTimestamp' \
    -o custom-columns='LAST SEEN:.lastTimestamp,TYPE:.type,REASON:.reason,SOURCE:.source.component,OBJECT:.involvedObject.kind/.involvedObject.name,MESSAGE:.message'
LAST SEEN              TYPE      REASON                    SOURCE                                                                                                                                       OBJECT   MESSAGE
2026-08-12T10:22:40Z   Normal    Provisioning              openshift-storage.cephfs.csi.ceph.com_openshift-storage.cephfs.csi.ceph.com-ctrlplugin-6b477dbcdr6zkf_9d5dbc82-2d0e-4ab9-9a97-8c6c1db80886   <none>   External provisioner is provisioning volume for claim "test-cephfs-bl/cephfs-rwx-health"
2026-08-12T10:22:41Z   Normal    ExternalProvisioning      persistentvolume-controller                                                                                                                  <none>   Waiting for a volume to be created either by the external provisioner 'openshift-storage.cephfs.csi.ceph.com' or manually by the system administrator. If volume creation is delayed, please verify that the provisioner is running and correctly registered.
2026-08-12T10:22:41Z   Normal    ProvisioningSucceeded     openshift-storage.cephfs.csi.ceph.com_openshift-storage.cephfs.csi.ceph.com-ctrlplugin-6b477dbcdr6zkf_9d5dbc82-2d0e-4ab9-9a97-8c6c1db80886   <none>   Successfully provisioned volume pvc-776ddbeb-9f03-4592-b51c-d46b28512159
2026-08-12T10:22:42Z   Normal    SuccessfulAttachVolume    attachdetach-controller                                                                                                                      <none>   AttachVolume.Attach succeeded for volume "pvc-776ddbeb-9f03-4592-b51c-d46b28512159"
2026-08-12T10:22:42Z   Warning   FailedMount               kubelet                                                                                                                                      <none>   Unable to attach or mount volumes: unmounted volumes=[kube-api-access-8xl2t vol], unattached volumes=[], failed to process volumes=[vol]: error processing PVC test-cephfs-bl/cephfs-rwx-health: PVC is not bound
2026-08-12T10:22:49Z   Normal    AddedInterface            multus                                                                                                                                       <none>   Add eth0 [10.131.1.108/23] from ovn-kubernetes
2026-08-12T10:22:49Z   Normal    Pulling                   kubelet                                                                                                                                      <none>   Pulling image "quay.io/centos/centos:latest"
2026-08-12T10:22:49Z   Normal    VolumeConditionHealthy    CSI-Addons                                                                                                                                   <none>   health checker started, status not yet available
2026-08-12T10:22:50Z   Normal    Created                   kubelet                                                                                                                                      <none>   Container created
2026-08-12T10:22:50Z   Normal    Started                   kubelet                                                                                                                                      <none>   Container started
2026-08-12T10:22:50Z   Normal    Pulled                    kubelet                                                                                                                                      <none>   Successfully pulled image "quay.io/centos/centos:latest" in 613ms (613ms including waiting). Image size: 316978699 bytes.
2026-08-12T10:23:49Z   Normal    VolumeConditionHealthy    CSI-Addons                                                                                                                                   <none>   volume is in a healthy condition
2026-08-12T10:24:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   stat /var/lib/kubelet/plugins/kubernetes.io/csi/openshift-storage.cephfs.csi.ceph.com/37a5aac76c5ed3f03b5b72794b4cd053d8e51c5329c6931a408aa8b2ab148d74/globalmount: permission denied
2026-08-12T10:25:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 120.144653 seconds
2026-08-12T10:26:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 180.135915 seconds
2026-08-12T10:27:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 240.167748 seconds
2026-08-12T10:28:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 300.192243 seconds
2026-08-12T10:29:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 360.170670 seconds
2026-08-12T10:30:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 420.167418 seconds
2026-08-12T10:31:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 480.143174 seconds
2026-08-12T10:32:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   health-check has not responded for 540.127266 seconds
2026-08-12T10:36:49Z   Warning   VolumeConditionAbnormal   CSI-Addons                                                                                                                                   <none>   (combined from similar events): health-check has not responded for 780.137011 seconds
Addons Sidecar Logs:
2026-08-12T05:56:51.255Z	INFO	csiaddonsnode	Watcher exited gracefully, will be restarted soon	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T05:56:51.297Z	INFO	csiaddonsnode	Starting watcher for CSIAddonsNode	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T07:22:30.601Z	INFO	csiaddonsnode	Watcher exited gracefully, will be restarted soon	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T07:22:30.734Z	INFO	csiaddonsnode	Starting watcher for CSIAddonsNode	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T09:11:48.515Z	INFO	csiaddonsnode	Watcher exited gracefully, will be restarted soon	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T09:11:48.613Z	INFO	csiaddonsnode	Starting watcher for CSIAddonsNode	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T10:21:56.554Z	INFO	csiaddonsnode	Watcher exited gracefully, will be restarted soon	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T10:21:56.588Z	INFO	csiaddonsnode	Starting watcher for CSIAddonsNode	{"name": "anajain-9aug-9cltv-worker-1-wb5px-openshift-storage-daemonset-openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addons"}
2026-08-12T10:22:49.422Z	INFO	volume-condition	Persistent volume is healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health checker started, status not yet available"}
2026-08-12T10:23:49.478Z	INFO	volume-condition	Persistent volume is healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "volume is in a healthy condition"}
2026-08-12T10:24:49.400Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "stat /var/lib/kubelet/plugins/kubernetes.io/csi/openshift-storage.cephfs.csi.ceph.com/37a5aac76c5ed3f03b5b72794b4cd053d8e51c5329c6931a408aa8b2ab148d74/globalmount: permission denied"}
2026-08-12T10:25:49.419Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 120.144653 seconds"}
2026-08-12T10:26:49.487Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 180.135915 seconds"}
2026-08-12T10:27:49.416Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 240.167748 seconds"}
2026-08-12T10:28:49.444Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 300.192243 seconds"}
2026-08-12T10:29:49.417Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 360.170670 seconds"}
2026-08-12T10:30:49.422Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 420.167418 seconds"}
2026-08-12T10:31:49.452Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 480.143174 seconds"}
2026-08-12T10:32:49.400Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 540.127266 seconds"}
2026-08-12T10:33:49.398Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 600.146132 seconds"}
2026-08-12T10:34:49.381Z	INFO	volume-condition	Persistent volume is not healthy	{"pvName": "pvc-776ddbeb-9f03-4592-b51c-d46b28512159", "message": "health-check has not responded for 660.134148 seconds"}                                                                                                                            

CI job ordering.

Depends-on: #6544

@SanjalKatiyar
SanjalKatiyar requested review from a team as code owners September 4, 2026 13:29
@SanjalKatiyar

Copy link
Copy Markdown
Contributor Author

/assign @nixpanic

@SanjalKatiyar

Copy link
Copy Markdown
Contributor Author

/assign @Madhu-1

@github-actions

github-actions Bot commented Sep 4, 2026

Copy link
Copy Markdown

Thanks for taking this issue! Let us know if you have any questions!

1 similar comment
@github-actions

github-actions Bot commented Sep 4, 2026

Copy link
Copy Markdown

Thanks for taking this issue! Let us know if you have any questions!

Comment thread internal/health-checker/checker.go Outdated
c.mutex.Lock()
c.healthy = false
c.err = fmt.Errorf("health-check has not responded for %f seconds", delay.Seconds())
c.err = errors.New("health-check has not responded for too long")

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@SanjalKatiyar having the timestamp in the logs helps in debugging, can you please see if we can trip down this error before sending?

@SanjalKatiyar SanjalKatiyar Sep 7, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ideally, I would have liked it as a log inside checker itself, but I see that the AGENTS.md explicitly says not to do that :/

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

parsing/trimming doesn't sound too clean, but let me check...

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about something like, “has not responded since Xxxx” where Xxx is the actual time object. We can deduce duration from the log timestamps while debugging?

@SanjalKatiyar SanjalKatiyar Sep 7, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if purpose is debugging (as mentioned by Madhu above), log timestamps are not very human friendly, or easily readable...

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The issue with many reported events is real, but the time when it started is also important to note. I prefer too many events with useful details, over one event that leaves the time of it's occurrence as a kin of scavenger hunt.

Maybe just include the fixed timeout (over and over again), and see if the timestamp of the event is sufficient?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

let me combine both @black-dragon74 and @nixpanic suggestions...

The health-checker reported the duration in its error message,
causing the string to change on every poll. The csi-addons sidecar
compares consecutive error texts and emits a new Event whenever
they defer, resulting in lots of seemingly duplicate
volume-condition Events.

Signed-off-by: SanjalKatiyar <sanjaldhir@gmail.com>
c.mutex.Lock()
c.healthy = false
c.err = fmt.Errorf("health-check has not responded for %f seconds", delay.Seconds())
c.err = fmt.Errorf("health-check has not responded since %s (timeout: %s)",

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

timeout in log is not useful.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe just include the fixed timeout (over and over again)

@Madhu-1 maybe I misunderstood @nixpanic, but I added it due to this #6540 (comment).

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@nixpanic what is the use of having const timeout in the log, i assume since last time should be enough?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The timeout makes helps in identifying the time range when the issue started to happen. Users that are troubleshooting the issue will be helped by it.

Is there a good reason to not include it?

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

its just a conts keep on repeating and not configurable as well. usually timeouts are not logged. it doesnt hurt as well if we want to include it

@nixpanic

Copy link
Copy Markdown
Member

Wait with /queue'ing until #6544 is merged.

@mergify

mergify Bot commented Sep 10, 2026

Copy link
Copy Markdown
Contributor

Merge Protections

🔴 1 of 2 protections blocking · waiting on ⛓️ dependency

Protection Waiting on
🔴 ⛓️ Depends-On Requirements ⛓️ dependency
🟢 🚦 Auto-queue

🔴 ⛓️ Depends-On Requirements

Waiting for

This rule is failing.

Requirement based on the presence of Depends-On in the body of the pull request


Show 1 satisfied protection

🟢 🚦 Auto-queue

When all merge protections are satisfied, this pull request will be queued automatically.

@nixpanic nixpanic added logging The Change is only in logging ci/skip/e2e skip running e2e CI jobs ci/skip/multi-arch-build skip building on multiple architectures labels Sep 10, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ci/skip/e2e skip running e2e CI jobs ci/skip/multi-arch-build skip building on multiple architectures logging The Change is only in logging

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants