Просмотр исходного кода

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 недель назад
Родитель
Сommit
f855d8dcca

+ 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.network_utils import get_network_interfaces
 from backend.app.services.printer_manager import printer_manager
 from backend.app.services.printer_manager import printer_manager
+from backend.app.utils.local_time import utcnow_naive
 
 
 router = APIRouter(prefix="/support", tags=["support"])
 router = APIRouter(prefix="/support", tags=["support"])
 logger = logging.getLogger(__name__)
 logger = logging.getLogger(__name__)
@@ -596,9 +597,12 @@ async def _collect_queue_info(db: AsyncSession) -> dict:
         )
         )
     ).scalar_one_or_none()
     ).scalar_one_or_none()
     if oldest_row is not 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)
         info["oldest_pending_age_seconds"] = int(age)
     else:
     else:
         info["oldest_pending_age_seconds"] = None
         info["oldest_pending_age_seconds"] = None

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

@@ -65,9 +65,43 @@ def _resolve_pool_kwargs() -> dict:
     return kwargs
     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():
 def _create_engine():
     """Create the async engine with dialect-appropriate settings."""
     """Create the async engine with dialect-appropriate settings."""
     kwargs = _resolve_pool_kwargs()
     kwargs = _resolve_pool_kwargs()
+    connect_args = _resolve_connect_args()
+    if connect_args:
+        kwargs["connect_args"] = connect_args
 
 
     global _pool_config
     global _pool_config
     _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.services.tasmota import tasmota_service
 from backend.app.utils.ams_drying import is_drying_active, temperature_alarm_suppressed
 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.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
 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()
                     setting = result.scalar_one_or_none()
                     retention_days = int(setting.value) if setting else AMS_HISTORY_RETENTION_DAYS
                     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))
                     result = await db.execute(delete(AMSSensorHistory).where(AMSSensorHistory.recorded_at < cutoff))
                     await db.commit()
                     await db.commit()
                     if result.rowcount > 0:
                     if result.rowcount > 0:
@@ -7446,7 +7447,7 @@ async def record_printer_sensor_history():
                     setting = result.scalar_one_or_none()
                     setting = result.scalar_one_or_none()
                     retention_days = int(setting.value) if setting else PRINTER_SENSOR_HISTORY_RETENTION_DAYS
                     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(
                     cleanup = await db.execute(
                         delete(PrinterSensorHistory).where(PrinterSensorHistory.recorded_at < cutoff)
                         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