Merge pull request #31009 from stbenjam/fix-list-images-json-parsing

NO-JIRA: Fix ListImages JSON parsing when extension binaries emit log lines

Author: openshift-merge-bot[bot]

pkg/test/extensions/binary.go

@@ -339,6 +339,36 @@ var extensionBinaries = []TestBinary{
 	},
 }
 
+// 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] == '{' || trimmed[0] == '[') {
+			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 jsonBegins == -1 {
+		return nil, fmt.Errorf("no valid JSON found in output: %s", string(output))
+	}
+
+	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)
+	}
+	return raw, nil
+}
+
 // Info returns information about this particular extension.
 func (b *TestBinary) Info(ctx context.Context) (*Extension, error) {
 	if b.info != nil {
@@ -356,30 +386,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)
@@ -561,13 +574,27 @@ 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 {
+		// 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)
 	}
 
 	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))

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))
+		})
+	}
+}