Logging in local timezone (#2971)

* Logging in local timezone

* fix convert

* Apply suggestions from code review

Co-authored-by: Joakim Sørensen <joasoe@gmail.com>

Co-authored-by: Joakim Sørensen <joasoe@gmail.com>

supervisor/bootstrap.py

@@ -88,23 +88,39 @@ async def initialize_coresys() -> CoreSys:
     setup_diagnostics(coresys)
 
     # bootstrap config
-    initialize_system_data(coresys)
+    initialize_system(coresys)
 
     # Set Machine/Host ID
     if MACHINE_ID.exists():
         coresys.machine_id = MACHINE_ID.read_text().strip()
 
+    # Check if ENV is in development mode
+    if coresys.dev:
+        _LOGGER.warning("Environment variable 'SUPERVISOR_DEV' is set")
+        coresys.config.logging = LogLevel.DEBUG
+        coresys.config.debug = True
+        coresys.updater.channel = UpdateChannel.DEV
+        coresys.security.content_trust = False
+    else:
+        coresys.config.modify_log_level()
+
+    # Convert datetime
+    logging.Formatter.converter = lambda *args: coresys.now().timetuple()
+
     # Set machine type
     if os.environ.get(ENV_SUPERVISOR_MACHINE):
         coresys.machine = os.environ[ENV_SUPERVISOR_MACHINE]
     elif os.environ.get(ENV_HOMEASSISTANT_REPOSITORY):
         coresys.machine = os.environ[ENV_HOMEASSISTANT_REPOSITORY][14:-14]
+        _LOGGER.warning(
+            "Missing SUPERVISOR_MACHINE environment variable. Fallback to deprecated extraction!"
+        )
     _LOGGER.info("Seting up coresys for machine: %s", coresys.machine)
 
     return coresys
 
 
-def initialize_system_data(coresys: CoreSys) -> None:
+def initialize_system(coresys: CoreSys) -> None:
     """Set up the default configuration and create folders."""
     config = coresys.config
 
@@ -179,17 +195,6 @@ def initialize_system_data(coresys: CoreSys) -> None:
         _LOGGER.debug("Creating Supervisor media folder at '%s'", config.path_media)
         config.path_media.mkdir()
 
-    # Update log level
-    coresys.config.modify_log_level()
-
-    # Check if ENV is in development mode
-    if coresys.dev:
-        _LOGGER.warning("Environment variables 'SUPERVISOR_DEV' is set")
-        coresys.config.logging = LogLevel.DEBUG
-        coresys.config.debug = True
-        coresys.updater.channel = UpdateChannel.DEV
-        coresys.security.content_trust = False
-
 
 def migrate_system_env(coresys: CoreSys) -> None:
     """Cleanup some stuff after update."""

supervisor/coresys.py

@@ -2,6 +2,7 @@
 from __future__ import annotations
 
 import asyncio
+from datetime import datetime
 import logging
 import os
 from typing import TYPE_CHECKING, Any, Callable, Coroutine, Optional, TypeVar
@@ -12,6 +13,7 @@ import sentry_sdk
 from .config import CoreConfig
 from .const import ENV_SUPERVISOR_DEV
 from .docker import DockerAPI
+from .utils.dt import UTC, get_time_zone
 
 if TYPE_CHECKING:
     from .addons import AddonManager
@@ -466,6 +468,24 @@ class CoreSys:
             raise RuntimeError("Machine-ID type already set!")
         self._machine_id = value
 
+    def now(self) -> datetime:
+        """Return now in local timezone."""
+        return datetime.now(get_time_zone(self.timezone) or UTC)
+
+    def run_in_executor(
+        self, funct: Callable[..., T], *args: Any
+    ) -> Coroutine[Any, Any, T]:
+        """Add an job to the executor pool."""
+        return self.loop.run_in_executor(None, funct, *args)
+
+    def create_task(self, coroutine: Coroutine) -> asyncio.Task:
+        """Create an async task."""
+        return self.loop.create_task(coroutine)
+
+    def capture_exception(self, err: Exception) -> None:
+        """Capture a exception."""
+        sentry_sdk.capture_exception(err)
+
 
 class CoreSysAttributes:
     """Inherit basic CoreSysAttributes."""
@@ -622,16 +642,20 @@ class CoreSysAttributes:
         """Return Job manager object."""
         return self.coresys.jobs
 
+    def now(self) -> datetime:
+        """Return now in local timezone."""
+        return self.coresys.now()
+
     def sys_run_in_executor(
         self, funct: Callable[..., T], *args: Any
     ) -> Coroutine[Any, Any, T]:
         """Add an job to the executor pool."""
-        return self.sys_loop.run_in_executor(None, funct, *args)
+        return self.coresys.run_in_executor(funct, *args)
 
     def sys_create_task(self, coroutine: Coroutine) -> asyncio.Task:
         """Create an async task."""
-        return self.sys_loop.create_task(coroutine)
+        return self.coresys.create_task(coroutine)
 
     def sys_capture_exception(self, err: Exception) -> None:
         """Capture a exception."""
-        sentry_sdk.capture_exception(err)
+        self.coresys.capture_exception(err)

tests/conftest.py

@@ -126,7 +126,7 @@ async def network_manager(dbus) -> NetworkManager:
 @pytest.fixture
 async def coresys(loop, docker, network_manager, aiohttp_client) -> CoreSys:
     """Create a CoreSys Mock."""
-    with patch("supervisor.bootstrap.initialize_system_data"), patch(
+    with patch("supervisor.bootstrap.initialize_system"), patch(
         "supervisor.bootstrap.setup_diagnostics"
     ):
         coresys_obj = await initialize_coresys()

tests/test_coresys.py

@@ -1,6 +1,9 @@
 """Testing handling with CoreState."""
 
+from datetime import timedelta
+
 from supervisor.coresys import CoreSys
+from supervisor.utils.dt import utcnow
 
 
 async def test_timezone(run_dir, coresys: CoreSys):
@@ -15,3 +18,14 @@ async def test_timezone(run_dir, coresys: CoreSys):
 
     coresys.config.timezone = "Europe/Zurich"
     assert coresys.timezone == "Europe/Zurich"
+
+
+def test_now(coresys: CoreSys):
+    """Test datetime now with local time."""
+    coresys.config.timezone = "Europe/Zurich"
+
+    zurich = coresys.now()
+    utc = utcnow()
+
+    assert zurich != utc
+    assert zurich - utc <= timedelta(hours=2)