From 5cb9f3ecfd10220562fba0f9eb49d2a1c82ba759 Mon Sep 17 00:00:00 2001 From: Stephen Benjamin Date: Tue, 14 Apr 2026 09:04:04 -0400 Subject: [PATCH 1/3] Fix ListImages failing to parse JSON when extension binaries emit log lines ListImages was unmarshalling the entire stdout output directly, so any warning or debug log lines emitted by extension binaries before the JSON payload caused parsing failures (e.g. "invalid character 'W' looking for beginning of value"). The Info method already handled this by scanning for the first JSON-starting line, but ListImages did not. Extract a shared extractJSON helper that both Info and ListImages now use, eliminating the duplicated JSON detection logic. The helper also handles the case where a binary outputs "null" (no images), which previously fell through to an unhelpful parse error. Co-Authored-By: Claude Opus 4.6 --- pkg/test/extensions/binary.go | 65 +++++++++++++++++++++++------------ 1 file changed, 43 insertions(+), 22 deletions(-) diff --git a/pkg/test/extensions/binary.go b/pkg/test/extensions/binary.go index 94eba6fe2ec5..702c1b4a82f5 100644 --- a/pkg/test/extensions/binary.go +++ b/pkg/test/extensions/binary.go @@ -335,6 +335,35 @@ var extensionBinaries = []TestBinary{ }, } +// extractJSON finds the first JSON value in output that starts with startChar and ends with endChar, +// skipping any non-JSON log lines that precede it. This is necessary because some extension binaries +// output warnings or debug logging to stdout before the JSON payload. +func extractJSON(output []byte, startChar byte, endChar byte) ([]byte, error) { + jsonBegins := -1 + lines := bytes.Split(output, []byte("\n")) + for i, line := range lines { + trimmed := bytes.TrimSpace(line) + if len(trimmed) > 0 && trimmed[0] == startChar { + jsonBegins = 0 + for j := 0; j < i; j++ { + jsonBegins += len(lines[j]) + 1 // +1 for the newline character + } + jsonBegins += len(line) - len(trimmed) // Add any leading whitespace + break + } + if bytes.Equal(trimmed, []byte("null")) { + return []byte("null"), nil + } + } + + jsonEnds := bytes.LastIndexByte(output, endChar) + if jsonBegins == -1 || jsonEnds == -1 || jsonBegins > jsonEnds { + return nil, fmt.Errorf("no valid JSON found in output: %s", string(output)) + } + + return output[jsonBegins : jsonEnds+1], nil +} + // Info returns information about this particular extension. func (b *TestBinary) Info(ctx context.Context) (*Extension, error) { if b.info != nil { @@ -352,30 +381,13 @@ func (b *TestBinary) Info(ctx context.Context) (*Extension, error) { logrus.Errorf("Command output for %s: %s", binName, string(infoJson)) return nil, fmt.Errorf("failed running '%s info': %w\nOutput: %s", b.binaryPath, err, infoJson) } - // Some binaries may output logging that includes JSON-like data, so we need to find the first line that starts with '{' - jsonBegins := -1 - lines := bytes.Split(infoJson, []byte("\n")) - for i, line := range lines { - trimmed := bytes.TrimSpace(line) - if bytes.HasPrefix(trimmed, []byte("{")) { - // Calculate the byte offset of this line in the original output - jsonBegins = 0 - for j := 0; j < i; j++ { - jsonBegins += len(lines[j]) + 1 // +1 for the newline character - } - jsonBegins += len(line) - len(trimmed) // Add any leading whitespace - break - } - } - - jsonEnds := bytes.LastIndexByte(infoJson, '}') - if jsonBegins == -1 || jsonEnds == -1 || jsonBegins > jsonEnds { + jsonData, err := extractJSON(infoJson, '{', '}') + if err != nil { logrus.Errorf("No valid JSON found in output from %s info command", binName) logrus.Errorf("Raw output from %s: %s", binName, string(infoJson)) return nil, fmt.Errorf("no valid JSON found in output from '%s info' command", binName) } var info Extension - jsonData := infoJson[jsonBegins : jsonEnds+1] err = json.Unmarshal(jsonData, &info) if err != nil { logrus.Errorf("Failed to unmarshal JSON from %s: %v", binName, err) @@ -557,13 +569,22 @@ func (b *TestBinary) ListImages(ctx context.Context) (ImageSet, error) { command := exec.Command(b.binaryPath, "images") output, err := runWithTimeout(ctx, command, 10*time.Minute) if err != nil { - return nil, fmt.Errorf("failed running '%s list': %w\nOutput: %s", b.binaryPath, err, output) + return nil, fmt.Errorf("failed running '%s images': %w\nOutput: %s", b.binaryPath, err, output) + } + + jsonData, err := extractJSON(output, '[', ']') + if err != nil { + logrus.Errorf("No valid JSON found in output from %s images command", binName) + logrus.Errorf("Raw output from %s: %s", binName, string(output)) + return nil, fmt.Errorf("no valid JSON found in output from '%s images' command", binName) } var images []Image - err = json.Unmarshal(output, &images) + err = json.Unmarshal(jsonData, &images) if err != nil { - return nil, err + logrus.Errorf("Failed to unmarshal JSON from %s: %v", binName, err) + logrus.Errorf("JSON data from %s: %s", binName, string(jsonData)) + return nil, errors.Wrapf(err, "couldn't unmarshal extension images from %s: %s", binName, string(jsonData)) } result := make(ImageSet, len(images)) From 5ebf4c41fec47ce186dcc1b43068d972bf6d117b Mon Sep 17 00:00:00 2001 From: Stephen Benjamin Date: Tue, 14 Apr 2026 09:16:02 -0400 Subject: [PATCH 2/3] Address review feedback: use json.Decoder, scope null handling to ListImages - Replace brittle LastIndexByte end-boundary detection with json.Decoder, which correctly extracts the first complete JSON value regardless of trailing log output. - Remove allowNull parameter from extractJSON; handle the null case in ListImages where it's semantically relevant, keeping the helper simple. Co-Authored-By: Claude Opus 4.6 --- pkg/test/extensions/binary.go | 29 +++++++++++++++++++---------- 1 file changed, 19 insertions(+), 10 deletions(-) diff --git a/pkg/test/extensions/binary.go b/pkg/test/extensions/binary.go index 702c1b4a82f5..35cedccdf20b 100644 --- a/pkg/test/extensions/binary.go +++ b/pkg/test/extensions/binary.go @@ -335,10 +335,10 @@ var extensionBinaries = []TestBinary{ }, } -// extractJSON finds the first JSON value in output that starts with startChar and ends with endChar, +// extractJSON finds the first JSON value in output that starts with startChar, // skipping any non-JSON log lines that precede it. This is necessary because some extension binaries // output warnings or debug logging to stdout before the JSON payload. -func extractJSON(output []byte, startChar byte, endChar byte) ([]byte, error) { +func extractJSON(output []byte, startChar byte) ([]byte, error) { jsonBegins := -1 lines := bytes.Split(output, []byte("\n")) for i, line := range lines { @@ -351,17 +351,21 @@ func extractJSON(output []byte, startChar byte, endChar byte) ([]byte, error) { jsonBegins += len(line) - len(trimmed) // Add any leading whitespace break } - if bytes.Equal(trimmed, []byte("null")) { - return []byte("null"), nil - } } - jsonEnds := bytes.LastIndexByte(output, endChar) - if jsonBegins == -1 || jsonEnds == -1 || jsonBegins > jsonEnds { + if jsonBegins == -1 { return nil, fmt.Errorf("no valid JSON found in output: %s", string(output)) } - return output[jsonBegins : jsonEnds+1], nil + var raw json.RawMessage + dec := json.NewDecoder(bytes.NewReader(output[jsonBegins:])) + if err := dec.Decode(&raw); err != nil { + return nil, fmt.Errorf("no valid JSON found in output: %w", err) + } + if len(raw) == 0 || raw[0] != startChar { + return nil, fmt.Errorf("no valid JSON found in output: %s", string(output)) + } + return raw, nil } // Info returns information about this particular extension. @@ -381,7 +385,7 @@ func (b *TestBinary) Info(ctx context.Context) (*Extension, error) { logrus.Errorf("Command output for %s: %s", binName, string(infoJson)) return nil, fmt.Errorf("failed running '%s info': %w\nOutput: %s", b.binaryPath, err, infoJson) } - jsonData, err := extractJSON(infoJson, '{', '}') + jsonData, err := extractJSON(infoJson, '{') if err != nil { logrus.Errorf("No valid JSON found in output from %s info command", binName) logrus.Errorf("Raw output from %s: %s", binName, string(infoJson)) @@ -572,8 +576,13 @@ func (b *TestBinary) ListImages(ctx context.Context) (ImageSet, error) { return nil, fmt.Errorf("failed running '%s images': %w\nOutput: %s", b.binaryPath, err, output) } - jsonData, err := extractJSON(output, '[', ']') + jsonData, err := extractJSON(output, '[') if err != nil { + // Extensions that have no images may output "null" instead of an array + if bytes.Contains(output, []byte("null")) { + logrus.Infof("Extension %q reported null images, treating as empty", binName) + return ImageSet{}, nil + } logrus.Errorf("No valid JSON found in output from %s images command", binName) logrus.Errorf("Raw output from %s: %s", binName, string(output)) return nil, fmt.Errorf("no valid JSON found in output from '%s images' command", binName) From 019f1841916ed4181fd345a917847a57fb0eac0c Mon Sep 17 00:00:00 2001 From: Stephen Benjamin Date: Tue, 14 Apr 2026 09:18:32 -0400 Subject: [PATCH 3/3] Simplify extractJSON: remove startChar param, add tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Drop the startChar parameter — the helper now finds the first line starting with '{' or '[' automatically. Use json.Decoder to extract the complete JSON value, which correctly handles trailing log lines that might contain braces. Keep null handling in ListImages where it's semantically relevant. Co-Authored-By: Claude Opus 4.6 --- pkg/test/extensions/binary.go | 17 +++--- pkg/test/extensions/extract_json_test.go | 70 ++++++++++++++++++++++++ 2 files changed, 77 insertions(+), 10 deletions(-) create mode 100644 pkg/test/extensions/extract_json_test.go diff --git a/pkg/test/extensions/binary.go b/pkg/test/extensions/binary.go index 35cedccdf20b..f8ed3a8789f3 100644 --- a/pkg/test/extensions/binary.go +++ b/pkg/test/extensions/binary.go @@ -335,15 +335,15 @@ var extensionBinaries = []TestBinary{ }, } -// extractJSON finds the first JSON value in output that starts with startChar, -// skipping any non-JSON log lines that precede it. This is necessary because some extension binaries -// output warnings or debug logging to stdout before the JSON payload. -func extractJSON(output []byte, startChar byte) ([]byte, error) { +// extractJSON finds the first JSON object or array in output, skipping any non-JSON log lines +// that precede it. This is necessary because some extension binaries output warnings or debug +// logging to stdout before the JSON payload. +func extractJSON(output []byte) ([]byte, error) { jsonBegins := -1 lines := bytes.Split(output, []byte("\n")) for i, line := range lines { trimmed := bytes.TrimSpace(line) - if len(trimmed) > 0 && trimmed[0] == startChar { + if len(trimmed) > 0 && (trimmed[0] == '{' || trimmed[0] == '[') { jsonBegins = 0 for j := 0; j < i; j++ { jsonBegins += len(lines[j]) + 1 // +1 for the newline character @@ -362,9 +362,6 @@ func extractJSON(output []byte, startChar byte) ([]byte, error) { if err := dec.Decode(&raw); err != nil { return nil, fmt.Errorf("no valid JSON found in output: %w", err) } - if len(raw) == 0 || raw[0] != startChar { - return nil, fmt.Errorf("no valid JSON found in output: %s", string(output)) - } return raw, nil } @@ -385,7 +382,7 @@ func (b *TestBinary) Info(ctx context.Context) (*Extension, error) { logrus.Errorf("Command output for %s: %s", binName, string(infoJson)) return nil, fmt.Errorf("failed running '%s info': %w\nOutput: %s", b.binaryPath, err, infoJson) } - jsonData, err := extractJSON(infoJson, '{') + jsonData, err := extractJSON(infoJson) if err != nil { logrus.Errorf("No valid JSON found in output from %s info command", binName) logrus.Errorf("Raw output from %s: %s", binName, string(infoJson)) @@ -576,7 +573,7 @@ func (b *TestBinary) ListImages(ctx context.Context) (ImageSet, error) { return nil, fmt.Errorf("failed running '%s images': %w\nOutput: %s", b.binaryPath, err, output) } - jsonData, err := extractJSON(output, '[') + jsonData, err := extractJSON(output) if err != nil { // Extensions that have no images may output "null" instead of an array if bytes.Contains(output, []byte("null")) { diff --git a/pkg/test/extensions/extract_json_test.go b/pkg/test/extensions/extract_json_test.go new file mode 100644 index 000000000000..e3a0ffae0b12 --- /dev/null +++ b/pkg/test/extensions/extract_json_test.go @@ -0,0 +1,70 @@ +package extensions + +import ( + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestExtractJSON(t *testing.T) { + tests := []struct { + name string + input string + want string + wantErr bool + }{ + { + name: "clean JSON object", + input: `{"key": "value"}`, + want: `{"key": "value"}`, + }, + { + name: "clean JSON array", + input: `[{"index": 1}]`, + want: `[{"index": 1}]`, + }, + { + name: "warning lines before JSON object", + input: "W0414 08:58:39.856273 46367 controller.go:47] some warning\nW0414 08:58:39.865859 46367 feature_gate.go:352] another warning\n{\"key\": \"value\"}\n", + want: `{"key": "value"}`, + }, + { + name: "warning lines before JSON array", + input: "W0414 08:58:39.856273 46367 controller.go:47] some warning\n[{\"index\": 1}]\n", + want: `[{"index": 1}]`, + }, + { + name: "log lines after JSON are ignored", + input: "{\"key\": \"value\"}\nW0414 trailing log with } brace\n", + want: `{"key": "value"}`, + }, + { + name: "no JSON in output", + input: "W0414 just warnings\nI0414 and info lines\n", + wantErr: true, + }, + { + name: "empty output", + input: "", + wantErr: true, + }, + { + name: "null is not a JSON object or array", + input: "W0414 warning\nnull\n", + wantErr: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got, err := extractJSON([]byte(tt.input)) + if tt.wantErr { + assert.Error(t, err) + return + } + require.NoError(t, err) + assert.JSONEq(t, tt.want, string(got)) + }) + } +}