diff --git a/aks-node-controller/README.md b/aks-node-controller/README.md index f1b960a2698..0539665d43b 100644 --- a/aks-node-controller/README.md +++ b/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: diff --git a/aks-node-controller/app.go b/aks-node-controller/app.go index 9284a6245d6..71942951b3e 100644 --- a/aks-node-controller/app.go +++ b/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 { diff --git a/aks-node-controller/app_test.go b/aks-node-controller/app_test.go index 827d9d772ed..f961ea161ad 100644 --- a/aks-node-controller/app_test.go +++ b/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) } diff --git a/aks-node-controller/goal_state.go b/aks-node-controller/goal_state.go index e8401bb21db..f0b7530bb90 100644 --- a/aks-node-controller/goal_state.go +++ b/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)) diff --git a/aks-node-controller/goal_state_test.go b/aks-node-controller/goal_state_test.go index a9b92c5f235..7d39ab26715 100644 --- a/aks-node-controller/goal_state_test.go +++ b/aks-node-controller/goal_state_test.go @@ -38,6 +38,8 @@ func TestSendHealthReport(t *testing.T) { {name: "failure", failed: true, description: `CSE failed: & "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")) diff --git a/aks-node-controller/provision_status.go b/aks-node-controller/provision_status.go new file mode 100644 index 00000000000..51d1e54b881 --- /dev/null +++ b/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 +} diff --git a/aks-node-controller/provision_status_test.go b/aks-node-controller/provision_status_test.go new file mode 100644 index 00000000000..75641b72542 --- /dev/null +++ b/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")) +}