Skip to content

Logins and sending keep working after a restart (dovecot waits for MariaDB; stale PID files removed) - #102

Merged
lejmr merged 2 commits into
masterfrom
fix/dovecot-waits-for-mariadb
Oct 6, 2026
Merged

lejmr merged 2 commits into
masterfrom
fix/dovecot-waits-for-mariadb

Conversation

@lejmr

@lejmr lejmr commented Oct 6, 2026 •

Copy link
Copy Markdown
Owner

Rows touched: 4, 13, 14 (and 5-11 when they follow a failed restart in the same run)
Rows added: none - one extra-tier test under row 4: three restarts in a row, a login and a submitted message after each
Rows removed: none
Everything else in the table: this PR's CI run 37480595394 (29/29 passed)

What broke

Since builds from 2026-10-05 the weekly CI and Refresh fail. After a container restart, logins are refused with [UNAVAILABLE] Temporary authentication failure (IMAP) or 535 5.7.8 ... (reason unavailable) (SMTP). This lasts minutes, and can last up to 30 minutes. Users who restart the container are affected in the same way.

Cause

  • supervisord starts mariadbd and dovecot together. Dovecot's SQL connection can fail before MariaDB listens.
  • Debian's dovecot 1:2.4.1+dfsg1-6+deb13u7 (DSA-6526-1, 2026-09-28) added patch 0006-auth-passdb_sql-connect-before-expanding-query-varia.patch. Since then, a passdb lookup fails immediately with "Not connected to database" while the connection is down.
  • A reconnect is tried only when the next login arrives. Each failure multiplies the delay by 5: 1, 5, 25, 125, 625 s, capped at 1800 s (SQL_CONNECT_MAX_DELAY).
  • With u6 the lookup waited and recovered within 60 s, so the race went unnoticed. MariaDB itself did not change between the working and the failing builds.

Evidence: Actions run 37412510200 (diagnostic branch, deleted since)

Native amd64, packages of 2026-10-06:

Variant Full suite 15 restarts + 5 down/up
master as is 4/4 runs red (row 14; once rows 4-14, the same pattern as Refresh) stuck >360 s on the 2nd restart; the dovecot log shows waiting for 1 -> 5 -> 25 -> 125 seconds before retry
dovecot waits for MariaDB (this PR) 4/4 green, 28/28 20/20, login within 17-23 s
clean MariaDB stop only (stop_grace_period: 90s) - stuck on the 2nd restart, so it is not the fix

Change

  • image/build/gen-supervisord.sh: dovecot starts once mysqladmin ping answers, the same way sogod already does, then runs dovecot -F as before.
  • No cap on the wait, unlike sogod. A dovecot started anyway would land in the backoff above. A dovecot that never starts leaves port 993 closed, so the healthcheck shows the failure.
  • Not covered: a MariaDB that supervisord restarts while the container runs. That case would need dovecot restarted too; it is out of scope here.
  • test/test_acceptance.py: test_row04_repeated_restarts_keep_login_and_sending_working. A single restart hits either race only sometimes.
  • image/scripts/entrypoint.sh: stale PID files removed at start (second cause, below).
  • CHANGELOG.md: two entries under Unreleased / Fixed.

Second cause, found by this PR's first CI run

The first version (7db83ef) failed rows 5, 6, 7, 9, 13 and 14 with 451 4.3.0 Error: queue file write error on submission. That is an independent race with the same trigger:

  • docker restart keeps /run. amavisd.pid therefore still names the previous run's PID.
  • PIDs start from low numbers again, so that number often belongs to another user's process by now.
  • Amavis ignores a stale PID file only if the file is older than the system uptime, which is the host's uptime in a container. Otherwise it calls kill(0, pid) and dies on EPERM: Can't send SIG 0 to process [690]: Operation not permitted.
  • supervisord then gives up (amavis entered FATAL state), and Postfix answers every submission/smtps message with 451 until the next restart.

Waiting for MariaDB does not help: a variant where every DB user waits did worse. Fix: entrypoint.sh deletes every *.pid under /run before supervisord starts. It is PID 1 at that point, so every PID file there is stale.

Evidence for the PR as it is now (97425ba), Actions run 37480650640 (diagnostic branch):

  • full suite: 4/4 runs 29/29;
  • two restart loops: 50 restarts and 10 down/up cycles, each followed by an IMAP login and a submission. 60/60 passed: login and mail within 24-27 s after a restart, 32-37 s after down/up.

Before this fix, the same loop failed at the 8th restart (run 37423269213).

Relation to #101

#101 waits up to 300 s for a login. That cannot help: the lockout can last up to 30 minutes. Recommendation: close #101, or keep only its part that saves the servers' logs.

Checked locally

  • bash -n, py_compile and shellcheck -S warning with CI's invocation: all OK.
  • The generated line is command=/bin/sh -c 'until mysqladmin ping -h 127.0.0.1 --silent 2>/dev/null; do sleep 1; done; exec /usr/sbin/dovecot -F'. It is the same as the variant tested in the diagnostic run, apart from the cap.
  • The image build and the suite are proved by this PR's CI.

After merge

Refresh builds from the release's tag, so a fix on master reaches :1.8.8 only with a release: 1.8.8-2 via the Release button. Until then, the scheduled Refresh will keep failing.

🤖 Generated with Claude Code

https://claude.ai/code/session_0174TWxjhknsgKUXC41iBwGQ

lejmr and others added 2 commits October 6, 2026 07:56
…er a restart

supervisord starts mariadbd and dovecot together, so dovecot's SQL
connection can fail before MariaDB listens. Since Debian's dovecot
1:2.4.1+dfsg1-6+deb13u7 (DSA-6526-1) a passdb lookup then fails at once and
a reconnect is tried only on a later login, with a 5x growing delay (cap
1800 s). Actions run 37412510200 (diagnostic branch): unchanged master failed
4/4 suite runs and got stuck >360 s on the 2nd restart; with dovecot waiting
for `mysqladmin ping` 4/4 suite runs (28/28) and 20/20 restarts passed, login
within 17-23 s. A clean MariaDB shutdown alone did not help.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0174TWxjhknsgKUXC41iBwGQ
…ter a restart

`docker restart` keeps /run, so amavisd.pid still names the previous run's
PID; when that number now belongs to another user's process amavis dies on
"Can't send SIG 0 ... Operation not permitted", supervisord gives up, and
every submission message gets "451 4.3.0 queue file write error". Seen in
PR #102's CI (run 37421098227) and on the 8th restart of run 37423269213.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0174TWxjhknsgKUXC41iBwGQ
lejmr added a commit that referenced this pull request Oct 6, 2026
@lejmr lejmr changed the title Dovecot waits for MariaDB at startup; logins no longer locked out after a restart Logins and sending keep working after a restart (dovecot waits for MariaDB; stale PID files removed) Oct 6, 2026
@lejmr
lejmr merged commit 41ae6ce into master Oct 6, 2026
2 checks passed
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.

1 participant