fix: shellCmd to Debug and stderr/stdout to Info logs

fn.go

@@ -139,7 +139,7 @@ func (f *Function) RunFunction(_ context.Context, req *fnv1.RunFunctionRequest)
 		exportCmds = exportCmds + "export " + k + "=\"" + v + "\";"
 	}
 
-	log.Info(shellCmd)
+	log.Debug(shellCmd)
 
 	var stdout, stderr bytes.Buffer
 	cmd := shell.Commandf(exportCmds + shellCmd)
@@ -150,7 +150,7 @@ func (f *Function) RunFunction(_ context.Context, req *fnv1.RunFunctionRequest)
 	sout := strings.TrimSpace(stdout.String())
 	serr := strings.TrimSpace(stderr.String())
 
-	log.Debug(shellCmd, "stdout", sout, "stderr", serr)
+	log.Info("Function output", "tag", req.GetMeta().GetTag(), "stdout", sout, "stderr", serr)
 
 	err = dxr.Resource.SetValue(stdoutField, sout)
 	if err != nil {

fn_test.go

@@ -17,6 +17,172 @@ import (
 	"github.com/crossplane/function-sdk-go/response"
 )
 
+type logEntry struct {
+	msg           string
+	keysAndValues []any
+}
+
+type testLogger struct {
+	infoEntries       []logEntry
+	debugEntries      []logEntry
+	withValuesEntries [][]any
+}
+
+func (l *testLogger) Info(msg string, keysAndValues ...any) {
+	l.infoEntries = append(l.infoEntries, logEntry{msg: msg, keysAndValues: keysAndValues})
+}
+func (l *testLogger) Debug(msg string, keysAndValues ...any) {
+	l.debugEntries = append(l.debugEntries, logEntry{msg: msg, keysAndValues: keysAndValues})
+}
+func (l *testLogger) WithValues(keysAndValues ...any) logging.Logger {
+	l.withValuesEntries = append(l.withValuesEntries, keysAndValues)
+	return l
+}
+
+// assertLogContainsKVs checks that at least one log entry in entries has the specified message and contains all of the specified key-value pairs.
+func assertLogContainsKVs(t *testing.T, entries []logEntry, msg string, wantKVs map[string]any) {
+	t.Helper()
+	for _, entry := range entries {
+		if entry.msg != msg {
+			continue
+		}
+		got := make(map[any]any, len(entry.keysAndValues)/2)
+		for i := 0; i+1 < len(entry.keysAndValues); i += 2 {
+			got[entry.keysAndValues[i]] = entry.keysAndValues[i+1]
+		}
+		for k, want := range wantKVs {
+			v, ok := got[k]
+			if !ok {
+				t.Errorf("log %q: missing key %q (got keys: %v)", msg, k, entry.keysAndValues)
+				continue
+			}
+			if v != want {
+				t.Errorf("log %q key %q: want %q, got %q", msg, k, want, v)
+			}
+		}
+		return
+	}
+	t.Errorf("no log entry with msg %q found (entries: %v)", msg, entries)
+}
+
+func TestRunFunctionLogs(t *testing.T) {
+	type args struct {
+		ctx context.Context
+		req *fnv1.RunFunctionRequest
+	}
+	type wantLog struct {
+		level string // "info" or "debug"
+		msg   string
+		kvs   map[string]any
+	}
+	type want struct {
+		logs       []wantLog
+		withValues []any
+	}
+
+	cases := map[string]struct {
+		reason string
+		args   args
+		want   want
+	}{
+		"LogsStdoutOnSuccess": {
+			reason: "Function output log should contain stdout key and empty stderr",
+			args: args{
+				req: &fnv1.RunFunctionRequest{
+					Meta: &fnv1.RequestMeta{Tag: "foo"},
+					Input: resource.MustStructJSON(`{
+						"apiVersion": "template.fn.crossplane.io/v1alpha1",
+						"kind": "Parameters",
+						"shellCommand": "echo hello",
+						"stdoutField": "spec.atFunction.shell.stdout"
+					}`),
+				},
+			},
+			want: want{
+				logs: []wantLog{
+					{level: "info", msg: "Running function", kvs: map[string]any{"tag": "foo"}},
+					{level: "debug", msg: "echo hello"},
+					{level: "info", msg: "Function output", kvs: map[string]any{"stdout": "hello", "stderr": "", "tag": "foo"}},
+				},
+			},
+		},
+		"LogsStderrOnError": {
+			reason: "Function output log should contain stderr key and empty stdout",
+			args: args{
+				req: &fnv1.RunFunctionRequest{
+					Meta: &fnv1.RequestMeta{Tag: "foo"},
+					Input: resource.MustStructJSON(`{
+						"apiVersion": "template.fn.crossplane.io/v1alpha1",
+						"kind": "Parameters",
+						"shellCommand": "echo hello> /dev/stderr; exit 1",
+						"stdoutField": "spec.atFunction.shell.stdout",
+						"stderrField": "spec.atFunction.shell.stderr"
+					}`),
+				},
+			},
+			want: want{
+				logs: []wantLog{
+					{level: "info", msg: "Running function", kvs: map[string]any{"tag": "foo"}},
+					{level: "debug", msg: "echo hello> /dev/stderr; exit 1"},
+					{level: "info", msg: "Function output", kvs: map[string]any{"stdout": "", "stderr": "hello", "tag": "foo"}},
+				},
+			},
+		},
+		"LogsWithValuesContextOnSuccess": {
+			reason: "WithValues should be called with oxr-version, oxr-kind and oxr-name",
+			args: args{
+				req: &fnv1.RunFunctionRequest{
+					Meta: &fnv1.RequestMeta{Tag: "foo"},
+					Input: resource.MustStructJSON(`{
+						"apiVersion": "template.fn.crossplane.io/v1alpha1",
+						"kind": "Parameters",
+						"shellCommand": "echo hello",
+						"stdoutField": "spec.atFunction.shell.stdout"
+					}`),
+					Observed: &fnv1.State{
+						Composite: &fnv1.Resource{
+							Resource: resource.MustStructJSON(`{
+								"apiVersion": "example.crossplane.io/v1",
+								"kind": "TestXRD",
+								"metadata": {"name": "my-xr"}
+							}`),
+						},
+					},
+				},
+			},
+			want: want{
+				withValues: []any{"oxr-version", "example.crossplane.io/v1", "oxr-kind", "TestXRD", "oxr-name", "my-xr"},
+			},
+		},
+	}
+
+	for name, tc := range cases {
+		t.Run(name, func(t *testing.T) {
+			log := &testLogger{}
+			f := &Function{log: log}
+
+			_, err := f.RunFunction(tc.args.ctx, tc.args.req)
+			if err != nil {
+				t.Fatalf("%s\nf.RunFunction(...): unexpected error: %v", tc.reason, err)
+			}
+
+			for _, wl := range tc.want.logs {
+				entries := log.infoEntries
+				if wl.level == "debug" {
+					entries = log.debugEntries
+				}
+				assertLogContainsKVs(t, entries, wl.msg, wl.kvs)
+			}
+
+			if tc.want.withValues != nil {
+				if diff := cmp.Diff([][]any{tc.want.withValues}, log.withValuesEntries); diff != "" {
+					t.Errorf("%s\nf.RunFunction(...): -want withValues, +got withValues:\n%s", tc.reason, diff)
+				}
+			}
+		})
+	}
+}
+
 func TestRunFunction(t *testing.T) {
 	type args struct {
 		ctx      context.Context