Cache pods and container IDs in log enricher

We now use a cache and a default timeout of 6 hours to cache the
container info as well as the PIDs. This should speedup the enricher in
general.

Signed-off-by: Sascha Grunert <[email protected]>

go.mod

@@ -3,6 +3,7 @@ module sigs.k8s.io/security-profiles-operator
 go 1.15
 
 require (
+	github.com/ReneKroon/ttlcache/v2 v2.7.0
 	github.com/containers/common v0.40.1
 	github.com/crossplane/crossplane-runtime v0.14.0
 	github.com/go-logr/logr v0.4.0

go.sum

@@ -82,6 +82,8 @@ github.com/PuerkitoBio/purell v1.1.0/go.mod h1:c11w/QuzBsJSee3cPx9rAFu61PvFxuPbt
 github.com/PuerkitoBio/purell v1.1.1/go.mod h1:c11w/QuzBsJSee3cPx9rAFu61PvFxuPbtSwDGJws/X0=
 github.com/PuerkitoBio/urlesc v0.0.0-20160726150825-5bd2802263f2/go.mod h1:uGdkoq3SwY9Y+13GIhn11/XLaGBb4BfwItxLd5jeuXE=
 github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578/go.mod h1:uGdkoq3SwY9Y+13GIhn11/XLaGBb4BfwItxLd5jeuXE=
+github.com/ReneKroon/ttlcache/v2 v2.7.0 h1:sZeaSwA2UN/y/h7CvkW15Kovd2Oiy76CBDORiOwHPwI=
+github.com/ReneKroon/ttlcache/v2 v2.7.0/go.mod h1:mBxvsNY+BT8qLLd6CuAJubbKo6r0jh3nb5et22bbfGY=
 github.com/Shopify/logrus-bugsnag v0.0.0-20171204204709-577dee27f20d/go.mod h1:HI8ITrYtUY+O+ZhtlqUnD8+KwNPOyugEhfP9fdUIaEQ=
 github.com/VividCortex/ewma v1.2.0/go.mod h1:nz4BbCtbLyFDeC9SUHbtcT5644juEuWfUAUnGx7j5l4=
 github.com/acarl005/stripansi v0.0.0-20180116102854-5a71ef0e047d/go.mod h1:asat636LX7Bqt5lYEZ27JNDcqxfjdBQuJ/MM4CN/Lzo=
@@ -1034,8 +1036,9 @@ golang.org/x/lint v0.0.0-20190909230951-414d861bb4ac/go.mod h1:6SW0HCj/g11FgYtHl
 golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
 golang.org/x/lint v0.0.0-20191125180803-fdd1cda4f05f/go.mod h1:5qLYkcX4OjUUV8bRuDixDT3tpyyb+LUpUlRWLxfhWrs=
 golang.org/x/lint v0.0.0-20200130185559-910be7a94367/go.mod h1:3xt1FjdF8hUf6vQPIChWIBhFzV8gjjsPE/fR3IyQdNY=
-golang.org/x/lint v0.0.0-20200302205851-738671d3881b h1:Wh+f8QHJXR411sJR8/vRBTZ7YapZaRvUcLFFJhusH0k=
 golang.org/x/lint v0.0.0-20200302205851-738671d3881b/go.mod h1:3xt1FjdF8hUf6vQPIChWIBhFzV8gjjsPE/fR3IyQdNY=
+golang.org/x/lint v0.0.0-20201208152925-83fdc39ff7b5 h1:2M3HP5CCK1Si9FQhwnzYhXdG6DXeebvUHFpre8QvbyI=
+golang.org/x/lint v0.0.0-20201208152925-83fdc39ff7b5/go.mod h1:3xt1FjdF8hUf6vQPIChWIBhFzV8gjjsPE/fR3IyQdNY=
 golang.org/x/mobile v0.0.0-20190312151609-d3739f865fa6/go.mod h1:z+o9i4GpDbdi3rU15maQ/Ox0txvL9dWGYEHz965HBQE=
 golang.org/x/mobile v0.0.0-20190719004257-d2bd2a29d028/go.mod h1:E/iHnbuqvinMTCcRqshq8CkpyQDoeVncDDYHnLhea+o=
 golang.org/x/mod v0.0.0-20190513183733-4bf6d317e70e/go.mod h1:mXi4GBBbnImb6dmsKGUJ2LatrhH/nqhxcFungHvyanc=
@@ -1120,6 +1123,8 @@ golang.org/x/sync v0.0.0-20200317015054-43a5402ce75a/go.mod h1:RxMgew5VJxzue5/jJ
 golang.org/x/sync v0.0.0-20200625203802-6e8e738ad208/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sync v0.0.0-20210220032951-036812b2e83c h1:5KslGYwFpkhGh+Q16bwMP3cOontH8FOep7tGV86Y7SQ=
+golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20170830134202-bb24a47a89ea/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20180823144017-11551d06cbcc/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20180830151530-49385e6e1522/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
@@ -1285,6 +1290,7 @@ golang.org/x/tools v0.0.0-20200825202427-b303f430e36d/go.mod h1:njjCfa9FT2d7l9Bc
 golang.org/x/tools v0.0.0-20201023174141-c8cfbd0f21e6/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
 golang.org/x/tools v0.0.0-20201224043029-2b0845dc783e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
 golang.org/x/tools v0.0.0-20210106214847-113979e3529a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
+golang.org/x/tools v0.0.0-20210112230658-8b4aab62c064/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
 golang.org/x/tools v0.1.0 h1:po9/4sTYwZU9lPhi1tOrb4hCv3qrhiQ77LZfGa2OjwY=
 golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

internal/pkg/daemon/enricher/container.go

@@ -21,7 +21,9 @@ import (
 	"fmt"
 	"path/filepath"
 	"regexp"
+	"strconv"
 
+	"github.com/ReneKroon/ttlcache/v2"
 	"github.com/go-logr/logr"
 	"github.com/pkg/errors"
 
@@ -33,7 +35,16 @@ import (
 // Cluster scoped
 // +kubebuilder:rbac:groups=core,resources=pods,verbs=get;list;watch;
 
-func (e *Enricher) getNodeContainers(logger logr.Logger, nodeName string) (map[string]containerInfo, error) {
+func (e *Enricher) getContainerInfo(
+	logger logr.Logger, nodeName, containerID string,
+) (*containerInfo, error) {
+	// Check the cache first
+	if info, err := e.infoCache.Get(
+		containerID,
+	); !errors.Is(err, ttlcache.ErrNotFound) {
+		return info.(*containerInfo), nil
+	}
+
 	config, err := e.impl.InClusterConfig()
 	if err != nil {
 		return nil, errors.Wrap(err, "get in-cluster config")
@@ -44,15 +55,15 @@ func (e *Enricher) getNodeContainers(logger logr.Logger, nodeName string) (map[s
 		return nil, errors.Wrap(err, "load in-cluster config")
 	}
 
-	containers := make(map[string]containerInfo)
-	err = util.Retry(
+	containers := make(map[string]*containerInfo)
+	if err := util.Retry(
 		func() (retryErr error) {
 			pods, err := e.impl.ListPods(clientset, nodeName)
 			if err != nil {
 				return errors.Wrapf(err, "list node %s's pods", nodeName)
 			}
 
-			containers = make(map[string]containerInfo)
+			containers = make(map[string]*containerInfo)
 			for p := range pods.Items {
 				pod := pods.Items[p]
 
@@ -77,24 +88,45 @@ func (e *Enricher) getNodeContainers(logger logr.Logger, nodeName string) (map[s
 						continue
 					}
 
-					containers[rawContainerID] = containerInfo{
+					info := &containerInfo{
 						podName:       pod.Name,
 						containerName: containerStatus.Name,
 						namespace:     pod.Namespace,
 						containerID:   rawContainerID,
 					}
+					containers[rawContainerID] = info
+
+					// Update the cache
+					if err := e.infoCache.Set(containerID, info); err != nil {
+						return errors.Wrap(err, "update cache")
+					}
 				}
 			}
 			return nil
 		},
 		func(inErr error) bool {
 			return errors.Is(inErr, errContainerIDEmpty)
 		},
-	)
-	return containers, err
+	); err != nil {
+		return nil, errors.Wrap(err, "get container info for pods")
+	}
+
+	info, found := containers[containerID]
+	if !found {
+		return nil, errors.Wrap(err, "no container info for container ID")
+	}
+
+	return info, err
 }
 
 func (e *Enricher) getContainerID(processID int) (string, error) {
+	// Check the cache first
+	if id, err := e.containerIDCache.Get(
+		strconv.Itoa(processID),
+	); !errors.Is(err, ttlcache.ErrNotFound) {
+		return id.(string), nil
+	}
+
 	cgroupFile := fmt.Sprintf("/proc/%d/cgroup", processID)
 	file, err := e.impl.Open(filepath.Clean(cgroupFile))
 	if err != nil {
@@ -111,6 +143,13 @@ func (e *Enricher) getContainerID(processID int) (string, error) {
 	scanner.Split(bufio.ScanLines)
 	for scanner.Scan() {
 		if containerID := extractID(scanner.Text()); containerID != "" {
+			// Update the cache
+			if err := e.containerIDCache.Set(
+				strconv.Itoa(processID), containerID,
+			); err != nil {
+				return "", errors.Wrap(err, "update cache")
+			}
+
 			return containerID, nil
 		}
 	}

internal/pkg/daemon/enricher/enricher.go

@@ -17,8 +17,11 @@ limitations under the License.
 package enricher
 
 import (
+	"fmt"
 	"os"
+	"time"
 
+	"github.com/ReneKroon/ttlcache/v2"
 	"github.com/go-logr/logr"
 	"github.com/hpcloud/tail"
 	"github.com/pkg/errors"
@@ -27,23 +30,41 @@ import (
 	"sigs.k8s.io/security-profiles-operator/internal/pkg/config"
 )
 
+// defaultCacheTimeout is the timeout for the container ID and info cache being
+// used. The chosen value is nothing more than a rough guess.
+const defaultCacheTimeout time.Duration = time.Hour
+
 // Enricher is the main structure of this package.
 type Enricher struct {
-	impl   impl
-	logger logr.Logger
+	impl             impl
+	logger           logr.Logger
+	containerIDCache ttlcache.SimpleCache
+	infoCache        ttlcache.SimpleCache
 }
 
 // New returns a new Enricher instance.
 func New(logger logr.Logger) *Enricher {
 	return &Enricher{
-		impl:   &defaultImpl{},
-		logger: logger,
+		impl:             &defaultImpl{},
+		logger:           logger,
+		containerIDCache: ttlcache.NewCache(),
+		infoCache:        ttlcache.NewCache(),
 	}
 }
 
 // Run the log-enricher to scrap audit logs and enrich them with
 // Kubernetes data (namespace, pod and container).
 func (e *Enricher) Run() error {
+	e.logger.Info(fmt.Sprintf("Setting up caches with expiry of %v", defaultCacheTimeout))
+	for _, cache := range []ttlcache.SimpleCache{
+		e.containerIDCache, e.infoCache,
+	} {
+		if err := cache.SetTTL(defaultCacheTimeout); err != nil {
+			return errors.Wrap(err, "set cache timeout")
+		}
+		defer cache.Close()
+	}
+
 	nodeName := e.impl.Getenv(config.NodeNameEnvKey)
 	if nodeName == "" {
 		err := errors.Errorf("%s environment variable not set", config.NodeNameEnvKey)
@@ -101,12 +122,10 @@ func (e *Enricher) Run() error {
 			continue
 		}
 
-		containers, err := e.getNodeContainers(e.logger, nodeName)
-		c, found := containers[cID]
-
-		if !found {
+		info, err := e.getContainerInfo(e.logger, nodeName, cID)
+		if err != nil {
 			e.logger.Error(
-				err, "containerID not found in cluster",
+				err, "container ID not found in cluster",
 				"processID", auditLine.processID,
 				"containerID", cID,
 			)
@@ -118,9 +137,9 @@ func (e *Enricher) Run() error {
 			"timestamp", auditLine.timestampID,
 			"type", auditLine.type_,
 			"node", nodeName,
-			"namespace", c.namespace,
-			"pod", c.podName,
-			"container", c.containerName,
+			"namespace", info.namespace,
+			"pod", info.podName,
+			"container", info.containerName,
 			"executable", auditLine.executable,
 			"pid", auditLine.processID,
 			"syscallID", auditLine.systemCallID,
@@ -136,9 +155,9 @@ func (e *Enricher) Run() error {
 			&api.MetricsAuditRequest{
 				Type:       metricsType,
 				Node:       nodeName,
-				Namespace:  c.namespace,
-				Pod:        c.podName,
-				Container:  c.containerName,
+				Namespace:  info.namespace,
+				Pod:        info.podName,
+				Container:  info.containerName,
 				Executable: auditLine.executable,
 				Syscall:    syscallName,
 			},