Launch leaks loggers liberally

[rotu]

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.

   launch/launch/launch/logging/__init__.py

   Lines 454 to 455 in cac43b1

   	logger.setLevel(logging.NOTSET)
   	del logger.handlers[:]

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.

   launch/launch/launch/actions/execute_process.py

   Line 617 in cac43b1

   self.__logger = launch.logging.get_logger(process_event_args['name'])

   launch/launch/launch/logging/__init__.py

   Lines 431 to 432 in cac43b1

   	logging.getLogger(process_name + '-stdout'),
   	logging.getLogger(process_name + '-stderr')

3. We accumulate LaunchLoggers into a list all_loggers that gets arbitrarily long.

   launch/launch/launch/logging/__init__.py

   Lines 436 to 447 in cac43b1

   	# 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
   	def __init__(self, *args, **kwargs):
   	super().__init__(*args, **kwargs)
   	self.propagate = False

[hidmic]

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.

So, on one hand we have internal launch logging needs. In that case, yes, one could even get away with a single launch logger if actions consistently self identify in each one of their logs. On the other hand, we have process output logging needs. If we collapse those into one of the aforementioned loggers, we can no longer configure different handlers and formatters for each. And we must if we want to respect ExecuteProcess output configurations. At some point, I entertained the idea of having a custom handler and formatter classes that could mux log records, reducing the total amount of loggers, but it seemed inappropriate.

I agree though that each action could and should shutdown their loggers, if any.

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.

That is true. And we could do better in many places.

We accumulate LaunchLoggers into a list all_loggers that gets arbitrarily long.

That is correct, but the only way to shutdown all launch loggers at once without affecting other logging loggers. launch logging uses Python's logging module and it is intended to coexist with client code that also uses it.

[rotu]

On the other hand, we have process output logging needs. If we collapse those into one of the aforementioned loggers, we can no longer configure different handlers and formatters for each.

What are these logging needs? Do they consist of having more than one logger per subprocess stream?

If not, there is no need to go through the logging infrastructure, in which case we can just use the Handler.emit instead.

At some point, I entertained the idea of having a custom handler and formatter classes that could mux log records, reducing the total amount of loggers, but it seemed inappropriate.

It seems that if that sort of flexibility is needed, it could be done with a QueueHandler.

[hidmic]

What are these logging needs? Do they consist of having more than one logger per subprocess stream?

In the most general case, different log formats and sinks for each process output descriptor. See get_output_loggers() documentation.

If not, there is no need to go through the logging infrastructure, in which case we can just use the Handler.emit instead.

I guess you could bypass much of the logging infrastructure, manually creating log records and such, but I fail to see why would you do that. Note this has nothing to do with explicitly cleaning up resources. That we can do.

It seems that if that sort of flexibility is needed, it could be done with a QueueHandler.

Sure, yeah, there're multiple ways to do it. The question is if we should.

[rotu]

In the most general case, different log formats and sinks for each process output descriptor. See get_output_loggers() documentation.

Excellent! I love good documentation and can definitely preserve that behavior.

I guess you could bypass much of the logging infrastructure, manually creating log records and such, but I fail to see why would you do that.

We would do that because right now we're abusing the logging infrastructure, particularly logging.getLogger, and creating objects that never get cleaned up.

Also, we're altering the global logging configuration so any loggers that get created after launch has been imported will be created as LaunchLoggers. I expect that e.g. loggers created by pytest will be very surprised to have their level changed by the launch.logging.reset function!

The question is if we should.

Agreed. I don't think it's the easiest approach nor the most correct one.

Would you like to take a crack at a fix PR or should I?

[hidmic]

Would you like to take a crack at a fix PR or should I?

If you have the time, go ahead. Many of your concerns are perfectly valid ones, but do bear in mind that the intent was (and is) to not re-implement logging functionality that later doesn't interplay with the logging module itself when/if launch is embedded in another application.

[rotu]

do bear in mind that the intent was (and is) to not re-implement logging functionality that later doesn't interplay with the logging module itself when/if launch is embedded in another application.

I don't understand what you mean. Explain?

[hidmic]

launch.logging reuses logging as much as possible in an attempt to not recreate what is already available in logging and to make it easy for launch to be integrated into a larger application/library that also uses logging. That is to say, it'd be a bummer if we end up with a custom logging-like module with half the features.

[rotu]

I still don't quite understand how this can fit into a larger application/library.

1. By setting propagate = False in LaunchLogger, we prevent any logging records from getting out of launch into an application handler.

2. I can't find any way for an application logging record to get into a launch handler.

Am I missing a piece of the puzzle?

At any rate, I'm sure I can do this without reinventing Logger significantly.

[hidmic]

1. By setting propagate = False in LaunchLogger, we prevent any logging records from getting out of launch into an application handler.

logging.Logger.propagate is mutable.

2. I can't find any way for an application logging record to get into a launch handler.

Any application can use a launch.logging.

With this I'm not saying it cannot be made better, but that we should try not making it worse.

[asymingt]

Perhaps related: #793. My workaround involved running launch.logging.reset() on test completion to reset the logging system and close these file handles. I also proposed an alternate solution involving modifying the ExecuteLocal class destructor to close its log files.