Store: close store when dropped, keep log callback alive

Locating the model JSON file used inspect.stack(), which created a reference cycle via frames.
This kept a no longer referenced Store alive until the cyclic GC ran, so the store stayed open.
On Windows this made tests fail ("another store is still open using the same path"),
as the DB files of an open store cannot be deleted there (Linux allows it).

- Walk the frames manually and release the frame reference
- Store keeps a reference to the C log callback object while it may be called
- Fix logging.info() call missing a format placeholder
- Tests: close stores explicitly; add test_store_closed_when_dropped

Author: greenrobot

objectbox/store.py

@@ -127,6 +127,7 @@ def __init__(self,
         """
 
         self._c_store = None
+        self._c_log_callback = None
         if not c_store:
             options = StoreOptions()
             try:
@@ -185,6 +186,8 @@ def __init__(self,
             except DbError:
                 options._free()
                 raise
+            # Keep the C callback object alive as long as the store, which may call it (options are freed by open)
+            self._c_log_callback = getattr(options, "_c_log_cb", None)
             self._c_store = c.obx_store_open(options._c_handle)
         else:
             self._c_store = c_store
@@ -220,24 +223,33 @@ def get_module_path(module: Optional[ModuleType]) -> Optional[str]:
         def json_file_inside_module_path(module: Optional[ModuleType]) -> Optional[str]:
             module_path = get_module_path(module)
             if module_path:
-                logging.info("Using module path to locate objectbox-model.json: ", module_path)
+                logging.info("Using module path to locate objectbox-model.json: %s", module_path)
                 return os.path.join(module_path, "objectbox-model.json")
             return None
 
-        # The (direct) calling module seems like a good first choice
+        # The (direct) calling module seems like a good first choice, i.e. the user module that creates the Store.
+        # To find it, go up the call stack, one frame (function call) at a time via f_back (the caller's frame),
+        # and pick the first frame whose module (identified via the frame's globals) is outside the objectbox package.
+        # Note: do not use inspect.stack() and delete the frame reference when done (finally block).
+        #       Holding on to frames creates a reference cycle, which would keep the Store being constructed (a local
+        #       of a caller's frame) alive until the cyclic GC runs; i.e. the store would not be closed when dropped.
         this_module = sys.modules[__name__]
         this_module_path = get_module_path(this_module)
-        stack = inspect.stack()
         calling_module: Optional[ModuleType] = None
-        for stack_element in stack:
-            module = inspect.getmodule(stack_element[0])
-            if module is not this_module:
-                path = get_module_path(module)
-                if not path:  # Cannot get the direct caller's path, so do not try further
-                    break
-                if path != this_module_path:  # Not inside the objectbox package
-                    calling_module = module
-                    break
+        frame = inspect.currentframe()
+        try:
+            while frame is not None:
+                module = sys.modules.get(frame.f_globals.get("__name__"))
+                if module is not this_module:
+                    path = get_module_path(module)
+                    if not path:  # Cannot get the direct caller's path, so do not try further
+                        break
+                    if path != this_module_path:  # Not inside the objectbox package
+                        calling_module = module
+                        break
+                frame = frame.f_back
+        finally:
+            del frame
         model_json_file = json_file_inside_module_path(calling_module)
 
         if not model_json_file:

tests/test_basics.py

@@ -11,6 +11,9 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import gc
+import weakref
+
 import objectbox
 from objectbox.exceptions import DbError, NotFoundError
 from tests.common import create_test_store
@@ -35,6 +38,23 @@ def test_open():
     store.close()
 
 
+def test_store_closed_when_dropped():
+    """A store that is no longer referenced must be closed right away, without relying on the cyclic GC."""
+    gc_was_enabled = gc.isenabled()
+    gc.disable()
+    try:
+        store = create_test_store()
+        store_ref = weakref.ref(store)
+        del store
+        assert store_ref() is None
+        # Reopen without deleting the DB files first; that would hide a still open store on Linux (not on Windows)
+        store = create_test_store(clear_db=False)  # Raises if the previous store at the same path is still open
+        store.close()
+    finally:
+        if gc_was_enabled:
+            gc.enable()
+
+
 def test_not_found_exception():
     try:
         raise NotFoundError()

tests/test_idsync.py

@@ -589,6 +589,10 @@ class EntityB2:
     #      This might require to store the (Python) model in the Store.
     # with pytest.raises(ValueError):
     #     store_b.box(EntityA)
+    store_a.close()
+    store_b.close()
+
+
 def test_sync_dynamic_entities(env):
     def create_entity(entity_name: str, dimensions: int, distance_type: VectorDistanceType, uid=0):
         DynamicEntity = type(entity_name, (), {

tests/test_store_options.py

@@ -104,4 +104,5 @@ def mylog(level: OBXLogLevel, message: str):
     assert log_entries[0][1].startswith("Opening store:")
     assert log_entries[1][0] == LogLevel.Debug
     assert log_entries[1][1].startswith("Opening store:")
+    store.close()
 

tests/test_userclass.py

@@ -42,3 +42,4 @@ def tick(self):
     id_empty = box.put(Person())
     empty = box.get(id_empty)
     assert empty.fullname() == " "
+    store.close()