bambuddy/backend/tests/unit/services/test_notification_write_lock.py
maziggy 328bac450a Stop auto-drying re-arming into a threshold it can never reach (#2770)
An H2D armed five 12-hour drying cycles inside four hours, one of them six
seconds after the previous one ended, and none ran more than a couple of
hours.

Two things combine. The firmware ends a cycle when it decides the filament
is dry rather than when the clock runs out, and reports no fault doing it --
across this printer's history the run length tracks how wet the spools were,
from nearly the full 12 hours starting at 32% down to minutes once the unit
sat at 10-13%. That part is the AMS doing its job.

The loop is ours. An AMS reports higher relative humidity while it is warm
than once it has cooled: the same unit read 10-13% cold and 15-20% through
every cycle. With the threshold at 14% the reading at the moment a cycle
ended was always still above it, so the next 30-second pass armed another
12-hour cycle. Nothing counted, nothing waited, and it only stopped when the
box finally cooled enough to read 13%.

Auto-drying now waits 30 minutes after a cycle ends before arming another on
the same unit, and gives up on a unit after two consecutive cycles that
bring the reading no lower -- logging why and sending a new notification,
on by default because it reports that Bambuddy has stopped acting. Progress
is judged against the lowest reading any cycle on that unit has ended at,
not against the threshold, so a genuinely wet spool in a humid room coming
down 40-37-35 keeps drying however far it still is from the target;
comparing against the best so far rather than the previous end stops a
sensor wobbling by one point reading as progress every other cycle. The
suspension lifts by itself once the reading falls below the threshold.

Neither guard can stop a running cycle, and a cycle Bambuddy cut short for a
print, or that the user stopped by hand, is not counted against the unit --
so a farm that dries between queue jobs is unaffected. The threshold field
now warns below 20%, and every cycle end logs the unit's temperature and
humidity, which is what made this diagnosable.

The same bundle showed unrelated tasks failing with "database is locked",
each inside a 30.000-second Discord connect timeout. Alarms are raised from
inside the loop that records sensor history, at a point where the new rows
are added but not committed; the first read in the notification path flushed
them to satisfy itself, opening a write transaction, and the provider was
then contacted over the network with that transaction still open. SQLite
allows one writer and 30 seconds outlives the 15-second busy timeout, so
every other write in that window failed. The two reads that run before a
provider is contacted no longer flush the caller's pending work, and the
connect timeout is 5 seconds rather than 30 -- the body keeps the full 30,
so image uploads on a slow uplink are unaffected. SQLite only; Postgres has
no single-writer limit.
2026-08-08 12:40:17 +02:00

102 lines
4.1 KiB
Python

"""A notification must never be sent while holding the SQLite write lock (#2770).
The reporter's bundle has two "database is locked" failures, and both sit inside
a Discord connect timeout::
17:36:55 Sending humidity alarm ... 15.0% > 14.0%
17:37:12 WARNING Printer sensor history recording failed: database is locked
17:37:25 ERROR httpx.ConnectTimeout <- exactly 30.000s later
The mechanism is not contention from writing too much. The AMS sensor loop does
``db.add(history)`` and only commits *after* the alarms have been dispatched, so
the first SELECT inside the notification path used to autoflush that pending
INSERT — opening a write transaction — and the provider was then contacted over
the network with that transaction still open. SQLite allows one writer, and the
30 s connect timeout comfortably outlived the 15 s ``busy_timeout``, so unrelated
background tasks failed.
These tests pin the two reads that run before the network call. They assert the
caller's pending row is still unflushed afterwards, which is the same thing as
"no write transaction was opened on its behalf" and holds on any dialect.
"""
import pytest
from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine
import backend.app.models # noqa: F401 - populate Base.metadata
from backend.app.core.database import Base
from backend.app.models.notification import NotificationProvider
from backend.app.models.notification_template import NotificationTemplate
from backend.app.services.notification_service import NotificationService
@pytest.fixture
async def session(tmp_path):
engine = create_async_engine(f"sqlite+aiosqlite:///{tmp_path / 'notify-lock.db'}")
async with engine.begin() as conn:
await conn.run_sync(Base.metadata.create_all)
maker = async_sessionmaker(engine, expire_on_commit=False)
async with maker() as s:
yield s
await engine.dispose()
def _pending_row() -> NotificationProvider:
"""A row the caller has added but not committed — the sensor loop's position."""
return NotificationProvider(name="pending", provider_type="discord", config="{}", enabled=False)
@pytest.mark.asyncio
async def test_provider_lookup_does_not_flush_the_callers_pending_writes(session):
service = NotificationService()
session.add(NotificationProvider(name="Discord", provider_type="discord", config="{}", enabled=True))
await session.commit()
pending = _pending_row()
session.add(pending)
providers = await service._get_providers_for_event(session, "on_ams_drying_suspended")
assert [p.name for p in providers] == ["Discord"]
assert pending in session.new, "the caller's pending INSERT was flushed, taking the SQLite write lock"
@pytest.mark.asyncio
async def test_template_lookup_does_not_flush_the_callers_pending_writes(session):
service = NotificationService()
session.add(
NotificationTemplate(
event_type="ams_drying_suspended",
name="Auto-Drying Suspended",
title_template="t",
body_template="b",
is_default=True,
)
)
await session.commit()
pending = _pending_row()
session.add(pending)
template = await service._get_template(session, "ams_drying_suspended")
assert template is not None
assert pending in session.new, "the caller's pending INSERT was flushed, taking the SQLite write lock"
@pytest.mark.asyncio
async def test_connect_timeout_stays_under_the_sqlite_busy_timeout():
"""15 s is the ``busy_timeout`` set in database.py. A connect timeout at or
above it guarantees the "database is locked" failure whenever a site's
internet is down, whatever else is fixed."""
service = NotificationService()
client = await service._get_client()
try:
assert client.timeout.connect is not None
assert client.timeout.connect < 15.0
# The body still gets the generous budget — image uploads on a slow
# uplink must not start failing.
assert client.timeout.read == 30.0
assert client.timeout.write == 30.0
finally:
await service.close()