Stop every start from logging ~320 errors on PostgreSQL

CHANGELOG.md

@@ -161,6 +161,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **The frontend build no longer warns about `path` and `crypto` being externalized for the STEP previewer (#2976)** — `occt-import-js`, the Emscripten build behind STEP previews, requires both modules, but only inside its `ENVIRONMENT_IS_NODE` branches; in the browser it loads its `.wasm` from the URL the preview worker passes and draws randomness from `crypto.getRandomValues`. Vite still externalized both and printed two warnings on every build. `vite.config.ts` now drops exactly those two warnings for that one package through `build.rolldownOptions.onLog`, so an externalization anywhere else, or of any other module, still shows.
 
 ### Fixed
+- **Every start filled the PostgreSQL log with about 320 errors** — On PostgreSQL, the startup migrations re-ran every column, index and constraint they had already added, and the database logged each of those as an `ERROR` with its statement, about 640 lines per start, before Bambuddy quietly skipped it. Nothing was wrong, but the noise buried real errors and alarmed anyone reading the log, on the appliance as much as on Docker with PostgreSQL. On PostgreSQL these statements now ask the database to skip what is already there (`IF NOT EXISTS`, or a check of the catalog for constraints and renames), so a normal start logs no errors. Columns, renames and constraints that are actually missing are still added, and SQLite is unchanged. PostgreSQL 13 or newer is required, and the wiki now says so: Bambuddy has never started on PostgreSQL 12 or older, whose startup migrations fail on a column type those versions reject.
 - **A large timelapse could not be attached when it took more than 5 minutes to download (#3272, reported by @dovmesiz)** — Scanning for a timelapse, picking one by hand and the automatic attach after a print all gave the download a flat 300 seconds. A 75 MB video that took 358 seconds over a healthy P1S link failed with "Failed to download timelapse", and each retry started the file again from scratch. The time allowed now follows the file's size, so a slow transfer completes; a link that stops sending still fails after the FTP timeout as before.
 - **A printing queue job showed the slot AMS Filament Backup had switched away from as empty** — When a spool ran out mid-print and the printer carried on from the backup spool, the job's card in the queue still named the original slot, now marked **Empty**, as if the print had a problem. The card now shows the backup spool the printer is using. It follows the printer's own record of the trays the print has drawn from, including a backup that ran out in turn. A switch between two slots the job uses is a normal colour change and is not taken for a backup. Queued jobs still warn about an empty slot as before.
 - **Slice dialog hid renamed printer profiles while "Only printers that are online" was on (#3172, reported by @gregspatrick)** — The filter read the printer model from the profile's name, so a copy saved as `Bambu Lab P1S 0.4 nozzle - Copy` read as an unknown model and was hidden even with a P1S online, until **Show all** was picked. It now reads the model from the profile the copy was saved from, as the loaded-spools filter already did.

README.md

@@ -831,7 +831,7 @@ Full documentation available at **[wiki.bambuddy.cool](http://wiki.bambuddy.cool
 |-----------|------------|
 | Backend | Python, FastAPI, SQLAlchemy |
 | Frontend | React, TypeScript, Tailwind CSS |
-| Database | SQLite (default) or PostgreSQL |
+| Database | SQLite (default) or PostgreSQL 13+ |
 | 3D Viewer | Three.js (models), libvgcode (G-code preview) |
 | Communication | MQTT (TLS), FTPS |
 

backend/app/core/database.py

@@ -1,5 +1,6 @@
 import asyncio
 import logging
+import re
 
 from sqlalchemy import event
 from sqlalchemy.exc import IntegrityError, OperationalError, ProgrammingError
@@ -680,6 +681,58 @@ def _is_already_applied(exc, sql: str) -> bool:
     return is_rename and "column" in msg and "does not exist" in msg
 
 
+# On PostgreSQL every statement that fails is written to the SERVER's log as an
+# ERROR, with its text, before _safe_execute gets to swallow it. Since nearly every
+# ADD COLUMN below is a re-run on every start, that was ~320 ERROR + STATEMENT
+# pairs per start on every PostgreSQL install -- harmless, but it buried real
+# errors and alarmed anyone who read the log. These rewrites let the server skip
+# what is already there with a NOTICE (not logged by default) instead.
+_PG_ADD_COLUMN = re.compile(r"^(\s*ALTER\s+TABLE\s+\S+\s+ADD\s+COLUMN\s+)(?!IF\s+NOT\s+EXISTS\b)", re.I)
+_PG_CREATE = re.compile(
+    r"^(\s*CREATE\s+(?:UNIQUE\s+)?(?:INDEX|TABLE)\s+)(?!IF\s+NOT\s+EXISTS\b)(?!CONCURRENTLY\b)", re.I
+)
+# No IF NOT EXISTS exists for these two, so the catalog is asked first.
+_PG_ADD_CONSTRAINT = re.compile(r"^\s*ALTER\s+TABLE\s+(\S+)\s+ADD\s+CONSTRAINT\s+(\S+)", re.I)
+_PG_RENAME_COLUMN = re.compile(r"^\s*ALTER\s+TABLE\s+(\S+)\s+RENAME\s+COLUMN\s+(\S+)\s+TO\s+", re.I)
+
+
+def _is_pg_conn(conn) -> bool:
+    """The connection's own dialect, so the rewrites never touch anything else."""
+    return getattr(getattr(conn, "dialect", None), "name", None) == "postgresql"
+
+
+def _pg_if_not_exists(sql: str) -> str:
+    """ADD COLUMN / CREATE INDEX / CREATE TABLE made a no-op when already applied."""
+    sql = _PG_ADD_COLUMN.sub(r"\1IF NOT EXISTS ", sql, count=1)
+    return _PG_CREATE.sub(r"\1IF NOT EXISTS ", sql, count=1)
+
+
+async def _pg_already_applied(conn, sql: str) -> bool:
+    """Whether a constraint or a rename has already run, asked of the catalog."""
+    from sqlalchemy import text
+
+    m = _PG_ADD_CONSTRAINT.match(sql)
+    if m:
+        found = await conn.scalar(
+            text("SELECT 1 FROM pg_constraint WHERE conname = :name AND conrelid = to_regclass(:table)"),
+            {"name": m.group(2).strip('"'), "table": m.group(1)},
+        )
+        return found is not None
+    m = _PG_RENAME_COLUMN.match(sql)
+    if m:
+        # The old column gone means the rename already ran -- the same reading
+        # _is_already_applied gives an undefined_column on a RENAME.
+        found = await conn.scalar(
+            text(
+                "SELECT 1 FROM information_schema.columns "
+                "WHERE table_schema = current_schema() AND table_name = :table AND column_name = :column"
+            ),
+            {"table": m.group(1).strip('"'), "column": m.group(2).strip('"')},
+        )
+        return found is None
+    return False
+
+
 async def _safe_execute(conn, sql):
     """Execute a DDL migration statement, silently ignoring idempotency errors.
 
@@ -702,6 +755,11 @@ async def _safe_execute(conn, sql):
     """
     from sqlalchemy import text
 
+    if _is_pg_conn(conn):
+        if await _pg_already_applied(conn, sql):
+            return
+        sql = _pg_if_not_exists(sql)
+
     try:
         async with conn.begin_nested():
             await conn.execute(text(sql))
@@ -1841,7 +1899,34 @@ async def _migrate_failure_reason_vocabulary(conn):
         logger.info("[#2974] converted %d failure_reason value(s) to the canonical vocabulary", total)
 
 
+def _pg_ddl_if_not_exists(conn, cursor, statement, parameters, context, executemany):
+    """before_cursor_execute hook: the _pg_if_not_exists rewrite for every statement.
+
+    About 40 older migrations run their DDL through conn.execute() in a
+    try/except of their own rather than through _safe_execute, so rewriting there
+    alone would leave their server-side errors in the log.
+    """
+    return _pg_if_not_exists(statement), parameters
+
+
 async def run_migrations(conn):
+    """Run _run_migrations; on PostgreSQL, with the IF NOT EXISTS rewrite in place.
+
+    The hook lives only on this connection and only for the migration run, so no
+    statement issued at runtime is ever rewritten.
+    """
+    if not _is_pg_conn(conn):
+        await _run_migrations(conn)
+        return
+    sync_conn = conn.sync_connection
+    event.listen(sync_conn, "before_cursor_execute", _pg_ddl_if_not_exists, retval=True)
+    try:
+        await _run_migrations(conn)
+    finally:
+        event.remove(sync_conn, "before_cursor_execute", _pg_ddl_if_not_exists)
+
+
+async def _run_migrations(conn):
     """Run all schema migrations and data backfills on startup.
 
     Includes ALTER TABLE (add columns, rename columns, add constraints),
@@ -3851,8 +3936,10 @@ async def run_migrations(conn):
             "CHECK (auto_link_existing_accounts = FALSE OR email_claim != 'email' OR require_email_verified = TRUE)"
         )
         try:
-            async with conn.begin_nested():
-                await conn.execute(text(add_constraint))
+            # Asked first so an existing constraint costs no ERROR in the server log.
+            if not (_is_pg_conn(conn) and await _pg_already_applied(conn, add_constraint)):
+                async with conn.begin_nested():
+                    await conn.execute(text(add_constraint))
         except (OperationalError, ProgrammingError) as exc:
             # Classified by SQLSTATE, not by message text: a non-English server
             # reports the constraint as already present in its own language (#2949).

backend/tests/unit/test_pg_migration_quiet_log.py

@@ -0,0 +1,145 @@
+"""Startup migrations leave no ERRORs in the PostgreSQL server log.
+
+Nearly every ADD COLUMN in run_migrations() is a re-run on every start, because
+create_all() has already made the column. _safe_execute swallowed the duplicate,
+but PostgreSQL had written it to its own log first: ~320 ERROR + STATEMENT pairs
+per start on every PostgreSQL install, measured on postgres:16. On PostgreSQL the
+DDL is now made a no-op when already applied (IF NOT EXISTS, or a catalog check
+where no IF NOT EXISTS exists), so the server skips it with a NOTICE instead.
+
+Measured against a real postgres:16 after the change: 0 ERRORs on a fresh
+database, 0 on a re-run, 0 on an older schema whose columns, rename and
+constraint were then applied, and pg_dump -s identical to the schema before.
+"""
+
+from __future__ import annotations
+
+from types import SimpleNamespace
+
+import pytest
+
+from backend.app.core import database
+from backend.app.core.database import _pg_already_applied, _pg_if_not_exists
+
+
+class TestTheRewrite:
+    @pytest.mark.parametrize(
+        "sql,expected",
+        [
+            (
+                "ALTER TABLE spool ADD COLUMN tag_type VARCHAR(20)",
+                "ALTER TABLE spool ADD COLUMN IF NOT EXISTS tag_type VARCHAR(20)",
+            ),
+            (
+                "ALTER TABLE print_queue ADD COLUMN batch_id INTEGER REFERENCES print_batches(id) ON DELETE SET NULL",
+                "ALTER TABLE print_queue ADD COLUMN IF NOT EXISTS batch_id INTEGER REFERENCES print_batches(id) "
+                "ON DELETE SET NULL",
+            ),
+            ("alter table t add column c int", "alter table t add column IF NOT EXISTS c int"),
+            ("CREATE INDEX ix_a ON t (a)", "CREATE INDEX IF NOT EXISTS ix_a ON t (a)"),
+            ("CREATE UNIQUE INDEX ux_a ON t (a)", "CREATE UNIQUE INDEX IF NOT EXISTS ux_a ON t (a)"),
+            ("CREATE TABLE t (id INTEGER)", "CREATE TABLE IF NOT EXISTS t (id INTEGER)"),
+        ],
+    )
+    def test_already_applied_ddl_becomes_a_no_op(self, sql, expected):
+        assert _pg_if_not_exists(sql) == expected
+
+    @pytest.mark.parametrize(
+        "sql",
+        [
+            "ALTER TABLE t ADD COLUMN IF NOT EXISTS c INT",
+            "CREATE INDEX IF NOT EXISTS ix_a ON t (a)",
+            "CREATE TABLE IF NOT EXISTS t (id INTEGER)",
+            # CONCURRENTLY has its own syntax position; leave it alone.
+            "CREATE INDEX CONCURRENTLY ix_a ON t (a)",
+            "ALTER TABLE t ALTER COLUMN c SET DEFAULT 0",
+            "ALTER TABLE t DROP COLUMN c",
+            "ALTER TABLE t ADD CONSTRAINT ck CHECK (a > 0)",
+            "UPDATE t SET c = 1 WHERE c IS NULL",
+            "SELECT 1",
+        ],
+    )
+    def test_everything_else_is_untouched(self, sql):
+        assert _pg_if_not_exists(sql) == sql
+
+
+class _CatalogConn:
+    """Answers the catalog query with a canned result and records it."""
+
+    def __init__(self, result):
+        self.result = result
+        self.asked = []
+
+    async def scalar(self, stmt, params):
+        self.asked.append((str(stmt), params))
+        return self.result
+
+
+class TestTheCatalogCheck:
+    ADD_CONSTRAINT = "ALTER TABLE oidc_providers ADD CONSTRAINT ck_x CHECK (a = FALSE OR b = TRUE)"
+    RENAME = "ALTER TABLE project_bom_items RENAME COLUMN notes TO remarks"
+
+    @pytest.mark.asyncio
+    async def test_an_existing_constraint_is_skipped(self):
+        conn = _CatalogConn(1)
+        assert await _pg_already_applied(conn, self.ADD_CONSTRAINT) is True
+        assert conn.asked[0][1] == {"name": "ck_x", "table": "oidc_providers"}
+
+    @pytest.mark.asyncio
+    async def test_a_missing_constraint_is_added(self):
+        assert await _pg_already_applied(_CatalogConn(None), self.ADD_CONSTRAINT) is False
+
+    @pytest.mark.asyncio
+    async def test_a_rename_whose_old_column_is_gone_already_ran(self):
+        conn = _CatalogConn(None)
+        assert await _pg_already_applied(conn, self.RENAME) is True
+        assert conn.asked[0][1] == {"table": "project_bom_items", "column": "notes"}
+
+    @pytest.mark.asyncio
+    async def test_a_rename_whose_old_column_is_there_still_runs(self):
+        assert await _pg_already_applied(_CatalogConn(1), self.RENAME) is False
+
+    @pytest.mark.asyncio
+    async def test_other_ddl_is_not_asked_about(self):
+        conn = _CatalogConn(1)
+        assert await _pg_already_applied(conn, "ALTER TABLE t ADD COLUMN c INT") is False
+        assert conn.asked == []
+
+
+class TestTheHookIsScoped:
+    @pytest.mark.asyncio
+    async def test_sqlite_gets_no_hook(self, monkeypatch):
+        listened = []
+        monkeypatch.setattr(database.event, "listen", lambda *a, **k: listened.append(a))
+
+        async def body(conn):
+            return None
+
+        monkeypatch.setattr(database, "_run_migrations", body)
+        await database.run_migrations(SimpleNamespace(dialect=SimpleNamespace(name="sqlite")))
+        assert listened == []
+
+    @pytest.mark.asyncio
+    async def test_postgres_hook_is_removed_even_when_a_migration_fails(self, monkeypatch):
+        """Only the migration run is rewritten, never a runtime statement."""
+        calls = []
+        monkeypatch.setattr(database.event, "listen", lambda target, name, fn, **k: calls.append(("listen", fn)))
+        monkeypatch.setattr(database.event, "remove", lambda target, name, fn: calls.append(("remove", fn)))
+
+        async def boom(conn):
+            raise RuntimeError("migration failed")
+
+        monkeypatch.setattr(database, "_run_migrations", boom)
+        conn = SimpleNamespace(dialect=SimpleNamespace(name="postgresql"), sync_connection=object())
+        with pytest.raises(RuntimeError):
+            await database.run_migrations(conn)
+        assert calls == [
+            ("listen", database._pg_ddl_if_not_exists),
+            ("remove", database._pg_ddl_if_not_exists),
+        ]
+
+    def test_the_hook_rewrites_and_keeps_the_parameters(self):
+        params = {"a": 1}
+        stmt, out = database._pg_ddl_if_not_exists(None, None, "ALTER TABLE t ADD COLUMN c INT", params, None, False)
+        assert stmt == "ALTER TABLE t ADD COLUMN IF NOT EXISTS c INT"
+        assert out is params