Job:
#1921157bug23 months ago[sig-api-machinery] Kubernetes APIs remain available for new connections ASSIGNED
T2: At 06:45:58: systemd-shutdown was sending SIGTERM to remaining processes...
T3: At 06:45:58: kube-apiserver-ci-op-z52cbzhi-6d7cd-pz2jw-master-0: Received signal to terminate, becoming unready, but keeping serving (TerminationStart event)
T4: At 06:47:08 kube-apiserver-ci-op-z52cbzhi-6d7cd-pz2jw-master-0: The minimal shutdown duration of 1m10s finished (TerminationMinimalShutdownDurationFinished event)
T5: At 06:47:08 kube-apiserver-ci-op-z52cbzhi-6d7cd-pz2jw-master-0: Server has stopped listening (TerminationStoppedServing event)
T5 is the last event reported from that api server. At T5 the server might wait up to 60s for all requests to complete and then it fires TerminationGracefulTerminationFinished event.
periodic-ci-openshift-release-master-nightly-4.10-upgrade-from-stable-4.9-e2e-aws-upgrade (all) - 20 runs, 55% failed, 9% of failures match = 5% impact
#1619415651930083328junit2 days ago
Jan 28 20:29:49.122 E ns/openshift-ingress-operator pod/ingress-operator-665cf85bf-j75d8 node/ip-10-0-163-162.us-west-1.compute.internal container/ingress-operator reason/TerminationStateCleared lastState.terminated was cleared on a pod (bug https://bugzilla.redhat.com/show_bug.cgi?id=1933760 or similar)
Jan 28 20:29:53.572 E ns/openshift-insights pod/insights-operator-854449444c-zj47k node/ip-10-0-163-162.us-west-1.compute.internal container/insights-operator reason/ContainerExit code/2 cause/Error plog.go:104] "HTTP" verb="GET" URI="/metrics" latency="5.073356ms" userAgent="Prometheus/2.29.2" audit-ID="f5e3cdd3-02ac-4bf8-b798-d553acf8730b" srcIP="10.128.2.10:49220" resp=200\nI0128 20:27:58.449961       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="2.981535ms" userAgent="Prometheus/2.29.2" audit-ID="49c46b5a-3d72-431f-a1ec-25a6006e658b" srcIP="10.129.2.15:53084" resp=200\nI0128 20:28:11.223523       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="7.373571ms" userAgent="Prometheus/2.29.2" audit-ID="25ffe97e-c050-4ce5-92ef-3544e95e39e7" srcIP="10.128.2.10:49220" resp=200\nI0128 20:28:28.224445       1 status.go:354] The operator is healthy\nI0128 20:28:28.224512       1 status.go:441] No status update necessary, objects are identical\nI0128 20:28:28.452004       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="4.842283ms" userAgent="Prometheus/2.29.2" audit-ID="00bca4a4-4223-4a8b-82c4-b6c378c2bd2a" srcIP="10.129.2.15:53084" resp=200\nI0128 20:28:41.220067       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="4.882534ms" userAgent="Prometheus/2.29.2" audit-ID="525f8a97-6847-40ad-aaf6-53ce5a1d88c6" srcIP="10.128.2.10:49220" resp=200\nI0128 20:28:58.451594       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="4.334825ms" userAgent="Prometheus/2.29.2" audit-ID="a9fdd77d-a0c4-4fb9-a915-3bd1c6935036" srcIP="10.129.2.15:53084" resp=200\nI0128 20:29:11.222814       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="6.806343ms" userAgent="Prometheus/2.29.2" audit-ID="0cd22a04-f358-4efd-9763-29248c778506" srcIP="10.128.2.10:49220" resp=200\nI0128 20:29:28.455196       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="8.103753ms" userAgent="Prometheus/2.29.2" audit-ID="76740529-023d-47b6-a5b0-4c9c9a594372" srcIP="10.129.2.15:53084" resp=200\nI0128 20:29:41.220301       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="4.421487ms" userAgent="Prometheus/2.29.2" audit-ID="c6d40833-477a-49a5-a3a3-b72b7c4c22e1" srcIP="10.128.2.10:49220" resp=200\n
Jan 28 20:29:53.572 E ns/openshift-insights pod/insights-operator-854449444c-zj47k node/ip-10-0-163-162.us-west-1.compute.internal container/insights-operator reason/TerminationStateCleared lastState.terminated was cleared on a pod (bug https://bugzilla.redhat.com/show_bug.cgi?id=1933760 or similar)
Jan 28 20:29:55.767 E ns/openshift-controller-manager-operator pod/openshift-controller-manager-operator-65ddc5dd7b-kwlwn node/ip-10-0-163-162.us-west-1.compute.internal container/openshift-controller-manager-operator reason/ContainerExit code/1 cause/Error eus/2.29.2" audit-ID="32814156-5306-41c3-a736-0324ed20887f" srcIP="10.128.2.10:39310" resp=200\nI0128 20:29:44.926882       1 httplog.go:104] "HTTP" verb="GET" URI="/metrics" latency="2.947144ms" userAgent="Prometheus/2.29.2" audit-ID="7ec9fcf1-6f3f-4a6d-9ec5-e3571d5e2b4e" srcIP="10.129.2.15:53548" resp=200\nI0128 20:29:52.691364       1 cmd.go:97] Received SIGTERM or SIGINT signal, shutting down controller.\nI0128 20:29:52.691648       1 genericapiserver.go:386] [graceful-termination] RunPreShutdownHooks has completed\nI0128 20:29:52.691675       1 genericapiserver.go:349] "[graceful-termination] shutdown event" name="ShutdownInitiated"\nI0128 20:29:52.691688       1 genericapiserver.go:352] "[graceful-termination] shutdown event" name="AfterShutdownDelayDuration"\nI0128 20:29:52.691722       1 genericapiserver.go:376] "[graceful-termination] shutdown event" name="InFlightRequestsDrained"\nI0128 20:29:52.691765       1 reflector.go:225] Stopping reflector *v1.ClusterOperator (10m0s) from k8s.io/client-go@v0.22.0-rc.0/tools/cache/reflector.go:167\nI0128 20:29:52.691804       1 base_controller.go:167] Shutting down StaticResourceController ...\nI0128 20:29:52.691816       1 base_controller.go:167] Shutting down ConfigObserver ...\nI0128 20:29:52.691824       1 base_controller.go:167] Shutting down ResourceSyncController ...\nI0128 20:29:52.691833       1 base_controller.go:167] Shutting down UserCAObservationController ...\nI0128 20:29:52.691837       1 reflector.go:225] Stopping reflector *v1.Service (10m0s) from k8s.io/client-go@v0.22.0-rc.0/tools/cache/reflector.go:167\nI0128 20:29:52.691843       1 base_controller.go:167] Shutting down StatusSyncer_openshift-controller-manager ...\nI0128 20:29:52.691847       1 base_controller.go:145] All StatusSyncer_openshift-controller-manager post start hooks have been terminated\nI0128 20:29:52.691898       1 operator.go:115] Shutting down OpenShiftControllerManagerOperator\nW0128 20:29:52.691950       1 builder.go:101] graceful termination failed, controllers failed with error: stopped\n
Jan 28 20:30:05.040 E ns/openshift-ingress-canary pod/ingress-canary-ctdmz node/ip-10-0-160-226.us-west-1.compute.internal container/serve-healthcheck-canary reason/ContainerExit code/2 cause/Error serving on 8888\nserving on 8080\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\nServing canary healthcheck request\n
Jan 28 20:30:07.641 E ns/openshift-console-operator pod/console-operator-6bbd4fcc8c-dqpd5 node/ip-10-0-225-228.us-west-1.compute.internal container/console-operator reason/ContainerExit code/1 cause/Error 0128 20:30:06.514235       1 cmd.go:97] Received SIGTERM or SIGINT signal, shutting down controller.\nI0128 20:30:06.514599       1 genericapiserver.go:398] [graceful-termination] RunPreShutdownHooks has completed\nI0128 20:30:06.514628       1 genericapiserver.go:709] Event(v1.ObjectReference{Kind:"Pod", Namespace:"openshift-console-operator", Name:"console-operator-6bbd4fcc8c-dqpd5", UID:"", APIVersion:"v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'TerminationPreShutdownHooksFinished' All pre-shutdown hooks have been finished\nI0128 20:30:06.514660       1 genericapiserver.go:355] "[graceful-termination] shutdown event" name="ShutdownInitiated"\nI0128 20:30:06.514673       1 genericapiserver.go:709] Event(v1.ObjectReference{Kind:"Pod", Namespace:"openshift-console-operator", Name:"console-operator-6bbd4fcc8c-dqpd5", UID:"", APIVersion:"v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'TerminationStart' Received signal to terminate, becoming unready, but keeping serving\nI0128 20:30:06.514696       1 genericapiserver.go:709] Event(v1.ObjectReference{Kind:"Pod", Namespace:"openshift-console-operator", Name:"console-operator-6bbd4fcc8c-dqpd5", UID:"", APIVersion:"v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'TerminationMinimalShutdownDurationFinished' The minimal shutdown duration of 0s finished\nI0128 20:30:06.514713       1 genericapiserver.go:362] "[graceful-termination] shutdown event" name="AfterShutdownDelayDuration"\nI0128 20:30:06.514731       1 genericapiserver.go:709] Event(v1.ObjectReference{Kind:"Pod", Namespace:"openshift-console-operator", Name:"console-operator-6bbd4fcc8c-dqpd5", UID:"", APIVersion:"v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'TerminationStoppedServing' Server has stopped listening\nI0128 20:30:06.514747       1 genericapiserver.go:387] "[graceful-termination] shutdown event" name="InFlightRequestsDrained"\nW0128 20:30:06.515988       1 builder.go:101] graceful termination failed, controllers failed with error: stopped\n
Jan 28 20:30:08.313 E ns/openshift-cluster-storage-operator pod/cluster-storage-operator-59456fcf98-2szq5 node/ip-10-0-163-162.us-west-1.compute.internal container/cluster-storage-operator reason/ContainerExit code/1 cause/Error eving resource lock openshift-cluster-storage-operator/cluster-storage-operator-lock: Get "https://172.30.0.1:443/api/v1/namespaces/openshift-cluster-storage-operator/configmaps/cluster-storage-operator-lock?timeout=1m47s": dial tcp 172.30.0.1:443: connect: connection refused\nI0128 19:47:52.262229       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 19:47:52.389786       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 19:47:55.345908       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 19:56:27.178837       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 19:57:52.262709       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:02:08.432453       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:07:52.265501       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:16:27.179639       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:17:52.265737       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:22:08.433100       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:27:52.265801       1 controller.go:174] Existing StorageClass gp2 found, reconciling\nI0128 20:30:06.376714       1 cmd.go:97] Received SIGTERM or SIGINT signal, shutting down controller.\nI0128 20:30:06.377211       1 genericapiserver.go:386] [graceful-termination] RunPreShutdownHooks has completed\nI0128 20:30:06.382347       1 genericapiserver.go:349] "[graceful-termination] shutdown event" name="ShutdownInitiated"\nI0128 20:30:06.383206       1 base_controller.go:167] Shutting down SnapshotCRDController ...\nI0128 20:30:06.383220       1 base_controller.go:167] Shutting down CSIDriverStarter ...\nI0128 20:30:06.383228       1 base_controller.go:167] Shutting down AWSEBSCSIDriverOperatorDeployment ...\nW0128 20:30:06.383531       1 builder.go:101] graceful termination failed, controllers failed with error: stopped\n
Jan 28 20:30:08.313 E ns/openshift-cluster-storage-operator pod/cluster-storage-operator-59456fcf98-2szq5 node/ip-10-0-163-162.us-west-1.compute.internal container/cluster-storage-operator reason/TerminationStateCleared lastState.terminated was cleared on a pod (bug https://bugzilla.redhat.com/show_bug.cgi?id=1933760 or similar)
Jan 28 20:30:09.509 E ns/openshift-image-registry pod/cluster-image-registry-operator-864d6d8695-f46nn node/ip-10-0-163-162.us-west-1.compute.internal container/cluster-image-registry-operator reason/TerminationStateCleared lastState.terminated was cleared on a pod (bug https://bugzilla.redhat.com/show_bug.cgi?id=1933760 or similar)
Jan 28 20:30:09.578 E ns/openshift-cluster-storage-operator pod/csi-snapshot-controller-operator-76f948cf74-gg99p node/ip-10-0-163-162.us-west-1.compute.internal container/csi-snapshot-controller-operator reason/ContainerExit code/1 cause/Error ator.go:159] Finished syncing operator at 23.473245ms\nI0128 20:30:06.151752       1 operator.go:157] Starting syncing operator at 2023-01-28 20:30:06.151741515 +0000 UTC m=+3249.410339410\nI0128 20:30:06.373333       1 operator.go:159] Finished syncing operator at 221.580642ms\nI0128 20:30:06.373469       1 operator.go:157] Starting syncing operator at 2023-01-28 20:30:06.37346416 +0000 UTC m=+3249.632062054\nI0128 20:30:06.561613       1 operator.go:159] Finished syncing operator at 188.130357ms\nI0128 20:30:06.561700       1 operator.go:157] Starting syncing operator at 2023-01-28 20:30:06.561696137 +0000 UTC m=+3249.820294032\nI0128 20:30:06.626206       1 operator.go:159] Finished syncing operator at 64.476445ms\nI0128 20:30:06.737858       1 cmd.go:97] Received SIGTERM or SIGINT signal, shutting down controller.\nI0128 20:30:06.738243       1 genericapiserver.go:386] [graceful-termination] RunPreShutdownHooks has completed\nI0128 20:30:06.738270       1 genericapiserver.go:349] "[graceful-termination] shutdown event" name="ShutdownInitiated"\nI0128 20:30:06.738281       1 genericapiserver.go:352] "[graceful-termination] shutdown event" name="AfterShutdownDelayDuration"\nI0128 20:30:06.738298       1 genericapiserver.go:376] "[graceful-termination] shutdown event" name="InFlightRequestsDrained"\nI0128 20:30:06.738635       1 base_controller.go:167] Shutting down StaticResourceController ...\nI0128 20:30:06.738652       1 base_controller.go:167] Shutting down CSISnapshotWebhookController ...\nI0128 20:30:06.738663       1 base_controller.go:167] Shutting down LoggingSyncer ...\nI0128 20:30:06.738672       1 base_controller.go:167] Shutting down StatusSyncer_csi-snapshot-controller ...\nI0128 20:30:06.738677       1 base_controller.go:145] All StatusSyncer_csi-snapshot-controller post start hooks have been terminated\nI0128 20:30:06.738687       1 base_controller.go:167] Shutting down ManagementStateController ...\nW0128 20:30:06.738821       1 builder.go:101] graceful termination failed, controllers failed with error: stopped\n
Jan 28 20:30:11.494 - 3s    E clusteroperator/csi-snapshot-controller condition/Available status/Unknown reason/CSISnapshotControllerAvailable: Waiting for the initial sync of the operator

Found in 5.00% of runs (9.09% of failures) across 20 total runs and 1 jobs (55.00% failed) in 121ms - clear search | chart view - source code located on github