[launch] provide default console and filesystem logging for executed processes

[wjwwood]

Currently in launch an executed process does not have anything printed to the console and nothing is logged to a file.

Some of the examples will create custom event handlers for this:

launch/launch/examples/launch_counters.py

Lines 51 to 62 in b78d87f

	# Setup a custom event handler for all stdout/stderr from processes.
	# Later, this will be a configurable, but always present, extension to the LaunchService.
	def on_output(event: launch.Event) -> None:
	for line in event.text.decode().splitlines():
	print('[{}] {}'.format(
	cast(launch.events.process.ProcessIO, event).process_name, line))
	ld.add_action(launch.actions.RegisterEventHandler(launch.event_handlers.OnProcessIO(
	# this is the action ^ and this, the event handler ^
	on_stdout=on_output,
	on_stderr=on_output,
	)))

The "default launch description" provided by launch_ros also creates an event handler to cause executed processes to print to the console if configured to do so (with the output= option to ExecuteProcess and it's derived classes like Node):

launch/launch_ros/launch_ros/default_launch_description.py

Lines 49 to 65 in b78d87f

	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

But even this doesn't handle writing process output to a log file:

launch/launch_ros/launch_ros/default_launch_description.py

Line 65 in b78d87f

# TODO(wjwwood): implement file logging

Ideally, there would be some facility for this built into launch and launch_ros could additionally configure it to write files to something like ROS_HOME where as it might go to ~/.launch_logs (or something like that) instead. The user could further configure this default event handler if desired.

The user would still be able to provide their own event handler for output from process, to be run along with the default or instead of it.

[jacobperron]

Looking back at roslaunch from ROS 1:

There are two lists of handlers for logging messages (for stdout and stderr) that are invoked every time a log function is called.
The provided functions for calling the handlers responsible for printing and logging are:

• printlog
• printlog_bold
• printerrlog

Each of the "printlog" functions prints to the screen as well as logs to a file:

https://github.com/ros/ros_comm/blob/a925610b0d6120e40414298ad060490238e8aaed/tools/roslaunch/src/roslaunch/core.py#L110-L123

Pythons logging module is used for writing to a log file

https://github.com/ros/ros_comm/blob/89ca9a7bf288b09d033a1ab6966ef8cfe39e1002/tools/roslaunch/src/roslaunch/__init__.py#L88-L90

An initial call to configure_logging sets the log file path to:

     <ROS_LOG_DIR>/<UUID>/roslaunch-<hostname>-<PID>.log

Where,

• <ROS_LOG_DIR> is from rospkg.get_log_dir() and prioritized as one of:
  1. $ROS_LOG_DIR
  2. $ROS_HOME/log
  3. ~/.ros/log
• <UUID> is based on the host hardware address, a random sequence number, and the current time. Generated with Pythons uuid.uuid1() function (source). This UUID represents the run ID (associated with the ROS master) and it's used by all nodes for finding the log directory.
• <hostname> is from socket.gethostname().
• <PID> is from os.getpid().

Node processes through launch are started with subprocess.Popen(), which is used to redirect stdout and stderr if a "log output" flag is set (ie. output="log" in XML):

https://github.com/ros/ros_comm/blob/6b9efd56d6882d1c017152ba11a5780a1496b30b/tools/roslaunch/src/roslaunch/nodeprocess.py#L242-L243

The format for the node process log files are:

    <ROS_LOG_DIR>/<UUID>/<name>-<counter>-stdout.log
    <ROS_LOG_DIR>/<UUID>/<name>-<counter>-stderr.log

Where,

• <name> is the node name.
• <counter> is a incremented for each node launched to avoid potential name collisions:

https://github.com/ros/ros_comm/blob/6b9efd56d6882d1c017152ba11a5780a1496b30b/tools/roslaunch/src/roslaunch/nodeprocess.py#L135-L138

Some other things worth noting:

• A processes stderr is never logged to a file. This feature has been disabled (never implemented?) in favor of always printing to the screen. There was an effort made for adding support for logging to both screen and a file (along with log rotation), but has not been completed (This is the pull request for the patch of issue #548 and the already existing PR #418 ros/ros_comm#551).
  • It would be a nice feature to have stderr and stdout interleaved in a log file for debugging.
• There does not seem to be a single file that contains logs from all nodes; instead logs for each node are found in separate log files. The closest thing is the rosout aggregates output on the "/rosout" topic process into a log file, but this does not capture regular stdout/stderr.
  • Having output from multiple nodes in a single log, or timestamped in separate logs, seems valuable for debugging.

---

Regarding ROS 2 launch, there are the following questions (with proposed answers):

1. How to capture a nodes stdout/stderr and direct to screen, a log file, or both?
   • We can use OnProcessIO event handler for processing stdout and stderr.
     • Callbacks can be directed to a new LaunchLogging API that can be configured to direct stdout and sterr to the screen, a file, or both.
     • LaunchLogging can encapsulate formatting and writing to log files and/or the screen.
     • Similar to ROS 1, we can use Pythons logging module for writing to a file.
     • A feature to configure the output of 'nodes' independently would be nice, but lieu of [launch] consider refactoring ExecuteProcess into Execute and Executable #114 and to keep things simple for the first iteration we can constrain configuration to the 'process' level (e.g. nodes in a shared process will share a configuration).
   • Output from LaunchService (or a future LaunchServer) should be directed to both the screen and a log.
   • The following info can be retreived from a ProcessIO event:
     • Node/process name.
     • The output.
     • Destination: screen, log, or both.
     • File descriptor: stdout or stderr.
2. How to organize log files?
   • Log files can be saved to a configurable directory (~/.ros/log).
     • Can be configured via the LaunchLogging API.
   • Launch log files can follow the naming scheme: ~/.ros/log/<DATETIME>-roslaunch-<hostname>-<counter>.log.
     • <DATETIME> can have the form YYYY-MM-DD-HH-MM-SS-UUUU and be retrieved with Pythons datetime module. This is a possible improvement over ROS 1 by allowing the user to easily sort logs by date-time. Alternatively, a random UUID could be used in place of time, but this seems less meaningful (or in the case of ROS 1 launch logs could compromise privacy since it contains the computer's network address).
     • <hostname> of the machine is useful for identifying the logs source.
     • <counter> can break ties in case two log files happen to have the same name. Maybe microseconds are good enough, but it doesn't hurt to check if a log file already exists.

---

Features such as log rotation, consolidation, and common logging methods (e.g. to "rosout" topic) in rcl and language client libraries can be considered separately, perhaps deserving a design document.

---

@wjwwood Let me know your thoughts and things I've overlooked.

[jacobperron]

From a discussion offline,

• Add PID to the log file name and make <counter> optional (only if file already exists): ~/.ros/log/<DATETIME>-roslaunch-<hostname>-<PID>-<counter>.log
• Include support for stripping color escape sequences when logging to a file.

[hidmic]

All standing PRs have been merged, though I cannot say #104 (comment) points are all addressed.

[jacobperron]

I don't think the two points in #104 (comment) are addressed, but I don't think they're critical and could be captured in separate tickets.

[jacobperron]

I think this is done. I'm not sure if there's support for stripping color escape sequences, but a separate ticket can be opened for that.