Launch leaks loggers liberally

Bug report

Required Info:

• Operating System:
  • Ubuntu Focal / CPython 3.8.2
• Installation type:
  • source
• Version or commit hash:
  • master
• DDS implementation:
  • N/A
• Client library (if applicable):
  • N/A

Steps to reproduce issue

python3-dbg -m colcon test --packages-select launch

Expected behavior

No leaks are reported.

Actual behavior

Many filehandle leaks are reported.

python3-dbg -m colcon test --packages-select launch
Starting >>> launch  
--- stderr: launch                     
/opt/ros/master/install/lib/python3.8/site-packages/osrf_pycommon/process_utils/async_execute_process_asyncio/impl.py:32: DeprecationWarning: "@coroutine" decorator is deprecated since Python 3.8, use "async def" instead
  def _async_execute_process_nopty(
/opt/ros/master/install/lib/python3.8/site-packages/osrf_pycommon/process_utils/async_execute_process_asyncio/impl.py:55: DeprecationWarning: "@coroutine" decorator is deprecated since Python 3.8, use "async def" instead
  def _async_execute_process_pty(
/opt/ros/master/install/lib/python3.8/site-packages/osrf_pycommon/process_utils/async_execute_process_asyncio/impl.py:133: DeprecationWarning: "@coroutine" decorator is deprecated since Python 3.8, use "async def" instead
  def async_execute_process(
Warning: You seem to already have a custom sys.excepthook handler installed. I'll skip installing Trio's custom handler, but this means MultiErrors will not show full tracebacks.
Warning: TerminalReporter.writer attribute is deprecated, use TerminalReporter._tw instead at your own risk.
See https://docs.pytest.org/en/latest/deprecations.html#terminalreporter-writer for more information.

=============================== warnings summary ===============================
/home/dan/.local/lib/python3.8/site-packages/_pytest/junitxml.py:417
  Warning: The 'junit_family' default value will change to 'xunit2' in pytest 6.0.
  Add 'junit_family=xunit1' to your pytest.ini file to keep the current format in future versions of pytest and silence this warning.

test/launch/test_logging.py::test_output_loggers_configuration[both-checks2]
  Warning: unclosed file <_io.TextIOWrapper name='/home/dan/.ros/log/2020-05-06-19-05-09-203150-Rhea-414991/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_output_loggers_configuration[log-checks1]
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs0/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_output_loggers_configuration[full-checks4]
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs1/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_log_default_format
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs2/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_log_default_format
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs2/some-proc-stdout.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_log_default_format
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs2/some-proc.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_log_default_format
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs2/some-proc-stderr.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_screen_default_format
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs3/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_output_loggers_configuration[own_log-checks3]
  Warning: unclosed file <_io.TextIOWrapper name='/home/dan/.ros/log/2020-05-06-19-05-16-993620-Rhea-414991/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_bad_logging_launch_config
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs5/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_bad_logging_launch_config
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs5/some-proc-stdout.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_bad_logging_launch_config
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs5/some-proc.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_bad_logging_launch_config
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs5/some-proc-stderr.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_output_loggers_configuration[screen-checks0]
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs6/launch.log' mode='a' encoding='utf-8'>

test/launch/test_logging.py::test_log_handler_factory
  Warning: unclosed file <_io.TextIOWrapper name='/tmp/pytest-of-dan/pytest-19/logs7/launch.log' mode='a' encoding='utf-8'>

-- Docs: https://docs.pytest.org/en/latest/warnings.html
---
Finished <<< launch [12.8s]

Summary: 1 package finished [15.5s]
  1 package had stderr output: launch

Additional information

These are all launch handlers registered in launch.

There are a few problems with our logging setup:

1. We don't close the logging handlers. We just delete the handler and hope it gets cleaned up by the system. I believe this is the most proximal cause to the above issues. https://github.com/ros2/launch/blob/cac43b195fb767128df1fdf494687973d538c792/launch/launch/logging/__init__.py#L454-L455
2. Loggers are designed to be predictably named and long-lived. We should not be creating 3 different loggers PER SUBPROCESS NAME. Instead we should probably be using one logger named launch and maybe one logging handler per subprocess, that lives no longer than the subprocess. https://github.com/ros2/launch/blob/cac43b195fb767128df1fdf494687973d538c792/launch/launch/actions/execute_process.py#L617 https://github.com/ros2/launch/blob/cac43b195fb767128df1fdf494687973d538c792/launch/launch/logging/__init__.py#L431-L432
3. We accumulate LaunchLoggers into a list all_loggers that gets arbitrarily long. https://github.com/ros2/launch/blob/cac43b195fb767128df1fdf494687973d538c792/launch/launch/logging/__init__.py#L436-L447

Start with test/launch/test_logging.py and reproduce the warnings using python3-dbg -m colcon test --packages-select launch. Read the logging setup in launch/launch/logging/init.py at the referenced handler and all_loggers code, then inspect launch/launch/actions/execute_process.py where per-subprocess loggers are created. Done means the launch tests no longer report unclosed log files and the logging lifecycle issues described in the report are addressed.