Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Update automation logger to include object_id like scripts #37948

Merged
merged 2 commits into from Jul 22, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
28 changes: 20 additions & 8 deletions homeassistant/components/automation/__init__.py
Expand Up @@ -23,7 +23,13 @@
SERVICE_TURN_ON,
STATE_ON,
)
from homeassistant.core import Context, CoreState, HomeAssistant, callback
from homeassistant.core import (
Context,
CoreState,
HomeAssistant,
callback,
split_entity_id,
)
from homeassistant.exceptions import HomeAssistantError
from homeassistant.helpers import condition, extract_domain_configs
import homeassistant.helpers.config_validation as cv
Expand Down Expand Up @@ -260,6 +266,7 @@ def __init__(
self._is_enabled = False
self._referenced_entities: Optional[Set[str]] = None
self._referenced_devices: Optional[Set[str]] = None
self._logger = _LOGGER

@property
def name(self):
Expand Down Expand Up @@ -337,13 +344,18 @@ async def async_added_to_hass(self) -> None:
"""Startup with initial state or previous state."""
await super().async_added_to_hass()

self._logger = logging.getLogger(
f"{__name__}.{split_entity_id(self.entity_id)[1]}"
)
self.action_script.update_logger(self._logger)

state = await self.async_get_last_state()
if state:
enable_automation = state.state == STATE_ON
last_triggered = state.attributes.get("last_triggered")
if last_triggered is not None:
self._last_triggered = parse_datetime(last_triggered)
_LOGGER.debug(
self._logger.debug(
"Loaded automation %s with state %s from state "
" storage last state %s",
self.entity_id,
Expand All @@ -352,15 +364,15 @@ async def async_added_to_hass(self) -> None:
)
else:
enable_automation = DEFAULT_INITIAL_STATE
_LOGGER.debug(
self._logger.debug(
"Automation %s not in state storage, state %s from default is used",
self.entity_id,
enable_automation,
)

if self._initial_state is not None:
enable_automation = self._initial_state
_LOGGER.debug(
self._logger.debug(
"Automation %s initial state %s overridden from "
"config initial_state",
self.entity_id,
Expand Down Expand Up @@ -403,12 +415,12 @@ async def async_trigger(self, variables, skip_condition=False, context=None):
context=trigger_context,
)

_LOGGER.info("Executing %s", self._name)
self._logger.info("Executing %s", self._name)

try:
await self.action_script.async_run(variables, trigger_context)
except Exception: # pylint: disable=broad-except
_LOGGER.exception("While executing automation %s", self.entity_id)
self._logger.exception("While executing automation %s", self.entity_id)

async def async_will_remove_from_hass(self):
"""Remove listeners when removing automation from Home Assistant."""
Expand Down Expand Up @@ -476,13 +488,13 @@ async def _async_attach_triggers(
results = await asyncio.gather(*triggers)

if None in results:
_LOGGER.error("Error setting up trigger %s", self._name)
self._logger.error("Error setting up trigger %s", self._name)

removes = [remove for remove in results if remove is not None]
if not removes:
return None

_LOGGER.info("Initialized trigger %s", self._name)
self._logger.info("Initialized trigger %s", self._name)

@callback
def remove_triggers():
Expand Down
32 changes: 22 additions & 10 deletions homeassistant/helpers/script.py
Expand Up @@ -620,13 +620,7 @@ def __init__(
self.name = name
self.change_listener = change_listener
self.script_mode = script_mode
if logger:
self._logger = logger
else:
logger_name = __name__
if name:
logger_name = ".".join([logger_name, slugify(name)])
self._logger = logging.getLogger(logger_name)
self._set_logger(logger)
self._log_exceptions = log_exceptions

self.last_action = None
Expand All @@ -638,12 +632,30 @@ def __init__(
self._queue_lck = asyncio.Lock()
self._config_cache: Dict[Set[Tuple], Callable[..., bool]] = {}
self._repeat_script: Dict[int, Script] = {}
self._choose_data: Dict[
int, List[Tuple[List[Callable[[HomeAssistant, Dict], bool]], Script]]
] = {}
self._choose_data: Dict[int, Dict[str, Any]] = {}
self._referenced_entities: Optional[Set[str]] = None
self._referenced_devices: Optional[Set[str]] = None

def _set_logger(self, logger: Optional[logging.Logger] = None) -> None:
if logger:
self._logger = logger
else:
logger_name = __name__
if self.name:
logger_name = ".".join([logger_name, slugify(self.name)])
self._logger = logging.getLogger(logger_name)

def update_logger(self, logger: Optional[logging.Logger] = None) -> None:
"""Update logger."""
self._set_logger(logger)
for script in self._repeat_script.values():
script.update_logger(self._logger)
for choose_data in self._choose_data.values():
for _, script in choose_data["choices"]:
script.update_logger(self._logger)
if choose_data["default"]:
choose_data["default"].update_logger(self._logger)

def _changed(self):
if self.change_listener:
self._hass.async_run_job(self.change_listener)
Expand Down
19 changes: 19 additions & 0 deletions tests/helpers/test_script.py
Expand Up @@ -1255,3 +1255,22 @@ async def test_shutdown_after(hass, caplog):
"Stopping scripts running too long after shutdown: test script"
in caplog.text
)


async def test_update_logger(hass, caplog):
"""Test updating logger."""
sequence = cv.SCRIPT_SCHEMA({"event": "test_event"})
script_obj = script.Script(hass, sequence)

await script_obj.async_run()
await hass.async_block_till_done()

assert script.__name__ in caplog.text

log_name = "testing.123"
script_obj.update_logger(logging.getLogger(log_name))

await script_obj.async_run()
await hass.async_block_till_done()

assert log_name in caplog.text