feat: enhance Authentik flow import with validation and logging

- Added comprehensive logging throughout flow import process to track success/failure
- Improved error handling by parsing response body for validation errors even on 200 OK status
- Added flow existence verification after import with exponential backoff retry (5 attempts)
- Enhanced retry logic for flow UUID lookups with increased attempts (5) and exponential delays
- Added debug logging of rendered YAML preview to verify template

Author: CodeMonkeyCybersecurity

pkg/authentik/flows.go

@@ -10,6 +10,9 @@ import (
 	"io"
 	"mime/multipart"
 	"net/http"
+
+	"github.com/uptrace/opentelemetry-go-extra/otelzap"
+	"go.uber.org/zap"
 )
 
 // FlowResponse represents an Authentik flow
@@ -202,25 +205,44 @@ func (c *APIClient) DeleteFlowBySlug(ctx context.Context, slug string) error {
 
 // ImportFlow uploads a blueprint YAML definition for a flow.
 func (c *APIClient) ImportFlow(ctx context.Context, yaml []byte) error {
+	logger := otelzap.Ctx(ctx)
+
+	logger.Debug("Importing Authentik flow",
+		zap.Int("yaml_size_bytes", len(yaml)))
+
 	url := fmt.Sprintf("%s/api/v3/flows/instances/import/", c.BaseURL)
 
 	body := &bytes.Buffer{}
 	writer := multipart.NewWriter(body)
 	part, err := writer.CreateFormFile("file", "flow.yaml")
 	if err != nil {
+		logger.Error("Failed to create multipart form for flow import",
+			zap.Error(err))
 		return fmt.Errorf("failed to create multipart form: %w", err)
 	}
 
 	if _, err := part.Write(yaml); err != nil {
+		logger.Error("Failed to write flow blueprint to multipart form",
+			zap.Error(err))
 		return fmt.Errorf("failed to write flow blueprint: %w", err)
 	}
 
 	if err := writer.Close(); err != nil {
+		logger.Error("Failed to finalize multipart form",
+			zap.Error(err))
 		return fmt.Errorf("failed to finalize multipart form: %w", err)
 	}
 
+	logger.Debug("Making flow import request",
+		zap.String("url", url),
+		zap.String("method", http.MethodPost),
+		zap.String("content_type", writer.FormDataContentType()))
+
 	req, err := http.NewRequestWithContext(ctx, http.MethodPost, url, body)
 	if err != nil {
+		logger.Error("Failed to create HTTP request for flow import",
+			zap.String("url", url),
+			zap.Error(err))
 		return fmt.Errorf("failed to create request: %w", err)
 	}
 
@@ -229,14 +251,84 @@ func (c *APIClient) ImportFlow(ctx context.Context, yaml []byte) error {
 
 	resp, err := c.HTTPClient.Do(req)
 	if err != nil {
+		logger.Error("Flow import request failed",
+			zap.String("url", url),
+			zap.Error(err))
 		return fmt.Errorf("flow import request failed: %w", err)
 	}
 	defer func() { _ = resp.Body.Close() }()
 
+	responseBody, readErr := io.ReadAll(io.LimitReader(resp.Body, 4096))
+	if readErr != nil {
+		logger.Error("Failed to read import response body",
+			zap.Error(readErr))
+		return fmt.Errorf("failed to read response body: %w", readErr)
+	}
+
+	// CRITICAL: Log response body at INFO level so we can see what Authentik returned
+	logger.Info("Received flow import response",
+		zap.Int("status_code", resp.StatusCode),
+		zap.Int("body_length", len(responseBody)),
+		zap.String("response_body", string(responseBody))) // CRITICAL: Log actual response
+
+	// CRITICAL FIX: Parse response body on ALL status codes, not just errors
+	// Authentik may return 200 OK but include validation errors in the response
+	var importResponse struct {
+		Success bool     `json:"success"`
+		Detail  string   `json:"detail"`
+		Logs    []string `json:"logs"`
+	}
+
+	// Try to parse the response (may be JSON or empty on 204 No Content)
+	if len(responseBody) > 0 {
+		if err := json.Unmarshal(responseBody, &importResponse); err != nil {
+			logger.Warn("Failed to parse import response as JSON",
+				zap.Error(err),
+				zap.String("raw_response", string(responseBody)))
+			// Continue - may be plain text or empty response
+		} else {
+			logger.Info("Parsed import response",
+				zap.Bool("success", importResponse.Success),
+				zap.String("detail", importResponse.Detail),
+				zap.Strings("logs", importResponse.Logs))
+		}
+	}
+
+	// Check for HTTP-level errors
 	if resp.StatusCode != http.StatusOK && resp.StatusCode != http.StatusCreated && resp.StatusCode != http.StatusNoContent {
-		body, _ := io.ReadAll(io.LimitReader(resp.Body, 2048))
-		return fmt.Errorf("flow import failed with status %d: %s", resp.StatusCode, string(body))
-	}
+		// HTTP error status
+		if importResponse.Detail != "" {
+			logger.Error("Flow import failed with API error",
+				zap.Int("status_code", resp.StatusCode),
+				zap.String("error_detail", importResponse.Detail),
+				zap.Strings("import_logs", importResponse.Logs))
+			return fmt.Errorf("flow import failed with status %d: %s (logs: %v)", resp.StatusCode, importResponse.Detail, importResponse.Logs)
+		}
+
+		logger.Error("Flow import failed",
+			zap.Int("status_code", resp.StatusCode),
+			zap.String("response_body", string(responseBody)))
+		return fmt.Errorf("flow import failed with status %d: %s", resp.StatusCode, string(responseBody))
+	}
+
+	// CRITICAL: Check response body for import validation errors even on 200 OK
+	if importResponse.Success == false && importResponse.Detail != "" {
+		logger.Error("Flow import returned success status but validation failed",
+			zap.Int("status_code", resp.StatusCode),
+			zap.String("error_detail", importResponse.Detail),
+			zap.Strings("import_logs", importResponse.Logs))
+		return fmt.Errorf("flow import validation failed: %s (logs: %v)", importResponse.Detail, importResponse.Logs)
+	}
+
+	// Log import logs if available (may contain warnings or info)
+	if len(importResponse.Logs) > 0 {
+		logger.Info("Flow import completed with logs",
+			zap.Strings("import_logs", importResponse.Logs))
+	}
+
+	logger.Debug("Flow import successful",
+		zap.Int("status_code", resp.StatusCode),
+		zap.String("note", "Flow may take a few seconds to become queryable due to API indexing"))
 
 	return nil
 }

pkg/hecate/default_flows.go

@@ -148,6 +148,12 @@ func EnableDefaultFlows(rc *eos_io.RuntimeContext, cfg *DefaultFlowsConfig) erro
 			return fmt.Errorf("failed to render flow template %q: %w", flow.Name, err)
 		}
 
+		// CRITICAL: Log rendered YAML preview to verify template interpolation
+		logger.Debug("Rendered flow YAML",
+			zap.String("flow", flow.Name),
+			zap.Int("yaml_size", len(rendered)),
+			zap.String("yaml_preview", string(rendered[:min(500, len(rendered))]))) // First 500 chars
+
 		if cfg.DryRun {
 			logger.Info("[dry-run] Would import Authentik flow",
 				zap.String("flow", flow.Name),
@@ -163,13 +169,31 @@ func EnableDefaultFlows(rc *eos_io.RuntimeContext, cfg *DefaultFlowsConfig) erro
 			}
 		}
 
+		logger.Info("Importing flow to Authentik",
+			zap.String("flow", flow.Name),
+			zap.String("slug", flow.Slug))
+
 		if err := client.ImportFlow(rc.Ctx, rendered); err != nil {
 			return fmt.Errorf("failed to import flow %q: %w", flow.Name, err)
 		}
 
-		logger.Info("✓ Flow imported",
+		// CRITICAL: Verify flow actually exists after import
+		// RATIONALE: Authentik may return 200 OK but not create the flow (validation errors, etc.)
+		// Use retry to handle eventual consistency (API indexing lag)
+		// RETRY STRATEGY: 5 attempts with 2s initial delay (2s, 4s, 8s, 16s, 32s = max 62s wait)
+		verifiedFlow := getFlowWithRetry(rc, client, logger, flow.Slug, 5, 2*time.Second)
+		if verifiedFlow == nil {
+			logger.Error("Flow import reported success but flow does not exist",
+				zap.String("flow_name", flow.Name),
+				zap.String("slug", flow.Slug),
+				zap.String("remediation", "Check Authentik logs and YAML syntax"))
+			return fmt.Errorf("flow import verification failed: flow %q does not exist after import", flow.Name)
+		}
+
+		logger.Info("✓ Flow imported and verified",
 			zap.String("flow", flow.Name),
-			zap.String("slug", flow.Slug))
+			zap.String("slug", flow.Slug),
+			zap.String("uuid", verifiedFlow.PK))
 		importedSlugs = append(importedSlugs, flow.Slug)
 	}
 
@@ -202,11 +226,12 @@ func EnableDefaultFlows(rc *eos_io.RuntimeContext, cfg *DefaultFlowsConfig) erro
 			// CRITICAL: Brand API requires flow UUIDs, not slugs
 			// Lookup each flow to get its PK (UUID) with retry logic for eventual consistency
 			// RATIONALE: Freshly imported flows may not be immediately queryable due to Authentik indexing
-			authFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-authentication", appSlug), 3, 2*time.Second)
-			enrollmentFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-enrollment", appSlug), 3, 2*time.Second)
-			invalidationGlobalFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-invalidation-global", appSlug), 3, 2*time.Second)
-			recoveryFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-recovery", appSlug), 3, 2*time.Second)
-			unenrollmentFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-unenrollment", appSlug), 3, 2*time.Second)
+			// RETRY STRATEGY: 5 attempts with exponential backoff (1s, 2s, 4s, 8s, 16s = max 31s wait)
+			authFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-authentication", appSlug), 5, 1*time.Second)
+			enrollmentFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-enrollment", appSlug), 5, 1*time.Second)
+			invalidationGlobalFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-invalidation-global", appSlug), 5, 1*time.Second)
+			recoveryFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-recovery", appSlug), 5, 1*time.Second)
+			unenrollmentFlow := getFlowWithRetry(rc, client, logger, fmt.Sprintf("%s-unenrollment", appSlug), 5, 1*time.Second)
 
 			// Only update brand if we successfully looked up all flow UUIDs
 			if authFlow != nil && enrollmentFlow != nil && invalidationGlobalFlow != nil && recoveryFlow != nil && unenrollmentFlow != nil {
@@ -963,41 +988,49 @@ entries:
       timeout: 30
 `
 
-// getFlowWithRetry attempts to retrieve a flow with retry logic for eventual consistency
-// RATIONALE: Freshly imported flows may not be immediately queryable in Authentik
-// This is a timing issue - the flow exists but the index hasn't updated yet
-func getFlowWithRetry(rc *eos_io.RuntimeContext, client *authentik.APIClient, logger otelzap.LoggerWithCtx, slug string, maxRetries int, retryDelay time.Duration) *authentik.FlowResponse {
+// getFlowWithRetry attempts to retrieve a flow with retry logic and exponential backoff
+// RATIONALE: Freshly imported flows may not be immediately queryable in Authentik due to indexing lag
+// This is a timing issue - the flow exists but the API index hasn't updated yet
+// RETRY STRATEGY: Exponential backoff (1s, 2s, 4s, 8s, 16s) for up to 5 attempts (max 31s wait)
+func getFlowWithRetry(rc *eos_io.RuntimeContext, client *authentik.APIClient, logger otelzap.LoggerWithCtx, slug string, maxRetries int, initialDelay time.Duration) *authentik.FlowResponse {
+	currentDelay := initialDelay
+
 	for attempt := 1; attempt <= maxRetries; attempt++ {
 		flow, err := client.GetFlow(rc.Ctx, slug)
 		if err != nil {
-			logger.Warn("Failed to lookup flow UUID",
+			logger.Warn("Failed to lookup flow UUID (API error)",
 				zap.String("slug", slug),
 				zap.Int("attempt", attempt),
 				zap.Int("max_retries", maxRetries),
 				zap.Error(err))
 		} else if flow != nil {
 			// Success - flow found
-			logger.Debug("Found flow UUID",
+			logger.Debug("Flow UUID resolved",
 				zap.String("slug", slug),
 				zap.String("uuid", flow.PK),
+				zap.String("flow_name", flow.Name),
 				zap.Int("attempt", attempt))
 			return flow
 		}
 
 		// Flow not found yet (flow == nil, err == nil means "not found" per GetFlow contract)
 		if attempt < maxRetries {
-			logger.Debug("Flow not found yet, waiting before retry",
+			logger.Debug("Flow not indexed yet, retrying with exponential backoff",
 				zap.String("slug", slug),
 				zap.Int("attempt", attempt),
 				zap.Int("max_retries", maxRetries),
-				zap.Duration("retry_delay", retryDelay))
-			time.Sleep(retryDelay)
+				zap.Duration("retry_delay", currentDelay),
+				zap.String("reason", "Authentik API eventual consistency"))
+			time.Sleep(currentDelay)
+			currentDelay *= 2 // Exponential backoff: 1s → 2s → 4s → 8s → 16s
 		}
 	}
 
-	// All retries exhausted
-	logger.Warn("Flow not found after all retries",
+	// All retries exhausted - flow may not exist or API is very slow
+	logger.Warn("Flow not found after all retries (may not exist or API indexing is slow)",
 		zap.String("slug", slug),
-		zap.Int("max_retries", maxRetries))
+		zap.Int("max_retries", maxRetries),
+		zap.Duration("total_wait_time", initialDelay*(1<<uint(maxRetries)-1)), // Sum of geometric series
+		zap.String("remediation", "Check if flow was actually imported successfully"))
 	return nil
 }