Memory leak in a Python project

Starting tracemalloc

... is easy:

diff --git a/ironic_inspector/cmd/all.py b/ironic_inspector/cmd/all.py
index 5dcf2a9..942df91 100644
--- a/ironic_inspector/cmd/all.py
+++ b/ironic_inspector/cmd/all.py
@@ -13,6 +13,7 @@
 """The Ironic Inspector service."""

 import sys
+import tracemalloc

 from oslo_config import cfg
 from oslo_service import service
@@ -26,6 +27,8 @@ CONF = cfg.CONF


 def main(args=sys.argv[1:]):
+    tracemalloc.start()
+
     # Parse config file and command line options, then start logging
     service_utils.prepare_service(args)

Collecting samples

Proudly stol^Wadapted from the Python documentation:

diff --git a/ironic_inspector/conductor/manager.py b/ironic_inspector/conductor/manager.py
index 44e2c43..e32511d 100644
--- a/ironic_inspector/conductor/manager.py
+++ b/ironic_inspector/conductor/manager.py
@@ -13,6 +13,7 @@

 import sys
 import traceback as traceback_mod
+import tracemalloc

 from eventlet import semaphore
 from futurist import periodics
@@ -219,7 +220,10 @@ def periodic_clean_up():  # pragma: no cover
         pxe_filter.driver().sync(ir_utils.get_client())


-def sync_with_ironic(conductor):
+_SNAPSHOT = None
+
+
+def _do_sync(conductor):
     if (conductor.coordinator is not None
             and not conductor.coordinator.is_leader):
         LOG.debug('The conductor is not a leader, skipping syncing '
@@ -234,6 +238,22 @@ def sync_with_ironic(conductor):
     node_cache.delete_nodes_not_in_list(ironic_node_uuids)


+def sync_with_ironic(conductor):
+    global _SNAPSHOT
+
+    _do_sync(conductor)
+
+    new_snapshot = tracemalloc.take_snapshot()
+    if _SNAPSHOT is not None:
+        diff = new_snapshot.compare_to(_SNAPSHOT, 'lineno')
+        if diff:
+            for stat in diff[:10]:
+                LOG.info("MEMORY %s", stat)
+        else:
+            LOG.debug("No memory usage difference")
+    _SNAPSHOT = new_snapshot

Looking at the source

First let's take a look at utils.py line 84. This is not literally the first thing that caught my attention, but it exposes a completely separate smaller issue. Here is the code:

 def get_string_format_keys(fmt_string, old_style=True):
     if old_style:

         class AccessSaver:
             def __init__(self):
                 self.keys = []

             def __getitem__(self, key):
                 self.keys.append(key)

         a = AccessSaver()
         fmt_string % a

         return a.keys

     # else ...

Ouch. A lesser known fact: creating new types in Python is not exactly cheap. Many years ago, I ended up creating namedtuples on each API request which made this API unbelievably slow. Now it seems like they are not necessarily deallocated?

A naive attempt to verify this idea with a simple Python script has not yielded a conclusive result, and it's possible that this leak is simply a byproduct of the larger issue. I have proposed a trivial fix to create the class only once and left it there. If you understand how classes are deallocated, definitely let me know!

What else do we have?

The other lines seem pretty boring at first sight:

 if project_name not in conf:
     _disable_service(
         config_dict,
         st,
         reason="No section for project '{project}' (service type "
         "'{service_type}') was present in the config.".format(
             project=project_name, service_type=st
         ),
     )
     continue

 def _make_key(key, service_type):
     if not service_type:
         return key
     else:
         service_type = service_type.lower().replace('-', '_')
         return "_".join([service_type, key])

 def normalize_keys(config):
     new_config = {}
     for key, value in config.items():
         key = key.replace('-', '_')
         if isinstance(value, dict):
             new_config[key] = normalize_keys(value)
         elif isinstance(value, bool):
             new_config[key] = value
         elif isinstance(value, int) and key not in (
             'verbose_level',
             'api_timeout',
         ):
             new_config[key] = str(value)
         elif isinstance(value, float):
             new_config[key] = str(value)
         else:
             new_config[key] = value
     return new_config

At first, nothing particularly interesting: allocating some strings in the first two examples, presumably reallocating the dictionary in the last one. The location of the first extract is important though: it's a part of the from_conf function that creates a new CloudRegion object, which, in turn, is a part of a Connection object. By re-tracing the code paths leading to the seemingly boring allocations, I'm able to conclude that connections are somehow not deallocated, which causes their configuration dictionaries to accumulate in the memory.

Do we actually close connections?

Well, we do not:

 def get_client(token=None):
     session = _get_ironic_session()

     try:
         return openstack.connection.Connection(
             session=session, oslo_conf=CONF).baremetal
     except Exception as exc:
         LOG.error('Failed to establish a connection with ironic, '
                   'reason: %s', exc)
         raise

Not closing connections is a potential problem, but it's usually not a huge problem in programming languages with garbage collection. Once the baremetal proxy is no longer used by the caller, it and thus the connection will be orphaned, causing Python to delete them. We won't have a chance to handle potential exceptions (which is why it's a bad practice), but memory should not be leaked.

At this point, I could add a missing close call or better keep the connection for the lifetime of the service (which is what I'm inclined to do in reality), but I wanted to understand the issue.

Diving into close

Let's check out the Connection's close call. How many seconds will it take you to go "wait, what"?

def close(self):
    self.config.set_auth_cache()
    if self.__pool_executor:
        self.__pool_executor.shutdown()
    atexit.unregister(self.close)

Okay, okay, I was in a bit different position: I was going through the git history and stumbled upon the patch that makes close look like this. I had some context, and here is the commit message:

finalizers execution order is not guaranteed in python3. This leads to
absence of builtins like "open" in the finalizers. Depending on the
keyring backend used inside of the set_auth_cache access to the file system
may be required.

Replace use of destructor to another builtin library "atexit" to
implement a more reliable exit handler.

Wait, what?

The first paragraph is correct: you should not rely on __del__ method to be called in a normal Python environment. If your process is already exiting, many things may have been deleted. And yes, even the open built-in function may no longer be available. What made me blink in a disbelief is the second part. Here is the change:

diff --git a/openstack/connection.py b/openstack/connection.py
index 819e16bd3..5722a01e2 100644
--- a/openstack/connection.py
+++ b/openstack/connection.py
@@ -176,6 +176,7 @@ try to find it and if that fails, you would create it::
 Additional information about the services can be found in the
 :ref:`service-proxies` documentation.
 """
+import atexit
 import concurrent.futures
 import warnings
 import weakref
@@ -472,9 +473,8 @@ class Connection(
                 'additional_metric_tags'
             ] = self.config.config['additional_metric_tags']

-    def __del__(self):
-        # try to force release of resources and save authorization
-        self.close()
+        # Register cleanup steps
+        atexit.register(self.close)

Since the connection's close method is doing something quite non-trivial that may easily fail during the process shutdown, the author moved this logic from the unreliable __del__ to the atexit machinery, so that it runs before anything is deallocated. Problem solved?

But what happens if close is never called? The answer is: exactly the thing described in this blog post.