Bläddra i källkod

Pin the PostgreSQL session to UTC so defaulted timestamps are UTC (#2855)

On a UTC+3 install every AMS humidity reading and every archive was
stamped three hours ahead of when it happened. Bambuddy stores naive
timestamps that hold UTC and the frontend's parseUTCDate reads an
offsetless timestamp as UTC, so the display added the offset to a value
that was already local.

The Python side has honoured that contract since #504. The reporter's
timestamps were not written by Python. Around ninety-six columns take
their value from server_default=func.now() and the migration DDL carries
another forty-nine on DEFAULT CURRENT_TIMESTAMP -- the database fills
those, and on PostgreSQL now() is a timestamptz, so storing it into a
timestamp without time zone casts it through the session TimeZone. A
Postgres container started with TZ=Europe/Istanbul bakes that zone into
postgresql.conf at initdb, and every defaulted column then receives local
wall-clock. recorded_at is the clearest case: nothing in the codebase
ever assigns it, so its value is entirely whatever the database decided.

Connections now carry timezone=UTC, which makes the cast a no-op whatever
the server is set to. Measured through the real engine factory against a
live PostgreSQL, a session on the reporter's configuration stored +10800s
and the fixed one +0s. Pinning the session was preferred over a hundred
and forty-five individual edits partly for its size but mostly because
half of those sites are raw DDL that no model-level change can reach.

SQLite needed nothing and gets nothing: its CURRENT_TIMESTAMP is UTC by
definition and it has no session timezone to get wrong, which is why this
survived two years of timezone fixes without showing itself. That also
makes it the reference -- the change moves Postgres onto SQLite's
behaviour rather than introducing a third convention -- so the SQLite
behaviour is now pinned by a test instead of being assumed. asyncpg is
the documented driver and takes the setting in its startup packet; any
other Postgres driver gets the same setting the libpq way, so a psycopg
URL does not fail at connect on a keyword asyncpg alone accepts.

Rows already written are deliberately left alone. The inverse cast is
computable and DST-correct, but it cannot be applied safely: created_at
is assigned explicitly on some paths and defaulted on others, an install
that began on SQLite holds correct and shifted rows side by side, and
nothing distinguishes them after the fact. Timestamps are right from the
upgrade forward and history keeps the times it was given.

One related mismatch goes with it, because fixing the database side alone
would have made it start lying on exactly the installs this repairs. The
support package's oldest_pending_age_seconds subtracted a naive local
clock from a naive UTC column, with a comment claiming it was UTC; on the
reporter's install the two errors cancelled. It reported a job queued
five minutes ago as three hours old east of Greenwich and a negative age
west of it. The two AMS and printer-sensor retention cutoffs move to the
same utcnow_naive helper -- correct in value already, but deprecated in
3.12 and emitting warnings on every sweep.
maziggy 2 veckor sedan
förälder
incheckning
28b2b9f151

+ 1 - 0
CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.6b1] - Unreleased
 
 ### Fixed
+- **PostgreSQL installs on a non-UTC timezone showed AMS History and Archive timestamps hours in the future (#2855, reported by @Tolga-Unal)** — On UTC+3 every AMS humidity reading and every archive was stamped three hours ahead of when it happened. Bambuddy stores timestamps without an offset and treats them as UTC everywhere, and the Python side has done so since #504 — but around a hundred and fifty timestamps are not written by Bambuddy at all. They are database defaults, filled in by the database, and PostgreSQL fills them from a clock whose timezone is the server's own. A Postgres container started with `TZ=Europe/Istanbul` bakes that zone in when the cluster is created, so those columns received local wall-clock while everything reading them assumed UTC, and the display added the offset a second time. Bambuddy's connections now pin their session to UTC, so what the database writes matches what the rest of the product means, whatever the server is set to. SQLite was never affected — its clock is UTC by definition, which is why this hid for as long as it did, and the fix makes Postgres agree with SQLite rather than inventing a third convention. **Timestamps already recorded are not rewritten**: which of them were written by the database and which by Bambuddy cannot be told apart after the fact, and an install that started on SQLite holds both kinds. Everything from the upgrade forward is correct; older rows keep the times they were given. One related mismatch went with it — the support package's "oldest pending queue item" age subtracted a local clock from a UTC column, reporting a job queued five minutes ago as three hours old east of Greenwich and a negative age west of it. Covered by backend tests, including one that reproduces the reporter's three-hour shift.
 - **K-profiles follow an AMS when it moves between Filament Track Switch inlets** — K-profiles are calibrated per nozzle, and the printer numbers its calibration table per nozzle too, so entry 16 exists on both hotends and means a different profile on each. An AMS tray, however, holds exactly one index. Move an AMS to the switch's other inlet and every configured slot in it silently keeps pointing at the old hotend's table: on the maintainer's H2C a black PLA calibrated 0.018 on the left and 0.020 on the right stayed on the left profile after the move, and a manual RFID re-read only re-asserted the same wrong one. Bambuddy already stores both profiles for a spool, so the move now re-selects the counterpart for the nozzle that AMS actually feeds. Only the calibration binding changes and only for slots whose spool already has a profile for the new nozzle — configuring a slot is a deliberate preparation step, so a slot Bambuddy knows nothing about, or a spool calibrated on one hotend only, is left exactly as you set it. Nothing is re-applied on the first sighting of a binding either, or every reconnect would overwrite a choice made by hand.
 - **Configure Slot picks the K-profile for the slot's own nozzle** — The profile dropdown identified an entry by name and K value alone, with nothing naming the hotend, so a filament calibrated on both appeared twice with no way to tell them apart, and two that happened to share a K value collapsed into whichever the printer listed first. The tie-break meant to prefer the slot's own nozzle was gated on a value that is never set on a machine with a Filament Track Switch, where no AMS reports a nozzle at all — so the pick was arbitrary, and the fallback for an unrecognised binding was simply the first profile in the list. Options now carry the hotend, matches are scoped to the nozzle the slot actually feeds (the other hotend's profiles remain available under **Other K profiles**), and the slot's active index is resolved against its own nozzle rather than followed into the wrong table. The K value shown per slot on the printer card was affected by the same confusion and is now resolved the same way. Covered by backend and frontend tests.
 - **Auto K-profile calibration no longer leaves an archive behind** — When flow dynamics calibration is on, the printer lays down a pressure-advance line before the print itself. It announces that over MQTT through the same print-start event a real print uses, so Bambuddy archived it: a row named `auto_pa_line_calib_mode`, marked as having no 3MF, in among your actual prints, plus a "Print started" and a "Print completed" notification for each one. Bambuddy has always skipped the printer's other internal jobs, but only by spotting the `/usr/` path they carry — and this one arrives as a bare subtask name with no path at all, so it went straight past. It is now recognised by name, from either field the printer might report it in, and matched exactly so that a file you have deliberately named after the calibration is still your file. The completion is quiet too, which matters more than the noise: with no archive to close, it would have fallen into the path that attributes an unmatched completion to any job the printer finished in the last five minutes — and a calibration that runs alongside a real print would have told that print's owner it was done, early. Skipping the run early also saves the pointless FTP sweep for a 3MF that cannot exist, roughly a hundred connections to a printer that is mid-calibration. Covered by backend tests.

+ 7 - 3
backend/app/api/routes/support.py

@@ -42,6 +42,7 @@ from backend.app.services.log_reader import (
 )
 from backend.app.services.network_utils import get_network_interfaces
 from backend.app.services.printer_manager import printer_manager
+from backend.app.utils.local_time import utcnow_naive
 
 router = APIRouter(prefix="/support", tags=["support"])
 logger = logging.getLogger(__name__)
@@ -596,9 +597,12 @@ async def _collect_queue_info(db: AsyncSession) -> dict:
         )
     ).scalar_one_or_none()
     if oldest_row is not None:
-        # created_at is naive in this codebase (server_default=func.now()); compare
-        # against naive utc-now to get the actual age without TZ-conversion surprises.
-        age = (datetime.now() - oldest_row).total_seconds()
+        # created_at is naive in this codebase (server_default=func.now()) and holds
+        # UTC, so the clock on the other side of the subtraction has to be naive UTC
+        # too. datetime.now() is naive *local*: on a UTC+3 host it reported an item
+        # queued five minutes ago as three hours old, and went negative west of
+        # Greenwich (#2855).
+        age = (utcnow_naive() - oldest_row).total_seconds()
         info["oldest_pending_age_seconds"] = int(age)
     else:
         info["oldest_pending_age_seconds"] = None

+ 34 - 0
backend/app/core/database.py

@@ -65,9 +65,43 @@ def _resolve_pool_kwargs() -> dict:
     return kwargs
 
 
+def _resolve_connect_args() -> dict:
+    """Connect args that pin a PostgreSQL session to UTC (issue #2855).
+
+    Bambuddy's ``DateTime`` columns are naive and hold UTC, and the frontend's
+    ``parseUTCDate()`` reads a timestamp with no offset as UTC. Python-side
+    writes honour that (``utcnow_naive()``), but ~96 columns take their value
+    from ``server_default=func.now()`` and the migration DDL has ~49 more on
+    ``DEFAULT CURRENT_TIMESTAMP`` — those are filled by the database, not by us.
+
+    On PostgreSQL ``now()`` is a ``timestamptz``, so storing it into a
+    ``timestamp without time zone`` column casts it through the session
+    ``TimeZone``. A Postgres container started with ``TZ=Europe/Istanbul`` bakes
+    that zone into ``postgresql.conf`` at initdb, and every defaulted timestamp
+    is then written as local wall-clock and rendered three hours in the future.
+    Pinning the session makes the cast a no-op regardless of the server's own
+    setting.
+
+    SQLite needs nothing: its ``CURRENT_TIMESTAMP`` is UTC by definition and has
+    no session timezone to get wrong. This makes Postgres match SQLite rather
+    than introducing a third convention.
+    """
+    if is_sqlite():
+        return {}
+    # asyncpg is the documented driver and sends these in the startup packet;
+    # anything else Postgres goes through libpq, which takes the same setting
+    # as a command-line option.
+    if "+asyncpg" in settings.database_url:
+        return {"server_settings": {"timezone": "UTC"}}
+    return {"options": "-c timezone=UTC"}
+
+
 def _create_engine():
     """Create the async engine with dialect-appropriate settings."""
     kwargs = _resolve_pool_kwargs()
+    connect_args = _resolve_connect_args()
+    if connect_args:
+        kwargs["connect_args"] = connect_args
 
     global _pool_config
     _pool_config = {

+ 3 - 2
backend/app/main.py

@@ -131,6 +131,7 @@ from backend.app.services.spoolman_tracking import (
 from backend.app.services.tasmota import tasmota_service
 from backend.app.utils.ams_drying import is_drying_active, temperature_alarm_suppressed
 from backend.app.utils.fts_routing import extruder_for_inlet, slot_extruder as resolve_slot_extruder
+from backend.app.utils.local_time import utcnow_naive
 from backend.app.utils.print_jobs import is_internal_printer_job
 
 
@@ -7320,7 +7321,7 @@ async def record_ams_history():
                     setting = result.scalar_one_or_none()
                     retention_days = int(setting.value) if setting else AMS_HISTORY_RETENTION_DAYS
 
-                    cutoff = datetime.utcnow() - timedelta(days=retention_days)
+                    cutoff = utcnow_naive() - timedelta(days=retention_days)
                     result = await db.execute(delete(AMSSensorHistory).where(AMSSensorHistory.recorded_at < cutoff))
                     await db.commit()
                     if result.rowcount > 0:
@@ -7446,7 +7447,7 @@ async def record_printer_sensor_history():
                     setting = result.scalar_one_or_none()
                     retention_days = int(setting.value) if setting else PRINTER_SENSOR_HISTORY_RETENTION_DAYS
 
-                    cutoff = datetime.utcnow() - timedelta(days=retention_days)
+                    cutoff = utcnow_naive() - timedelta(days=retention_days)
                     cleanup = await db.execute(
                         delete(PrinterSensorHistory).where(PrinterSensorHistory.recorded_at < cutoff)
                     )

+ 169 - 0
backend/tests/unit/test_db_session_timezone.py

@@ -0,0 +1,169 @@
+"""Database-side timestamps are UTC on both dialects (#2855).
+
+Bambuddy stores naive datetimes that hold UTC, and the frontend's
+``parseUTCDate()`` reads a timestamp with no offset as UTC. #504 swept the
+Python side onto ``datetime.now(timezone.utc)``, but roughly 96 columns take
+their value from ``server_default=func.now()`` and the migration DDL carries
+another ~49 ``DEFAULT CURRENT_TIMESTAMP`` — those are filled by the database.
+
+SQLite's ``CURRENT_TIMESTAMP`` is UTC by definition, which is why the gap stayed
+invisible for two years. PostgreSQL's ``now()`` is a ``timestamptz``, so writing
+it into a ``timestamp without time zone`` column casts it through the session
+``TimeZone``, and a Postgres container started with ``TZ=Europe/Istanbul`` bakes
+that zone into postgresql.conf at initdb. Every defaulted timestamp then lands
+as local wall-clock and renders three hours in the future.
+
+Measured against a live PostgreSQL 16 while fixing this:
+
+    no connect_args            TimeZone=UTC              now()::timestamp=05:50:46
+    server_settings=Istanbul   TimeZone=Europe/Istanbul  now()::timestamp=08:50:46
+    server_settings=UTC        TimeZone=UTC              now()::timestamp=05:50:46
+"""
+
+import os
+import time
+from datetime import datetime, timedelta
+
+import pytest
+from sqlalchemy import Column, DateTime, Integer, MetaData, Table, func, select
+from sqlalchemy.ext.asyncio import create_async_engine
+
+
+class TestConnectArgs:
+    """What we hand the driver, per dialect."""
+
+    def test_sqlite_gets_none(self, monkeypatch):
+        """SQLite has no session timezone to pin, and passing an unknown connect
+        arg to aiosqlite would be a TypeError at connect time."""
+        from backend.app.core import database
+
+        monkeypatch.setattr(database, "is_sqlite", lambda: True)
+
+        assert database._resolve_connect_args() == {}
+
+    def test_asyncpg_pins_the_session_to_utc(self, monkeypatch):
+        from backend.app.core import database
+
+        monkeypatch.setattr(database, "is_sqlite", lambda: False)
+        monkeypatch.setattr(
+            database.settings, "database_url", "postgresql+asyncpg://u:p@host:5432/bambuddy", raising=False
+        )
+
+        assert database._resolve_connect_args() == {"server_settings": {"timezone": "UTC"}}
+
+    def test_other_postgres_drivers_go_through_libpq(self, monkeypatch):
+        """``server_settings`` is an asyncpg keyword. psycopg would reject it, so
+        a non-asyncpg URL gets the same setting the libpq way."""
+        from backend.app.core import database
+
+        monkeypatch.setattr(database, "is_sqlite", lambda: False)
+        monkeypatch.setattr(
+            database.settings, "database_url", "postgresql+psycopg://u:p@host:5432/bambuddy", raising=False
+        )
+
+        assert database._resolve_connect_args() == {"options": "-c timezone=UTC"}
+
+    def test_create_engine_actually_passes_them(self, monkeypatch):
+        """The resolver is only useful if it reaches ``create_async_engine`` —
+        pin the wiring, not just the value."""
+        from backend.app.core import database
+
+        captured: dict = {}
+
+        def fake_create_async_engine(url, **kwargs):
+            captured.update(kwargs)
+            return create_async_engine("sqlite+aiosqlite:///:memory:")
+
+        monkeypatch.setattr(database, "is_sqlite", lambda: False)
+        monkeypatch.setattr(
+            database.settings, "database_url", "postgresql+asyncpg://u:p@host:5432/bambuddy", raising=False
+        )
+        monkeypatch.setattr(database, "create_async_engine", fake_create_async_engine)
+
+        database._create_engine()
+
+        assert captured["connect_args"] == {"server_settings": {"timezone": "UTC"}}
+
+    def test_sqlite_engine_gets_no_connect_args(self, monkeypatch):
+        """aiosqlite would raise on an unexpected keyword, so the empty dict has
+        to be dropped rather than passed through."""
+        from backend.app.core import database
+
+        captured: dict = {}
+
+        def fake_create_async_engine(url, **kwargs):
+            captured.update(kwargs)
+            return create_async_engine("sqlite+aiosqlite:///:memory:")
+
+        monkeypatch.setattr(database, "is_sqlite", lambda: True)
+        monkeypatch.setattr(database, "create_async_engine", fake_create_async_engine)
+
+        database._create_engine()
+
+        assert "connect_args" not in captured
+
+
+@pytest.fixture
+def istanbul_tz():
+    """Run the process on UTC+3, the reporter's zone."""
+    original = os.environ.get("TZ")
+    os.environ["TZ"] = "Europe/Istanbul"
+    time.tzset()
+    yield
+    if original is None:
+        del os.environ["TZ"]
+    else:
+        os.environ["TZ"] = original
+    time.tzset()
+
+
+class TestSqliteIsTheReference:
+    """SQLite is what Postgres is being made to match, so pin its behaviour."""
+
+    @pytest.mark.asyncio
+    async def test_server_default_writes_utc_not_local(self, istanbul_tz):
+        """``server_default=func.now()`` compiles to ``CURRENT_TIMESTAMP``, which
+        SQLite defines as UTC regardless of the host clock. If this ever changed,
+        every naive timestamp in the product would shift by the host offset."""
+        metadata = MetaData()
+        probe = Table(
+            "tz_probe",
+            metadata,
+            Column("id", Integer, primary_key=True),
+            Column("created_at", DateTime, server_default=func.now()),
+        )
+
+        engine = create_async_engine("sqlite+aiosqlite:///:memory:")
+        try:
+            async with engine.begin() as conn:
+                await conn.run_sync(metadata.create_all)
+                await conn.execute(probe.insert())
+                stored = (await conn.execute(select(probe.c.created_at))).scalar()
+        finally:
+            await engine.dispose()
+
+        # Local is three hours ahead of UTC here; a stored local value would sit
+        # ~3h from utcnow and only ~0s from the local clock.
+        assert abs(stored - datetime.utcnow()) < timedelta(minutes=5)
+        assert abs(stored - datetime.now()) > timedelta(hours=2)
+
+
+class TestQueueAgeUsesUtc:
+    """The support bundle's ``oldest_pending_age_seconds`` (#2855)."""
+
+    @pytest.mark.asyncio
+    async def test_age_of_a_fresh_item_is_near_zero_on_a_non_utc_host(self, db_session, istanbul_tz):
+        """The old code subtracted a naive *local* now() from a naive UTC column,
+        so on UTC+3 a just-queued item reported as three hours old — and west of
+        Greenwich the age came out negative."""
+        from backend.app.api.routes.support import _collect_queue_info
+        from backend.app.models.print_queue import PrintQueueItem
+        from backend.app.utils.local_time import utcnow_naive
+
+        db_session.add(PrintQueueItem(printer_id=1, status="pending", created_at=utcnow_naive()))
+        await db_session.commit()
+
+        info = await _collect_queue_info(db_session)
+
+        assert info["pending_total"] == 1
+        assert 0 <= info["oldest_pending_age_seconds"] < 60