Separate CRT logging from Python logging to avoid deadlock when enabling CRT logs (#156)

* Separate CRT logging from Python logging to avoid deadlock
when enabling CRT logs.
* Use sys.executable and leverage rusty-fork crate for separate 
process testing, and return error on logger initialization failure.
* Update logging setup to log to file if CRT_LOGS_DIR_PATH environment
variable is set with a logging directory path.

Author: dnanuti

CHANGELOG.md

@@ -1,5 +1,11 @@
 ## Unreleased
 
+### New features
+
+### Bug Fixes
+* Fix deadlock when enabling CRT debug logs. Removed former experimental method _enable_debug_logging().
+
+
 ## v1.1.4 (February 26, 2024)
 
 ### New features

s3torchconnectorclient/Cargo.lock

@@ -22,9 +22,11 @@ futures = "0.3.28"
 mountpoint-s3-client = { version = "0.7.0", features = ["mock"] }
 mountpoint-s3-crt = "0.6.1"
 log = "0.4.20"
-tracing = { version = "0.1.37", features = ["log"] }
-tracing-subscriber = "0.3.17"
+tracing = { version = "0.1.40", default-features = false, features = ["std", "log"] }
+tracing-subscriber = { version = "0.3.18", features = ["fmt", "env-filter"]}
 nix = { version = "0.27.1", features = ["process"] }
+rusty-fork = "0.3.0"
+tracing-appender = "0.2.3"
 
 [features]
 extension-module = ["pyo3/extension-module"]

s3torchconnectorclient/Cargo.toml

@@ -4,7 +4,7 @@
 import copyreg
 
 from ._logger_patch import TRACE as LOG_TRACE
-from ._logger_patch import _install_trace_logging, _enable_debug_logging
+from ._logger_patch import _install_trace_logging
 from ._mountpoint_s3_client import S3Exception, __version__
 
 _install_trace_logging()
@@ -16,4 +16,4 @@ def _s3exception_reduce(exc: S3Exception):
 
 copyreg.pickle(S3Exception, _s3exception_reduce)
 
-__all__ = ["LOG_TRACE", "S3Exception", "__version__", "_enable_debug_logging"]
+__all__ = ["LOG_TRACE", "S3Exception", "__version__"]

s3torchconnectorclient/python/src/s3torchconnectorclient/__init__.py

@@ -2,19 +2,9 @@
 #  // SPDX-License-Identifier: BSD
 
 import logging
-import atexit
-
-from ._mountpoint_s3_client import _enable_crt_logging, _disable_logging
 
 TRACE = 5
 
 
 def _install_trace_logging():
     logging.addLevelName(TRACE, "TRACE")
-
-
-# Experimental method for enabling verbose logging.
-# Please do NOT use unless otherwise instructed.
-def _enable_debug_logging():
-    atexit.register(_disable_logging)
-    _enable_crt_logging()

s3torchconnectorclient/python/src/s3torchconnectorclient/_logger_patch.py

@@ -0,0 +1,114 @@
+#  Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+#  // SPDX-License-Identifier: BSD
+import os.path
+import sys
+import tempfile
+
+import pytest
+
+PYTHON_TEST_CODE = """
+import logging
+import os
+import sys
+
+s3_uri = sys.argv[1]
+region = sys.argv[2]
+os.environ["ENABLE_CRT_LOGS"] = sys.argv[3]
+logs_dir_path = sys.argv[4]
+if logs_dir_path != "":
+    os.environ["CRT_LOGS_DIR_PATH"] = logs_dir_path
+
+from s3torchconnector import S3MapDataset
+
+logging.basicConfig(
+    stream=sys.stdout,
+    format="%(levelname)s %(name)s %(asctime)-15s %(filename)s:%(lineno)d %(message)s",
+)
+logging.getLogger().setLevel(logging.INFO)
+
+map_dataset = S3MapDataset.from_prefix(s3_uri, region=region)
+obj = map_dataset[0]
+assert obj is not None
+"""
+
+import subprocess
+
+
+@pytest.mark.parametrize(
+    "log_level, should_contain, should_not_contain",
+    [
+        (
+            "info",
+            ["INFO s3torchconnector.s3map_dataset"],
+            ["DEBUG", "TRACE"],
+        ),
+        (
+            "DEBUG",
+            [
+                "INFO s3torchconnector.s3map_dataset",
+                "DEBUG awscrt::AWSProfile",
+                "DEBUG awscrt::AuthCredentialsProvider",
+                "DEBUG awscrt::S3Client",
+            ],
+            ["TRACE"],
+        ),
+        (
+            "TRACE",
+            [
+                "INFO s3torchconnector.s3map_dataset",
+                "DEBUG awscrt::AWSProfile",
+                "DEBUG awscrt::AuthCredentialsProvider",
+                "TRACE awscrt::event-loop",
+                "TRACE awscrt::socket",
+                "TRACE awscrt::event-loop",
+            ],
+            # Python log level is set to INFO in the test script
+            ["TRACE s3torchconnector.s3map_dataset"],
+        ),
+        ("OFF", ["INFO s3torchconnector.s3map_dataset"], ["awscrt"]),
+    ],
+)
+def test_logging_valid(log_level, should_contain, should_not_contain, image_directory):
+    out, err = _start_subprocess(log_level, image_directory)
+    assert err == ""
+    assert all(s in out for s in should_contain)
+    assert all(s not in out for s in should_not_contain)
+
+
+def test_logging_to_file(image_directory):
+    with tempfile.TemporaryDirectory() as log_dir:
+        print("Created temporary directory", log_dir)
+        out, err = _start_subprocess("INFO", image_directory, log_dir)
+        # Standard output contains Python output
+        assert err == ""
+        assert "INFO s3torchconnector.s3map_dataset" in out
+        assert "awscrt" not in out
+        files = os.listdir(log_dir)
+        assert len(files) == 1
+        log_file = os.path.join(log_dir, files[0])
+        assert os.path.isfile(log_file)
+        with open(log_file) as f:
+            file_content = f.read()
+            assert all(s in file_content for s in ["awscrt", "INFO"])
+            assert all(
+                s not in file_content
+                for s in ["INFO s3torchconnector.s3map_dataset", "DEBUG", "TRACE"]
+            )
+
+
+def _start_subprocess(log_level, image_directory, logs_directory=""):
+    process = subprocess.Popen(
+        [
+            sys.executable,
+            "-c",
+            PYTHON_TEST_CODE,
+            image_directory.s3_uri,
+            image_directory.region,
+            log_level,
+            logs_directory,
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+        text=True,
+    )
+    return process.communicate()