Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

deletion of a SelinuxProfile object hangs forever #2215

Closed
astoycos opened this issue Apr 17, 2024 · 6 comments
Closed

deletion of a SelinuxProfile object hangs forever #2215

astoycos opened this issue Apr 17, 2024 · 6 comments
Labels
kind/bug Categorizes issue or PR as related to a bug.

Comments

@astoycos
Copy link
Member

With the security-profiles-operator.v0.8.2

What happened:

I attempt to delete a selinuxProfile but am unable to because the finalizers are never removed by the node agents.

oc get selinuxprofile -o yaml
apiVersion: v1
items:
- apiVersion: security-profiles-operator.x-k8s.io/v1alpha2
  kind: SelinuxProfile
  metadata:
    annotations:
      kubectl.kubernetes.io/last-applied-configuration: |
        {"apiVersion":"security-profiles-operator.x-k8s.io/v1alpha2","kind":"SelinuxProfile","metadata":{"annotations":{},"name":"bpfman-secure","namespace":"go-xdp-counter"},"spec":{"allow":{"@self":{"bpf":["map_read","map_write"]},"spc_t":{"bpf":["map_read","map_write"]}},"inherit":[{"kind":"System","name":"container"}]}}
    creationTimestamp: "2024-04-17T16:20:57Z"
    deletionGracePeriodSeconds: 0
    deletionTimestamp: "2024-04-17T16:25:35Z"
    finalizers:
    - ci-ln-8ffw50k-72292-t77gq-worker-b-2gsk9-deleted
    - ci-ln-8ffw50k-72292-t77gq-worker-c-ks2vb-deleted
    - ci-ln-8ffw50k-72292-t77gq-master-2-deleted
    - ci-ln-8ffw50k-72292-t77gq-master-1-deleted
    - ci-ln-8ffw50k-72292-t77gq-worker-a-wpk2r-deleted
    - ci-ln-8ffw50k-72292-t77gq-master-0-deleted
    generation: 3

The SPO shows some

astoycos@nfvsdn-02-oot:~/go/src/github.com/bpfd-dev/bpfman$ oc logs -n openshift-security-profiles  security-profiles-operator-79597c547f-962w5
I0417 16:06:57.159515       1 main.go:263] "Set logging verbosity to 0"
I0417 16:06:57.159741       1 main.go:269] "Profiling support enabled: false"
I0417 16:06:57.160179       1 main.go:289] "starting component: security-profiles-operator" logger="setup" version="0.8.2" 
...
I0417 16:06:57.161926       1 main.go:368] "watching all namespaces" logger="setup"
I0417 16:06:57.190520       1 setup.go:174] "matched selinuxd image against nodeInfo" logger="spod-config" image="registry.redhat.io/compliance/openshift-selinuxd-rhel9@sha256:07386b0e0416b1c053e10d6a02479fbdd35ca97cc583a919ed53daacd029915d"
I0417 16:06:57.238648       1 main.go:351] "starting manager" logger="setup"
I0417 16:06:57.238747       1 server.go:185] "Starting metrics server" logger="controller-runtime.metrics"
I0417 16:06:57.239346       1 server.go:224] "Serving metrics server" logger="controller-runtime.metrics" bindAddress=":8080" secure=false
I0417 16:06:57.440388       1 leaderelection.go:250] attempting to acquire leader lease openshift-security-profiles/security-profiles-operator-lock...
I0417 16:06:57.458550       1 leaderelection.go:260] successfully acquired lease openshift-security-profiles/security-profiles-operator-lock
I0417 16:06:57.458994       1 controller.go:178] "Starting EventSource" controller="nodestatus" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfileNodeStatus" source="kind source: *v1alpha1.SecurityProfileNodeStatus"
I0417 16:06:57.459006       1 controller.go:178] "Starting EventSource" controller="spod-config" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfilesOperatorDaemon" source="kind source: *v1alpha1.SecurityProfilesOperatorDaemon"
I0417 16:06:57.459069       1 controller.go:178] "Starting EventSource" controller="policymerger" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="ProfileRecording" source="kind source: *v1alpha1.ProfileRecording"
I0417 16:06:57.459081       1 controller.go:178] "Starting EventSource" controller="pods" controllerGroup="" controllerKind="Pod" source="kind source: *v1.Pod"
I0417 16:06:57.459365       1 controller.go:186] "Starting Controller" controller="pods" controllerGroup="" controllerKind="Pod"
I0417 16:06:57.459192       1 controller.go:178] "Starting EventSource" controller="spod-config" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfilesOperatorDaemon" source="kind source: *v1.DaemonSet"
I0417 16:06:57.459507       1 controller.go:186] "Starting Controller" controller="spod-config" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfilesOperatorDaemon"
I0417 16:06:57.459126       1 controller.go:186] "Starting Controller" controller="nodestatus" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfileNodeStatus"
I0417 16:06:57.459304       1 controller.go:186] "Starting Controller" controller="policymerger" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="ProfileRecording"
I0417 16:06:57.559522       1 controller.go:220] "Starting workers" controller="policymerger" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="ProfileRecording" worker count=1
I0417 16:06:57.559577       1 controller.go:220] "Starting workers" controller="nodestatus" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfileNodeStatus" worker count=1
I0417 16:06:57.563543       1 controller.go:220] "Starting workers" controller="spod-config" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfilesOperatorDaemon" worker count=1
I0417 16:06:57.563543       1 controller.go:220] "Starting workers" controller="pods" controllerGroup="" controllerKind="Pod" worker count=1
I0417 16:06:57.563792       1 spod_controller.go:244] "Adding an initial status to the SPOD instance" logger="spod-config" profile="spod" namespace="openshift-security-profiles"
I0417 16:06:57.781124       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:06:57.781380       1 spod_controller.go:325] "Deploying operator webhook" logger="spod-config"
I0417 16:06:57.833646       1 warning_handler.go:65] "spec.template.metadata.annotations[seccomp.security.alpha.kubernetes.io/pod]: non-functional in v1.27+; use the \"seccompProfile\" field instead" logger="KubeAPIWarningLogger"
I0417 16:06:57.940699       1 spod_controller.go:331] "Creating operator resources" logger="spod-config"
I0417 16:06:57.940810       1 spod_controller.go:336] "Deploying operator daemonset" logger="spod-config"
I0417 16:06:58.343011       1 spod_controller.go:344] "Deploying operator default profiles" logger="spod-config"
I0417 16:06:58.343043       1 spod_controller.go:359] "Deploying metrics service" logger="spod-config"
I0417 16:06:58.398805       1 spod_controller.go:367] "Deploying operator service monitor" logger="spod-config"
I0417 16:06:58.447630       1 spod_controller.go:259] "Adding 'Creating' status to the SPOD instance" logger="spod-config" profile="spod" namespace="openshift-security-profiles"
I0417 16:06:58.488450       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:06:58.589335       1 spod_controller.go:298] "Adding 'Running' status to the SPOD instance" logger="spod-config" profile="spod" namespace="openshift-security-profiles"
...
I0417 16:20:57.605173       1 nodestatus.go:134] "Initializing Profile status" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-b-2gsk9" namespace="go-xdp-counter" Profile.Name="bpfman-secure" Profile.Namespace="go-xdp-counter" Profile.Kind="security-profiles-operator.x-k8s.io/v1alpha2, Kind=SelinuxProfile"
I0417 16:20:57.620807       1 nodestatus.go:134] "Initializing Profile status" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-b-2gsk9" namespace="go-xdp-counter" Profile.Name="bpfman-secure" Profile.Namespace="go-xdp-counter" Profile.Kind="security-profiles-operator.x-k8s.io/v1alpha2, Kind=SelinuxProfile"
E0417 16:20:57.631648       1 controller.go:329] "Reconciler error" err="updating policy status: Operation cannot be fulfilled on selinuxprofiles.security-profiles-operator.x-k8s.io \"bpfman-secure\": the object has been modified; please apply your changes to the latest version and try again" controller="nodestatus" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfileNodeStatus" SecurityProfileNodeStatus="go-xdp-counter/bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-b-2gsk9" namespace="go-xdp-counter" name="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-b-2gsk9" reconcileID="71170f6b-6c0b-4e44-a418-4f435e787818"
I0417 16:20:57.637107       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-b-2gsk9" namespace="go-xdp-counter" has=1 wants=6
I0417 16:20:58.110422       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-c-ks2vb" namespace="go-xdp-counter" has=2 wants=6
I0417 16:20:58.127245       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-c-ks2vb" namespace="go-xdp-counter" has=2 wants=6
I0417 16:20:58.185476       1 warning_handler.go:65] "metadata.finalizers: \"in-use-by-active-pods\": prefer a domain-qualified finalizer name to avoid accidental conflicts with other finalizer writers" logger="KubeAPIWarningLogger"
I0417 16:20:58.869480       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-2" namespace="go-xdp-counter" has=3 wants=6
I0417 16:20:58.884666       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-2" namespace="go-xdp-counter" has=3 wants=6
I0417 16:21:00.015345       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-1" namespace="go-xdp-counter" has=4 wants=6
I0417 16:21:00.025627       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-1" namespace="go-xdp-counter" has=4 wants=6
I0417 16:21:01.764830       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-a-wpk2r" namespace="go-xdp-counter" has=5 wants=6
I0417 16:21:01.776381       1 nodestatus.go:174] "Not updating policy: not all statuses are ready" logger="nodestatus" nodeStatus="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-worker-a-wpk2r" namespace="go-xdp-counter" has=5 wants=6
E0417 16:21:02.288259       1 controller.go:329] "Reconciler error" err="updating policy status: Operation cannot be fulfilled on selinuxprofiles.security-profiles-operator.x-k8s.io \"bpfman-secure\": the object has been modified; please apply your changes to the latest version and try again" controller="nodestatus" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfileNodeStatus" SecurityProfileNodeStatus="go-xdp-counter/bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-0" namespace="go-xdp-counter" name="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-0" reconcileID="f926e0a6-1639-4306-b408-d83ad0919410"
I0417 16:21:26.634914       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:21:56.606819       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:22:26.577805       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:22:56.549663       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:23:26.520745       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:23:56.492573       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:24:26.463670       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:24:56.434687       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:25:26.405691       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
E0417 16:25:35.611883       1 controller.go:329] "Reconciler error" err="updating policy status: Operation cannot be fulfilled on selinuxprofiles.security-profiles-operator.x-k8s.io \"bpfman-secure\": the object has been modified; please apply your changes to the latest version and try again" controller="nodestatus" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SecurityProfileNodeStatus" SecurityProfileNodeStatus="go-xdp-counter/bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-0" namespace="go-xdp-counter" name="bpfman-secure-ci-ln-8ffw50k-72292-t77gq-master-0" reconcileID="a6d74d37-6964-41e7-9232-6c1e5d283e37"
I0417 16:25:56.377004       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:26:26.348560       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:26:56.320100       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:27:26.292064       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:27:56.263831       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:28:26.234985       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:28:56.206421       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:29:26.177641       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:29:56.149434       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:30:26.121207       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:30:56.093096       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:31:26.064133       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:31:56.035341       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:32:26.006555       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:32:55.977617       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:33:25.948526       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:33:55.919482       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:34:25.891078       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:34:55.862927       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:35:25.834001       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:35:55.805298       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"
I0417 16:36:25.776940       1 ca.go:59] "Using OpenShift as certificate provider" logger="spod-config"

The node daemon completes successfully

astoycos@nfvsdn-02-oot:~/go/src/github.com/bpfd-dev/bpfman$ oc logs -n openshift-security-profiles spod-7dsz2 -c selinuxd
{"level":"info","ts":1713370063.0483968,"caller":"version/version.go:42","msg":"selinuxd information","version":"","buildDate":"'2024-01-17T01:53:17Z'","compiler":"gc","platform":"linux/amd64"}
{"level":"info","ts":1713370063.0488312,"caller":"daemon/daemon.go:30","msg":"Started daemon"}
{"level":"info","ts":1713370063.056219,"logger":"state-server","caller":"daemon/status_server.go:190","msg":"Serving status","path":"/var/run/selinuxd/selinuxd.sock","uid":0,"gid":65535}
{"level":"info","ts":1713370063.0566123,"caller":"daemon/status_server.go:73","msg":"Status Server got READY signal"}
{"level":"info","ts":1713370969.767558,"logger":"file-watcher","caller":"daemon/daemon.go:93","msg":"Installing policy","file":"/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"}
{"level":"info","ts":1713370969.7676404,"logger":"file-watcher","caller":"daemon/daemon.go:93","msg":"Installing policy","file":"/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"}
{"level":"info","ts":1713370979.8619545,"caller":"policycoreutils/policycoreutils.go:45","msg":"Installing policy","modulePath":"/etc/selinux.d/bpfman-secure_go-xdp-counter.cil","output":""}
{"level":"info","ts":1713370979.8785255,"logger":"policy-installer","caller":"daemon/daemon.go:131","msg":"The operation was successful","operation":"install - /etc/selinux.d/bpfman-secure_go-xdp-counter.cil"}
{"level":"info","ts":1713370979.8789628,"logger":"policy-installer","caller":"daemon/daemon.go:131","msg":"The operation was successful","operation":"install - /etc/selinux.d/bpfman-secure_go-xdp-counter.cil"}
{"level":"info","ts":1713371135.569909,"logger":"file-watcher","caller":"daemon/daemon.go:90","msg":"Removing policy","file":"/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"}
{"level":"info","ts":1713371145.5565286,"caller":"policycoreutils/policycoreutils.go:72","msg":"Removing a policy","output":"libsemanage.semanage_direct_remove_key: Removing last bpfman-secure_go-xdp-counter module (no other bpfman-secure_go-xdp-counter module exists at another priority).\n"}
{"level":"info","ts":1713371145.5592377,"logger":"policy-installer","caller":"daemon/daemon.go:131","msg":"The operation was successful","operation":"remove - /etc/selinux.d/bpfman-secure_go-xdp-counter.cil"}

The Node operator container looks wierd

astoycos@nfvsdn-02-oot:~/go/src/github.com/bpfd-dev/bpfman$ oc logs -n openshift-security-profiles spod-7dsz2  -c security-profiles-operator
I0417 16:07:42.165888       1 main.go:263] "Set logging verbosity to 0"
I0417 16:07:42.165933       1 main.go:269] "Profiling support enabled: false"
I0417 16:07:42.165972       1 main.go:289] "starting component: spod" logger="setup" version="0.8.2" gitCommit="unknown" 
...
I0417 16:07:42.167987       1 metrics.go:217] "Registering metric: apparmor_profile_error_total" logger="metrics"
I0417 16:07:42.168087       1 metrics.go:217] "Registering metric: seccomp_profile_bpf_total" logger="metrics"
I0417 16:07:42.168105       1 metrics.go:217] "Registering metric: apparmor_profile_audit_total" logger="metrics"
I0417 16:07:42.168114       1 metrics.go:217] "Registering metric: seccomp_profile_error_total" logger="metrics"
I0417 16:07:42.168123       1 metrics.go:217] "Registering metric: selinux_profile_total" logger="metrics"
I0417 16:07:42.168135       1 metrics.go:217] "Registering metric: selinux_profile_audit_total" logger="metrics"
I0417 16:07:42.168143       1 metrics.go:217] "Registering metric: selinux_profile_error_total" logger="metrics"
I0417 16:07:42.168153       1 metrics.go:217] "Registering metric: apparmor_profile_total" logger="metrics"
I0417 16:07:42.168165       1 metrics.go:217] "Registering metric: seccomp_profile_total" logger="metrics"
I0417 16:07:42.168172       1 metrics.go:217] "Registering metric: seccomp_profile_audit_total" logger="metrics"
I0417 16:07:42.169455       1 main.go:368] "watching all namespaces" logger="setup"
I0417 16:07:42.169658       1 grpc.go:60] "Starting GRPC server API" logger="metrics"
I0417 16:07:42.171759       1 main.go:497] "starting daemon" logger="setup"
I0417 16:07:42.172009       1 server.go:185] "Starting metrics server" logger="controller-runtime.metrics"
I0417 16:07:42.172182       1 server.go:50] "starting server" kind="health probe" addr="[::]:8085"
I0417 16:07:42.172180       1 server.go:224] "Serving metrics server" logger="controller-runtime.metrics" bindAddress=":8080" secure=false
I0417 16:07:42.172560       1 controller.go:178] "Starting EventSource" controller="profile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SeccompProfile" source="kind source: *v1beta1.SeccompProfile"
I0417 16:07:42.172592       1 controller.go:178] "Starting EventSource" controller="rawselinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="RawSelinuxProfile" source="kind source: *v1alpha2.RawSelinuxProfile"
I0417 16:07:42.172696       1 controller.go:186] "Starting Controller" controller="rawselinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="RawSelinuxProfile"
I0417 16:07:42.172647       1 controller.go:178] "Starting EventSource" controller="profile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SeccompProfile" source="kind source: *v1alpha1.SecurityProfilesOperatorDaemon"
I0417 16:07:42.172769       1 controller.go:186] "Starting Controller" controller="profile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SeccompProfile"
I0417 16:07:42.172815       1 controller.go:178] "Starting EventSource" controller="selinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SelinuxProfile" source="kind source: *v1alpha2.SelinuxProfile"
I0417 16:07:42.172915       1 controller.go:186] "Starting Controller" controller="selinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SelinuxProfile"
I0417 16:07:42.291417       1 controller.go:220] "Starting workers" controller="profile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SeccompProfile" worker count=1
I0417 16:07:42.294735       1 controller.go:220] "Starting workers" controller="rawselinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="RawSelinuxProfile" worker count=1
I0417 16:07:42.294745       1 controller.go:220] "Starting workers" controller="selinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SelinuxProfile" worker count=1
I0417 16:20:57.451694       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:20:58.095153       1 warning_handler.go:65] "metadata.finalizers: \"ci-ln-8ffw50k-72292-t77gq-master-0-deleted\": prefer a domain-qualified finalizer name to avoid accidental conflicts with other finalizer writers" logger="KubeAPIWarningLogger"
E0417 16:21:01.709638       1 controller.go:329] "Reconciler error" err="cannot ensure node status: cannot create finalizer for bpfman-secure: wait on retry: timed out waiting for the condition" controller="selinuxprofile" controllerGroup="security-profiles-operator.x-k8s.io" controllerKind="SelinuxProfile" SelinuxProfile="go-xdp-counter/bpfman-secure" namespace="go-xdp-counter" name="bpfman-secure" reconcileID="4786bcaf-5172-484f-958e-0f136e797791"
I0417 16:21:01.709936       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
...
I0417 16:25:35.503877       1 common_controller.go:275] "Checking if policy deployed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.504487       1 common_controller.go:308] "Policy deployed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" status="Installed"
I0417 16:25:35.529225       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.529891       1 common_controller.go:275] "Checking if policy deployed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.530225       1 common_controller.go:308] "Policy deployed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" status="Installed"
I0417 16:25:35.552359       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.568945       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.569113       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.576230       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.593642       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.593826       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.594188       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.594279       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.594387       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.608382       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.608569       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.608916       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.609019       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.609186       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.629776       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.629967       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.630294       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.630374       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.630452       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.653703       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.653891       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.654247       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.654336       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.671021       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.689524       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.689720       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.690751       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.690773       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.857600       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.870142       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:35.870192       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:35.870438       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:35.870515       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.191167       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.202502       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:36.202558       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:36.202889       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.202928       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.835463       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.854955       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:36.855006       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:36.855356       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.855386       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.855445       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.865498       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:36.865580       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:36.866089       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:36.866115       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.371611       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.385547       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:37.385735       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:37.386184       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.386279       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.386726       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.398202       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:37.398253       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:37.398471       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.398492       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.912635       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.924836       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:37.924914       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:37.925236       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:37.925413       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:38.136512       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:38.147116       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:38.147166       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:38.147512       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:38.147533       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:41.010651       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:41.022681       1 common_controller.go:395] "Removing policy file" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyPath="/etc/selinux.d/bpfman-secure_go-xdp-counter.cil"
I0417 16:25:41.022875       1 common_controller.go:358] "Checking if policy is removed" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure" policyName="bpfman-secure"
I0417 16:25:41.023259       1 common_controller.go:372] "Policy still installed, requeue" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:25:41.023371       1 common_controller.go:218] "Re-queueing delete request to make sure the policy is gone" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:26:09.400042       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:26:19.107720       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:26:37.790343       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:27:06.180351       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:27:34.570622       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:28:02.960708       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:28:31.350584       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:28:59.739993       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:29:28.129440       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:29:56.519519       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:30:24.909153       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:30:53.298971       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:31:21.689125       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:31:50.078630       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:32:18.468061       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"
I0417 16:32:46.858216       1 common_controller.go:161] "Reconciling object in selinuxprofile" logger="selinuxprofile" Request.Namespace="go-xdp-counter" Request.Name="bpfman-secure"

What you expected to happen:

Selinux Profile is cleaned up correctly

How to reproduce it (as minimally and precisely as possible):

Spin up an OCP cluster, in this case

astoycos@nfvsdn-02-oot:~/go/src/github.com/bpfd-dev/bpfman$ oc version
Client Version: 4.7.19
Server Version: 4.16.0-0.nightly-2024-04-16-195622
Kubernetes Version: v1.29.3+5fa1806`

install the SPO from operatorhub

install a selinux profile, use it in a pod, then delete it

Anything else we need to know?:

I can manually remove the finalizers and deletion works.

Environment:

  • Cloud provider or hardware configuration: OCP on GCP
  • OS (e.g: cat /etc/os-release):
sh-5.1# cat /etc/os-release
NAME="Red Hat Enterprise Linux CoreOS"
ID="rhcos"
ID_LIKE="rhel fedora"
VERSION="416.94.202404160241-0"
VERSION_ID="4.16"
VARIANT="CoreOS"
VARIANT_ID=coreos
PLATFORM_ID="platform:el9"
PRETTY_NAME="Red Hat Enterprise Linux CoreOS 416.94.202404160241-0"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:redhat:enterprise_linux:9::baseos::coreos"
HOME_URL="https://www.redhat.com/"
DOCUMENTATION_URL="https://docs.okd.io/latest/welcome/index.html"
BUG_REPORT_URL="https://access.redhat.com/labs/rhir/"
REDHAT_BUGZILLA_PRODUCT="OpenShift Container Platform"
REDHAT_BUGZILLA_PRODUCT_VERSION="4.16"
REDHAT_SUPPORT_PRODUCT="OpenShift Container Platform"
REDHAT_SUPPORT_PRODUCT_VERSION="4.16"
OPENSHIFT_VERSION="4.16"
RHEL_VERSION=9.4
OSTREE_VERSION="416.94.202404160241-0"
  • Kernel (e.g. uname -a): sh-5.1# uname -r 5.14.0-427.el9.x86_64
  • Others:
@astoycos astoycos added the kind/bug Categorizes issue or PR as related to a bug. label Apr 17, 2024
@saschagrunert
Copy link
Member

@astoycos thank you for the report! Are the nodes existing in the cluster or have they removed?

@astoycos
Copy link
Member Author

Sorry it actually was a cluster-bot cluster so they were pruned :/

I'll let you know if I can re-create, are there any other logs I can collect to help?

@saschagrunert
Copy link
Member

I think the issue may be related to #2067

@astoycos
Copy link
Member Author

Thanks I'll try and repro!

@ccojocar
Copy link
Contributor

I think this can be closed now since #2067 was resolved. @astoycos please feel free to reopen it if you see the issue still persist after using the next release version which should contains the fix. Thanks

@astoycos
Copy link
Member Author

Ack thanks!

@Billy99 Billy99 mentioned this issue Jan 21, 2025
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug Categorizes issue or PR as related to a bug.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ccojocar @saschagrunert @astoycos