From 1639701de3af70885c8989975159e4ef446913fb Mon Sep 17 00:00:00 2001 From: mixeme Date: Sun, 9 Aug 2026 09:12:47 +0300 Subject: [PATCH] test(e2e): entrypoint ERR trap and richer CI failure logs CI showed exit=1 in ~3s with empty docker logs after /data/opendkim was created. Log each entrypoint step and trap ERR with LINENO; also read the container LogPath and docker logs by container id when compose logs are empty. Co-Authored-By: Composer Co-authored-by: Cursor --- build/entrypoint.sh | 15 ++++++++++++++ test/e2e/hostname_gate_test.go | 36 ++++++++++++++++++++++++++-------- test/e2e/process_check.go | 25 ++++++++++++++++++++--- 3 files changed, 65 insertions(+), 11 deletions(-) diff --git a/build/entrypoint.sh b/build/entrypoint.sh index c24179f..ab54583 100644 --- a/build/entrypoint.sh +++ b/build/entrypoint.sh @@ -6,6 +6,12 @@ # looks like a permissions or packaging problem (and so the e2e hostname-gate # tests see the FATAL text rather than an earlier set -e abort). set -e +# #region agent log +# Debug: CI showed exit=1 with empty docker logs after /data/opendkim was +# created — surface the failing line under set -e (session 816647). +trap 'echo "entrypoint: command failed at line $LINENO (exit $?)" >&2' ERR +step() { echo "entrypoint: $*" >&2; } +# #endregion # SELFPOST_HOSTNAME is an identity, not a setting with a safe default: it must # simultaneously match the PTR/rDNS record, the certificate CN/SAN, and the @@ -62,6 +68,7 @@ esac # trees under /data as other users. Go's testing.TempDir is 0700, and a bare # chown would leave that mode in place — opendkim then cannot read KeyTable and # the container crash-loops (e2e TestHostnameGate/valid_hostname_starts). +step "chown/chmod /data" chown panel:panel /data chmod 755 /data # Restored backups or previously-created state may contain panel-owned files @@ -69,6 +76,7 @@ chmod 755 /data # later phase deliberately hands to another service. /data/log is exempt: it is # deliberately owned by postfix (postlogd writes the delivery log there) and is # normalised on its own below. +step "normalize existing /data children" find /data -mindepth 1 -maxdepth 1 ! -user panel ! -name log -exec chown -R panel:panel {} + # DKIM key tree (spec 6, 9). The panel (user `panel`) generates keys and writes @@ -80,6 +88,7 @@ find /data -mindepth 1 -maxdepth 1 ! -user panel ! -name log -exec chown -R pane # - private keys and tables group-readable (0640); # - both table files present (empty is fine) BEFORE OpenDKIM starts, so the # daemon comes up cleanly with no domains yet. +step "opendkim tree" mkdir -p /data/opendkim/keys for t in /data/opendkim/KeyTable /data/opendkim/SigningTable; do [ -e "$t" ] || : > "$t" @@ -94,6 +103,7 @@ find /data/opendkim/keys -type f -name '*.private' -exec chmod 0640 {} + # clients. Share it through the `selfpost` group the same way as the DKIM tree: # setgid directory so new files inherit the group, and the database itself # group-readable (0640). +step "sasl tree" mkdir -p /data/sasl chown -R panel:selfpost /data/sasl chmod 2750 /data/sasl @@ -102,6 +112,7 @@ chmod 2750 /data/sasl # Postfix sender_login_maps (spec 5.1). The panel writes it; Postfix reads it. # Ensure the file exists (empty is fine) before Postfix starts so a reload that # references it never fails on a missing file, and keep it group-readable. +step "postfix sender map" mkdir -p /data/postfix [ -e /data/postfix/sender_login_maps ] || : > /data/postfix/sender_login_maps chown -R panel:selfpost /data/postfix @@ -119,6 +130,7 @@ chmod 0640 /data/postfix/sender_login_maps # directory keeps the shared group on anything created inside it later, and # 2750 keeps it group-traversable but not group-writable — logrotate refuses to # rotate a log whose directory is writable by a non-root group. +step "mail.log tree" mkdir -p /data/log [ -e /data/log/mail.log ] || : > /data/log/mail.log chown -R postfix:selfpost /data/log @@ -133,6 +145,7 @@ find /data/log -type f -exec chmod 0640 {} + # each socket created inside inherits group `selfpost`, and group-traversable # (2750) lets postfix reach it. Without this, smtpd cannot talk to OpenDKIM and, # because signing is strict (default_action=tempfail), rejects all mail. +step "milter run dirs" mkdir -p /run/opendkim /run/selfpost chown opendkim:selfpost /run/opendkim chown panel:selfpost /run/selfpost @@ -142,6 +155,8 @@ chmod 2750 /run/opendkim /run/selfpost # 5). Kept out of the image build so cert paths, rate limits, hostname and the # optional 587 service are all driven by env at run time, and re-derived on every # start the same way the /data normalisation above is. +step "postfix-config.sh" /usr/local/bin/postfix-config.sh +step "exec supervisord" exec /usr/bin/supervisord -c /etc/supervisor/supervisord.conf diff --git a/test/e2e/hostname_gate_test.go b/test/e2e/hostname_gate_test.go index 02f6248..ca654b0 100644 --- a/test/e2e/hostname_gate_test.go +++ b/test/e2e/hostname_gate_test.go @@ -128,6 +128,21 @@ func runEntrypointBackground(t *testing.T, hostnameEnv string) (output string, s 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() + // Exited containers sometimes yield empty `docker logs` in CI; also read + // the JSON-file log path docker recorded on the container. + logPathOut, _ := exec.Command("docker", "inspect", name, "--format", "{{.LogPath}}").CombinedOutput() + logPath := strings.TrimSpace(string(logPathOut)) + logFileHead := "" + if logPath != "" { + if b, e := os.ReadFile(logPath); e == nil { + logFileHead = truncateForDebug(string(b), 4000) + if strings.TrimSpace(string(logs)) == "" && len(b) > 0 { + logs = b + } + } else { + logFileHead = "read LogPath: " + e.Error() + } + } 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() @@ -147,16 +162,18 @@ func runEntrypointBackground(t *testing.T, hostnameEnv string) (output string, s 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)), + "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), + "inspect": strings.TrimSpace(string(inspect)), + "waitErr": fmt.Sprintf("%v", err), + "logErr": fmt.Sprintf("%v", logErr), + "logLen": len(logs), + "logPath": logPath, + "logFileHead": logFileHead, }) agentDebugLog("H3", "hostname_gate_test.go:post-wait", "supervisor and logs", map[string]any{ "supervisorctl": strings.TrimSpace(string(supStatus)), @@ -167,8 +184,11 @@ func runEntrypointBackground(t *testing.T, hostnameEnv string) (output string, s diag := string(logs) if strings.TrimSpace(diag) == "" { diag = "(empty docker logs)\ninspect: " + strings.TrimSpace(string(inspect)) + + "\nlogPath: " + logPath + + "\nlogFileHead: " + logFileHead + "\nsupervisorctl: " + strings.TrimSpace(string(supStatus)) + - "\n/data mode: " + strings.TrimSpace(string(dataMode)) + "\n/data mode: " + strings.TrimSpace(string(dataMode)) + + "\nhost /data: " + hostDataListing } return diag, err == nil } diff --git a/test/e2e/process_check.go b/test/e2e/process_check.go index 3bc5063..ce051a7 100644 --- a/test/e2e/process_check.go +++ b/test/e2e/process_check.go @@ -54,17 +54,36 @@ func checkSupervisorProcesses(s *stack) error { ps, _ := s.compose("ps", "-a", "--format", "json") inspectOut, _ := exec.Command("docker", "ps", "-a", "--filter", "name=selfpost-e2e", "--format", "{{.Names}} {{.Status}} {{.ID}}").CombinedOutput() + // compose logs can be empty for a fast-exit container; pull docker logs by id. + rawDockerLogs := "" + for _, line := range strings.Split(string(inspectOut), "\n") { + fields := strings.Fields(line) + if len(fields) < 3 || !strings.Contains(fields[0], "selfpost-1") { + continue + } + id := fields[len(fields)-1] + if b, e := exec.Command("docker", "logs", id).CombinedOutput(); e == nil { + rawDockerLogs = string(b) + } else { + rawDockerLogs = e.Error() + "\n" + string(b) + } + if strings.TrimSpace(logs) == "" && strings.TrimSpace(rawDockerLogs) != "" { + logs = rawDockerLogs + } + break + } 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() + "-c", "grep -n 'chmod 755 /data\\|entrypoint: command failed\\|step()' /usr/local/bin/entrypoint.sh | head -30").CombinedOutput() agentDebugLog("H4", "process_check.go:fail", "compose selfpost not ready", map[string]any{ "waitErr": err.Error(), "logsLen": len(logs), "logsHead": truncateForDebug(logs, 4000), + "rawDockerLogsHead": truncateForDebug(rawDockerLogs, 4000), "composePs": truncateForDebug(string(ps), 2000), "dockerPs": strings.TrimSpace(string(inspectOut)), "hostDataMode": dataMode, @@ -74,8 +93,8 @@ func checkSupervisorProcesses(s *stack) error { "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 fmt.Errorf("%w\n==== selfpost logs ====\n%s\n==== docker logs (by id) ====\n%s\n==== docker ps ====\n%s\n==== entrypoint markers ====\n%s", + err, logs, rawDockerLogs, inspectOut, entrypointSnippet) } return nil }