Pseudo-Bug: Default 90 s systemd start timeout breaks Passbolt and Nextcloud after an unclean shutdown — and during module updates

Bug
, ,
1

Disclaimer: Analyzed and Summarized with AI

After a power outage at home my node came back up but two modules did not: Passbolt and Nextcloud, both returning Bad Gateway through Traefik. I diagnosed both and found the same mechanism, so I am posting it here as @mrmarkuz suggested — maybe others have seen it too.

Environment

  • NS8 core 3.21.0
  • Modules: passbolt1 1.0.6, nextcloud1 1.7.3 → 1.7.4
  • Node: single node, Proxmox VM, 16 GiB RAM
  • Images: passbolt 5.14.3-1-ce-non-root, mariadb 10.11.18 (Passbolt), mariadb 10.6.27 (Nextcloud)
  • Storage: ZFS RAIDZ1. Relevant caveat: at the time of the incident the pool was two Samsung SSDs plus one WD Red HDD — mid-migration to all-SSD. In a RAIDZ1 the slowest member sets the pace, so write latency was at HDD level. See the measurement at the end.

I had rebooted this system many times before without trouble. What was new was an unclean shutdown.

The common mechanism

None of the affected units set their own TimeoutStartSec, so the user manager default applies: DefaultTimeoutStartUSec=1min 30s. That limit applies per phase — every ExecStartPre and every ExecStartPost gets its own 90 s.

After an unclean shutdown InnoDB needs crash recovery, and all modules start concurrently competing for the same I/O. The budget runs out before the work finishes.

Case 1 — Passbolt: the DB phase times out and the service cannot self-recover

passbolt-db.service uses an unbounded wait loop as its second ExecStartPost:

while ! mysqladmin ping -h localhost -P 3306 -u root; do sleep 1; done

It has no timeout of its own and is terminated only by the systemd start timeout. Journal:

08:43:30  ping loop begins
08:44:56  passbolt-db.service: start-post operation timed out. Terminating.   (86 s)
08:45:16  InnoDB: Starting crash recovery from checkpoint LSN=33302486
08:45:41  InnoDB: To recover: 246 pages
08:45:58  mariadbd: ready for connections
08:46:06  State 'stop-sigterm' timed out. Killing.  → SIGKILL
08:46:47  Failed with result 'timeout', restart counter 1

The database became available 62 s after systemd had given up, and was SIGKILLed 8 s after announcing readiness. That kill leaves the redo log unclean again, so the next automatic retry needs crash recovery once more and hits the same timeout. Restart=always kept the service in that loop (retries at 08:47:50, 08:55:42, 09:03:07, all failed). Only a manual module restart broke it — the start at 09:11:38 completed in 34 s because by then the redo log was clean.

Case 2 — Nextcloud: pod creation times out first, then nginx burns its retry counter

08:44:49  Starting nextcloud.service
08:46:19  start-pre operation timed out    (exactly 90 s)

Consequence: nextcloud-app.service fails with result 'dependency' because the pod does not exist. nextcloud-nginx starts anyway with --volumes-from nextcloud-app and fails with:

Error: looking up container "nextcloud-app" for volumes-from: no container with name or ID "nextcloud-app" found

Ten times in a row, then Start request repeated too quickly — after which Restart=always no longer applies and the unit sits in failed state indefinitely. nextcloud-db.service hit the same start-post timeout as Passbolt.

Case 3 — the same timeout hits a normal module update

This one worries me most. Updating nextcloud1 from 1.7.3 to 1.7.4 through the Software Center: the Software Center reports 100 % success, but the instance is left in maintenance mode with needsDbUpgrade: true and is unreachable.

10:04:28.811  nextcloud-app: Turned on maintenance mode
10:05:53.852  nextcloud-app.service: start-post operation timed out. Terminating.
10:07:24.102  State 'stop-sigterm' timed out. Killing.

The entrypoint enables maintenance mode and starts the occ upgrade; 85 s later systemd aborts the start phase and 90 s after that sends SIGKILL — killing the upgrade mid-migration. Running occ upgrade manually afterwards completed it. A schema migration being killed by a start timeout is a data risk, not just an availability problem, and a silently failed update reported as successful is hard to notice.

This has now happened on two independent systems here.

Case 4 — nextcloud-app never gets through its post-start chain

After a second power outage the same day (this time with a ZFS resilver running, so the pool was genuinely slow), nextcloud-app.service stayed in activating (start-post) indefinitely while the container itself was healthy (fpm is running, ready to handle connections).

The unit has three post-start steps sharing one 90 s budget:

ExecStartPost=runagent wait-startup
ExecStartPost=runagent setup-smtp
ExecStartPost=runagent setup-ldap

setup-ldap sets every LDAP config value through its own occ call, each spawning a PHP process in the container — observed at roughly 1 s per call (occ ldap:set-config s01 ldapGroupDisplayName cn, then occ ldap:set-config s01 ldapPort 20001, …). With ~20 values plus the other two steps the budget is gone, systemd kills the service, and the chain restarts from scratch. It never converges. A drop-in with TimeoutStartSec=1800 let it finish.

While reading wait-startup (~/.config/bin/wait-startup) I noticed three things:

  1. The except branch calls continue before time.sleep(1) — on errors the loop burns all 60 attempts in milliseconds instead of 60 seconds.
  2. After 60 unsuccessful attempts the script exits 0. Failure to reach the app is not signalled.
  3. There is no timeout on the individual occ call. One hanging call blocks the whole ExecStartPost until systemd aborts at 90 s.

What it is not

  • Not memory pressure. 16 GiB total, ~2.4 GiB used, swap untouched. status=137 matches the SIGKILL from podman stop -t 10 in ExecStop, not OOM.
  • Not a corrupt database. Crash recovery completed cleanly every time.
  • Not modified units. No drop-ins were present before I added one, and I have since removed it.

On the disk speed question — with a measurement

@mrmarkuz pointed out that fast disks are a system requirement and that the apps are tested on fast storage. That is fair and it applies here: with one HDD still in the RAIDZ1, pod create took 65 s, container remove 40 s, and a trivial printf into a container 21 s.

The disk migration is now complete — all-SSD RAIDZ1, resilver finished without errors. Reference measurement on the same node:

# time runagent -m nextcloud1 systemctl --user restart nextcloud-app.service
real    0m26.955s

27 s for the full restart including the three-step post-start chain, i.e. comfortably inside the 90 s default with a factor of ~3.3 to spare. So slow storage was clearly what pushed these operations past the limit.

My argument is that slow storage exposes these issues rather than causing them:

  • SIGKILLing a mariadbd that reported ready for connections 8 s earlier is what turns one slow start into a non-converging loop. A failed start should not leave the data directory in a state that guarantees the next attempt is slow too.
  • A schema migration should not run under a start timeout at all.
  • A module update killed mid-migration should not be reported as successful.

Note the 27 s figure was measured with a clean database, no crash recovery, and no other modules starting simultaneously. Those three conditions together are what broke the 90 s budget.

Suggestions

  1. Explicit TimeoutStartSec on the DB units, sized for crash recovery on a loaded host rather than a warm start.
  2. Bound the readiness wait itself (the mysqladmin ping loop, the occ status loop) so it is not governed by the systemd start timeout as a side effect.
  3. Avoid SIGKILLing a running mariadbd on start failure.
  4. Nextcloud: nginx retrying ten times against a non-existent nextcloud-app and burning its retry counter is fragile — a dependency would be more robust than a blind retry.
  5. Consider whether setup-ldap needs one occ invocation per config value.

Already fixed

@mrmarkuz confirmed a separate typo I found in nextcloud-nginx.service (%t/nextcloud-.pid instead of %t/nextcloud-nginx.pid, so the cleanup line never matches the actual PID file) and opened a PR: Fix typo by mrmarkuz · Pull Request #257 · NethServer/ns8-nextcloud · GitHub

Also, for anyone hitting the maintenance-mode case: you can simply run occ upgrade — no need for the full podman exec -u www-data nextcloud-app php occ upgrade I used.

Happy to provide full journals for any of the four cases.

2

Oh, and this morning I noticed webserver was also affected, but now, after resilvering, I am running on three SSD while the webserver case seems to be a relict from yesterday

:slight_smile:

3

Thanks a lot for the writeup, and for confirming the SSD details — that made this much easier to pin down.

In hindsight, running a module update while a ZFS resilver was in progress probably wasn’t the best timing — but that’s unrelated to the power outage itself, which obviously wasn’t on you. With the Christmas coming up, a UPS might be a nice gift for that node.

For Nextcloud, we’re going to raise TimeoutStartSec on the affected units, the same way it’s already handled for the postgres service in ns8-webtop — Nextcloud keeps getting heavier, so it makes sense to give it more room by default rather than relying on the systemd default.

For Passbolt, the fix needs two parts: a larger TimeoutStartSec on passbolt-db.service, plus a bounded retry limit in the readiness check itself so it fails fast and explicitly instead of waiting the full timeout — there’s no point waiting up to 10 minutes for a database that’s stuck. We’ll follow the same pattern already used for wait-postgres-init in ns8-webtop.

Thanks again for the thorough report.

4

Hi @stephdl

sorry, maybe it was too much text at once, or I did not review clearly. So the latter is not related to the topic itself but for clearification:

No, there was no module update during ZFS resilver, the sequence was:

a) First Blackout at night (approx. 23:00) while family was sleeping

b) Detection / solution of not starting modules at morning around 6:00, server on 2x SSD and HDD

c) Module update (accomplished at approximatly 8:00, while I was waiting for an electrician)

d) Second (scheduled) Blackout approx. 10:00, interruption during shutdown as the electrician pulled the fuses before I gave status update - the server was not clean

e) Startup at 10:15, but not came to full boot up, as the

f) third Blackout (approx. 10:30)

g) power up (approx. 12:15),

h) exchange of HDD-> SSD (because the server was down anyway), server ZFS still on 2x SSD and HDD,

i) approx. 12:30: solution of not starting modules similar as in the morning,

i) resilver started at 15:00 overnight (but finished approx. 20:00)

Amendment to b): two main fuses (L1, L2) at home entrance were burned, while L3 was still active. I had not to call a simple electrician, but I needed repair by the supplier (failure before first fuse). At 6:00 I was bridging fridges and the server via cables to L3.

I have a UPS in place, but the first blackout was for more than 8 h while the UPS lasts vor 30-50 min. The second blackout was just 20 min, while the third was 2 h. Even though, the battery was exhausted from the first blackout and had no time to recover.

Best

5

out of scope of this, but normally a UPS can communicate with serial (yes I am old) or by usb with the server and stop it when the battery goes off

6

yes, correct, but you must not forget to configure …most blackout until now were << 20 min, so there was no need to act until now.:innocent: