diff --git a/test/e2e/debug_agent.go b/test/e2e/debug_agent.go new file mode 100644 index 0000000..194cf87 --- /dev/null +++ b/test/e2e/debug_agent.go @@ -0,0 +1,46 @@ +package e2e + +import ( + "encoding/json" + "os" + "path/filepath" + "time" +) + +// agentDebugLog appends one NDJSON line for debug-mode hypothesis testing. +// Best-effort only — never fails the suite. +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 + } + b = append(b, '\n') + // Prefer repo-root log (workspace); also try cwd-relative for CI artifacts. + 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 +} diff --git a/test/e2e/hostname_gate_test.go b/test/e2e/hostname_gate_test.go index 0da2e2c..02f6248 100644 --- a/test/e2e/hostname_gate_test.go +++ b/test/e2e/hostname_gate_test.go @@ -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] + "…" } diff --git a/test/e2e/process_check.go b/test/e2e/process_check.go index 399a234..3bc5063 100644 --- a/test/e2e/process_check.go +++ b/test/e2e/process_check.go @@ -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 }