Skip to content

Wait for a working IMAP login after a restart; keep the servers' logs of every run - #101

Closed
lejmr wants to merge 2 commits into
masterfrom
claude/wait-for-auth-after-restart
Closed

lejmr wants to merge 2 commits into
masterfrom
claude/wait-for-auth-after-restart

Conversation

@lejmr

@lejmr lejmr commented Oct 5, 2026 •

Copy link
Copy Markdown
Owner

Decision for the maintainer

This PR does not fix the failure; it makes it diagnosable. The failure is intermittent (see below), so a green run here is no proof of a fix. Merge it for the diagnostics, or hold it until the cause is known - your call. The fix itself will be a change to the image, i.e. a new release (1.8.8-2).

Refresh checks out the release's git tag and runs that tag's suite and bin/test.sh. So this change does not alter the next Refresh of 1.8.8 (Mon 07:23 UTC): it keeps the old 40 s wait and writes no compose.log. I did not make Refresh overlay master's tests onto an old tag - that would change what "that release's acceptance suite" means. Say if you want that instead.

What happened

The scheduled runs of 2026-10-05 failed on commit 1bde062, which passed the same suite on 2026-09-28:

Run Failing rows Symptom
CI (11:37 UTC) 13, 14 IMAP [UNAVAILABLE] Temporary authentication failure, SMTP 535 (reason unavailable)
Refresh (16:07 UTC) 4, 5, 6, 7, 9, 11, 13, 14 same; row 11's FolderSync listed calendars and contacts but no INBOX

All of it comes right after a container restart or recreate. Rows that need no mail login (8, 10, 12, 20, 21) passed. The suite waited only for TCP 993 after a restart (rows 4, 13), which is not the moment a user could log in.

What this changes

  • _retry_imap_login waits for a login that succeeds, up to 300 s (was 8 x 5 s), and fails with a TimeoutError that says how long it waited and the last error.
  • bin/test.sh saves docker compose logs --timestamps to test-results/compose.log before it removes the containers, on every exit path. CI and Refresh upload it as acceptance-logs (14 days) and, on a red run, also print it into the job log (the artifact sits on a host some environments cannot reach). Nothing asserts on it.
  • DEVELOPMENT.md describes both (and fixes the junit.xml path).

What the CI runs of this branch showed

The same test code both failed and passed:

Run Head Result
33 fdc918e red: row 4 restart passed (20 s); row 13 (down + up over the same volumes) got Temporary authentication failure for the whole 300 s, row 14 followed
34 02fb894 (same tests, plus the log-printing step) green: row 4 restart 20 s, row 13 23 s end to end, suite 209 s

So the failure is intermittent and all-or-nothing - about 20 s or stuck beyond 300 s - not a slow start. The 300 s wait therefore does not address it; it only makes a stuck run fail later (and may be shortened once the cause is known).

Not known: why dovecot cannot authenticate in the bad case. Correlation only, not verified as the cause: the runs of 2026-09-28 (image with dovecot 2.4.1+dfsg1-6+deb13u6; CI 27-31 and Refresh 1) were all green on rows 13/14, while three of the four runs of 2026-10-05, built with u7, were red. The log of the red run 33 should show it: artifact acceptance-logs of https://github.com/lejmr/iredmail-docker/actions/runs/37342361517

Checked

  • bash -n, py_compile, both workflows parse; CI's static checks (shellcheck, hadolint) are green.
  • _retry_imap_login against a stub: recovers when auth returns after 120 s; after 300 s raises the TimeoutError above.
  • bin/test.sh against a faked docker/pytest: exit code kept (0 / 1 / 3 on a failing up), compose.log written before down -v on every path, and a failing logs command does not stop the cleanup.
  • The artifact acceptance-logs is produced by CI (run 33 and 34). The print-on-red step has run only on green so far (it is skipped then).
  • CHANGELOG.md untouched: it is written for people running the image, and this changes only the test harness.

The artifact is readable by anyone who can read the repository; it holds only what the throwaway test servers logged.

🤖 Generated with Claude Code

https://claude.ai/code/session_01Ssq3DtuKuHzpzwtq9Fi88e

claude added 2 commits October 5, 2026 16:37
… of every run

The scheduled runs of 2026-10-05 failed on a commit that had passed on
2026-09-28: CI on rows 13 and 14, Refresh on rows 4, 5, 6, 7, 9, 11, 13 and
14. Every failure is the same symptom right after a container restart, IMAP
`[UNAVAILABLE] Temporary authentication failure` or SMTP `535 (reason
unavailable)`; the rows that need no mail login passed. The suite only waited
for TCP 993 to open and then retried the login for 40 s, which is not the
moment a user could log in.

- `_retry_imap_login` now waits for a login that succeeds, up to 300 s, and
  fails with a TimeoutError that says how long it waited and the last error.
- `bin/test.sh` saves `docker compose logs --timestamps` to
  test-results/compose.log before it removes the containers, on every exit
  path; CI and Refresh upload it as `acceptance-logs` (14 days). Nothing
  asserts on it - it is the record of which service was slow.

Whether the servers were only slow or were stuck is not decided by the logs
we had: the next run's compose.log shows it. Refresh runs the suite of the
release's own tag, so compose.log exists there only for releases that carry
this bin/test.sh.

Co-Authored-By: Claude <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Ssq3DtuKuHzpzwtq9Fi88e
The first CI run of this branch showed the wider login wait is not the
fix: row 13 (down + up over the same volumes) still gets `Temporary
authentication failure` for the whole 300 s, so the server is stuck, not
slow. The reason is in compose.log, but an artifact has to be downloaded
from a different host, which is not possible from every place a failure is
looked at. On a red run, CI and Refresh now also print compose.log into the
job log (a collapsed group).

Co-Authored-By: Claude <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Ssq3DtuKuHzpzwtq9Fi88e

lejmr commented Oct 5, 2026

Copy link
Copy Markdown
Owner Author

First CI run of this branch (fdc918e): red on rows 13 and 14, and the wider wait did not fix it. Not caused by this PR - master's scheduled CI (11:37 UTC) and Refresh failed the same way today.

  • Row 4 (restart of the same container) passed this time, in 20 s.
  • Row 13 (docker compose down + up -d over the same volumes) got [UNAVAILABLE] Temporary authentication failure for the whole 300 s (TimeoutError: no IMAP login for row13user@a.example within 300s). Row 14 then fails with 535 for the same reason.
  • So the server is stuck, not slow. The "slow start" explanation is out; the cause is in the image, and this PR's 300 s wait is not what makes the suite pass (I will revisit its size once the cause is known).
  • A recreated container starts from the image's pristine /etc and relies on render-config.sh to put the persisted secrets back; a plain restart does not. Row 13 was green on 2026-09-28 with dovecot 2.4.1+dfsg1-6+deb13u6; the rebuilt images carry u7. That is a correlation I have not verified.

compose.log was produced (artifact acceptance-logs), but I could not read it from where I work. 02fb894 therefore also prints it into the job log when the run is red. The next run should show what dovecot logs on the recreated container; I will report that here.


Generated by Claude Code

lejmr commented Oct 5, 2026

Copy link
Copy Markdown
Owner Author

Correction to my previous comment: CI run 34 on 02fb894 is green (rows 13 and 14 included), with the same test code that failed in run 33. Row 13 took 23 s end to end this time.

So the failure is intermittent, not "deterministic since u7" as I wrote; what I got right is that it is not a slow start (about 20 s or stuck beyond 300 s). Consequences:

  • A green run on this PR proves nothing about the cause, and the 300 s wait does not help in the bad case. The description is rewritten accordingly.
  • The u6 -> u7 link is still only a correlation (28 Sep runs green, 3 of 4 runs on 5 Oct red).
  • The log that explains it is the acceptance-logs artifact of the red run 33; I cannot download it from where I work. Nothing else is needed on this PR until the cause is known.

Generated by Claude Code

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants