From fd8e787104d638ccc47f4aedbc4acfa5b4deaf72 Mon Sep 17 00:00:00 2001 From: nagelm <10207686+nagelm@users.noreply.github.com> Date: Wed, 15 Jul 2026 11:21:13 +1200 Subject: [PATCH] fix(logging): render log timestamps in the system display timezone Application log timestamps are pinned to UTC no matter what the operator configures, while nginx in the same container honors TZ - one container, two timezones (issue 1439). Two mechanisms force this: 1. docker/entrypoint.sh launches the app tree via `su - dispatch`, which strips the environment; only whitelisted vars are re-exported through /etc/environment and /etc/profile.d, and TZ is not among them, so no app process ever sees the operator's declared zone. 2. Whitelisting TZ alone cannot fix Django-managed processes anyway: Django's settings loader unconditionally re-stamps os.environ["TZ"] = TIME_ZONE ("UTC") and calls time.tzset() in every uwsgi, celery and management-command process. Stdlib logging's %(asctime)s renders via time.localtime(), so it can never show local time in a Django process regardless of the environment. The fix, keeping TIME_ZONE = "UTC" / USE_TZ untouched (DB truth and every wire surface - XMLTV offsets, XC server_info/time_now/EPG timestamps - stay UTC by design): - entrypoint: normalize a DISPATCHARR_TIME_ZONE bootstrap var from the standard TZ env and whitelist it. TZ itself is deliberately NOT whitelisted: pam_env would hand it to every su- child including initdb/postgres, silently flipping the database server timezone on fresh installs - the precondition for the EPG-offset corruption class tracked in issue 651, and (with an invalid zone) a source of psycopg "unknown PostgreSQL timezone" warnings emitted while the connection lock is held. Verified empirically: with TZ whitelisted, a fresh install ran its sessions at the container zone; without it, the server default stays UTC. - settings: capture DISPATCHARR_DISPLAY_TZ at module import, before Django's tzset re-stamp, as the pre-database display default. - logging: the verbose formatter renders timestamps with datetime/ZoneInfo from an in-process cached zone - never time.localtime(), and never a database query at emit time. An emit-time query can self-deadlock: a log record that originates inside a psycopg call (e.g. its timezone warning) would re-enter the same non-reentrant connection lock the ORM query then needs. The cache is refreshed out-of-band from provably safe contexts instead: request_started, celery task_prerun, and a CoreSettings post_save receiver (immediate in the process that saves the UI setting). The zone resolves to the UI's System > Time Zone setting - already canonical for DVR rules, celery crontabs and backup naming - with the env capture as the value before the first refresh, and any database error or invalid stored zone keeps the previous value. - first-boot seed: the fresh-install default that the settings consolidation migration writes for the system time zone now derives from the same env capture (validated against zoneinfo, falling back to UTC) instead of a hardcoded "UTC", so a new install honors the declared container timezone from first boot. Existing installs are untouched: the migration only manufactures a default when no stored value exists, and installs that already ran it never re-run it. Known residuals: uWSGI's native request log renders its own C-level ftime outside Python logging and keeps UTC, as do celery's internal worker_log_format lines; idle workers adopt a changed UI zone on their next request/task. All documented rather than patched. --- ..._change_coresettings_value_to_jsonfield.py | 11 +- core/signals.py | 18 ++- core/tests/test_display_timezone.py | 103 ++++++++++++++++++ dispatcharr/display_timezone.py | 49 +++++++++ dispatcharr/settings.py | 7 ++ docker/entrypoint.sh | 8 +- 6 files changed, 193 insertions(+), 3 deletions(-) create mode 100644 core/tests/test_display_timezone.py create mode 100644 dispatcharr/display_timezone.py diff --git a/core/migrations/0020_change_coresettings_value_to_jsonfield.py b/core/migrations/0020_change_coresettings_value_to_jsonfield.py index ac6ad089..ef9145b4 100644 --- a/core/migrations/0020_change_coresettings_value_to_jsonfield.py +++ b/core/migrations/0020_change_coresettings_value_to_jsonfield.py @@ -1,6 +1,8 @@ # Generated migration to change CoreSettings value field to JSONField and consolidate settings import json +import zoneinfo +from django.conf import settings as django_settings from django.db import migrations, models @@ -113,8 +115,15 @@ def consolidate_settings(apps, schema_editor): ) # SYSTEM SETTINGS + default_time_zone = ( + getattr(django_settings, "DISPATCHARR_DISPLAY_TZ", None) or "UTC" + ) + try: + zoneinfo.ZoneInfo(default_time_zone) + except Exception: + default_time_zone = "UTC" system_settings = { - "time_zone": get_value("system-time-zone", "UTC"), + "time_zone": get_value("system-time-zone", default_time_zone), "max_system_events": int(get_value("max-system-events", 100) or 100), } CoreSettings.objects.update_or_create( diff --git a/core/signals.py b/core/signals.py index bbb73dd9..7c5abcb7 100644 --- a/core/signals.py +++ b/core/signals.py @@ -1,13 +1,29 @@ +from celery.signals import task_prerun +from django.core.signals import request_started from django.db.models.signals import pre_delete, post_save from django.dispatch import receiver from django.core.exceptions import ValidationError -from .models import StreamProfile, CoreSettings, NETWORK_ACCESS_KEY +from dispatcharr.display_timezone import refresh_display_zone +from .models import StreamProfile, CoreSettings, NETWORK_ACCESS_KEY, SYSTEM_SETTINGS_KEY @receiver(pre_delete, sender=StreamProfile) def prevent_deletion_if_locked(sender, instance, **kwargs): if instance.locked: raise ValidationError("This profile is locked and cannot be deleted.") +@receiver(request_started, dispatch_uid="core_refresh_log_display_zone") +def refresh_log_display_zone_on_request(sender, **kwargs): + refresh_display_zone() + +@task_prerun.connect(weak=False) +def refresh_log_display_zone_on_task(**kwargs): + refresh_display_zone() + +@receiver(post_save, sender=CoreSettings) +def refresh_log_display_zone_on_settings_change(sender, instance, **kwargs): + if instance.key == SYSTEM_SETTINGS_KEY: + refresh_display_zone(force=True) + @receiver(post_save, sender=CoreSettings) def handle_network_access_update(sender, instance, **kwargs): """Invalidate cache and sync notifications when network access settings change.""" diff --git a/core/tests/test_display_timezone.py b/core/tests/test_display_timezone.py new file mode 100644 index 00000000..ae09c301 --- /dev/null +++ b/core/tests/test_display_timezone.py @@ -0,0 +1,103 @@ +"""Log timestamps must render in the configured display timezone.""" + +import logging +from datetime import datetime +from unittest import mock +from zoneinfo import ZoneInfo +from django.db import ProgrammingError +from django.test import TestCase, override_settings +from core.models import CoreSettings +from dispatcharr import display_timezone +from dispatcharr.display_timezone import DisplayTimezoneFormatter, refresh_display_zone + +FIXED_EPOCH = 1784073600.0 + + +def _record(): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg="message", + args=(), + exc_info=None, + ) + record.created = FIXED_EPOCH + record.msecs = 123.0 + return record + + +def _expected(zone_name): + stamp = datetime.fromtimestamp(FIXED_EPOCH, ZoneInfo(zone_name)).strftime( + "%Y-%m-%d %H:%M:%S" + ) + return f"{stamp},123" + + +class DisplayTimezoneFormatterTests(TestCase): + def setUp(self): + self._reset_cache() + self.addCleanup(self._reset_cache) + self.formatter = DisplayTimezoneFormatter( + format="{asctime} {levelname} {name} {message}", style="{" + ) + + @staticmethod + def _reset_cache(): + display_timezone._cache.update({"zone": None, "checked": 0.0}) + + @override_settings(DISPATCHARR_DISPLAY_TZ="Europe/Zurich") + def test_env_capture_used_before_first_refresh(self): + self.assertEqual( + self.formatter.formatTime(_record()), _expected("Europe/Zurich") + ) + + def test_settings_change_refreshes_through_signal(self): + CoreSettings.set_system_time_zone("Pacific/Auckland") + self.assertEqual( + self.formatter.formatTime(_record()), _expected("Pacific/Auckland") + ) + + @override_settings(DISPATCHARR_DISPLAY_TZ="Europe/Zurich") + def test_database_errors_keep_previous_value(self): + with mock.patch.object( + CoreSettings, + "get_system_time_zone", + side_effect=ProgrammingError("relation does not exist"), + ): + refresh_display_zone(force=True) + self.assertEqual( + self.formatter.formatTime(_record()), _expected("Europe/Zurich") + ) + + def test_invalid_stored_zone_keeps_previous_value(self): + CoreSettings.set_system_time_zone("Pacific/Auckland") + with mock.patch.object( + CoreSettings, "get_system_time_zone", return_value="Not/AZone" + ): + refresh_display_zone(force=True) + self.assertEqual( + self.formatter.formatTime(_record()), _expected("Pacific/Auckland") + ) + + def test_refresh_respects_interval_unless_forced(self): + CoreSettings.set_system_time_zone("UTC") + with mock.patch.object( + CoreSettings, "get_system_time_zone", return_value="Pacific/Auckland" + ): + refresh_display_zone() + self.assertEqual(self.formatter.formatTime(_record()), _expected("UTC")) + refresh_display_zone(force=True) + self.assertEqual( + self.formatter.formatTime(_record()), _expected("Pacific/Auckland") + ) + + def test_custom_datefmt_is_respected(self): + CoreSettings.set_system_time_zone("Pacific/Auckland") + expected = datetime.fromtimestamp( + FIXED_EPOCH, ZoneInfo("Pacific/Auckland") + ).strftime("%H:%M") + self.assertEqual( + self.formatter.formatTime(_record(), datefmt="%H:%M"), expected + ) diff --git a/dispatcharr/display_timezone.py b/dispatcharr/display_timezone.py new file mode 100644 index 00000000..066aaec1 --- /dev/null +++ b/dispatcharr/display_timezone.py @@ -0,0 +1,49 @@ +import logging +import time +from datetime import datetime +from zoneinfo import ZoneInfo + +_REFRESH_INTERVAL_SECONDS = 5.0 +_cache = {"zone": None, "checked": 0.0} + + +def _env_zone(): + from django.conf import settings + + try: + return ZoneInfo(getattr(settings, "DISPATCHARR_DISPLAY_TZ", "UTC")) + except Exception: + return ZoneInfo("UTC") + + +def refresh_display_zone(force=False): + """Refresh the cached display zone from CoreSettings. + + Only call from contexts that may safely run a database query + (request/task start, settings writes) — never from the logging path: + an emit-time query deadlocks on the psycopg connection lock when the + log record itself originates inside a database call. + """ + now = time.monotonic() + if not force and now - _cache["checked"] < _REFRESH_INTERVAL_SECONDS: + return + _cache["checked"] = now + try: + from core.models import CoreSettings + + _cache["zone"] = ZoneInfo(CoreSettings.get_system_time_zone()) + except Exception: + # Database or app registry not ready, or an invalid stored zone — + # keep the previous value (the env capture until a refresh lands). + pass + + +class DisplayTimezoneFormatter(logging.Formatter): + def __init__(self, format=None, datefmt=None, style="%"): + super().__init__(fmt=format, datefmt=datefmt, style=style) + + def formatTime(self, record, datefmt=None): + dt = datetime.fromtimestamp(record.created, tz=_cache["zone"] or _env_zone()) + if datefmt: + return dt.strftime(datefmt) + return f"{dt.strftime('%Y-%m-%d %H:%M:%S')},{int(record.msecs):03d}" diff --git a/dispatcharr/settings.py b/dispatcharr/settings.py index 5b8de973..ddd3743f 100644 --- a/dispatcharr/settings.py +++ b/dispatcharr/settings.py @@ -522,12 +522,19 @@ else: LOG_LEVEL = LOG_LEVEL_MAP.get(LOG_LEVEL_NAME, 20) # Default to INFO (20) if invalid +# Read at module import: Django re-stamps os.environ["TZ"] to TIME_ZONE +# ("UTC") via time.tzset() as soon as settings finish loading. +DISPATCHARR_DISPLAY_TZ = ( + os.environ.get("DISPATCHARR_TIME_ZONE") or os.environ.get("TZ") or "UTC" +) + # Add this to your existing LOGGING configuration or create one if it doesn't exist LOGGING = { "version": 1, "disable_existing_loggers": False, "formatters": { "verbose": { + "()": "dispatcharr.display_timezone.DisplayTimezoneFormatter", "format": "{asctime} {levelname} {name} {message}", "style": "{", }, diff --git a/docker/entrypoint.sh b/docker/entrypoint.sh index 505b64b5..5d3f4216 100755 --- a/docker/entrypoint.sh +++ b/docker/entrypoint.sh @@ -153,6 +153,12 @@ echo "Environment DISPATCHARR_LOG_LEVEL set to: '${DISPATCHARR_LOG_LEVEL}'" # Also make the log level available in /etc/environment for all login shells #grep -q "DISPATCHARR_LOG_LEVEL" /etc/environment || echo "DISPATCHARR_LOG_LEVEL=${DISPATCHARR_LOG_LEVEL}" >> /etc/environment +export DISPATCHARR_TIME_ZONE +# Normalize from the standard TZ env when not set explicitly +DISPATCHARR_TIME_ZONE=${DISPATCHARR_TIME_ZONE:-${TZ:-UTC}} + +echo "Environment DISPATCHARR_TIME_ZONE set to: '${DISPATCHARR_TIME_ZONE}'" + # Translate Dispatcharr POSTGRES_SSL_* env vars into libpq-recognized PGSSL* # env vars. Called once before any external PostgreSQL connection; all child # processes (psql, pg_dump, pg_isready, createdb, dropdb) inherit these @@ -180,7 +186,7 @@ variables=( DISPATCHARR_ENV DISPATCHARR_DEBUG DISPATCHARR_LOG_LEVEL DISPATCHARR_ENABLE_IP_LOOKUP REDIS_HOST REDIS_PORT REDIS_DB REDIS_PASSWORD REDIS_USER POSTGRES_DIR DISPATCHARR_PORT DISPATCHARR_VERSION DISPATCHARR_TIMESTAMP LIBVA_DRIVERS_PATH LIBVA_DRIVER_NAME LD_LIBRARY_PATH - CELERY_NICE_LEVEL UWSGI_NICE_LEVEL DJANGO_SECRET_KEY + CELERY_NICE_LEVEL UWSGI_NICE_LEVEL DJANGO_SECRET_KEY DISPATCHARR_TIME_ZONE ) # TLS variables are optional — only propagate when set to avoid noisy warnings