cli/genpolicy: never log existing policy annotation on 'debug' + handle missing log prefix

cli/genpolicy/logtranslator.go

@@ -33,18 +33,40 @@ func (l logTranslator) Write(p []byte) (n int, err error) {
 	return l.w.Write(p)
 }
 
-var genpolicyLogPrefixReg = regexp.MustCompile(`^\[[^\]\s]+\s+(\w+)\s+([^\]\s]+)\] (.*)`)
+var (
+	genpolicyLogPrefixReg = regexp.MustCompile(`^\[[^\]\s]+\s+(\w+)\s+([^\]\s]+)\] (.*)`)
+	errorMessage          = regexp.MustCompile(`^thread\s+'main'\s+panicked\s+at`)
+)
 
 func (l logTranslator) startTranslate() {
 	go func() {
 		defer close(l.stopDoneC)
 		scanner := bufio.NewScanner(l.r)
+		// Default log level is initially set to 'WARN'. This is only relevant if the first line does not match the logging pattern.
+		logLevel := "WARN"
+
 		for scanner.Scan() {
 			line := scanner.Text()
 			match := genpolicyLogPrefixReg.FindStringSubmatch(line)
 			if len(match) != 4 {
 				// genpolicy prints some warnings without the logger
-				l.logger.Warn(line)
+				// we continue logging on the latest used log-level
+
+				// Error is written to stderr by genpolicy without using the logger,
+				// simple regex to detect the error message on stderr
+				if errorMessage.MatchString(line) {
+					logLevel = "ERROR"
+				}
+				switch logLevel {
+				case "ERROR":
+					l.logger.Error(line)
+				case "WARN":
+					l.logger.Warn(line)
+				case "INFO":
+					fallthrough
+				case "DEBUG":
+					l.logger.Debug(line)
+				}
 			} else {
 				switch match[1] {
 				case "ERROR":
@@ -56,7 +78,10 @@ func (l logTranslator) startTranslate() {
 				case "DEBUG":
 					l.logger.Debug(match[3], "position", match[2])
 				}
+				// Update the latest log level
+				logLevel = match[1]
 			}
+
 		}
 	}()
 }

cli/genpolicy/logtranslator_test.go

@@ -11,11 +11,12 @@ import (
 
 func TestGenpolicyLogPrefixReg(t *testing.T) {
 	testCases := []struct {
-		logLine      string
-		wantMatch    bool
-		wantLevel    string
-		wantPosition string
-		wantMessage  string
+		logLine              string
+		wantMatch            bool
+		wantLevel            string
+		wantPosition         string
+		wantMessage          string
+		wantNoPrefixErrMatch bool
 	}{
 		{
 			logLine:      `[2024-06-26T09:09:40Z INFO  genpolicy::registry] ============================================`,
@@ -52,6 +53,11 @@ func TestGenpolicyLogPrefixReg(t *testing.T) {
 			wantPosition: "genpolicy::registry",
 			wantMessage:  "Using cache file",
 		},
+		{
+			logLine:              `thread 'main' panicked at src/registry.rs:131:17:`,
+			wantMatch:            false,
+			wantNoPrefixErrMatch: true,
+		},
 		{
 			logLine:   `Success!"`,
 			wantMatch: false,
@@ -66,6 +72,9 @@ func TestGenpolicyLogPrefixReg(t *testing.T) {
 
 			if !tc.wantMatch {
 				assert.Nil(match)
+				if tc.wantNoPrefixErrMatch {
+					assert.True(errorMessage.MatchString(tc.logLine))
+				}
 				return
 			}
 			assert.Len(match, 4)

packages/by-name/kata/kata-runtime/0018-genpolicy-do-not-log-policy-annotation-in-debug.patch

@@ -0,0 +1,64 @@
+From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001
+From: jmxnzo <[email protected]>
+Date: Tue, 10 Dec 2024 11:19:29 +0100
+Subject: [PATCH] genpolicy: do not log policy annotation in 'debug'
+
+---
+ src/tools/genpolicy/src/obj_meta.rs | 38 ++++++++++++++++++++++++++++-
+ 1 file changed, 37 insertions(+), 1 deletion(-)
+
+diff --git a/src/tools/genpolicy/src/obj_meta.rs b/src/tools/genpolicy/src/obj_meta.rs
+index 3da75fc0ff67068af04ea98a6dfdc6989961e17c..327ef13ad4cd6ff8f08d25228e6c108dea3f1606 100644
+--- a/src/tools/genpolicy/src/obj_meta.rs
++++ b/src/tools/genpolicy/src/obj_meta.rs
+@@ -8,9 +8,10 @@
+
+ use serde::{Deserialize, Serialize};
+ use std::collections::BTreeMap;
++use std::fmt;
+
+ /// See ObjectMeta in the Kubernetes API reference.
+-#[derive(Clone, Debug, Default, Serialize, Deserialize)]
++#[derive(Clone, Default, Serialize, Deserialize)]
+ pub struct ObjectMeta {
+     #[serde(skip_serializing_if = "Option::is_none")]
+     pub name: Option<String>,
+@@ -43,3 +44,38 @@ impl ObjectMeta {
+         self.namespace.as_ref().cloned()
+     }
+ }
++
++
++impl fmt::Debug for ObjectMeta {
++    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
++        let mut debug_struct = f.debug_struct("ObjectMeta");
++
++        if let Some(ref name) = self.name {
++            debug_struct.field("name", name);
++        }
++        if let Some(ref generate_name) = self.generateName {
++            debug_struct.field("generateName", generate_name);
++        }
++        if let Some(ref labels) = self.labels {
++            debug_struct.field("labels", labels);
++        }
++        if let Some(ref annotations) = self.annotations {
++            let truncated_annotations: BTreeMap<_, _> = annotations
++                .iter()
++                .map(|(key, value)| {
++                    if value.len() > 4096 {
++                        (key, format!("{}<... truncated ...>", &value[..4096].to_string()))
++                    } else {
++                        (key, value.to_string())
++                    }
++                })
++                .collect();
++            debug_struct.field("annotations", &truncated_annotations);
++        }
++        if let Some(ref namespace) = self.namespace {
++            debug_struct.field("namespace", namespace);
++        }
++
++        debug_struct.finish()
++    }
++}

packages/by-name/kata/kata-runtime/package.nix

@@ -102,6 +102,11 @@ buildGoModule rec {
       # No upstream patch available, changes first need to be discussed with Kata maintainers.
       # See https://katacontainers.slack.com/archives/C879ACQ00/p1731928491942299
       ./0017-runtime-allow-initrd-AND-image-to-be-set.patch
+
+      # Simple genpolicy logging redaction of the policy annotation
+      # This avoids printing the entire annotation on log level debug, which resulted in errors of the logtranslator.go
+      # TODO(jmxnzo): remove when upstream patch is merged: https://github.com/kata-containers/kata-containers/pull/10647
+      ./0018-genpolicy-do-not-log-policy-annotation-in-debug.patch
     ];
   };
 

packages/by-name/microsoft/genpolicy/0009-genpolicy-do-not-log-policy-annotation-in-debug.patch

@@ -0,0 +1,63 @@
+From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001
+From: jmxnzo <[email protected]>
+Date: Mon, 9 Dec 2024 09:56:56 +0100
+Subject: [PATCH] genpolicy: do not log policy annotation in 'debug'
+
+---
+ src/tools/genpolicy/src/obj_meta.rs | 37 ++++++++++++++++++++++++++++-
+ 1 file changed, 36 insertions(+), 1 deletion(-)
+
+diff --git a/src/tools/genpolicy/src/obj_meta.rs b/src/tools/genpolicy/src/obj_meta.rs
+index 3da75fc0ff67068af04ea98a6dfdc6989961e17c..55ec12f4a9261e340950dc94afe42092d18bc859 100644
+--- a/src/tools/genpolicy/src/obj_meta.rs
++++ b/src/tools/genpolicy/src/obj_meta.rs
+@@ -8,9 +8,10 @@
+
+ use serde::{Deserialize, Serialize};
+ use std::collections::BTreeMap;
++use std::fmt;
+
+ /// See ObjectMeta in the Kubernetes API reference.
+-#[derive(Clone, Debug, Default, Serialize, Deserialize)]
++#[derive(Clone, Default, Serialize, Deserialize)]
+ pub struct ObjectMeta {
+     #[serde(skip_serializing_if = "Option::is_none")]
+     pub name: Option<String>,
+@@ -43,3 +44,37 @@ impl ObjectMeta {
+         self.namespace.as_ref().cloned()
+     }
+ }
++
++impl fmt::Debug for ObjectMeta {
++    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
++        let mut debug_struct = f.debug_struct("ObjectMeta");
++
++        if let Some(ref name) = self.name {
++            debug_struct.field("name", name);
++        }
++        if let Some(ref generate_name) = self.generateName {
++            debug_struct.field("generateName", generate_name);
++        }
++        if let Some(ref labels) = self.labels {
++            debug_struct.field("labels", labels);
++        }
++        if let Some(ref annotations) = self.annotations {
++            let truncated_annotations: BTreeMap<_, _> = annotations
++                .iter()
++                .map(|(key, value)| {
++                    if value.len() > 4096 {
++                        (key, format!("{}<... truncated ...>", &value[..4096].to_string()))
++                    } else {
++                        (key, value.to_string())
++                    }
++                })
++                .collect();
++            debug_struct.field("annotations", &truncated_annotations);
++        }
++        if let Some(ref namespace) = self.namespace {
++            debug_struct.field("namespace", namespace);
++        }
++
++        debug_struct.finish()
++    }
++}

packages/by-name/microsoft/genpolicy/package.nix

@@ -65,7 +65,12 @@ rustPlatform.buildRustPackage rec {
       # This will be achieved when updating oci_distribution to oci_client crate on microsoft/kata-containers fork.
       # kata/kata-runtime/0011-genpolicy-bump-oci-distribution-to-v0.12.0.patch introduces this update to kata-containers.
       # After upstreaming, microsoft/kata-containers fork would need to pick up the changes.
-      ./0008-genpolicy-include-reference-in-logs-when-auth-failure.patch
+      ./0008-genpolicy-include-reference-in-logs-when-auth-failur.patch
+
+      # Simple genpolicy logging redaction of the policy annotation
+      # This avoids printing the entire annotation on log level debug, which resulted in errors of the logtranslator.go
+      # TODO(jmxnzo): remove when https://github.com/kata-containers/kata-containers/pull/10647 is picked up by microsoft/kata-containers fork
+      ./0009-genpolicy-do-not-log-policy-annotation-in-debug.patch
     ];
   };