Add LaunchLogger class (#145)

* Add LaunchLogger class

Supports logging messages from multiple processes and modules to the screen, a common log file, or both.
LaunchLogger is a singleton and when it is first instantiated a log file is created of the form 'DATETIME-launch-HOSTNAME-PID.log'.
Messages sent to the screen or the log file will have the format 'TIME [LEVEL] NAME: MESSAGE'.

* Add different formats for log and screen in launch logger

The timestamp in the screen format is optional.

* Use LoggerLevel.INFO instead of logging.INFO

* Fixup 'screen' logging logic

Also extends LaunchLogger interface.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Refactors launch logging.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Preconfigures launch.logging loggers.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Addresses peer review comments.

- Fix style and documentation issues.
- Removes dangling TODO.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* style and documentation fixups

Signed-off-by: William Woodall <william@osrfoundation.org>

* fix name shadowing (mypy complained)

Signed-off-by: William Woodall <william@osrfoundation.org>

* Replace capfd with capsys in launch.logging tests.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Integrate LaunchLogger in launch

Replacing usage of the Python logging module with the new LaunchLogger.

* Integrate LaunchLogger in launch_ros

Also, removed unecessary logging logic.

* Clean up LaunchLogger integration with launch

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Refactor launch logging integration.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Switch to non-relative launch.logging imports.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Turn ExecuteProcess output_prefix into an output_format.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Convert launch logging API names to snake case.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

* Minor fixes after rebase.

Signed-off-by: Michel Hidalgo <michel@ekumenlabs.com>

launch/launch/__init__.py

@@ -17,6 +17,7 @@
 from . import actions
 from . import conditions
 from . import events
+from . import logging
 from .action import Action
 from .condition import Condition
 from .event import Event
@@ -37,6 +38,7 @@
     'actions',
     'conditions',
     'events',
+    'logging',
     'Action',
     'Condition',
     'Event',

launch/launch/actions/declare_launch_argument.py

@@ -14,20 +14,19 @@
 
 """Module for the DeclareLaunchArgument action."""
 
-import logging
 from typing import List
 from typing import Optional
 from typing import Text
 
+import launch.logging
+
 from ..action import Action
 from ..launch_context import LaunchContext
 from ..some_substitutions_type import SomeSubstitutionsType
 from ..substitution import Substitution
 from ..utilities import normalize_to_list_of_substitutions
 from ..utilities import perform_substitutions
 
-_logger = logging.getLogger('launch.actions.DeclareLaunchArgument')
-
 
 class DeclareLaunchArgument(Action):
     """
@@ -88,6 +87,8 @@ def __init__(
             self.__default_value = normalize_to_list_of_substitutions(default_value)
         self.__description = description
 
+        self.__logger = launch.logging.get_logger(__name__)
+
         # This is used later to determine if this launch argument will be
         # conditionally visited.
         # Its value will be read and set at different times and so the value
@@ -114,9 +115,9 @@ def execute(self, context: LaunchContext):
         if self.name not in context.launch_configurations:
             if self.default_value is None:
                 # Argument not already set and no default value given, error.
-                _logger.error(
-                    "Required launch argument '{}' (description: '{}') was not provided"
-                    .format(self.name, self.description)
+                self.__logger.error(
+                    "Required launch argument '{}' (description: '{}') was not provided".format(
+                        self.name, self.description)
                 )
                 raise RuntimeError(
                     "Required launch argument '{}' was not provided.".format(self.name))

launch/launch/actions/execute_process.py

@@ -15,7 +15,6 @@
 """Module for the ExecuteProcess action."""
 
 import asyncio
-import logging
 import os
 import platform
 import shlex
@@ -33,20 +32,25 @@
 from typing import Tuple  # noqa: F401
 from typing import Union
 
+import launch.logging
+
 from osrf_pycommon.process_utils import async_execute_process
 from osrf_pycommon.process_utils import AsyncSubprocessProtocol
 
 from .emit_event import EmitEvent
 from .opaque_function import OpaqueFunction
 from .timer_action import TimerAction
+
 from ..action import Action
 from ..event import Event
 from ..event_handler import EventHandler
 from ..event_handlers import OnProcessExit
+from ..event_handlers import OnProcessIO
 from ..event_handlers import OnShutdown
 from ..events import matches_action
 from ..events import Shutdown
 from ..events.process import ProcessExited
+from ..events.process import ProcessIO
 from ..events.process import ProcessStarted
 from ..events.process import ProcessStderr
 from ..events.process import ProcessStdin
@@ -65,8 +69,6 @@
 from ..utilities import normalize_to_list_of_substitutions
 from ..utilities import perform_substitutions
 
-_logger = logging.getLogger(name='launch')
-
 _global_process_counter_lock = threading.Lock()
 _global_process_counter = 0  # in Python3, this number is unbounded (no rollover)
 
@@ -87,7 +89,8 @@ def __init__(
         sigkill_timeout: SomeSubstitutionsType = LaunchConfiguration(
             'sigkill_timeout', default=5),
         prefix: Optional[SomeSubstitutionsType] = None,
-        output: Optional[Text] = None,
+        output: Text = 'log',
+        output_format: Text = '[{this.name}] {line}',
         log_cmd: bool = False,
         on_exit: Optional[Union[
             SomeActionsType,
@@ -162,10 +165,13 @@ def __init__(
         :param: prefix a set of commands/arguments to preceed the cmd, used for
             things like gdb/valgrind and defaults to the LaunchConfiguration
             called 'launch-prefix'
-        :param: output either 'log' or 'screen'; if 'screen' stderr is directed
-            to stdout and stdout is printed to the screen; if 'log' stderr is
-            directed to the screen and both stdout and stderr are directed to
-            a log file; the default is 'log'
+        :param: output configuration for process output logging. Default is 'log' i.e.
+            log both stdout and stderr to launch main log file and stderr to the screen.
+            See `launch.logging.get_output_loggers()` documentation for further reference
+            on all available options.
+        :param: output_format for logging each output line, supporting `str.format()`
+            substitutions with the following keys in scope: `line` to reference the raw
+            output line and `this` to reference this action instance.
         :param: log_cmd if True, prints the final cmd before executing the
             process, which is useful for debugging when substitutions are
             involved.
@@ -188,15 +194,9 @@ def __init__(
         self.__prefix = normalize_to_list_of_substitutions(
             LaunchConfiguration('launch-prefix', default='') if prefix is None else prefix
         )
-        self.__output = output if output is not None else 'log'
-        allowed_output_options = ['log', 'screen']
-        if self.__output not in allowed_output_options:
-            raise ValueError(
-                "output argument to ExecuteProcess is '{}', expected one of [{}]".format(
-                    self.__output,
-                    allowed_output_options,
-                )
-            )
+        self.__output = output
+        self.__output_format = output_format
+
         self.__log_cmd = log_cmd
         self.__on_exit = on_exit
 
@@ -257,19 +257,21 @@ def __on_signal_process_event(
             raise RuntimeError('Signal event received before subprocess transport available.')
         if self._subprocess_protocol.complete.done():
             # the process is done or is cleaning up, no need to signal
-            _logger.debug("signal '{}' not sent to '{}' because it is already closing".format(
-                typed_event.signal_name, self.process_details['name']
-            ))
+            self.__logger.debug(
+                "signal '{}' not set to '{}' because it is already closing".format(
+                    typed_event.signal_name, self.process_details['name']),
+            )
             return None
         if platform.system() == 'Windows' and typed_event.signal_name == 'SIGINT':
             # TODO(wjwwood): remove this when/if SIGINT is fixed on Windows
-            _logger.warning(
+            self.__logger.warning(
                 "'SIGINT' sent to process[{}] not supported on Windows, escalating to 'SIGTERM'"
-                .format(self.process_details['name']))
+                .format(self.process_details['name']),
+            )
             typed_event = SignalProcess(
                 signal_number=signal.SIGTERM,
                 process_matcher=lambda process: True)
-        _logger.info("sending signal '{}' to process[{}]".format(
+        self.__logger.info("sending signal '{}' to process[{}]".format(
             typed_event.signal_name, self.process_details['name']
         ))
         try:
@@ -279,19 +281,38 @@ def __on_signal_process_event(
             self._subprocess_transport.send_signal(typed_event.signal)
             return None
         except ProcessLookupError:
-            _logger.debug("signal '{}' not sent to '{}' because it has closed already".format(
-                typed_event.signal_name, self.process_details['name']
-            ))
+            self.__logger.debug(
+                "signal '{}' not sent to '{}' because it has closed already".format(
+                    typed_event.signal_name, self.process_details['name']
+                )
+            )
 
-    def __on_process_stdin_event(
+    def __on_process_stdin(
         self,
-        event: Event,
-        context: LaunchContext
-    ) -> Optional[LaunchDescription]:
-        _logger.warning("in ExecuteProcess('{}').__on_process_stdin_event()".format(id(self)))
+        event: ProcessIO
+    ) -> Optional[SomeActionsType]:
+        self.__logger.warning(
+            "in ExecuteProcess('{}').__on_process_stdin_event()".format(id(self)),
+        )
         cast(ProcessStdin, event)
         return None
 
+    def __on_process_stdout(
+        self, event: ProcessIO
+    ) -> Optional[SomeActionsType]:
+        for line in event.text.decode().splitlines():
+            self.__stdout_logger.info(
+                self.__output_format.format(line=line, this=self)
+            )
+
+    def __on_process_stderr(
+        self, event: ProcessIO
+    ) -> Optional[SomeActionsType]:
+        for line in event.text.decode().splitlines():
+            self.__stderr_logger.info(
+                self.__output_format.format(line=line, this=self)
+            )
+
     def __on_shutdown(self, event: Event, context: LaunchContext) -> Optional[SomeActionsType]:
         return self._shutdown_process(
             context,
@@ -303,7 +324,7 @@ def __get_shutdown_timer_actions(self) -> List[Action]:
             "process[{}] failed to terminate '{}' seconds after receiving '{}', escalating to '{}'"
 
         def printer(context, msg, timeout_substitutions):
-            _logger.error(msg.format(
+            self.__logger.error(msg.format(
                 context.locals.process_name,
                 perform_substitutions(context, timeout_substitutions),
             ))
@@ -377,12 +398,12 @@ def __init__(
             self.__context = context
             self.__action = action
             self.__process_event_args = process_event_args
+            self.__logger = launch.logging.get_logger(process_event_args['name'])
 
         def connection_made(self, transport):
-            _logger.info('process[{}]: started with pid [{}]'.format(
-                self.__process_event_args['name'],
-                transport.get_pid(),
-            ))
+            self.__logger.info(
+                'process started with pid [{}]'.format(transport.get_pid()),
+            )
             super().connection_made(transport)
             self.__process_event_args['pid'] = transport.get_pid()
             self.__action._subprocess_transport = transport
@@ -402,7 +423,7 @@ def __expand_substitutions(self, context):
         with _global_process_counter_lock:
             global _global_process_counter
             _global_process_counter += 1
-            name = '{}-{}'.format(name, _global_process_counter)
+            self.__name = '{}-{}'.format(name, _global_process_counter)
         cwd = None
         if self.__cwd is not None:
             cwd = ''.join([context.perform_substitution(x) for x in self.__cwd])
@@ -416,7 +437,7 @@ def __expand_substitutions(self, context):
         # store packed kwargs for all ProcessEvent based events
         self.__process_event_args = {
             'action': self,
-            'name': name,
+            'name': self.__name,
             'cmd': cmd,
             'cwd': cwd,
             'env': env,
@@ -427,13 +448,12 @@ async def __execute_process(self, context: LaunchContext) -> None:
         process_event_args = self.__process_event_args
         if process_event_args is None:
             raise RuntimeError('process_event_args unexpectedly None')
-        name = process_event_args['name']
         cmd = process_event_args['cmd']
         cwd = process_event_args['cwd']
         env = process_event_args['env']
         if self.__log_cmd:
-            _logger.info("process[{}] details: cmd=[{}], cwd='{}', custom_env?={}".format(
-                name, ', '.join(cmd), cwd, 'True' if env is not None else 'False'
+            self.__logger.info("process details: cmd=[{}], cwd='{}', custom_env?={}".format(
+                ', '.join(cmd), cwd, 'True' if env is not None else 'False'
             ))
         try:
             transport, self._subprocess_protocol = await async_execute_process(
@@ -445,11 +465,9 @@ async def __execute_process(self, context: LaunchContext) -> None:
                 env=env,
                 shell=self.__shell,
                 emulate_tty=False,
-                stderr_to_stdout=(self.__output == 'screen'),
             )
         except Exception:
-            _logger.error('exception occurred while executing process[{}]:\n{}'.format(
-                name,
+            self.__logger.error('exception occurred while executing process:\n{}'.format(
                 traceback.format_exc()
             ))
             self.__cleanup()
@@ -461,10 +479,10 @@ async def __execute_process(self, context: LaunchContext) -> None:
 
         returncode = await self._subprocess_protocol.complete
         if returncode == 0:
-            _logger.info('process[{}]: process has finished cleanly'.format(name))
+            self.__logger.info('process has finished cleanly [pid {}]'.format(pid))
         else:
-            _logger.error("process[{}] process has died [pid {}, exit code {}, cmd '{}'].".format(
-                name, pid, returncode, ' '.join(cmd)
+            self.__logger.error("process has died [pid {}, exit code {}, cmd '{}'].".format(
+                pid, returncode, ' '.join(cmd)
             ))
         await context.emit_event(ProcessExited(returncode=returncode, **process_event_args))
         self.__cleanup()
@@ -477,6 +495,7 @@ def execute(self, context: LaunchContext) -> Optional[List['Action']]:
         - register an event handler for the shutdown process event
         - register an event handler for the signal process event
         - register an event handler for the stdin event
+        - configures logging for the IO process event
         - create a task for the coroutine that monitors the process
         """
         if self.__shutdown_received:
@@ -492,9 +511,11 @@ def execute(self, context: LaunchContext) -> Optional[List['Action']]:
                 matcher=lambda event: is_a_subclass(event, SignalProcess),
                 entities=OpaqueFunction(function=self.__on_signal_process_event),
             ),
-            EventHandler(
-                matcher=lambda event: is_a_subclass(event, ProcessStdin),
-                entities=OpaqueFunction(function=self.__on_process_stdin_event),
+            OnProcessIO(
+                target_action=self,
+                on_stdin=self.__on_process_stdin,
+                on_stdout=self.__on_process_stdout,
+                on_stderr=self.__on_process_stderr
             ),
             OnShutdown(
                 on_shutdown=self.__on_shutdown,
@@ -510,6 +531,9 @@ def execute(self, context: LaunchContext) -> Optional[List['Action']]:
         try:
             self.__completed_future = create_future(context.asyncio_loop)
             self.__expand_substitutions(context)
+            self.__logger = launch.logging.get_logger(self.__name)
+            self.__stdout_logger, self.__stderr_logger = \
+                launch.logging.get_output_loggers(self.__name, self.__output)
             context.asyncio_loop.create_task(self.__execute_process(context))
         except Exception:
             for event_handler in event_handlers:
@@ -521,6 +545,11 @@ def get_asyncio_future(self) -> Optional[asyncio.Future]:
         """Return an asyncio Future, used to let the launch system know when we're done."""
         return self.__completed_future
 
+    @property
+    def name(self):
+        """Getter for name."""
+        return self.__name
+
     @property
     def cmd(self):
         """Getter for cmd."""

launch/launch/actions/log_info.py

@@ -14,19 +14,18 @@
 
 """Module for the LogInfo action."""
 
-import logging
 from typing import List
 from typing import overload
 from typing import Text
 from typing import Union
 
+import launch.logging
+
 from ..action import Action
 from ..launch_context import LaunchContext
 from ..substitution import Substitution
 from ..utilities import normalize_to_list_of_substitutions
 
-_logger = logging.getLogger('launch.user')
-
 
 class LogInfo(Action):
     """Action that logs a message when executed."""
@@ -46,6 +45,7 @@ def __init__(self, *, msg, **kwargs):  # noqa: F811
         super().__init__(**kwargs)
 
         self.__msg = normalize_to_list_of_substitutions(msg)
+        self.__logger = launch.logging.get_logger(__name__)
 
     @property
     def msg(self) -> List[Substitution]:
@@ -54,5 +54,7 @@ def msg(self) -> List[Substitution]:
 
     def execute(self, context: LaunchContext) -> None:
         """Execute the action."""
-        _logger.info(''.join([context.perform_substitution(sub) for sub in self.msg]))
+        self.__logger.info(
+            ''.join([context.perform_substitution(sub) for sub in self.msg])
+        )
         return None