AEA-660 Set logger for each component and prepend agent_name to log messages

aea/aea.py

@@ -34,6 +34,7 @@
 from aea.exceptions import AEAException
 from aea.helpers.exception_policy import ExceptionPolicyEnum
 from aea.helpers.exec_timeout import ExecTimeoutThreadGuard, TimeoutException
+from aea.helpers.logging import AgentLoggerAdapter
 from aea.identity.base import Identity
 from aea.mail.base import Envelope
 from aea.protocols.base import Message
@@ -135,6 +136,8 @@ def __init__(
 
         self._skills_exception_policy = skill_exception_policy
 
+        self._setup_loggers()
+
     @property
     def decision_maker(self) -> DecisionMaker:
         """Get decision maker."""
@@ -383,3 +386,18 @@ def teardown(self) -> None:
         self.task_manager.stop()
         self.resources.teardown()
         ExecTimeoutThreadGuard.stop()
+
+    def _setup_loggers(self):
+        """Setup logger with agent name. """
+        for element in [
+            self.main_loop,
+            self.multiplexer,
+            self.task_manager,
+            self.resources.component_registry,
+            self.resources.behaviour_registry,
+            self.resources.handler_registry,
+            self.resources.model_registry,
+        ]:
+            element.logger = AgentLoggerAdapter(
+                element.logger, agent_name=self._identity.name
+            )

aea/aea_builder.py

@@ -84,6 +84,7 @@
 from aea.exceptions import AEAException
 from aea.helpers.base import load_aea_package, load_module
 from aea.helpers.exception_policy import ExceptionPolicyEnum
+from aea.helpers.logging import AgentLoggerAdapter
 from aea.helpers.pypi import is_satisfiable
 from aea.helpers.pypi import merge_dependencies
 from aea.identity.base import Identity
@@ -879,11 +880,12 @@ def build(self, connection_ids: Optional[Collection[PublicId]] = None,) -> AEA:
             copy(self.private_key_paths), copy(self.connection_private_key_paths)
         )
         identity = self._build_identity_from_wallet(wallet)
-        self._load_and_add_components(ComponentType.PROTOCOL, resources)
-        self._load_and_add_components(ComponentType.CONTRACT, resources)
+        self._load_and_add_components(ComponentType.PROTOCOL, resources, identity.name)
+        self._load_and_add_components(ComponentType.CONTRACT, resources, identity.name)
         self._load_and_add_components(
             ComponentType.CONNECTION,
             resources,
+            identity.name,
             identity=identity,
             crypto_store=wallet.connection_cryptos,
         )
@@ -908,7 +910,7 @@ def build(self, connection_ids: Optional[Collection[PublicId]] = None,) -> AEA:
             **deepcopy(self._context_namespace),
         )
         self._load_and_add_components(
-            ComponentType.SKILL, resources, agent_context=aea.context
+            ComponentType.SKILL, resources, identity.name, agent_context=aea.context
         )
         self._build_called = True
         self._populate_contract_registry()
@@ -1346,28 +1348,36 @@ def from_aea_project(
         return builder
 
     def _load_and_add_components(
-        self, component_type: ComponentType, resources: Resources, **kwargs
+        self,
+        component_type: ComponentType,
+        resources: Resources,
+        agent_name: str,
+        **kwargs,
     ) -> None:
         """
         Load and add components added to the builder to a Resources instance.
 
         :param component_type: the component type for which
         :param resources: the resources object to populate.
+        :param agent_name: the AEA name for logging purposes.
         :param kwargs: keyword argument to forward to the component loader.
         :return: None
         """
         for configuration in self._package_dependency_manager.get_components_by_type(
             component_type
         ).values():
+            if configuration.is_abstract_component:
+                load_aea_package(configuration)
+                continue
+
             if configuration in self._component_instances[component_type].keys():
                 component = self._component_instances[component_type][configuration]
-                resources.add_component(component)
-            elif configuration.is_abstract_component:
-                load_aea_package(configuration)
             else:
                 configuration = deepcopy(configuration)
                 component = load_component_from_config(configuration, **kwargs)
-                resources.add_component(component)
+
+            _set_logger_to_component(component, configuration, agent_name)
+            resources.add_component(component)
 
     def _populate_contract_registry(self):
         """Populate contract registry."""
@@ -1413,6 +1423,25 @@ def _check_we_can_build(self):
             )
 
 
+def _set_logger_to_component(
+    component: Component, configuration: ComponentConfiguration, agent_name: str,
+) -> None:
+    """
+    Set the logger to the component.
+
+    :param component: the component instance.
+    :param configuration: the component configuration
+    :param agent_name: the agent name
+    :return: None
+    """
+    if configuration.component_type == ComponentType.SKILL:
+        # skip because skill object already have their own logger from the skill context.
+        return
+    logger_name = f"aea.packages.{configuration.author}.{configuration.component_type.to_plural()}.{configuration.name}"
+    logger = AgentLoggerAdapter(logging.getLogger(logger_name), agent_name)
+    component.logger = logger
+
+
 # TODO this function is repeated in 'aea.cli.utils.package_utils.py'
 def _verify_or_create_private_keys(aea_project_path: Path) -> None:
     """Verify or create private keys."""

aea/agent_loop.py

@@ -39,6 +39,7 @@
     PeriodicCaller,
     ensure_loop,
 )
+from aea.helpers.logging import WithLogger
 from aea.multiplexer import InBox
 from aea.skills.base import Behaviour
 
@@ -50,7 +51,7 @@
     from aea.agent import Agent  # pragma: no cover
 
 
-class BaseAgentLoop(ABC):
+class BaseAgentLoop(WithLogger, ABC):
     """Base abstract  agent loop class."""
 
     def __init__(
@@ -61,6 +62,7 @@ def __init__(
         :params agent: Agent or AEA to run.
         :params loop: optional asyncio event loop. if not specified a new loop will be created.
         """
+        WithLogger.__init__(self, logger)
         self._agent: "Agent" = agent
         self.set_loop(ensure_loop(loop))
         self._tasks: List[asyncio.Task] = []
@@ -77,7 +79,7 @@ def start(self) -> None:
 
     async def run_loop(self) -> None:
         """Run agent loop."""
-        logger.debug("agent loop started")
+        self.logger.debug("agent loop started")
         self._state.set(AgentLoopStates.started)
         self._set_tasks()
         try:
@@ -171,7 +173,9 @@ def _behaviour_exception_callback(self, fn: Callable, exc: Exception) -> None:
 
         :return: None
         """
-        logger.exception(f"Loop: Exception: `{exc}` occured during `{fn}` processing")
+        self.logger.exception(
+            f"Loop: Exception: `{exc}` occured during `{fn}` processing"
+        )
         self._exceptions.append(exc)
         self._state.set(AgentLoopStates.error)
 
@@ -200,7 +204,7 @@ def _register_behaviour(self, behaviour: Behaviour) -> None:
         )
         self._behaviours_registry[behaviour] = periodic_caller
         periodic_caller.start()
-        logger.debug(f"Behaviour {behaviour} registered.")
+        self.logger.debug(f"Behaviour {behaviour} registered.")
 
     def _register_all_behaviours(self) -> None:
         """Register all AEA behaviours to run periodically."""
@@ -237,7 +241,7 @@ def _stop_tasks(self):
     def _set_tasks(self):
         """Set run loop tasks."""
         self._tasks = self._create_tasks()
-        logger.debug("tasks created!")
+        self.logger.debug("tasks created!")
 
     def _create_tasks(self) -> List[Task]:
         """
@@ -256,7 +260,7 @@ def _create_tasks(self) -> List[Task]:
     async def _task_process_inbox(self) -> None:
         """Process incoming messages."""
         inbox: InBox = self._agent.inbox
-        logger.info("[{}]: Start processing messages...".format(self._agent.name))
+        self.logger.info("[{}]: Start processing messages...".format(self._agent.name))
         while self.is_running:
             await inbox.async_wait()
 

aea/components/base.py

@@ -30,11 +30,12 @@
     ComponentType,
     PublicId,
 )
+from aea.helpers.logging import WithLogger
 
 logger = logging.getLogger(__name__)
 
 
-class Component(ABC):
+class Component(ABC, WithLogger):
     """Abstract class for an agent component."""
 
     def __init__(
@@ -48,6 +49,7 @@ def __init__(
         :param configuration: the package configuration.
         :param is_vendor: whether the package is vendorized.
         """
+        WithLogger.__init__(self)
         self._configuration = configuration
         self._directory = None  # type: Optional[Path]
         self._is_vendor = is_vendor

aea/helpers/logging.py

@@ -0,0 +1,72 @@
+# -*- coding: utf-8 -*-
+# ------------------------------------------------------------------------------
+#
+#   Copyright 2018-2019 Fetch.AI Limited
+#
+#   Licensed under the Apache License, Version 2.0 (the "License");
+#   you may not use this file except in compliance with the License.
+#   You may obtain a copy of the License at
+#
+#       http://www.apache.org/licenses/LICENSE-2.0
+#
+#   Unless required by applicable law or agreed to in writing, software
+#   distributed under the License is distributed on an "AS IS" BASIS,
+#   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#   See the License for the specific language governing permissions and
+#   limitations under the License.
+#
+# ------------------------------------------------------------------------------
+"""Logging helpers."""
+import logging
+from logging import Logger, LoggerAdapter
+from typing import Any, MutableMapping, Optional, Tuple, Union
+
+
+class AgentLoggerAdapter(LoggerAdapter):
+    """This class is a logger adapter that prepends the agent name to log messages."""
+
+    def __init__(self, logger: Logger, agent_name: str):
+        """
+        Initialize the logger adapter.
+
+        :param agent_name: the agent name.
+        """
+        super().__init__(logger, dict(agent_name=agent_name))
+
+    def process(
+        self, msg: Any, kwargs: MutableMapping[str, Any]
+    ) -> Tuple[Any, MutableMapping[str, Any]]:
+        """Prepend the agent name to every log message."""
+        return f"[{self.extra['agent_name']}] {msg}", kwargs
+
+
+class WithLogger:
+    """Interface to endow subclasses with a logger."""
+
+    def __init__(
+        self,
+        logger: Optional[Union[Logger, LoggerAdapter]] = None,
+        default_logger_name: str = "aea",
+    ):
+        """
+        Initialize the logger.
+
+        :param logger: the logger object.
+        :param default_logger_name: the default logger name, if a logger is not provided.
+        """
+        self._logger = logger
+        self._default_logger_name = default_logger_name
+
+    @property
+    def logger(self) -> Union[Logger, LoggerAdapter]:
+        """Get the component logger."""
+        if self._logger is None:
+            # if not set (e.g. programmatic instantiation)
+            # return a default one with the default logger name.
+            return logging.getLogger(self._default_logger_name)
+        return self._logger
+
+    @logger.setter
+    def logger(self, logger: Union[Logger, LoggerAdapter]):
+        """Set the logger."""
+        self._logger = logger