feat: report entire provision output from ANC

aks-node-controller/README.md

@@ -223,6 +223,7 @@ Key components:
 
 - **provision**: Parses the node configuration and starts the bootstrap sequence.
     - When `/var/lib/waagent/experimental_skip_ready_report` marks an active readiness handoff, ANC reports provisioning status directly in Go (`goal_state.go`), without a Python script. It writes Hyper-V KVP diagnostics and sends a GoalState health report to Azure wireserver: `Ready` on success, or `NotReady` with `ProvisioningFailed` on failure, including failures before the provisioning command starts. HTTP reporting uses three attempts with five-second retry delays and 30-second request timeouts, without a proxy. KVP and HTTP reporting errors are logged without replacing the original provisioning result, and dry runs do not send reports.
+    - Failure descriptions include the structured CSE JSON emitted by the current command, including `Output` and boot-timing fields. If no matching CSE JSON was emitted, ANC reports its captured `ExitCode`, `Error`, and `Output` instead. WireServer descriptions are limited to 4,096 bytes after XML escaping: oversized output retains its tail and sets `OutputTruncated`; oversized metadata also sets `DetailsTruncated` and falls back to the core result fields. The complete captured output remains in ANC's local logs. Hyper-V KVP diagnostics retain their existing smaller limits.
     - The controller performs a tolerant (forward‑compatible) parse of `aksnodeconfigv1.Configuration`: unknown fields, additional enum values, or future‑version knobs are ignored (and may be logged) so that a newer control‑plane can talk to an older VHD image.
     - If the config cannot be safely interpreted (e.g. unsupported `Version`, malformed required field, or incompatible schema change), the controller fails fast. It writes the sentinel file `provision.complete` early so the `provision-wait` process stops polling and can surface an error instead of hanging indefinitely.
     - In a fail‑fast path the normal bootstrap scripts never run, therefore `provision.json` (which would contain the serialized `CSEStatus`) is never created. A typical error looks like:

aks-node-controller/app.go

@@ -729,7 +729,12 @@ func (a *App) reportProvisionStatus(ctx context.Context, result *ProvisionResult
 
 	description := ""
 	if provisionErr != nil {
-		description = fmt.Sprintf("ExitCode: %s, %s", result.ExitCode, result.Error)
+		var err error
+		description, err = provisionFailureDescription(result)
+		if err != nil {
+			slog.Error("failed to format CSE failure description", "error", err)
+			description = fmt.Sprintf("ExitCode: %s, %s", result.ExitCode, result.Error)
+		}
 	}
 	reporter := a.goalStateReporter
 	if reporter == nil {

aks-node-controller/app_test.go

@@ -242,7 +242,10 @@ func runPreScriptFailureReportingCase(t *testing.T, tc preScriptFailureCase, mar
 	require.Equal(t, err.Error(), result.Error)
 	require.Empty(t, commands)
 	if markerExists && !dryRun {
-		require.Equal(t, []string{"ExitCode: 240, " + err.Error()}, reports)
+		require.Len(t, reports, 1)
+		var reported ProvisionResult
+		require.NoError(t, json.Unmarshal([]byte(reports[0]), &reported))
+		require.Equal(t, *result, reported)
 	} else {
 		require.Empty(t, reports)
 	}
@@ -314,7 +317,10 @@ func TestApp_ProvisionReportsAfterScriptExecution(t *testing.T) {
 				require.Len(t, commands, 1, "report must follow provisioning")
 				require.Equal(t, scriptErr != nil, failed)
 				if failed {
-					require.Equal(t, "ExitCode: -1, "+scriptErr.Error(), description)
+					var reported ProvisionResult
+					require.NoError(t, json.Unmarshal([]byte(description), &reported))
+					require.Equal(t, "-1", reported.ExitCode)
+					require.Equal(t, scriptErr.Error(), reported.Error)
 				} else {
 					require.Empty(t, description)
 				}
@@ -378,7 +384,10 @@ func TestApp_ProvisionReportsPanic(t *testing.T) {
 			require.Equal(t, "240", result.ExitCode)
 			require.Equal(t, err.Error(), result.Error)
 			if markerExists {
-				require.Equal(t, []string{"ExitCode: 240, " + err.Error()}, reports)
+				require.Len(t, reports, 1)
+				var reported ProvisionResult
+				require.NoError(t, json.Unmarshal([]byte(reports[0]), &reported))
+				require.Equal(t, *result, reported)
 			} else {
 				require.Empty(t, reports)
 			}

aks-node-controller/goal_state.go

@@ -25,7 +25,9 @@ const (
 	kvpValueSize       = 2048
 	kvpReportLimit     = 1024
 	descriptionLimit   = 512
-	healthReportTries  = 3
+	// WireServer accepts at most 4096 bytes of XML-escaped description text.
+	healthDescriptionLimit = 4096
+	healthReportTries      = 3
 )
 
 type goalState struct {
@@ -66,7 +68,7 @@ func reportGoalState(ctx context.Context, failed bool, description string) error
 }
 
 func sendHealthReport(ctx context.Context, client *http.Client, endpoint string, failed bool, description string, retryDelay time.Duration) error {
-	description = trimReportDescription(description)
+	description = trimHealthReportDescription(description)
 	state := "Ready"
 	if failed {
 		state = "NotReady"
@@ -204,6 +206,29 @@ func trimReportDescription(description string) string {
 	return string(runes[:min(len(runes), descriptionLimit)])
 }
 
+func healthDescriptionFits(description string) bool {
+	var escaped bytes.Buffer
+	_ = xml.EscapeText(&escaped, []byte(description))
+	return escaped.Len() <= healthDescriptionLimit
+}
+
+func trimHealthReportDescription(description string) string {
+	if healthDescriptionFits(description) {
+		return description
+	}
+	runes := []rune(description)
+	low, high := 0, min(len(runes), healthDescriptionLimit)
+	for low < high {
+		mid := low + (high-low+1)/2
+		if healthDescriptionFits(string(runes[:mid])) {
+			low = mid
+		} else {
+			high = mid - 1
+		}
+	}
+	return string(runes[:low])
+}
+
 // cloud-init uses pipe-delimited CSV with single quotes, unlike encoding/csv.
 func encodeProvisioningReport(fields []string) string {
 	encoded := make([]string, len(fields))

aks-node-controller/goal_state_test.go

@@ -38,6 +38,8 @@ func TestSendHealthReport(t *testing.T) {
 		{name: "failure", failed: true, description: `CSE failed: <bad> & "quoted"`, statusCode: http.StatusOK},
 		{name: "empty failure", failed: true, statusCode: http.StatusOK},
 		{name: "long failure", failed: true, description: strings.Repeat("\u00e9", 600), statusCode: http.StatusOK},
+		{name: "oversized failure", failed: true, description: strings.Repeat("x", 5000), statusCode: http.StatusOK},
+		{name: "XML-escaped failure", failed: true, description: strings.Repeat("<&'\"\u00e9", 1000), statusCode: http.StatusOK},
 	} {
 		t.Run(tc.name, func(t *testing.T) {
 			var posted atomic.Int32
@@ -65,8 +67,11 @@ func TestSendHealthReport(t *testing.T) {
 					assert.Equal(t, "NotReady", report.State)
 					if assert.NotNil(t, report.Details) {
 						assert.Equal(t, "ProvisioningFailed", report.Details.SubStatus)
-						expected := []rune(tc.description)
-						assert.Equal(t, string(expected[:min(len(expected), 512)]), report.Details.Description)
+						assert.True(t, strings.HasPrefix(tc.description, report.Details.Description))
+						var escaped bytes.Buffer
+						assert.NoError(t, xml.EscapeText(&escaped, []byte(report.Details.Description)))
+						assert.LessOrEqual(t, escaped.Len(), 4096)
+						assert.Equal(t, trimHealthReportDescription(tc.description), report.Details.Description)
 					}
 				} else {
 					assert.Equal(t, "Ready", report.State)
@@ -202,6 +207,28 @@ func TestReportValueLimits(t *testing.T) {
 	}
 }
 
+func TestTrimHealthReportDescription(t *testing.T) {
+	require.Equal(t, strings.Repeat("\u00e9", 600), trimHealthReportDescription(strings.Repeat("\u00e9", 600)))
+	require.Equal(t, strings.Repeat("x", 4096), trimHealthReportDescription(strings.Repeat("x", 4096)))
+	for _, input := range []string{
+		strings.Repeat("x", 4097),
+		strings.Repeat("\u00e9", 2049),
+		strings.Repeat("<&'\"\n", 1000),
+	} {
+		got := trimHealthReportDescription(input)
+		require.True(t, utf8.ValidString(got))
+		require.True(t, strings.HasPrefix(input, got))
+		var escaped bytes.Buffer
+		require.NoError(t, xml.EscapeText(&escaped, []byte(got)))
+		require.LessOrEqual(t, escaped.Len(), 4096)
+		remaining := []rune(strings.TrimPrefix(input, got))
+		require.NotEmpty(t, remaining)
+		escaped.Reset()
+		require.NoError(t, xml.EscapeText(&escaped, []byte(got+string(remaining[0]))))
+		require.Greater(t, escaped.Len(), 4096, "must retain the largest safe prefix")
+	}
+}
+
 func TestWriteKVPRecord(t *testing.T) {
 	path := filepath.Join(t.TempDir(), "kvp")
 	require.NoError(t, writeKVPRecord(path, "dmesg", "kernel output"))

aks-node-controller/provision_status.go

@@ -0,0 +1,94 @@
+package main
+
+import (
+	"encoding/json"
+	"fmt"
+	"strings"
+)
+
+const truncatedProvisionOutput = "[...output truncated...]\n"
+
+func provisionFailureDescription(result *ProvisionResult) (string, error) {
+	status := cseStatusFromOutput(result.Output, result.ExitCode)
+	if status == nil {
+		status = map[string]any{
+			"ExitCode": result.ExitCode,
+			"Error":    result.Error,
+			"Output":   result.Output,
+		}
+	}
+	payload, err := json.Marshal(status)
+	if err != nil {
+		return "", fmt.Errorf("marshal CSE failure: %w", err)
+	}
+	if healthDescriptionFits(string(payload)) {
+		return string(payload), nil
+	}
+
+	output, _ := status["Output"].(string)
+	status["Output"] = truncatedProvisionOutput
+	status["OutputTruncated"] = true
+	payload, err = json.Marshal(status)
+	if err != nil {
+		return "", fmt.Errorf("marshal truncated CSE failure: %w", err)
+	}
+	if !healthDescriptionFits(string(payload)) {
+		// Oversized metadata must not crowd out the final provisioning error.
+		errorRunes := []rune(result.Error)
+		status = map[string]any{
+			"ExitCode":         result.ExitCode,
+			"Error":            string(errorRunes[max(0, len(errorRunes)-256):]),
+			"Output":           truncatedProvisionOutput,
+			"OutputTruncated":  true,
+			"DetailsTruncated": true,
+		}
+	}
+
+	runes := []rune(output)
+	low, high := 0, len(runes)
+	for low < high {
+		mid := low + (high-low+1)/2
+		status["Output"] = truncatedProvisionOutput + string(runes[len(runes)-mid:])
+		payload, err = json.Marshal(status)
+		if err != nil {
+			return "", fmt.Errorf("marshal truncated CSE failure: %w", err)
+		}
+		if healthDescriptionFits(string(payload)) {
+			low = mid
+		} else {
+			high = mid - 1
+		}
+	}
+	status["Output"] = truncatedProvisionOutput + string(runes[len(runes)-low:])
+	payload, err = json.Marshal(status)
+	if err != nil {
+		return "", fmt.Errorf("marshal truncated CSE failure: %w", err)
+	}
+	if !healthDescriptionFits(string(payload)) {
+		return "", fmt.Errorf("CSE failure metadata exceeds the %d-byte health description limit", healthDescriptionLimit)
+	}
+	return string(payload), nil
+}
+
+func cseStatusFromOutput(output, exitCode string) map[string]any {
+	for offset := 0; offset < len(output); {
+		start := strings.IndexByte(output[offset:], '{')
+		if start < 0 {
+			break
+		}
+		offset += start
+		decoder := json.NewDecoder(strings.NewReader(output[offset:]))
+		decoder.UseNumber()
+		var status map[string]any
+		if err := decoder.Decode(&status); err == nil {
+			code, hasCode := status["ExitCode"].(string)
+			_, hasOutput := status["Output"].(string)
+			_, hasError := status["Error"].(string)
+			if hasCode && code == exitCode && hasOutput && hasError {
+				return status
+			}
+		}
+		offset++
+	}
+	return nil
+}

aks-node-controller/provision_status_test.go

@@ -0,0 +1,128 @@
+package main
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"encoding/xml"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+	"unicode/utf8"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestProvisionFailureDescription(t *testing.T) {
+	for _, tc := range []struct {
+		name     string
+		output   string
+		metadata string
+	}{
+		{name: "complete", output: "configureHTTPProxyCA\nbase64: invalid input\nexit 161"},
+		{name: "long", output: strings.Repeat("older log line\n", 1000) + "base64: invalid input\nexit 161"},
+		{name: "XML and Unicode", output: strings.Repeat("<&'\"\u00e9\n", 1000) + "base64: invalid input\nexit 161"},
+		{name: "oversized metadata", output: strings.Repeat("log\n", 1000) + "exit 161", metadata: strings.Repeat("metadata", 1000)},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			status := map[string]any{
+				"ExitCode": "161", "Output": tc.output, "Error": "",
+				"ExecDuration": "4", "SystemdSummary": tc.metadata,
+				"BootDatapoints": map[string]string{"KubeletStartTime": "n/a"},
+			}
+			raw, err := json.Marshal(status)
+			require.NoError(t, err)
+			result := &ProvisionResult{
+				ExitCode: "161", Error: "exit status 161",
+				Output: "command output before status\n" + string(raw) + "\ndate: invalid date 'n/a'",
+			}
+
+			description, err := provisionFailureDescription(result)
+
+			require.NoError(t, err)
+			require.True(t, utf8.ValidString(description))
+			var escaped bytes.Buffer
+			require.NoError(t, xml.EscapeText(&escaped, []byte(description)))
+			require.LessOrEqual(t, escaped.Len(), 4096)
+			var reported map[string]any
+			require.NoError(t, json.Unmarshal([]byte(description), &reported))
+			require.Equal(t, "161", reported["ExitCode"])
+			output, ok := reported["Output"].(string)
+			require.True(t, ok)
+			if tc.name == "complete" {
+				require.JSONEq(t, string(raw), description)
+			} else {
+				require.Equal(t, true, reported["OutputTruncated"])
+				require.True(t, strings.HasPrefix(output, truncatedProvisionOutput))
+				require.True(t, strings.HasSuffix(tc.output, strings.TrimPrefix(output, truncatedProvisionOutput)))
+				require.True(t, strings.HasSuffix(output, "exit 161"))
+			}
+			if tc.metadata == "" {
+				require.Equal(t, "4", reported["ExecDuration"])
+				require.Equal(t, map[string]any{"KubeletStartTime": "n/a"}, reported["BootDatapoints"])
+			} else {
+				require.Equal(t, true, reported["DetailsTruncated"])
+			}
+		})
+	}
+}
+
+func TestProvisionFailureDescriptionFallback(t *testing.T) {
+	for _, output := range []string{
+		"",
+		"script failed before emitting JSON",
+		`{"ExitCode":"0","Error":"","Output":"stale success"}`,
+		`{"ExitCode":"161","Error":"","Output":123}`,
+		`{"ExitCode":"161","Error":"","Output":"incomplete"`,
+	} {
+		result := &ProvisionResult{ExitCode: "161", Error: "exit status 161", Output: output}
+		description, err := provisionFailureDescription(result)
+		require.NoError(t, err)
+		var reported ProvisionResult
+		require.NoError(t, json.Unmarshal([]byte(description), &reported))
+		require.Equal(t, *result, reported)
+	}
+}
+
+func TestAppProvisionReportsCSEJSONToWireServer(t *testing.T) {
+	output := strings.Repeat("old log line <&'\"\n", 1000) + "base64: invalid input\nexit 161"
+	raw, err := json.Marshal(map[string]any{
+		"ExitCode": "161", "Error": "", "Output": output, "ExecDuration": "4",
+	})
+	require.NoError(t, err)
+	descriptions := make(chan string, 1)
+	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		if r.Method == http.MethodGet {
+			_, _ = io.WriteString(w, testGoalState)
+			return
+		}
+		var report healthReport
+		assert.NoError(t, xml.NewDecoder(r.Body).Decode(&report))
+		assert.Equal(t, "NotReady", report.State)
+		if assert.NotNil(t, report.Details) {
+			descriptions <- report.Details.Description
+		}
+	}))
+	defer server.Close()
+	tt := NewTestApp(t, TestAppConfig{RunFunc: cmdRunner})
+	tt.App.goalStateReporter = func(ctx context.Context, failed bool, description string) error {
+		return sendHealthReport(ctx, server.Client(), server.URL, failed, description, 0)
+	}
+	require.NoError(t, os.WriteFile(tt.App.readyReportMarkerPath, nil, 0o600))
+	path := filepath.Join(t.TempDir(), "nbc-cmd.sh")
+	require.NoError(t, os.WriteFile(path, []byte("#!/bin/bash\ncat <<'EOF'\n"+string(raw)+"\nEOF\nexit 161\n"), 0o600))
+
+	_, err = tt.App.runProvision(t.Context(), ProvisionFlags{NBCCmd: path}, false)
+
+	require.ErrorContains(t, err, "exit status 161")
+	require.Len(t, descriptions, 1)
+	var reported ProvisionResult
+	require.NoError(t, json.Unmarshal([]byte(<-descriptions), &reported))
+	require.Equal(t, "161", reported.ExitCode)
+	require.True(t, strings.HasSuffix(reported.Output, "base64: invalid input\nexit 161"))
+}