diff --git a/launch/launch/__init__.py b/launch/launch/__init__.py index 4286bac49..1cdc897b7 100644 --- a/launch/launch/__init__.py +++ b/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', diff --git a/launch/launch/actions/declare_launch_argument.py b/launch/launch/actions/declare_launch_argument.py index df6da1dee..afa31c9db 100644 --- a/launch/launch/actions/declare_launch_argument.py +++ b/launch/launch/actions/declare_launch_argument.py @@ -14,11 +14,12 @@ """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 @@ -26,8 +27,6 @@ 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)) diff --git a/launch/launch/actions/execute_process.py b/launch/launch/actions/execute_process.py index 1f1939b87..b54f3be7a 100644 --- a/launch/launch/actions/execute_process.py +++ b/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.""" diff --git a/launch/launch/actions/log_info.py b/launch/launch/actions/log_info.py index 9b41d93a9..2f60ea81c 100644 --- a/launch/launch/actions/log_info.py +++ b/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 diff --git a/launch/launch/actions/timer_action.py b/launch/launch/actions/timer_action.py index ef27dd78c..34f2ca7bb 100644 --- a/launch/launch/actions/timer_action.py +++ b/launch/launch/actions/timer_action.py @@ -15,8 +15,7 @@ """Module for the TimerAction action.""" import asyncio -import collections.abc -import logging +import collections from typing import Any # noqa: F401 from typing import cast from typing import Dict # noqa: F401 @@ -27,7 +26,10 @@ from typing import Tuple from typing import Union +import launch.logging + from .opaque_function import OpaqueFunction + from ..action import Action from ..event_handler import EventHandler from ..events import Shutdown @@ -43,8 +45,6 @@ from ..utilities import normalize_to_list_of_substitutions from ..utilities import perform_substitutions -_logger = logging.getLogger('launch.timer_action') - class TimerAction(Action): """ @@ -76,6 +76,7 @@ def __init__( self.__canceled = False self.__canceled_future = None # type: Optional[asyncio.Future] self.__cancel_on_shutdown = cancel_on_shutdown + self.__logger = launch.logging.get_logger(__name__) async def __wait_to_fire_event(self, context): done, pending = await asyncio.wait( @@ -132,8 +133,8 @@ def execute(self, context: LaunchContext) -> Optional[List['Action']]: if self.__canceled: # In this case, the action was canceled before being executed. - _logger.debug( - 'timer {} not waiting because it was canceled before being executed'.format(self) + self.__logger.debug( + 'timer {} not waiting because it was canceled before being executed'.format(self), ) self.__completed_future.set_result(None) return None diff --git a/launch/launch/launch_context.py b/launch/launch/launch_context.py index 4b5cc956f..91840aba3 100644 --- a/launch/launch/launch_context.py +++ b/launch/launch/launch_context.py @@ -16,7 +16,6 @@ import asyncio import collections -import logging from typing import Any from typing import Dict from typing import Iterable @@ -24,12 +23,12 @@ from typing import Optional from typing import Text +import launch.logging + from .event import Event from .event_handler import EventHandler from .substitution import Substitution -_logger = logging.getLogger(name='launch') - class LaunchContext: """Runtime context used by various launch entities when being visited or executed.""" @@ -57,6 +56,8 @@ def __init__(self, *, argv: Optional[Iterable[Text]] = None) -> None: self.__is_shutdown = False self.__asyncio_loop = None # type: Optional[asyncio.AbstractEventLoop] + self.__logger = launch.logging.get_logger(__name__) + @property def argv(self): """Getter for argv.""" @@ -170,12 +171,12 @@ def unregister_event_handler(self, event_handler: EventHandler) -> None: def emit_event_sync(self, event: Event) -> None: """Emit an event synchronously.""" - _logger.debug("emitting event synchronously: '{}'".format(event.name)) + self.__logger.debug("emitting event synchronously: '{}'".format(event.name)) self._event_queue.put_nowait(event) async def emit_event(self, event: Event) -> None: """Emit an event.""" - _logger.debug("emitting event: '{}'".format(event.name)) + self.__logger.debug("emitting event: '{}'".format(event.name)) await self._event_queue.put(event) def perform_substitution(self, substitution: Substitution) -> Text: diff --git a/launch/launch/launch_description_sources/python_launch_description_source.py b/launch/launch/launch_description_sources/python_launch_description_source.py index 368c50670..cbb5ca8ba 100644 --- a/launch/launch/launch_description_sources/python_launch_description_source.py +++ b/launch/launch/launch_description_sources/python_launch_description_source.py @@ -14,20 +14,20 @@ """Module for the PythonLaunchDescriptionSource class.""" -import logging import traceback from typing import Optional from typing import Text # noqa: F401 +import launch.logging + from .python_launch_file_utilities import get_launch_description_from_python_launch_file + from ..launch_context import LaunchContext from ..launch_description import LaunchDescription from ..some_substitutions_type import SomeSubstitutionsType from ..utilities import normalize_to_list_of_substitutions from ..utilities import perform_substitutions -_logger = logging.getLogger('launch.launch_description_sources.PythonLaunchDescriptionSource') - class PythonLaunchDescriptionSource: """Encapsulation of a Python launch file, which can be loaded during launch.""" @@ -53,6 +53,7 @@ def __init__( self.__launch_file_path = normalize_to_list_of_substitutions(launch_file_path) self.__expanded_launch_file_path = None # type: Optional[Text] self.__launch_description = None # type: Optional[LaunchDescription] + self.__logger = launch.logging.get_logger(__name__) def try_get_launch_description_without_context(self) -> Optional[LaunchDescription]: """Get the LaunchDescription, attempting to load it if necessary.""" @@ -64,8 +65,10 @@ def try_get_launch_description_without_context(self) -> Optional[LaunchDescripti perform_substitutions(context, self.__launch_file_path) return get_launch_description_from_python_launch_file(expanded_launch_file_path) except Exception as exc: - _logger.debug(traceback.format_exc()) - _logger.debug('Failed to load the launch file without a context: ' + str(exc)) + self.__logger.debug(traceback.format_exc()) + self.__logger.debug( + 'Failed to load the launch file without a context: ' + str(exc), + ) return self.__launch_description def get_launch_description(self, context: LaunchContext) -> LaunchDescription: diff --git a/launch/launch/launch_introspector.py b/launch/launch/launch_introspector.py index e927e2ddd..2fdcc7b24 100644 --- a/launch/launch/launch_introspector.py +++ b/launch/launch/launch_introspector.py @@ -14,7 +14,6 @@ """Module for the LaunchIntrospector class.""" -import logging from typing import cast from typing import List from typing import Text @@ -31,8 +30,6 @@ from .utilities import is_a from .utilities import normalize_to_list_of_substitutions -_logger = logging.getLogger(name='launch') - def indent(lines: List[Text], indention: Text = ' ') -> List[Text]: """Indent a list of strings and return them.""" diff --git a/launch/launch/launch_service.py b/launch/launch/launch_service.py index eebccd965..17413671a 100644 --- a/launch/launch/launch_service.py +++ b/launch/launch/launch_service.py @@ -28,6 +28,8 @@ from typing import Text from typing import Tuple # noqa: F401 +import launch.logging + import osrf_pycommon.process_utils from .event import Event @@ -45,7 +47,6 @@ from .utilities import on_sigterm from .utilities import visit_all_entities_and_collect_futures -_logger = logging.getLogger('launch.LaunchService') _g_loops_used = set() # type: Set @@ -81,23 +82,20 @@ def __init__( :param: argv stored in the context for access by the entities, None results in [] :param: debug if True (not default), asyncio the logger are seutp for debug """ + # Setup logging and debugging. + launch.logging.launch_config( + level=logging.DEBUG if debug else logging.INFO + ) + self.__debug = debug + + # Setup logging + self.__logger = launch.logging.get_logger('launch') # Install signal handlers if not already installed, will raise if not # in main-thread, call manually in main-thread to avoid this. install_signal_handlers() self.__argv = argv if argv is not None else [] - # Setup logging and debugging. - logging.basicConfig( - level=logging.INFO, - format='[%(levelname)s] [%(name)s]: %(msg)s', - ) - self.__debug = debug - if self.__debug: - logging.getLogger('launch').setLevel(logging.DEBUG) - else: - logging.getLogger('launch').setLevel(logging.INFO) - # Setup context and register a built-in event handler for bootstrapping. self.__context = LaunchContext(argv=self.__argv) self.__context.register_event_handler(OnIncludeLaunchDescription()) @@ -179,10 +177,10 @@ async def _process_one_event(self) -> None: await self.__process_event(next_event) async def __process_event(self, event: Event) -> None: - _logger.debug("processing event: '{}'".format(event)) + self.__logger.debug("processing event: '{}'".format(event)) for event_handler in tuple(self.__context._event_handlers): if event_handler.matches(event): - _logger.debug( + self.__logger.debug( "processing event: '{}' ✓ '{}'".format(event, event_handler)) self.__context._push_locals() entities = event_handler.handle(event, self.__context) @@ -201,7 +199,8 @@ async def __process_event(self, event: Event) -> None: else: pass # Keep this commented for now, since it's very chatty. - # _logger.debug( + # self.__logger.debug( + # 'launch.LaunchService', # "processing event: '{}' x '{}'".format(event, event_handler)) async def __run_loop(self) -> None: @@ -234,7 +233,9 @@ async def __run_loop(self) -> None: timeout=1.0, return_when=asyncio.FIRST_COMPLETED) if not done: - _logger.debug('still waiting on futures: {}'.format(entity_futures)) + self.__logger.debug( + 'still waiting on futures: {}'.format(entity_futures) + ) else: await process_one_event_task @@ -299,13 +300,14 @@ def _on_sigint(signum, frame): nonlocal sigint_received base_msg = 'user interrupted with ctrl-c (SIGINT)' if not sigint_received: - _logger.warning(base_msg) + self.__logger.warning(base_msg) ret = self._shutdown( reason='ctrl-c (SIGINT)', due_to_sigint=True, force_sync=True) assert ret is None, ret sigint_received = True else: - _logger.warning('{} again, ignoring...'.format(base_msg)) + + self.__logger.warning('{} again, ignoring...'.format(base_msg)) signal.signal(signal.SIGINT, prev_handler) @@ -317,8 +319,8 @@ def _on_sigterm(signum, frame): return # TODO(wjwwood): try to terminate running subprocesses before exiting. - _logger.error('using SIGTERM or SIGQUIT can result in orphaned processes') - _logger.error('make sure no processes launched are still running') + self.__logger.error('using SIGTERM or SIGQUIT can result in orphaned processes') + self.__logger.error('make sure no processes launched are still running') nonlocal run_loop_task self.__loop_from_run_thread.call_soon_threadsafe(run_loop_task.cancel) @@ -331,7 +333,7 @@ def _on_sigquit(signum, frame): # This function has been called re-entrantly. return - _logger.error('user interrupted with ctrl-\\ (SIGQUIT), terminating...') + self.__logger.error('user interrupted with ctrl-\\ (SIGQUIT), terminating...') _on_sigterm(signum, frame) signal.signal(signal.SIGQUIT, prev_handler) @@ -346,11 +348,11 @@ def _on_sigquit(signum, frame): except KeyboardInterrupt: pass except asyncio.CancelledError: - _logger.error('asyncio run loop was canceled') + self.__logger.error('asyncio run loop was canceled') except Exception as exc: msg = 'Caught exception in launch (see debug for traceback): {}'.format(exc) - _logger.debug(traceback.format_exc()) - _logger.error(msg) + self.__logger.debug(traceback.format_exc()) + self.__logger.error(msg) self.__return_code = 1 ret = self._shutdown(reason=msg, due_to_sigint=False, force_sync=True) assert ret is None, ret diff --git a/launch/launch/logging.py b/launch/launch/logging.py new file mode 100644 index 000000000..2f54fd05a --- /dev/null +++ b/launch/launch/logging.py @@ -0,0 +1,431 @@ +# Copyright 2019 Open Source Robotics Foundation, Inc. +# +# 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. + +"""Module for the launch specific logging.""" + +import datetime +import logging +import logging.handlers + +import os +import socket +import sys + +from typing import List + + +__all__ = [ + 'get_logger', + 'get_log_file_handler', + 'get_log_file_path', + 'get_output_loggers', + 'get_screen_handler', + 'launch_config', + 'reset', +] + + +def with_per_logger_formatting(cls): + """Add per logger formatting capabilities to the given logging.Handler.""" + class _trait(cls): + """A logging.Handler subclass to enable per logger formatting.""" + + def __init__(self, *args, **kwargs): + super(_trait, self).__init__(*args, **kwargs) + self._formatters = {} + + def setFormatterFor(self, logger, formatter): + """Set formatter for a given logger instance or logger name.""" + logger_name = logger if isinstance(logger, str) else logger.name + self._formatters[logger_name] = formatter + + def unsetFormatterFor(self, logger): + """Unset formatter for a given logger instance or logger name, if any.""" + logger_name = logger if isinstance(logger, str) else logger.name + if logger_name in self._formatters: + del self._formatters[logger_name] + + def format(self, record): # noqa + if record.name in self._formatters: + formatter = self._formatters[record.name] + return formatter.format(record) + return super(_trait, self).format(record) + return _trait + + +def attributes(**attr): + """Inject attributes into a function (a singleton by definition).""" + def _decorator(f): + for name, value in attr.items(): + setattr(f, name, value) + return f + return _decorator + + +@attributes(screen_handler=None, file_handlers={}) +def launch_config( + *, + level=None, + log_dir=None, + screen_format=None, + screen_style=None, + log_format=None, + log_style=None +): + """ + Set up launch logging. + + This function allows you to: + + - Set the default verbosity level for all loggers. + - Configure the location of log files on disk. + - Configure screen and log file formats. + + Setup only has side effects for the arguments provided. + The setup process is idempotent. + + For the ``screen_format`` argument there are a few aliases: + + - 'default' to log verbosity level, logger name and logged message + - 'default_with_timestamp' to add timestamps to the 'default' format + + :param level: the default log level used for all loggers. + :param log_dir: used as base path for all log file collections. + :param screen_format: format specification used when logging to the screen, + as expected by the `logging.Formatter` constructor. + Alternatively, aliases for common formats are available, see above. + :param screen_style: the screen style used if no alias is used for + screen_format. + No style can be provided if a format alias is given. + :param log_format: the format used when logging to the main launch log file, + as expected by the `logging.Formatter` constructor. + Alternatively, the 'default' alias can be given to log verbosity level, + logger name and logged message. + :param log_style: the log style used if no alias is given for log_format. + No style can be provided if a format alias is given. + """ + if level is not None: + logging.root.setLevel(level) + if screen_format is not None: + if screen_format == 'default': + screen_format = '[{levelname}] [{name}]: {msg}' + if screen_style is not None: + raise ValueError( + 'Cannot set a custom format style for the "default" screen format.' + ) + if screen_format == 'default_with_timestamp': + screen_format = '{created:.7f} [{levelname}] [{name}]: {msg}' + if screen_style is not None: + raise ValueError( + 'Cannot set a custom format style for the ' + '"default_with_timestamp" screen format.' + ) + if screen_style is None: + screen_style = '{' + launch_config.screen_formatter = logging.Formatter( + screen_format, style=screen_style + ) + if launch_config.screen_handler is not None: + launch_config.screen_handler.setFormatter(launch_config.screen_formatter) + if log_format is not None: + if log_format == 'default': + log_format = '{created:.7f} [{levelname}] [{name}]: {msg}' + if log_style is not None: + raise ValueError( + 'Cannot set a custom format style for the "default" log format.' + ) + if log_style is None: + log_style = '{' + launch_config.file_formatter = logging.Formatter( + log_format, style=log_style + ) + for handler in launch_config.file_handlers.values(): + handler.setFormatter(launch_config.file_formatter) + if log_dir is not None: + if any(launch_config.file_handlers): + import warnings + warnings.warn(( + 'Loggers have been already configured to output to log files below {}. ' + 'Proceed at your own risk.' + ).format(launch_config.log_dir)) + if not os.path.isdir(log_dir): + raise ValueError('{} is not a directory'.format(log_dir)) + launch_config.log_dir = log_dir + + +def get_logger(name=None): + """Get named logger, configured to output to screen and launch main log file.""" + logger = logging.getLogger(name) + screen_handler = get_screen_handler() + if screen_handler not in logger.handlers: + logger.addHandler(screen_handler) + launch_log_file_handler = get_log_file_handler() + if launch_log_file_handler not in logger.handlers: + logger.addHandler(launch_log_file_handler) + return logger + + +def _normalize_output_configuration(config): + """ + Normalize output configuration to a dict representation. + + See `get_output_loggers()` documentation for further reference. + """ + normalized_config = { + 'both': set(), 'stdout': set(), 'stderr': set() + } + if isinstance(config, str): + if config == 'screen': + normalized_config.update({ + 'both': {'screen'} + }) + elif config == 'log': + normalized_config.update({ + 'both': {'log'}, + 'stderr': {'screen'} + }) + elif config == 'both': + normalized_config.update({ + 'both': {'log', 'screen'}, + }) + elif config == 'own_log': + normalized_config.update({ + 'both': {'own_log'}, + 'stdout': {'own_log'}, + 'stderr': {'own_log'} + }) + elif config == 'full': + normalized_config.update({ + 'both': {'screen', 'log', 'own_log'}, + 'stdout': {'own_log'}, + 'stderr': {'own_log'} + }) + else: + raise ValueError(( + '{} is not a valid standard output config ' + 'i.e. "screen", "log" or "both"' + ).format(config)) + elif isinstance(config, dict): + for source, destinations in config.items(): + if source not in ('stdout', 'stderr', 'both'): + raise ValueError(( + '{} is not a valid output source ' + 'i.e. "stdout", "stderr" or "both"' + ).format(source)) + if isinstance(destinations, str): + destinations = {destinations} + for destination in destinations: + if destination not in ('screen', 'log', 'own_log'): + raise ValueError(( + '{} is not a valid output destination ' + 'i.e. "screen", "log" or "own_log"' + ).format(destination)) + normalized_config[source] = set(destinations) + else: + raise ValueError( + '{} is not a valid output configuration'.format(config) + ) + return normalized_config + + +def get_output_loggers(process_name, output_config): + """ + Get the stdout and stderr output loggers for the given process name. + + The output_config may be a dictionary with one or more of the optional keys + 'stdout', 'stderr', or 'both' (stdout and stderr combined) which represent + the various process output sources, and values for those keys to assign one + or more logging destinations to the source. + The logging destination values may be: + + - 'screen': log it to the screen, + - 'log': log it to launch log file, or + - 'own_log': log it to a separate log file. + + When logging the stdout and stderr separately, the log file names follow + the ``-.log`` pattern where ```` is either + 'stdout' or 'stderr' + When the 'both' logging destination is used the log file name follows the + ``.log`` pattern. + + The "launch log file" is a log file which is create for each run of + the launch.LaunchService, and at least captures the log output from launch + itself, but may also include output from subprocess's if configured so. + + Alternatively, the output_config parameter may be a string which represents + one of a couple available aliases for common logging configurations. + The available aliases are: + + - 'screen': stdout and stderr are logged to the screen, + - 'log': stdout and stderr are logged to launch log file and stderr to + the screen, + - 'both': both stdout and stderr are logged to the screen and to launch + main log file, + - 'own_log' for stdout, stderr and their combination to be logged to + their own log files, and + - 'full' to have stdout and stderr sent to the screen, to the main launch + log file, and their own separate and combined log files. + + :param process_name: the process-like action whose outputs want to be logged. + :param output_config: configuration for the output loggers, + see above for details. + :returns: a tuple with the stdout and stderr output loggers. + """ + output_config = _normalize_output_configuration(output_config) + for source in ('stdout', 'stderr'): + logger = logging.getLogger('{}-{}'.format(process_name, source)) + # If a 'screen' output is configured for this source or for + # 'both' sources, this logger should output to screen. + if 'screen' in (output_config['both'] | output_config[source]): + screen_handler = get_screen_handler() + # Add screen handler if necessary. + if screen_handler not in logger.handlers: + screen_handler.setFormatterFor( + logger, logging.Formatter('{msg}', style='{') + ) + logger.addHandler(screen_handler) + + # If a 'log' output is configured for this source or for + # 'both' sources, this logger should output to launch main log file. + if 'log' in (output_config['both'] | output_config[source]): + launch_log_file_handler = get_log_file_handler() + # Add launch main log file handler if necessary. + if launch_log_file_handler not in logger.handlers: + launch_log_file_handler.setFormatterFor( + logger, logging.Formatter('{created:.7f} {msg}', style='{') + ) + logger.addHandler(launch_log_file_handler) + + # If an 'own_log' output is configured for this source, this logger + # should output to its own log file. + if 'own_log' in output_config[source]: + own_log_file_handler = get_log_file_handler( + '{}-{}.log'.format(process_name, source) + ) + own_log_file_handler.setFormatter(logging.Formatter(fmt=None)) + # Add own log file handler if necessary. + if own_log_file_handler not in logger.handlers: + logger.addHandler(own_log_file_handler) + # If an 'own_log' output is configured for 'both' sources, + # this logger should output to a combined log file. + if 'own_log' in output_config['both']: + combined_log_file_handler = get_log_file_handler(process_name + '.log') + combined_log_file_handler.setFormatter(logging.Formatter('{msg}', style='{')) + # Add combined log file handler if necessary. + if combined_log_file_handler not in logger.handlers: + logger.addHandler(combined_log_file_handler) + # Retrieve both loggers. + return ( + logging.getLogger(process_name + '-stdout'), + logging.getLogger(process_name + '-stderr') + ) + + +def get_screen_handler(): + """ + Get the one and only screen logging handler. + + See launch_config() documentation for screen logging configuration. + """ + if launch_config.screen_handler is None: + handler_cls = with_per_logger_formatting(logging.StreamHandler) + launch_config.screen_handler = handler_cls(sys.stdout) + launch_config.screen_handler.setFormatter(launch_config.screen_formatter) + return launch_config.screen_handler + + +def get_log_file_path(file_name='launch.log'): + return os.path.join(launch_config.log_dir, file_name) + + +def get_log_file_handler(file_name='launch.log'): + """ + Get the logging handler to a log file. + + See launch_config() documentation for application wide log file + logging configuration. + + :param: file_name of the log file whose handler is to be retrieved. + :return: the logging handler associated to the file (always the same + once constructed). + """ + if file_name not in launch_config.file_handlers: + file_path = get_log_file_path(file_name) + if os.name != 'nt': + handler_cls = with_per_logger_formatting( + logging.handlers.WatchedFileHandler + ) + else: + handler_cls = with_per_logger_formatting(logging.FileHandler) + file_handler = handler_cls(file_path) + file_handler.setFormatter(launch_config.file_formatter) + launch_config.file_handlers[file_name] = file_handler + return launch_config.file_handlers[file_name] + + +def _make_unique_log_dir(*, base_path): + """ + Make a unique directory for logging. + + :param: base_path for directory creation + :return: the path to the created directory + """ + while True: + now = datetime.datetime.now() + datetime_str = now.strftime('%Y-%m-%d-%H-%M-%S-%f') + log_dirname = '{0}-{1}-{2}'.format( + datetime_str, socket.gethostname(), os.getpid() + ) + log_dir = os.path.join(base_path, log_dirname) + # Check that filename does not exist + # TODO(hidmic): fix (unlikely) TOCTTOU race + if not os.path.isdir(log_dir): + os.makedirs(log_dir, exist_ok=True) + return log_dir + + +# Track all loggers to support module resets +class LaunchLogger(logging.getLoggerClass()): + all_loggers: List[logging.Logger] = [] + + def __new__(cls, *args, **kwargs): + instance = super(LaunchLogger, cls).__new__(cls) + LaunchLogger.all_loggers.append(instance) + return instance + + +default_log_dir = _make_unique_log_dir( + base_path=os.path.join(os.path.expanduser('~'), '.ros/log') +) + + +def reset(): + """Reset logging.""" + # Reset existing logging infrastructure + for logger in LaunchLogger.all_loggers: + logger.setLevel(logging.NOTSET) + del logger.handlers[:] + # Back to default logging setup + launch_config.log_dir = None + launch_config.file_handlers = {} + launch_config.screen_handler = None + launch_config( + level=logging.INFO, log_dir=default_log_dir, + log_format='default', screen_format='default' + ) + logging.setLoggerClass(LaunchLogger) + + +# Initial module reset +reset() diff --git a/launch/launch/utilities/signal_management.py b/launch/launch/utilities/signal_management.py index b11a118d2..fd2a759fc 100644 --- a/launch/launch/utilities/signal_management.py +++ b/launch/launch/utilities/signal_management.py @@ -14,19 +14,18 @@ """Module for the signal management functionality.""" -import logging import platform import signal import threading +import launch.logging + __signal_handlers_installed_lock = threading.Lock() __signal_handlers_installed = False __custom_sigint_handler = None __custom_sigquit_handler = None __custom_sigterm_handler = None -_logger = logging.getLogger('launch.utilities.signal_management') - def on_sigint(handler): """ @@ -143,6 +142,7 @@ def __on_sigterm(signum, frame): # Windows does not support SIGQUIT signal.signal(signal.SIGQUIT, __on_sigquit) except ValueError: - _logger.error("failed to set signal handlers in 'launch.utilities.signal_management.py'") - _logger.error('this function must be called in the main thread') + logger = launch.logging.get_logger(__name__) + logger.error("failed to set signal handlers in '{}'".format(__name__)) + logger.error('this function must be called in the main thread') raise diff --git a/launch/test/launch/test_logging.py b/launch/test/launch/test_logging.py new file mode 100644 index 000000000..97ecec00c --- /dev/null +++ b/launch/test/launch/test_logging.py @@ -0,0 +1,230 @@ +# Copyright 2019 Open Source Robotics Foundation, Inc. +# +# 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. + +"""Tests for the launch.logging module.""" + +import logging +import os +import re + +import launch.logging + +import pytest + + +@pytest.fixture +def log_dir(tmpdir_factory): + """Test fixture that generates a temporary directory for log files.""" + return str(tmpdir_factory.mktemp('logs')) + + +def test_bad_logging_launch_config(): + """Tests that setup throws at bad configuration.""" + launch.logging.reset() + + with pytest.raises(ValueError): + launch.logging.launch_config(log_dir='not/a/real/dir') + + with pytest.raises(ValueError): + launch.logging.launch_config(screen_format='default', screen_style='%') + + with pytest.raises(ValueError): + launch.logging.launch_config(log_format='default', log_style='%') + + +def test_output_loggers_bad_configuration(log_dir): + """Tests that output loggers setup throws at bad configuration.""" + launch.logging.reset() + + launch.logging.launch_config(log_dir=log_dir) + + with pytest.raises(ValueError): + launch.logging.get_output_loggers('some-proc', 'not_an_alias') + + with pytest.raises(ValueError): + launch.logging.get_output_loggers('some-proc', {'garbage': {'log'}}) + + with pytest.raises(ValueError): + launch.logging.get_output_loggers('some-proc', {'stdout': {'garbage'}}) + + +@pytest.mark.parametrize('config,checks', [ + ('screen', {'stdout': {'screen'}, 'stderr': {'screen'}}), + ('log', {'stdout': {'log'}, 'stderr': {'log', 'screen'}}), + ('both', {'both': {'log', 'screen'}}), + ('own_log', { + 'stdout': {'own_log'}, + 'stderr': {'own_log'}, + 'both': {'own_log'}, + }), + ('full', { + 'stdout': {'log', 'own_log', 'screen'}, + 'stderr': {'log', 'own_log', 'screen'}, + 'both': {'own_log'}, + }), + ( + {'stdout': {'screen', 'log'}, 'stderr': {'own_log'}}, + { + 'stdout': {'screen', 'log'}, + 'stderr': {'own_log'} + }, + ) +]) +def test_output_loggers_configuration(capsys, log_dir, config, checks): + checks = {'stdout': set(), 'stderr': set(), 'both': set(), **checks} + launch.logging.reset() + launch.logging.launch_config( + level=logging.INFO, + log_dir=log_dir, + screen_format='default', + log_format='default' + ) + logger = launch.logging.get_logger('some-proc') + logger.addHandler(launch.logging.get_screen_handler()) + logger.addHandler(launch.logging.get_log_file_handler()) + logger.setLevel(logging.ERROR) + stdout_logger, stderr_logger = launch.logging.get_output_loggers('some-proc', config) + + logger.debug('oops') + logger.error('baz') + stdout_logger.info('foo') + stderr_logger.info('bar') + + capture = capsys.readouterr() + lines = list(reversed(capture.out.splitlines())) + assert '[ERROR] [some-proc]: baz' == lines.pop() + if 'screen' in (checks['stdout'] | checks['both']): + assert 'foo' == lines.pop() + if 'screen' in (checks['stderr'] | checks['both']): + assert 'bar' == lines.pop() + assert 0 == len(lines) + assert 0 == len(capture.err) + + launch.logging.get_log_file_handler().flush() + main_log_path = launch.logging.get_log_file_path() + assert os.path.exists(main_log_path) + assert 0 != os.stat(main_log_path).st_size + with open(main_log_path, 'r') as f: + lines = list(reversed(f.readlines())) + assert re.match(r'[0-9]+\.[0-9]+ \[ERROR\] \[some-proc\]: baz', lines.pop()) is not None + if 'log' in (checks['stdout'] | checks['both']): + assert re.match(r'[0-9]+\.[0-9]+ foo', lines.pop()) is not None + if 'log' in (checks['stderr'] | checks['both']): + assert re.match(r'[0-9]+\.[0-9]+ bar', lines.pop()) is not None + assert 0 == len(lines) + + if 'own_log' in (checks['stdout'] | checks['both']): + launch.logging.get_log_file_handler('some-proc-stdout.log').flush() + own_log_path = launch.logging.get_log_file_path('some-proc-stdout.log') + assert os.path.exists(own_log_path) + assert 0 != os.stat(own_log_path).st_size + with open(own_log_path, 'r') as f: + lines = f.read().splitlines() + assert 1 == len(lines) + assert 'foo' == lines[0] + else: + own_log_path = launch.logging.get_log_file_path('some-proc-stdout.log') + assert (not os.path.exists(own_log_path) or 0 == os.stat(own_log_path).st_size) + + if 'own_log' in (checks['stderr'] | checks['both']): + launch.logging.get_log_file_handler('some-proc-stderr.log').flush() + own_log_path = launch.logging.get_log_file_path('some-proc-stderr.log') + assert os.path.exists(own_log_path) + assert 0 != os.stat(own_log_path).st_size + with open(own_log_path, 'r') as f: + lines = f.read().splitlines() + assert 1 == len(lines) + assert 'bar' == lines[0] + else: + own_log_path = launch.logging.get_log_file_path('some-proc-stderr.log') + assert (not os.path.exists(own_log_path) or 0 == os.stat(own_log_path).st_size) + + if 'own_log' in checks['both']: + launch.logging.get_log_file_handler('some-proc.log').flush() + own_log_path = launch.logging.get_log_file_path('some-proc.log') + assert os.path.exists(own_log_path) + assert 0 != os.stat(own_log_path).st_size + with open(own_log_path, 'r') as f: + lines = f.read().splitlines() + assert 2 == len(lines) + assert 'foo' == lines[0] + assert 'bar' == lines[1] + else: + own_log_path = launch.logging.get_log_file_path('some-proc.log') + assert (not os.path.exists(own_log_path) or 0 == os.stat(own_log_path).st_size) + + +def test_screen_default_format_with_timestamps(capsys, log_dir): + """Test screen logging when using the default logs format with timestamps.""" + launch.logging.reset() + launch.logging.launch_config( + level=logging.DEBUG, + log_dir=log_dir, + screen_format='default_with_timestamp', + ) + logger = launch.logging.get_logger('some-proc') + logger.addHandler(launch.logging.get_screen_handler()) + assert logger.getEffectiveLevel() == logging.DEBUG + + logger.debug('foo') + + capture = capsys.readouterr() + lines = capture.out.splitlines() + assert 1 == len(lines) + assert re.match(r'[0-9]+\.[0-9]+ \[DEBUG\] \[some-proc\]: foo', lines[0]) is not None + assert 0 == len(capture.err) + + +def test_screen_default_format(capsys): + """Test screen logging when using the default logs format.""" + launch.logging.reset() + launch.logging.launch_config( + level=logging.INFO, + screen_format='default' + ) + + logger = launch.logging.get_logger('some-proc') + logger.addHandler(launch.logging.get_screen_handler()) + assert logger.getEffectiveLevel() == logging.INFO + + logger.info('bar') + capture = capsys.readouterr() + lines = capture.out.splitlines() + assert 1 == len(lines) + assert '[INFO] [some-proc]: bar' == lines[0] + assert 0 == len(capture.err) + + +def test_log_default_format(log_dir): + """Test logging to the main log file when using the default logs format.""" + launch.logging.reset() + launch.logging.launch_config( + level=logging.WARN, + log_dir=log_dir, + log_format='default' + ) + logger = launch.logging.get_logger('some-proc') + logger.addHandler(launch.logging.get_log_file_handler()) + assert logger.getEffectiveLevel() == logging.WARN + + logger.error('baz') + + launch.logging.get_log_file_handler().flush() + assert os.path.exists(launch.logging.get_log_file_path()) + assert 0 != os.stat(launch.logging.get_log_file_path()).st_size + + with open(launch.logging.get_log_file_path(), 'r') as f: + lines = f.readlines() + assert 1 == len(lines) + assert re.match(r'[0-9]+\.[0-9]+ \[ERROR\] \[some-proc\]: baz', lines[0]) is not None diff --git a/launch_ros/launch_ros/actions/lifecycle_node.py b/launch_ros/launch_ros/actions/lifecycle_node.py index 9cf7087b4..894263ab8 100644 --- a/launch_ros/launch_ros/actions/lifecycle_node.py +++ b/launch_ros/launch_ros/actions/lifecycle_node.py @@ -15,7 +15,6 @@ """Module for the LifecycleNode action.""" import functools -import logging from typing import cast from typing import List from typing import Optional @@ -23,6 +22,7 @@ import launch from launch.action import Action +import launch.logging import lifecycle_msgs.msg import lifecycle_msgs.srv @@ -31,8 +31,6 @@ from ..events.lifecycle import ChangeState from ..events.lifecycle import StateTransition -_logger = logging.getLogger(name='launch_ros') - class LifecycleNode(Node): """Action that executes a ROS lifecycle node.""" @@ -62,6 +60,7 @@ def __init__(self, *, node_name: Text, **kwargs) -> None: to change state, see its documentation for more details. """ super().__init__(node_name=node_name, **kwargs) + self.__logger = launch.logging.get_logger(__name__) self.__rclpy_subscription = None self.__current_state = \ ChangeState.valid_states[lifecycle_msgs.msg.State.PRIMARY_STATE_UNKNOWN] @@ -72,21 +71,25 @@ def _on_transition_event(self, context, msg): self.__current_state = ChangeState.valid_states[msg.goal_state.id] context.asyncio_loop.call_soon_threadsafe(lambda: context.emit_event_sync(event)) except Exception as exc: - _logger.error( + self.__logger.error( "Exception in handling of 'lifecycle.msg.TransitionEvent': {}".format(exc)) def _call_change_state(self, request, context: launch.LaunchContext): while not self.__rclpy_change_state_client.wait_for_service(timeout_sec=1.0): if context.is_shutdown: - _logger.warning("Abandoning wait for the '{}' service, due to shutdown.".format( - self.__rclpy_change_state_client.srv_name)) + self.___logger.warning( + "Abandoning wait for the '{}' service, due to shutdown.".format( + self.__rclpy_change_state_client.srv_name), + ) return response = self.__rclpy_change_state_client.call(request) if not response.success: - _logger.error("Failed to make transition '{}' for LifecycleNode '{}'".format( - ChangeState.valid_transitions[request.transition.id], - self.node_name, - )) + self.__logger.error( + "Failed to make transition '{}' for LifecycleNode '{}'".format( + ChangeState.valid_transitions[request.transition.id], + self.node_name, + ) + ) def _on_change_state_event(self, context: launch.LaunchContext) -> None: typed_event = cast(ChangeState, context.locals.event) diff --git a/launch_ros/launch_ros/actions/node.py b/launch_ros/launch_ros/actions/node.py index 219b8d893..c53a27b3f 100644 --- a/launch_ros/launch_ros/actions/node.py +++ b/launch_ros/launch_ros/actions/node.py @@ -15,7 +15,6 @@ """Module for the Node action.""" from collections.abc import Mapping -import logging import os import pathlib from tempfile import NamedTemporaryFile @@ -29,6 +28,9 @@ from launch.action import Action from launch.actions import ExecuteProcess from launch.launch_context import LaunchContext + +import launch.logging + from launch.some_substitutions_type import SomeSubstitutionsType from launch.substitutions import LocalSubstitution from launch.utilities import ensure_argument_type @@ -47,8 +49,6 @@ import yaml -_logger = logging.getLogger(name='launch_ros') - class Node(ExecuteProcess): """Action that executes a ROS node.""" @@ -176,6 +176,8 @@ def __init__( self.__substitutions_performed = False + self.__logger = launch.logging.get_logger(__name__) + @property def node_name(self): """Getter for node_name.""" @@ -211,7 +213,7 @@ def _perform_substitutions(self, context: LaunchContext) -> None: self.__expanded_node_namespace = '/' + self.__expanded_node_namespace validate_namespace(self.__expanded_node_namespace) except Exception: - _logger.error( + self.__logger.error( "Error while expanding or validating node name or namespace for '{}':" .format('package={}, node_executable={}, name={}, namespace={}'.format( self.__package, @@ -237,8 +239,9 @@ def _perform_substitutions(self, context: LaunchContext) -> None: else: raise RuntimeError('invalid normalized parameters {}'.format(repr(params))) if not os.path.isfile(param_file_path): - _logger.warning( - 'Parameter file path is not a file: {}'.format(param_file_path)) + self.__logger.warning( + 'Parameter file path is not a file: {}'.format(param_file_path), + ) # Don't skip adding the file to the parameter list since space has been # reserved for it in the ros_specific_arguments. self.__expanded_parameter_files.append(param_file_path) diff --git a/launch_ros/launch_ros/default_launch_description.py b/launch_ros/launch_ros/default_launch_description.py index 97c76d0d7..2556bc6a9 100644 --- a/launch_ros/launch_ros/default_launch_description.py +++ b/launch_ros/launch_ros/default_launch_description.py @@ -14,12 +14,9 @@ """Module containing the default LaunchDescription for ROS.""" -import functools -import logging import threading -from typing import cast from typing import Dict # noqa: F401 -from typing import Text +from typing import Text # noqa: F401 from typing import TextIO # noqa: F401 import launch @@ -29,43 +26,6 @@ import rclpy from rclpy.executors import SingleThreadedExecutor -_logger = logging.getLogger('launch_ros') -_process_log_files = {} # type: Dict[Text, TextIO] - - -def _on_process_started(context: launch.LaunchContext): - typed_event = cast(launch.events.process.ProcessStarted, context.locals.event) - if typed_event.execute_process_action.output == 'log': - # TODO(wjwwood): implement file logging - _logger.warning( - "process '{}' asked for 'output=log', but that's not currently implemented.") - - -def _on_process_exited(context: launch.LaunchContext): - typed_event = cast(launch.events.process.ProcessExited, context.locals.event) - if typed_event.execute_process_action.output == 'log': - # TODO(wjwwood): implement file logging - pass - - -def _on_process_output(event: launch.Event, *, file_name: Text, prefix_output: bool): - typed_event = cast(launch.events.process.ProcessIO, event) - text = event.text.decode() - if typed_event.execute_process_action.output == 'screen': - if prefix_output: - for line in text.splitlines(): - print('[{}] {}'.format(event.process_name, line)) - else: - print(text, end='') - elif typed_event.execute_process_action.output == 'log': - if file_name == 'stderr': - if prefix_output: - for line in text.splitlines(): - print('[{}:{}] {}'.format(event.process_name, file_name, line)) - else: - print(text, end='') - # TODO(wjwwood): implement file logging - class ROSSpecificLaunchStartup(launch.actions.OpaqueFunction): """Does ROS specific launch startup.""" @@ -116,13 +76,10 @@ def _function(self, context: launch.LaunchContext): self.__rclpy_spin_thread.start() -def get_default_launch_description(*, prefix_output_with_name=False, rclpy_context=None): +def get_default_launch_description(*, rclpy_context=None): """ Return a LaunchDescription to be included before user descriptions. - :param: prefix_output_with_name if True, each line of output is prefixed - with the name of the process as `[process_name] `, else it is printed - unmodified :param: rclpy_context Provide a context other than the default rclpy context to pass down to rclpy.init. The context is expected to have already been initialized by the caller @@ -130,23 +87,6 @@ def get_default_launch_description(*, prefix_output_with_name=False, rclpy_conte """ default_ros_launch_description = launch.LaunchDescription([ # ROS initialization (create node and other stuff). - ROSSpecificLaunchStartup(rclpy_context=rclpy_context), - # Handle process starts. - launch.actions.RegisterEventHandler(launch.EventHandler( - matcher=lambda event: isinstance(event, launch.events.process.ProcessStarted), - entities=[launch.actions.OpaqueFunction(function=_on_process_started)], - )), - # Handle process exit. - launch.actions.RegisterEventHandler(launch.EventHandler( - matcher=lambda event: isinstance(event, launch.events.process.ProcessExited), - entities=[launch.actions.OpaqueFunction(function=_on_process_exited)], - )), - # Add default handler for output from processes. - launch.actions.RegisterEventHandler(launch.event_handlers.OnProcessIO( - on_stdout=functools.partial( - _on_process_output, file_name='stdout', prefix_output=prefix_output_with_name), - on_stderr=functools.partial( - _on_process_output, file_name='stderr', prefix_output=prefix_output_with_name), - )), + ROSSpecificLaunchStartup(rclpy_context=rclpy_context) ]) return default_ros_launch_description