Repository: kubernetes-sigs/security-profiles-operator
Pull request #491 (2021-06-21 10:07:27)

Retry log-enricher if container ID is empty
#### What type of PR is this?

/kind feature


#### What this PR does / why we need it:
During the creation of a container, it may be possible that the
container ID is still empty while looking up for log enrichment.

We now retry the whole process to be able to make the enricher more
robust.
#### Which issue(s) this PR fixes:

<!--
*Automatically closes linked issue when PR is merged.
Usage: `Fixes #<issue number>`, or `Fixes (paste link of issue)`.

Fixes #

or

None
-->
None
#### Does this PR have test?
None
<!--
If tests aren't applicable just write N/A.
-->

#### Special notes for your reviewer:
None
#### Does this PR introduce a user-facing change?

<!--
If no, just write "NONE" in the release-note block below.
If yes, a release note is required:
Enter your extended release note in the block below. If the PR requires additional action from users switching to the new release, include the string "action required".

For more information on release notes see: https://git.k8s.io/community/contributors/guide/release-notes.md
-->

```release-note
Add retry functionality to log enricher if container ID is still empty during pod creation.
```


k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes-sigs/security-profiles-operator/pull/491#" title="Author self-approved">saschagrunert</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes-sigs%2Fsecurity-profiles-operator).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/kubernetes-sigs/security-profiles-operator/blob/master/OWNERS)~~ [saschagrunert]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
k8s-ci-robot: @saschagrunert: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-security-profiles-operator-test-e2e | 7a8377462225a82ecfb4b4f2b5a42e6e55b419aa | [link](https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/kubernetes-sigs_security-profiles-operator/491/pull-security-profiles-operator-test-e2e/1406916672673026048) | `/test pull-security-profiles-operator-test-e2e`

[Full PR test history](https://prow.k8s.io/pr-history?org=kubernetes-sigs&repo=security-profiles-operator&pr=491). [Your PR dashboard](https://prow.k8s.io/pr?query=is%3Apr%20state%3Aopen%20author%3Asaschagrunert). Please help us cut down on flakes by [linking to](https://git.k8s.io/community/contributors/devel/sig-testing/flaky-tests.md#filing-issues-for-flaky-tests) an [open issue](https://github.com/kubernetes-sigs/security-profiles-operator/issues?q=is:issue+is:open) when you hit one in your PR.

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository. I understand the commands that are listed [here](https://go.k8s.io/bot-commands).
</details>
<!-- test report -->
saschagrunert: /test pull-security-profiles-operator-test-e2e

Patch:
diff --git a/cmd/security-profiles-operator/main.go b/cmd/security-profiles-operator/main.go
index fcb2874b8..8bc487144 100644
--- a/cmd/security-profiles-operator/main.go
+++ b/cmd/security-profiles-operator/main.go
@@ -133,11 +133,9 @@ func main() {
 			},
 		},
 		&cli.Command{
-			Name:  "non-root-enabler",
-			Usage: "run the non root enabler",
-			Action: func(*cli.Context) error {
-				return nonrootenabler.New().Run()
-			},
+			Name:   "non-root-enabler",
+			Usage:  "run the non root enabler",
+			Action: runNonRootEnabler,
 		},
 		&cli.Command{
 			Name:    "log-enricher",
@@ -324,8 +322,15 @@ func runDaemon(ctx *cli.Context) error {
 }
 
 func runLogEnricher(ctx *cli.Context) error {
-	printInfo("log-enricher")
-	return enricher.Run(ctrl.Log.WithName("log-enricher"))
+	const component = "log-enricher"
+	printInfo(component)
+	return enricher.Run(ctrl.Log.WithName(component))
+}
+
+func runNonRootEnabler(ctx *cli.Context) error {
+	const component = "non-root-enabler"
+	printInfo(component)
+	return nonrootenabler.New().Run(ctrl.Log.WithName(component))
 }
 
 func runWebhook(ctx *cli.Context) error {
diff --git a/go.mod b/go.mod
index 54a2112e6..4ae617bfd 100644
--- a/go.mod
+++ b/go.mod
@@ -18,7 +18,7 @@ require (
 	google.golang.org/grpc/cmd/protoc-gen-go-grpc v1.1.0
 	google.golang.org/protobuf v1.26.0
 	k8s.io/api v0.20.6
-	k8s.io/apimachinery v0.21.1
+	k8s.io/apimachinery v0.21.2
 	k8s.io/client-go v0.20.6
 	k8s.io/klog/v2 v2.9.0
 	sigs.k8s.io/controller-runtime v0.8.3
diff --git a/go.sum b/go.sum
index 3d430e119..23c9668d7 100644
--- a/go.sum
+++ b/go.sum
@@ -1174,7 +1174,6 @@ golang.org/x/sys v0.0.0-20201202213521-69691e467435/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210112080510-489259a85091/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210225134936-a50acf3fe073/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210324051608-47abb6519492/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
@@ -1437,8 +1436,8 @@ k8s.io/apimachinery v0.20.1/go.mod h1:WlLqWAHZGg07AeltaI0MV5uk1Omp8xaN0JGLY6gkRp
 k8s.io/apimachinery v0.20.2/go.mod h1:WlLqWAHZGg07AeltaI0MV5uk1Omp8xaN0JGLY6gkRpU=
 k8s.io/apimachinery v0.20.4/go.mod h1:WlLqWAHZGg07AeltaI0MV5uk1Omp8xaN0JGLY6gkRpU=
 k8s.io/apimachinery v0.20.6/go.mod h1:ejZXtW1Ra6V1O5H8xPBGz+T3+4gfkTCeExAHKU57MAc=
-k8s.io/apimachinery v0.21.1 h1:Q6XuHGlj2xc+hlMCvqyYfbv3H7SRGn2c8NycxJquDVs=
-k8s.io/apimachinery v0.21.1/go.mod h1:jbreFvJo3ov9rj7eWT7+sYiRx+qZuCYXwWT1bcDswPY=
+k8s.io/apimachinery v0.21.2 h1:vezUc/BHqWlQDnZ+XkrpXSmnANSLbpnlpwo0Lhk0gpc=
+k8s.io/apimachinery v0.21.2/go.mod h1:CdTY8fU/BlvAbJ2z/8kBwimGki5Zp8/fbVuLY8gJumM=
 k8s.io/apiserver v0.0.0-20190918160949-bfa5e2e684ad/go.mod h1:XPCXEwhjaFN29a8NldXA901ElnKeKLrLtREO9ZhFyhg=
 k8s.io/apiserver v0.18.3/go.mod h1:tHQRmthRPLUtwqsOnJJMoI8SW3lnoReZeE861lH8vUw=
 k8s.io/apiserver v0.20.1/go.mod h1:ro5QHeQkgMS7ZGpvf4tSMx6bBOgPfE+f52KwvXfScaU=
diff --git a/internal/pkg/daemon/enricher/container.go b/internal/pkg/daemon/enricher/container.go
index 002542783..8a96f2ce3 100644
--- a/internal/pkg/daemon/enricher/container.go
+++ b/internal/pkg/daemon/enricher/container.go
@@ -30,6 +30,8 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/client-go/kubernetes"
 	"k8s.io/client-go/rest"
+
+	"sigs.k8s.io/security-profiles-operator/internal/pkg/util"
 )
 
 const (
@@ -42,7 +44,7 @@ const (
 // Cluster scoped
 // +kubebuilder:rbac:groups=core,resources=pods,verbs=get;list;watch;
 
-func getNodeContainers(nodeName string) (map[string]containerInfo, error) {
+func getNodeContainers(logger logr.Logger, nodeName string) (map[string]containerInfo, error) {
 	config, err := rest.InClusterConfig()
 	if err != nil {
 		return nil, errors.Wrap(err, "get in-cluster config")
@@ -53,30 +55,56 @@ func getNodeContainers(nodeName string) (map[string]containerInfo, error) {
 		return nil, errors.Wrap(err, "load in-cluster config")
 	}
 
-	pods, err := clientset.CoreV1().Pods("").List(context.TODO(), metav1.ListOptions{
-		FieldSelector: "spec.nodeName=" + nodeName,
-	})
-	if err != nil {
-		return nil, errors.Wrapf(err, "list node %s's pods", nodeName)
-	}
-
 	containers := make(map[string]containerInfo)
-	for p := range pods.Items {
-		for c := range pods.Items[p].Status.ContainerStatuses {
-			containerID, err := containerIDRaw(pods.Items[p].Status.ContainerStatuses[c].ContainerID)
+	err = util.Retry(
+		func() (retryErr error) {
+			pods, err := clientset.CoreV1().Pods("").List(context.TODO(), metav1.ListOptions{
+				FieldSelector: "spec.nodeName=" + nodeName,
+			})
 			if err != nil {
-				return nil, errors.Wrap(err, "container id")
+				return errors.Wrapf(err, "list node %s's pods", nodeName)
 			}
 
-			containers[containerID] = containerInfo{
-				PodName:       pods.Items[p].Name,
-				ContainerName: pods.Items[p].Status.ContainerStatuses[c].Name,
-				Namespace:     pods.Items[p].Namespace,
-				ContainerID:   containerID,
+			containers = make(map[string]containerInfo)
+			for p := range pods.Items {
+				pod := pods.Items[p]
+
+				for c := range pod.Status.ContainerStatuses {
+					containerStatus := pod.Status.ContainerStatuses[c]
+					containerID := containerStatus.ContainerID
+
+					if containerID == "" {
+						logger.Info(
+							"container ID is still empty, retrying",
+							"containerName", containerStatus.Name,
+						)
+						return errContainerIDEmpty
+					}
+
+					rawContainerID, err := containerIDRaw(containerID)
+					if err != nil {
+						logger.Error(
+							err, "unable to get container ID",
+							"containerName", pod.Name,
+						)
+						continue
+					}
+
+					containers[rawContainerID] = containerInfo{
+						PodName:       pod.Name,
+						ContainerName: containerStatus.Name,
+						Namespace:     pod.Namespace,
+						ContainerID:   rawContainerID,
+					}
+				}
 			}
-		}
-	}
-	return containers, nil
+			return nil
+		},
+		func(inErr error) bool {
+			return errors.Is(inErr, errContainerIDEmpty)
+		},
+	)
+	return containers, err
 }
 
 func containerIDRaw(containerID string) (string, error) {
@@ -87,12 +115,11 @@ func containerIDRaw(containerID string) (string, error) {
 	return "", errors.Wrap(errUnsupportedContainerRuntime, containerID)
 }
 
-func getContainerID(logger logr.Logger, processID int) string {
+func getContainerID(processID int) (string, error) {
 	cgroupFile := fmt.Sprintf("/proc/%d/cgroup", processID)
 	file, err := os.Open(filepath.Clean(cgroupFile))
 	if err != nil {
-		logger.Error(nil, "could not open cgroup", "process-id", processID)
-		return ""
+		return "", errors.Errorf("could not open cgroup path %s", cgroupFile)
 	}
 	defer func() {
 		cerr := file.Close()
@@ -105,11 +132,11 @@ func getContainerID(logger logr.Logger, processID int) string {
 	scanner.Split(bufio.ScanLines)
 	for scanner.Scan() {
 		if containerID := extractID(scanner.Text()); containerID != "" {
-			return containerID
+			return containerID, nil
 		}
 	}
 
-	return ""
+	return "", errors.New("unable to find container ID from cgroup path")
 }
 
 func extractID(cgroup string) string {
diff --git a/internal/pkg/daemon/enricher/enricher.go b/internal/pkg/daemon/enricher/enricher.go
index 32861a7ad..6551f915f 100644
--- a/internal/pkg/daemon/enricher/enricher.go
+++ b/internal/pkg/daemon/enricher/enricher.go
@@ -17,7 +17,6 @@ limitations under the License.
 package enricher
 
 import (
-	"fmt"
 	"os"
 	"time"
 
@@ -78,22 +77,37 @@ func Run(logger logr.Logger) error {
 			continue
 		}
 
-		cID := getContainerID(logger, auditLine.ProcessID)
-		containers, err := getNodeContainers(nodeName)
+		cID, err := getContainerID(auditLine.ProcessID)
+		if err != nil {
+			logger.Error(err, "unable to get container ID", "processID", auditLine.ProcessID)
+			continue
+		}
+
+		containers, err := getNodeContainers(logger, nodeName)
 		c, found := containers[cID]
 
 		if !found {
-			logger.Error(err, "containerID not found", "processID", auditLine.ProcessID)
+			logger.Error(
+				err, "containerID not found in cluster",
+				"processID", auditLine.ProcessID,
+				"containerID", cID,
+			)
 			continue
 		}
 
 		name := systemCalls[auditLine.SystemCallID]
-		logger.Info(fmt.Sprintf(
-			"audit(%s) type=%s node=%s pid=%d ns=%s pod=%s c=%s exe=%s scid=%d scname=%s",
-			auditLine.TimestampID, auditLine.Type, nodeName,
-			auditLine.ProcessID, c.Namespace, c.PodName,
-			c.ContainerName, auditLine.Executable, auditLine.SystemCallID, name,
-		))
+		logger.Info("audit",
+			"timestamp", auditLine.TimestampID,
+			"type", auditLine.Type,
+			"node", nodeName,
+			"namespace", c.Namespace,
+			"pod", c.PodName,
+			"container", c.ContainerName,
+			"executable", auditLine.Executable,
+			"pid", auditLine.ProcessID,
+			"syscallID", auditLine.SystemCallID,
+			"syscallName", name,
+		)
 	}
 
 	logger.Error(tailFile.Err(), "enricher failed")
diff --git a/internal/pkg/daemon/enricher/types.go b/internal/pkg/daemon/enricher/types.go
index 4ee5bbb12..3eda81008 100644
--- a/internal/pkg/daemon/enricher/types.go
+++ b/internal/pkg/daemon/enricher/types.go
@@ -21,6 +21,7 @@ import "errors"
 var (
 	errUnsupportedContainerRuntime = errors.New("unsupported container runtime")
 	errUnsupportedLogLine          = errors.New("unsupported log line")
+	errContainerIDEmpty            = errors.New("container ID is empty")
 )
 
 type auditLine struct {
diff --git a/internal/pkg/nonrootenabler/nonrootenabler.go b/internal/pkg/nonrootenabler/nonrootenabler.go
index 7ccae2c16..d28af8f75 100644
--- a/internal/pkg/nonrootenabler/nonrootenabler.go
+++ b/internal/pkg/nonrootenabler/nonrootenabler.go
@@ -19,6 +19,7 @@ package nonrootenabler
 import (
 	"os"
 
+	"github.com/go-logr/logr"
 	"github.com/pkg/errors"
 	"sigs.k8s.io/release-utils/util"
 
@@ -42,9 +43,10 @@ func (n *NonRootEnabler) SetImpl(i impl) {
 }
 
 // Run executes the NonRootEnabler and returns an error if anything fails.
-func (n *NonRootEnabler) Run() error {
+func (n *NonRootEnabler) Run(logger logr.Logger) error {
 	const dirPermissions os.FileMode = 0o744
 
+	logger.Info("Ensuring seccomp root path: " + config.KubeletSeccompRootPath)
 	if err := n.impl.MkdirAll(
 		config.KubeletSeccompRootPath, dirPermissions,
 	); err != nil {
@@ -53,6 +55,7 @@ func (n *NonRootEnabler) Run() error {
 		)
 	}
 
+	logger.Info("Ensuring operator root path: " + config.OperatorRoot)
 	if err := n.impl.MkdirAll(
 		config.OperatorRoot, dirPermissions,
 	); err != nil {
@@ -60,12 +63,15 @@ func (n *NonRootEnabler) Run() error {
 			err, "create operator root path %s", config.KubeletSeccompRootPath,
 		)
 	}
+
 	// In case the directory already existed
+	logger.Info("Setting operator root permissions")
 	if err := n.impl.Chmod(config.OperatorRoot, dirPermissions); err != nil {
 		return errors.Wrap(err, "change operator root path permissions")
 	}
 
 	if _, err := n.impl.Stat(config.ProfilesRootPath); os.IsNotExist(err) {
+		logger.Info("Linking profiles root path")
 		if err := n.impl.Symlink(
 			config.OperatorRoot, config.ProfilesRootPath,
 		); err != nil {
@@ -73,12 +79,14 @@ func (n *NonRootEnabler) Run() error {
 		}
 	}
 
+	logger.Info("Setting operator root user and group")
 	if err := n.impl.Chown(
 		config.OperatorRoot, config.UserRootless, config.UserRootless,
 	); err != nil {
 		return errors.Wrap(err, "change operator root permissions")
 	}
 
+	logger.Info("Copying profiles into root path")
 	if err := n.impl.CopyDirContentsLocal(
 		"/opt/spo-profiles", config.KubeletSeccompRootPath,
 	); err != nil {
diff --git a/vendor/modules.txt b/vendor/modules.txt
index bd5ca3066..2afcf1dba 100644
--- a/vendor/modules.txt
+++ b/vendor/modules.txt
@@ -501,7 +501,7 @@ k8s.io/api/storage/v1beta1
 k8s.io/apiextensions-apiserver/pkg/apis/apiextensions
 k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1
 k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1beta1
-# k8s.io/apimachinery v0.21.1
+# k8s.io/apimachinery v0.21.2
 ## explicit
 k8s.io/apimachinery/pkg/api/equality
 k8s.io/apimachinery/pkg/api/errors


Test patch:
diff --git a/internal/pkg/nonrootenabler/nonrootenabler_test.go b/internal/pkg/nonrootenabler/nonrootenabler_test.go
index 88cb8f1da..4a7bb5ca0 100644
--- a/internal/pkg/nonrootenabler/nonrootenabler_test.go
+++ b/internal/pkg/nonrootenabler/nonrootenabler_test.go
@@ -21,6 +21,7 @@ import (
 	"os"
 	"testing"
 
+	"github.com/go-logr/logr"
 	"github.com/stretchr/testify/require"
 
 	"sigs.k8s.io/security-profiles-operator/internal/pkg/nonrootenabler"
@@ -88,7 +89,7 @@ func TestRun(t *testing.T) {
 		tc.prepare(mock)
 		sut.SetImpl(mock)
 
-		err := sut.Run()
+		err := sut.Run(logr.DiscardLogger{})
 		if tc.shouldError {
 			require.NotNil(t, err)
 		} else {