Account sync scheduler fires before Fava client init at LNbits startup #22

New issue

Open

opened 2026-05-22 09:14:56 +00:00 by padreug · 0 comments

padreug commented

2026-05-22 09:14:56 +00:00

Owner

Symptom

On LNbits cold start, the libra extension logs an ERROR-level line within a couple hundred ms of boot:

2026-05-22 09:08:11.99 | INFO    | [LIBRA] Account sync background task started
2026-05-22 09:08:11.99 | INFO    | [LIBRA] Running scheduled account sync at 2026-05-22 09:08:11.991275
2026-05-22 09:08:11.99 | INFO    | Starting account sync from Beancount to Libra DB
2026-05-22 09:08:11.99 | ERROR   | [LIBRA] Error in scheduled account sync: Fava client not initialized. Call init_fava_client() first. Libra requires Fava for all accounting operations.
2026-05-22 09:08:11.99 | ERROR   | [LIBRA] Account sync error: Fava client not initialized. ...
2026-05-22 09:08:12.15 | INFO    | Loaded Libra settings from DB: http://localhost:3333/demo-ledger
2026-05-22 09:08:12.15 | INFO    | Fava client initialized: http://localhost:3333/demo-ledger

Observed on aio-demo 2026-05-22 after a routine LNbits restart. Same pattern on other castle hosts I'd assume — it's a startup-ordering bug, not host-specific.

Diagnosis

Two startup paths race:

Account-sync background task — starts the hourly scheduler and immediately fires its first tick at t=0 against init_fava_client()-uninitialized state.
Settings load + Fava client init — runs ~160 ms later, populating the Fava client.

The first scheduled tick loses the race; subsequent ticks (one hour later, then hourly) succeed because Fava is ready by then.

Impact

Cosmetic in production — the next tick recovers. But it logs two ERROR-level lines on every boot, which:

Spams monitoring / alerting that's set up to page on ERROR | [LIBRA].
Pollutes log noise during deploy verification — needed an extra moment of triage to confirm it was unrelated to the events extension deploy we were verifying.
Makes it harder to spot the genuinely-broken case where Fava is misconfigured for real (the message is identical).

Fix options (cheapest first)

Defer the first scheduled tick until Fava client init completes — gate the scheduler's first run on a readiness signal / await.
Have the sync method await Fava readiness instead of failing — if fava_client is None, sleep until init or skip this tick gracefully (downgrade to INFO or WARNING).
Reorder the startup sequence so settings/Fava init runs before the background task scheduler kicks. Cleanest but most invasive.

I'd lean (2) — it's defensive against any future race and downgrades the log level appropriately. (1) is the minimum viable fix if (2) is hard to reach.

Out of scope

The hourly-tick behavior itself is fine; this is purely about the first-tick-at-boot edge case.
Doesn't block any other libra functionality once startup completes.

## Symptom On LNbits cold start, the libra extension logs an `ERROR`-level line within a couple hundred ms of boot: ``` 2026-05-22 09:08:11.99 | INFO | [LIBRA] Account sync background task started 2026-05-22 09:08:11.99 | INFO | [LIBRA] Running scheduled account sync at 2026-05-22 09:08:11.991275 2026-05-22 09:08:11.99 | INFO | Starting account sync from Beancount to Libra DB 2026-05-22 09:08:11.99 | ERROR | [LIBRA] Error in scheduled account sync: Fava client not initialized. Call init_fava_client() first. Libra requires Fava for all accounting operations. 2026-05-22 09:08:11.99 | ERROR | [LIBRA] Account sync error: Fava client not initialized. ... 2026-05-22 09:08:12.15 | INFO | Loaded Libra settings from DB: http://localhost:3333/demo-ledger 2026-05-22 09:08:12.15 | INFO | Fava client initialized: http://localhost:3333/demo-ledger ``` Observed on `aio-demo` 2026-05-22 after a routine LNbits restart. Same pattern on other castle hosts I'd assume — it's a startup-ordering bug, not host-specific. ## Diagnosis Two startup paths race: 1. **Account-sync background task** — starts the hourly scheduler and immediately fires its first tick at `t=0` against `init_fava_client()`-uninitialized state. 2. **Settings load + Fava client init** — runs ~160 ms later, populating the Fava client. The first scheduled tick loses the race; subsequent ticks (one hour later, then hourly) succeed because Fava is ready by then. ## Impact Cosmetic in production — the next tick recovers. But it logs two `ERROR`-level lines on every boot, which: - Spams monitoring / alerting that's set up to page on `ERROR | [LIBRA]`. - Pollutes log noise during deploy verification — needed an extra moment of triage to confirm it was unrelated to the events extension deploy we were verifying. - Makes it harder to spot the genuinely-broken case where Fava is misconfigured for real (the message is identical). ## Fix options (cheapest first) 1. **Defer the first scheduled tick** until Fava client init completes — gate the scheduler's first run on a readiness signal / await. 2. **Have the sync method await Fava readiness** instead of failing — if `fava_client is None`, sleep until init or skip this tick gracefully (downgrade to `INFO` or `WARNING`). 3. **Reorder the startup sequence** so settings/Fava init runs before the background task scheduler kicks. Cleanest but most invasive. I'd lean (2) — it's defensive against any future race and downgrades the log level appropriately. (1) is the minimum viable fix if (2) is hard to reach. ## Out of scope - The hourly-tick behavior itself is fine; this is purely about the first-tick-at-boot edge case. - Doesn't block any other libra functionality once startup completes.

No labels

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

aiolabs/libra#22

No description provided.

Rows
Columns