test(e2e): instrument hostname gate and startup for CI debug

Capture docker inspect, /data modes, supervisorctl, and entrypoint markers on failure (stderr DEBUG816647 lines + debug-816647.log) so release CI can show why valid_hostname_starts / startup_processes_running die with empty logs. Co-Authored-By: Composer <noreply@cursor.com> Co-authored-by: Cursor <cursoragent@cursor.com>
2026-08-09 08:51:18 +03:00
parent 231d341d0d
commit d43a86c4bd
3 changed files with 152 additions and 3 deletions
@@ -0,0 +1,48 @@
+package e2e
+
+import (
+	"encoding/json"
+	"fmt"
+	"os"
+	"path/filepath"
+	"time"
+)
+
+// agentDebugLog appends one NDJSON line for debug-mode hypothesis testing.
+// Best-effort only — never fails the suite. Also prints to stderr so GitHub
+// Actions captures the evidence when there is no local log file.
+func agentDebugLog(hypothesisID, location, message string, data map[string]any) {
+	// #region agent log
+	payload := map[string]any{
+		"sessionId":    "816647",
+		"hypothesisId": hypothesisID,
+		"location":     location,
+		"message":      message,
+		"data":         data,
+		"timestamp":    time.Now().UnixMilli(),
+		"runId":        "pre-fix",
+	}
+	b, err := json.Marshal(payload)
+	if err != nil {
+		return
+	}
+	fmt.Fprintf(os.Stderr, "DEBUG816647 %s\n", b)
+	b = append(b, '\n')
+	paths := []string{
+		filepath.Join("..", "..", "debug-816647.log"),
+		"debug-816647.log",
+	}
+	if wd, err := os.Getwd(); err == nil {
+		paths = append([]string{filepath.Join(wd, "..", "..", "debug-816647.log")}, paths...)
+	}
+	for _, p := range paths {
+		f, err := os.OpenFile(p, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
+		if err != nil {
+			continue
+		}
+		_, _ = f.Write(b)
+		_ = f.Close()
+		return
+	}
+	// #endregion
+}
@@ -1,8 +1,10 @@
 package e2e

 import (
+	"fmt"
 	"os"
 	"os/exec"
+	"path/filepath"
 	"strings"
 	"testing"
 	"time"
@@ -88,12 +90,29 @@ func runEntrypointBackground(t *testing.T, hostnameEnv string) (output string, s
 	_ = exec.Command("docker", "rm", "-f", name).Run()
 	defer exec.Command("docker", "rm", "-f", name).Run()

+	// #region agent log
+	if fi, err := os.Stat(dataDir); err == nil {
+		agentDebugLog("H1", "hostname_gate_test.go:pre-run", "host dataDir before docker run", map[string]any{
+			"mode": fmt.Sprintf("%04o", fi.Mode().Perm()),
+			"path": dataDir,
+		})
+	}
+	imgInspect, _ := exec.Command("docker", "image", "inspect", "selfpost:e2e",
+		"--format", "{{.Id}} created={{.Created}}").CombinedOutput()
+	agentDebugLog("H5", "hostname_gate_test.go:pre-run", "selfpost:e2e image", map[string]any{
+		"inspect": strings.TrimSpace(string(imgInspect)),
+	})
+	// #endregion
+
 	up := exec.Command("docker", "run", "-d", "--name", name,
 		"-e", "SELFPOST_HOSTNAME="+hostnameEnv,
 		"-v", dataDir+":/data",
 		"-v", certDir+":/etc/postfix/tls:ro",
 		"selfpost:e2e")
 	if out, err := up.CombinedOutput(); err != nil {
+		agentDebugLog("H2", "hostname_gate_test.go:run", "docker run -d failed", map[string]any{
+			"out": string(out), "err": err.Error(),
+		})
 		return string(out), false
 	}

@@ -104,6 +123,59 @@ func runEntrypointBackground(t *testing.T, hostnameEnv string) (output string, s
 		}
 		return false, err
 	})
-	logs, _ := exec.Command("docker", "logs", name).CombinedOutput()
-	return string(logs), err == nil
+
+	// #region agent log
+	inspect, _ := exec.Command("docker", "inspect", name, "--format",
+		"status={{.State.Status}} exit={{.State.ExitCode}} err={{.State.Error}} oom={{.State.OOMKilled}} started={{.State.StartedAt}} finished={{.State.FinishedAt}}").CombinedOutput()
+	logs, logErr := exec.Command("docker", "logs", name).CombinedOutput()
+	dataMode, _ := exec.Command("docker", "exec", name, "stat", "-c", "%a %U:%G", "/data").CombinedOutput()
+	opendkimStat, _ := exec.Command("docker", "exec", name, "stat", "-c", "%a %U:%G", "/data/opendkim").CombinedOutput()
+	keyTableStat, _ := exec.Command("docker", "exec", name, "stat", "-c", "%a %U:%G", "/data/opendkim/KeyTable").CombinedOutput()
+	supStatus, _ := exec.Command("docker", "exec", name, "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "status").CombinedOutput()
+	hostDataListing := ""
+	if entries, e := os.ReadDir(dataDir); e == nil {
+		var parts []string
+		for _, ent := range entries {
+			p := filepath.Join(dataDir, ent.Name())
+			fi, _ := os.Stat(p)
+			mode := "?"
+			if fi != nil {
+				mode = fmt.Sprintf("%04o", fi.Mode().Perm())
+			}
+			parts = append(parts, ent.Name()+":"+mode)
+		}
+		hostDataListing = strings.Join(parts, ",")
+	}
+	agentDebugLog("H1", "hostname_gate_test.go:post-wait", "data permissions", map[string]any{
+		"dataMode":      strings.TrimSpace(string(dataMode)),
+		"opendkimStat":  strings.TrimSpace(string(opendkimStat)),
+		"keyTableStat":  strings.TrimSpace(string(keyTableStat)),
+		"hostDataListing": hostDataListing,
+	})
+	agentDebugLog("H2", "hostname_gate_test.go:post-wait", "container inspect", map[string]any{
+		"inspect": strings.TrimSpace(string(inspect)),
+		"waitErr": fmt.Sprintf("%v", err),
+		"logErr":  fmt.Sprintf("%v", logErr),
+		"logLen":  len(logs),
+	})
+	agentDebugLog("H3", "hostname_gate_test.go:post-wait", "supervisor and logs", map[string]any{
+		"supervisorctl": strings.TrimSpace(string(supStatus)),
+		"logsHead":      truncateForDebug(string(logs), 4000),
+	})
+	// #endregion
+
+	diag := string(logs)
+	if strings.TrimSpace(diag) == "" {
+		diag = "(empty docker logs)\ninspect: " + strings.TrimSpace(string(inspect)) +
+			"\nsupervisorctl: " + strings.TrimSpace(string(supStatus)) +
+			"\n/data mode: " + strings.TrimSpace(string(dataMode))
+	}
+	return diag, err == nil
+}
+
+func truncateForDebug(s string, n int) string {
+	if len(s) <= n {
+		return s
+	}
+	return s[:n] + "…"
 }
@@ -2,6 +2,9 @@ package e2e

 import (
 	"fmt"
+	"os"
+	"os/exec"
+	"path/filepath"
 	"strings"
 	"time"
 )
@@ -46,7 +49,33 @@ func checkSupervisorProcesses(s *stack) error {
 		return true, nil
 	})
 	if err != nil {
-		return fmt.Errorf("%w\n==== selfpost logs ====\n%s", err, s.logs("selfpost"))
+		logs := s.logs("selfpost")
+		// #region agent log
+		ps, _ := s.compose("ps", "-a", "--format", "json")
+		inspectOut, _ := exec.Command("docker", "ps", "-a", "--filter", "name=selfpost-e2e",
+			"--format", "{{.Names}} {{.Status}} {{.ID}}").CombinedOutput()
+		dataPath := filepath.Join(s.stageDir, "data")
+		dataMode := ""
+		if fi, e := os.Stat(dataPath); e == nil {
+			dataMode = fmt.Sprintf("%04o", fi.Mode().Perm())
+		}
+		entrypointSnippet, _ := exec.Command("docker", "run", "--rm", "--entrypoint", "sh", "selfpost:e2e",
+			"-c", "grep -n 'chmod 755 /data\\|SELFPOST_HOSTNAME is not set' /usr/local/bin/entrypoint.sh | head -20").CombinedOutput()
+		agentDebugLog("H4", "process_check.go:fail", "compose selfpost not ready", map[string]any{
+			"waitErr":            err.Error(),
+			"logsLen":            len(logs),
+			"logsHead":           truncateForDebug(logs, 4000),
+			"composePs":          truncateForDebug(string(ps), 2000),
+			"dockerPs":           strings.TrimSpace(string(inspectOut)),
+			"hostDataMode":       dataMode,
+			"entrypointSnippets": strings.TrimSpace(string(entrypointSnippet)),
+		})
+		agentDebugLog("H5", "process_check.go:fail", "image entrypoint markers", map[string]any{
+			"snippet": strings.TrimSpace(string(entrypointSnippet)),
+		})
+		// #endregion
+		return fmt.Errorf("%w\n==== selfpost logs ====\n%s\n==== docker ps ====\n%s\n==== entrypoint markers ====\n%s",
+			err, logs, inspectOut, entrypointSnippet)
 	}
 	return nil
 }