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>

.github/workflows/ci.yaml

@@ -394,7 +394,7 @@ jobs:
             -o console_output_style=count \
             tests
       - name: Upload coverage artifact
-        uses: actions/upload-artifact@v2.2.3
+        uses: actions/upload-artifact@v2.2.4
         with:
           name: coverage-${{ matrix.python-version }}
           path: .coverage

requirements.txt

@@ -11,7 +11,7 @@ cpe==1.2.1
 cryptography==3.4.6
 debugpy==1.3.0
 docker==5.0.0
-gitpython==3.1.17
+gitpython==3.1.18
 jinja2==3.0.1
 pulsectl==21.5.18
 pyudev==0.22.0

supervisor/addons/addon.py

@@ -65,6 +65,7 @@ from ..utils import check_port
 from ..utils.apparmor import adjust_profile
 from ..utils.json import read_json_file, write_json_file
 from ..utils.tar import atomic_contents_add, secure_path
+from .const import SnapshotAddonMode
 from .model import AddonModel, Data
 from .options import AddonOptions
 from .utils import remove_data
@@ -695,6 +696,8 @@ class Addon(AddonModel):
 
     async def snapshot(self, tar_file: tarfile.TarFile) -> None:
         """Snapshot state of an add-on."""
+        is_running = await self.is_running()
+
         with TemporaryDirectory(dir=self.sys_config.path_tmp) as temp:
             temp_path = Path(temp)
 
@@ -744,8 +747,15 @@ class Addon(AddonModel):
                         arcname="data",
                     )
 
-            if self.snapshot_pre is not None:
+            if (
+                is_running
+                and self.snapshot_mode == SnapshotAddonMode.HOT
+                and self.snapshot_pre is not None
+            ):
                 await self._snapshot_command(self.snapshot_pre)
+            elif is_running and self.snapshot_mode == SnapshotAddonMode.COLD:
+                _LOGGER.info("Shutdown add-on %s for cold snapshot", self.slug)
+                await self.instance.stop()
 
             try:
                 _LOGGER.info("Building snapshot for add-on %s", self.slug)
@@ -754,8 +764,15 @@ class Addon(AddonModel):
                 _LOGGER.error("Can't write tarfile %s: %s", tar_file, err)
                 raise AddonsError() from err
             finally:
-                if self.snapshot_post is not None:
+                if (
+                    is_running
+                    and self.snapshot_mode == SnapshotAddonMode.HOT
+                    and self.snapshot_post is not None
+                ):
                     await self._snapshot_command(self.snapshot_post)
+                elif is_running and self.snapshot_mode is SnapshotAddonMode.COLD:
+                    _LOGGER.info("Starting add-on %s again", self.slug)
+                    await self.start()
 
         _LOGGER.info("Finish snapshot for addon %s", self.slug)
 

supervisor/addons/const.py

@@ -0,0 +1,12 @@
+"""Add-on static data."""
+from enum import Enum
+
+
+class SnapshotAddonMode(str, Enum):
+    """Snapshot mode of an Add-on."""
+
+    HOT = "hot"
+    COLD = "cold"
+
+
+ATTR_SNAPSHOT = "snapshot"

supervisor/addons/model.py

@@ -5,6 +5,8 @@ from typing import Any, Awaitable, Dict, List, Optional
 
 from awesomeversion import AwesomeVersion, AwesomeVersionException
 
+from supervisor.addons.const import SnapshotAddonMode
+
 from ..const import (
     ATTR_ADVANCED,
     ATTR_APPARMOR,
@@ -76,6 +78,7 @@ from ..const import (
 )
 from ..coresys import CoreSys, CoreSysAttributes
 from ..docker.const import Capabilities
+from .const import ATTR_SNAPSHOT
 from .options import AddonOptions, UiOptions
 from .validate import RE_SERVICE, RE_VOLUME
 
@@ -370,6 +373,11 @@ class AddonModel(CoreSysAttributes, ABC):
         """Return post-snapshot command."""
         return self.data.get(ATTR_SNAPSHOT_POST)
 
+    @property
+    def snapshot_mode(self) -> SnapshotAddonMode:
+        """Return if snapshot is hot/cold."""
+        return self.data[ATTR_SNAPSHOT]
+
     @property
     def default_init(self) -> bool:
         """Return True if the add-on have no own init."""

supervisor/addons/validate.py

@@ -7,6 +7,8 @@ import uuid
 
 import voluptuous as vol
 
+from supervisor.addons.const import SnapshotAddonMode
+
 from ..const import (
     ARCH_ALL,
     ATTR_ACCESS_TOKEN,
@@ -107,6 +109,7 @@ from ..validate import (
     uuid_match,
     version_tag,
 )
+from .const import ATTR_SNAPSHOT
 from .options import RE_SCHEMA_ELEMENT
 
 _LOGGER: logging.Logger = logging.getLogger(__name__)
@@ -161,6 +164,14 @@ def _warn_addon_config(config: Dict[str, Any]):
             name,
         )
 
+    if config.get(ATTR_SNAPSHOT, SnapshotAddonMode.HOT) == SnapshotAddonMode.COLD and (
+        config.get(ATTR_SNAPSHOT_POST) or config.get(ATTR_SNAPSHOT_PRE)
+    ):
+        _LOGGER.warning(
+            "Add-on which only support COLD backups trying to use post/pre commands. Please report this to the maintainer of %s",
+            name,
+        )
+
     return config
 
 
@@ -284,6 +295,9 @@ _SCHEMA_ADDON_CONFIG = vol.Schema(
         vol.Optional(ATTR_SNAPSHOT_EXCLUDE): [str],
         vol.Optional(ATTR_SNAPSHOT_PRE): str,
         vol.Optional(ATTR_SNAPSHOT_POST): str,
+        vol.Optional(ATTR_SNAPSHOT, default=SnapshotAddonMode.HOT): vol.Coerce(
+            SnapshotAddonMode
+        ),
         vol.Optional(ATTR_OPTIONS, default={}): dict,
         vol.Optional(ATTR_SCHEMA, default={}): vol.Any(
             vol.Schema(

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)

supervisor/hassos.py

@@ -26,6 +26,7 @@ class HassOS(CoreSysAttributes):
         self._available: bool = False
         self._version: Optional[AwesomeVersion] = None
         self._board: Optional[str] = None
+        self._os_name: Optional[str] = None
 
     @property
     def available(self) -> bool:
@@ -55,18 +56,30 @@ class HassOS(CoreSysAttributes):
         """Return board name."""
         return self._board
 
+    @property
+    def os_name(self) -> Optional[str]:
+        """Return OS name."""
+        return self._os_name
+
     def _get_download_url(self, version: AwesomeVersion) -> str:
         raw_url = self.sys_updater.ota_url
         if raw_url is None:
             raise HassOSUpdateError("Don't have an URL for OTA updates!", _LOGGER.error)
 
         update_board = self.board
+        update_os_name = self.os_name
 
         # OS version 6 and later renamed intel-nuc to generic-x86-64...
         if update_board == "intel-nuc" and version >= 6.0:
             update_board = "generic-x86-64"
 
-        url = raw_url.format(version=str(version), board=update_board)
+        # The OS name used to be hassos before renaming to haos...
+        if version < 6.0:
+            update_os_name = "hassos"
+
+        url = raw_url.format(
+            version=str(version), board=update_board, os_name=update_os_name
+        )
         return url
 
     async def _download_raucb(self, url: str, raucb: Path) -> None:
@@ -115,13 +128,13 @@ class HassOS(CoreSysAttributes):
         except NotImplementedError:
             _LOGGER.info("No Home Assistant Operating System found")
             return
-        else:
-            self._available = True
-            self.sys_host.supported_features.cache_clear()
 
         # Store meta data
+        self._available = True
+        self.sys_host.supported_features.cache_clear()
         self._version = AwesomeVersion(cpe.get_version()[0])
         self._board = cpe.get_target_hardware()[0]
+        self._os_name = cpe.get_product()[0]
 
         await self.sys_dbus.rauc.update()
 

supervisor/updater.py

@@ -256,13 +256,13 @@ class Updater(FileConfiguration, CoreSysAttributes):
             self._data[ATTR_MULTICAST] = AwesomeVersion(data["multicast"])
 
             # Update images for that versions
-            self._data[ATTR_IMAGE][ATTR_HOMEASSISTANT] = data["image"]["core"]
-            self._data[ATTR_IMAGE][ATTR_SUPERVISOR] = data["image"]["supervisor"]
-            self._data[ATTR_IMAGE][ATTR_AUDIO] = data["image"]["audio"]
-            self._data[ATTR_IMAGE][ATTR_CLI] = data["image"]["cli"]
-            self._data[ATTR_IMAGE][ATTR_DNS] = data["image"]["dns"]
-            self._data[ATTR_IMAGE][ATTR_OBSERVER] = data["image"]["observer"]
-            self._data[ATTR_IMAGE][ATTR_MULTICAST] = data["image"]["multicast"]
+            self._data[ATTR_IMAGE][ATTR_HOMEASSISTANT] = data["images"]["core"]
+            self._data[ATTR_IMAGE][ATTR_SUPERVISOR] = data["images"]["supervisor"]
+            self._data[ATTR_IMAGE][ATTR_AUDIO] = data["images"]["audio"]
+            self._data[ATTR_IMAGE][ATTR_CLI] = data["images"]["cli"]
+            self._data[ATTR_IMAGE][ATTR_DNS] = data["images"]["dns"]
+            self._data[ATTR_IMAGE][ATTR_OBSERVER] = data["images"]["observer"]
+            self._data[ATTR_IMAGE][ATTR_MULTICAST] = data["images"]["multicast"]
 
         except KeyError as err:
             raise UpdaterError(

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)

tests/test_hassos.py

@@ -20,3 +20,39 @@ async def test_ota_url_generic_x86_64_rename(coresys: CoreSys) -> None:
     url = coresys.updater.ota_url.format(version=str(version6), board="generic-x86-64")
 
     assert coresys.hassos._get_download_url(version6) == url
+
+
+def test_ota_url_os_name(coresys: CoreSys) -> None:
+    """Test download URL generated with os_name."""
+
+    board = "generic-x86-64"
+    os_name = "haos"
+    versionstr = "6.0"
+
+    url = "https://github.com/home-assistant/operating-system/releases/download/{version}/{os_name}_{board}-{version}.raucb"
+    url_formatted = url.format(version=versionstr, board=board, os_name=os_name)
+
+    coresys.hassos._board = board
+    coresys.hassos._os_name = os_name
+    coresys.updater._data = {"ota": url}
+
+    url = coresys.hassos._get_download_url(AwesomeVersion(versionstr))
+    assert url == url_formatted
+
+
+def test_ota_url_os_name_rel_5_downgrade(coresys: CoreSys) -> None:
+    """Test download URL generated with os_name."""
+
+    board = "generic-x86-64"
+    versionstr = "5.9"
+
+    # On downgrade below 6.0 we need to use hassos as os_name.
+    url = "https://github.com/home-assistant/operating-system/releases/download/{version}/{os_name}_{board}-{version}.raucb"
+    url_formatted = url.format(version=versionstr, board=board, os_name="hassos")
+
+    coresys.hassos._board = board
+    coresys.hassos._os_name = "haos"
+    coresys.updater._data = {"ota": url}
+
+    url = coresys.hassos._get_download_url(AwesomeVersion(versionstr))
+    assert url == url_formatted

tests/test_updater.py

@@ -26,25 +26,25 @@ async def test_fetch_versions(coresys: CoreSys) -> None:
     assert coresys.updater.version_multicast == data["multicast"]
     assert coresys.updater.version_observer == data["observer"]
 
-    assert coresys.updater.image_homeassistant == data["image"]["core"].format(
+    assert coresys.updater.image_homeassistant == data["images"]["core"].format(
         machine=coresys.machine
     )
 
-    assert coresys.updater.image_supervisor == data["image"]["supervisor"].format(
+    assert coresys.updater.image_supervisor == data["images"]["supervisor"].format(
         arch=coresys.arch.supervisor
     )
-    assert coresys.updater.image_cli == data["image"]["cli"].format(
+    assert coresys.updater.image_cli == data["images"]["cli"].format(
         arch=coresys.arch.supervisor
     )
-    assert coresys.updater.image_audio == data["image"]["audio"].format(
+    assert coresys.updater.image_audio == data["images"]["audio"].format(
         arch=coresys.arch.supervisor
     )
-    assert coresys.updater.image_dns == data["image"]["dns"].format(
+    assert coresys.updater.image_dns == data["images"]["dns"].format(
         arch=coresys.arch.supervisor
     )
-    assert coresys.updater.image_observer == data["image"]["observer"].format(
+    assert coresys.updater.image_observer == data["images"]["observer"].format(
         arch=coresys.arch.supervisor
     )
-    assert coresys.updater.image_multicast == data["image"]["multicast"].format(
+    assert coresys.updater.image_multicast == data["images"]["multicast"].format(
         arch=coresys.arch.supervisor
     )