surfacing the error from provision-wait mode (#7382)

Author: Devinwong

aks-node-controller/app.go

@@ -3,6 +3,7 @@ package main
 import (
 	"bytes"
 	"context"
+	"encoding/json"
 	"errors"
 	"flag"
 	"fmt"
@@ -11,6 +12,7 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"strconv"
 
 	"github.com/Azure/agentbaker/aks-node-controller/parser"
 	"github.com/Azure/agentbaker/aks-node-controller/pkg/nodeconfigutils"
@@ -157,14 +159,6 @@ func (a *App) writeCompleteFileOnError(err error) {
 }
 
 func (a *App) ProvisionWait(ctx context.Context, filepaths ProvisionStatusFiles) (string, error) {
-	if _, err := os.Stat(filepaths.ProvisionCompleteFile); err == nil {
-		data, err := os.ReadFile(filepaths.ProvisionJSONFile)
-		if err != nil {
-			return "", fmt.Errorf("failed to read provision.json: %w. One reason could be that AKSNodeConfig is not properly set", err)
-		}
-		return string(data), nil
-	}
-
 	watcher, err := fsnotify.NewWatcher()
 	if err != nil {
 		return "", fmt.Errorf("failed to create watcher: %w", err)
@@ -179,15 +173,19 @@ func (a *App) ProvisionWait(ctx context.Context, filepaths ProvisionStatusFiles)
 		return "", fmt.Errorf("failed to watch directory: %w", err)
 	}
 
+	if _, statErr := os.Stat(filepaths.ProvisionCompleteFile); statErr == nil {
+		// Fast path: provision.complete already exists when we enter. Avoid watcher overhead.
+		// We read and evaluate once and return immediately. Only this branch executes in this scenario.
+		return readAndEvaluateProvision(filepaths.ProvisionJSONFile)
+	}
+
 	for {
 		select {
 		case event := <-watcher.Events:
 			if event.Op&fsnotify.Create == fsnotify.Create && event.Name == filepaths.ProvisionCompleteFile {
-				data, err := os.ReadFile(filepaths.ProvisionJSONFile)
-				if err != nil {
-					return "", fmt.Errorf("failed to read provision.json: %w. One reason could be that AKSNodeConfig is not properly set", err)
-				}
-				return string(data), nil
+				// Event path: provision.complete was created after we started watching. Read and evaluate now.
+				// This is mutually exclusive with the fast path above; only one of these calls runs per invocation.
+				return readAndEvaluateProvision(filepaths.ProvisionJSONFile)
 			}
 
 		case err := <-watcher.Errors:
@@ -198,6 +196,45 @@ func (a *App) ProvisionWait(ctx context.Context, filepaths ProvisionStatusFiles)
 	}
 }
 
+// evaluateProvisionStatus inspects the serialized CSEStatus (provision.json contents).
+// If ExitCode is non-zero we return an error so that provision-wait exits with a failure code.
+// We still surface the full JSON on stdout (handled by caller) for diagnostics.
+func evaluateProvisionStatus(data []byte) error {
+	// provision.json values are emitted as strings by the shell jq invocation.
+	// We only care about ExitCode + Error + Output (snippet) for failure detection.
+	type provisionResult struct {
+		ExitCode string `json:"ExitCode"`
+		Error    string `json:"Error"`
+		Output   string `json:"Output"`
+	}
+	var result provisionResult
+	if err := json.Unmarshal(data, &result); err != nil {
+		return fmt.Errorf("parse provision.json: %w", err)
+	}
+	if result.ExitCode == "" {
+		return fmt.Errorf("missing ExitCode in provision.json")
+	}
+	code, err := strconv.Atoi(result.ExitCode)
+	if err != nil {
+		return fmt.Errorf("invalid ExitCode in provision.json: %s", result.ExitCode)
+	}
+	if code != 0 {
+		outSnippet := result.Output
+		return fmt.Errorf("provision failed: exitCode=%d error=%s output=%q", code, result.Error, outSnippet)
+	}
+	return nil
+}
+
+// readAndEvaluateProvision reads provision.json content from the given path and evaluates its status.
+// It returns the raw JSON string plus any error derived from its parsed ExitCode.
+func readAndEvaluateProvision(path string) (string, error) {
+	data, err := os.ReadFile(path)
+	if err != nil {
+		return "", fmt.Errorf("failed to read provision.json: %w. One reason could be that AKSNodeConfig is not properly set", err)
+	}
+	return string(data), evaluateProvisionStatus(data)
+}
+
 var _ ExitCoder = &exec.ExitError{}
 
 type ExitCoder interface {

aks-node-controller/app_test.go

@@ -120,9 +120,7 @@ func TestApp_Provision(t *testing.T) {
 			name:  "command runner error",
 			flags: ProvisionFlags{ProvisionConfig: "parser/testdata/test_aksnodeconfig.json"},
 			setupMocks: func(mc *MockCmdRunner) {
-				mc.RunFunc = func(cmd *exec.Cmd) error {
-					return errors.New("command runner error")
-				}
+				mc.RunFunc = func(cmd *exec.Cmd) error { return errors.New("command runner error") }
 			},
 			wantErr: true,
 		},
@@ -134,11 +132,7 @@ func TestApp_Provision(t *testing.T) {
 			if tt.setupMocks != nil {
 				tt.setupMocks(mc)
 			}
-
-			app := &App{
-				cmdRunner: mc.Run,
-			}
-
+			app := &App{cmdRunner: mc.Run}
 			err := app.Provision(context.Background(), tt.flags)
 			if tt.wantErr {
 				assert.Error(t, err)
@@ -150,9 +144,7 @@ func TestApp_Provision(t *testing.T) {
 }
 
 func TestApp_Provision_DryRun(t *testing.T) {
-	app := &App{
-		cmdRunner: cmdRunner,
-	}
+	app := &App{cmdRunner: cmdRunner}
 	result := app.Run(context.Background(), []string{"aks-node-controller", "provision", "--provision-config=parser/testdata/test_aksnodeconfig.json", "--dry-run"})
 	assert.Equal(t, 0, result)
 	if reflect.ValueOf(app.cmdRunner).Pointer() != reflect.ValueOf(cmdRunnerDryRun).Pointer() {
@@ -161,31 +153,39 @@ func TestApp_Provision_DryRun(t *testing.T) {
 }
 
 func TestApp_ProvisionWait(t *testing.T) {
-	testData := "hello world"
-
+	testData := `{"ExitCode": "0", "Output": "hello world", "Error": ""}`
 	tests := []struct {
 		name      string
 		wantsErr  bool
 		errString string
-		setup     func(provisionStatusFiles ProvisionStatusFiles)
+		setup     func(ProvisionStatusFiles)
 	}{
 		{
-			name:     "provision already complete",
-			wantsErr: false,
+			name: "event path (file created after call)",
 			setup: func(provisionStatusFiles ProvisionStatusFiles) {
-				// Run the test in a goroutine to simulate file creation after some delay
+				// This goroutine simulates an external process writing the files after a short delay.
+				// It's running asynchronously from the main test flow.
 				go func() {
-					time.Sleep(200 * time.Millisecond) // Simulate file creation delay
+					time.Sleep(150 * time.Millisecond)
 					_ = os.WriteFile(provisionStatusFiles.ProvisionJSONFile, []byte(testData), 0644)
 					_, _ = os.Create(provisionStatusFiles.ProvisionCompleteFile)
 				}()
 			},
 		},
 		{
-			name:     "wait for provision completion",
-			wantsErr: false,
+			name: "fast path (file exists before call)",
 			setup: func(provisionStatusFiles ProvisionStatusFiles) {
 				_ = os.WriteFile(provisionStatusFiles.ProvisionJSONFile, []byte(testData), 0644)
+				_, _ = os.Create(provisionStatusFiles.ProvisionCompleteFile) // pre-create to trigger immediate return
+			},
+		},
+		{
+			name:      "provision completion with failure ExitCode",
+			wantsErr:  true,
+			errString: "provision failed",
+			setup: func(provisionStatusFiles ProvisionStatusFiles) {
+				failJSON := `{"ExitCode": "7", "Error": "boom", "Output": "trace"}`
+				_ = os.WriteFile(provisionStatusFiles.ProvisionJSONFile, []byte(failJSON), 0644)
 				_, _ = os.Create(provisionStatusFiles.ProvisionCompleteFile)
 			},
 		},
@@ -199,25 +199,21 @@ func TestApp_ProvisionWait(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			mc := &MockCmdRunner{}
-			// Setup a temporary directory
 			tempDir, err := os.MkdirTemp("", "provisiontest")
 			assert.NoError(t, err)
 			tempFile := filepath.Join(tempDir, "testfile.txt")
 			completeFile := filepath.Join(tempDir, "provision.complete")
 			defer os.RemoveAll(tempDir)
 
-			provisionStatusFiles := ProvisionStatusFiles{ProvisionJSONFile: tempFile, ProvisionCompleteFile: completeFile}
+			p := ProvisionStatusFiles{ProvisionJSONFile: tempFile, ProvisionCompleteFile: completeFile}
 			ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond)
 			defer cancel()
-
-			app := &App{
-				cmdRunner: mc.Run,
-			}
+			app := &App{cmdRunner: mc.Run}
 			if tt.setup != nil {
-				tt.setup(provisionStatusFiles)
+				tt.setup(p)
 			}
 
-			data, err := app.ProvisionWait(ctx, ProvisionStatusFiles{ProvisionJSONFile: tempFile, ProvisionCompleteFile: completeFile})
+			data, err := app.ProvisionWait(ctx, p)
 			if tt.wantsErr {
 				assert.Error(t, err)
 				assert.Contains(t, err.Error(), tt.errString)
@@ -273,3 +269,83 @@ func TestApp_Run_Integration(t *testing.T) {
 		assert.Equal(t, 1, exitCode)
 	})
 }
+
+func Test_readAndEvaluateProvision(t *testing.T) {
+	type testCase struct {
+		name           string
+		fileContent    string // raw content to place in file (empty => file absent)
+		createFile     bool   // whether to create the file
+		expectErrSub   string // substring that should appear in error; empty means success expected
+		expectContains string // substring that must appear in successful content
+	}
+
+	tests := []testCase{
+		{
+			name:           "valid provision file",
+			createFile:     true,
+			fileContent:    `{"ExitCode":"0","Output":"ok","Error":"","ExecDuration":"1"}`,
+			expectContains: `"ExitCode":"0"`,
+		},
+		{
+			name:         "missing provision file",
+			createFile:   false,
+			expectErrSub: "no such file",
+		},
+		{
+			name:         "invalid provision file (bad JSON)",
+			createFile:   true,
+			fileContent:  `not-json`,
+			expectErrSub: "invalid character",
+		},
+		{
+			name:         "non-zero ExitCode returns error",
+			createFile:   true,
+			fileContent:  `{"ExitCode":"7","Output":"boom","Error":"bad"}`,
+			expectErrSub: "provision failed",
+		},
+		{
+			name:         "invalid ExitCode returns error",
+			createFile:   true,
+			fileContent:  `{"ExitCode":"unknown","Output":"boom","Error":"bad"}`,
+			expectErrSub: "invalid ExitCode",
+		},
+		{
+			name:         "missing ExitCode returns error",
+			createFile:   true,
+			fileContent:  `{"Output":"boom","Error":"bad"}`,
+			expectErrSub: "missing ExitCode",
+		},
+	}
+
+	writeTemp := func(t *testing.T, content string) string {
+		t.Helper()
+		f, err := os.CreateTemp(t.TempDir(), "provision_*.json")
+		assert.NoError(t, err)
+		_, errWS := f.WriteString(content)
+		assert.NoError(t, errWS)
+		f.Close()
+		return f.Name()
+	}
+
+	for _, tc := range tests {
+		tc := tc
+		t.Run(tc.name, func(t *testing.T) {
+			p := filepath.Join(t.TempDir(), "does_not_exist.json")
+			if tc.createFile {
+				p = writeTemp(t, tc.fileContent)
+			}
+			got, err := readAndEvaluateProvision(p)
+			if tc.expectErrSub != "" { // expected error
+				assert.Error(t, err, "expected an error")
+				if err != nil { // avoid panic if err is nil
+					assert.Contains(t, err.Error(), tc.expectErrSub, "error should contain substring")
+				}
+			} else { // success
+				assert.NoError(t, err, "unexpected error")
+				if tc.expectContains != "" {
+					assert.Contains(t, got, tc.expectContains, "content should contain substring")
+				}
+			}
+		})
+	}
+}