diff --git a/backend/app/api/routes/support.py b/backend/app/api/routes/support.py index f2c0b2ae7..30d69e11a 100644 --- a/backend/app/api/routes/support.py +++ b/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 diff --git a/backend/app/core/database.py b/backend/app/core/database.py index 02379bdf1..9a71a42eb 100644 --- a/backend/app/core/database.py +++ b/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 = { diff --git a/backend/app/main.py b/backend/app/main.py index 7ddb2bed1..a02df1681 100644 --- a/backend/app/main.py +++ b/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) ) diff --git a/backend/tests/unit/test_db_session_timezone.py b/backend/tests/unit/test_db_session_timezone.py new file mode 100644 index 000000000..f53439c82 --- /dev/null +++ b/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