Update logging setup and add tests

.pre-commit-config.yaml

@@ -67,7 +67,7 @@ repos:
     hooks:
       - id: mypy
         name: mypy
-        entry: "python"
+        entry: "python3"
         language: system
         types: [python]
         args: ["-m", "mypy", "--config-file", "mypy.ini"]

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Changelog
 
+# v26.18.0
+
+- Disable logging of initialisation events by default, can be enabled by setting env var `OTG_LOG_INIT_EVENTS=1`
+- Ensure that setting `OTF_LOG_LEVEL` to `DEBUG` actually sets the log level to `DEBUG` in the root logger, which ensures addons like the AWS addon will trigger `botocore` to log it's debug messages too.
+- Update `README.md` and help text to include new environment variables, and any missing ones.
+
 # v26.15.0
 
 - Add `OTF_STALE_RUNNING_LOG_SECONDS` environment variable to allow resuming of batches from a `_running` log file that is older than the specified number of seconds.

README.md

@@ -172,6 +172,8 @@ options:
 These are some environment variables that can be used to customise the behaviour of the application. There are some internally used variables too, but changing them without a full understanding of the code is not advised.
 
 - `OTF_NO_LOG` - Disable logging to file. Only log to stderr. Set to `1` to enable
+- `OTF_LOG_LEVEL` - Set the log level.
+- `OTF_LOG_INIT_EVENTS` - Set to `1` to enable logging of log initialisation events. Defaults to `0`
 - `OTF_LOG_JSON` - Stderr logging will be in JSON format. Set to `1` to enable
 - `OTF_LOG_DIRECTORY` - Path under which log files are written
 - `OTF_NO_THREAD_SLEEP` - Disable the 1-second sleep between batch task thread creation. This sleep exists to prevent race conditions with concurrent protocol imports. Only disable this if you understand the implications. Set to `1` to disable.

pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "opentaskpy"
-version = "v26.15.0"
+version = "v26.18.0"
 authors = [{ name = "Adam McDonagh", email = "adam@elitemonkey.net" }]
 license-files = [ "LICENSE" ]
 
@@ -71,7 +71,7 @@ otf-batch-validator = "opentaskpy.cli.batch_validator:main"
 profile = 'black'
 
 [tool.bumpver]
-current_version = "v26.15.0"
+current_version = "v26.18.0"
 version_pattern = "vYY.WW.PATCH[-TAG]"
 commit_message = "bump version {old_version} -> {new_version}"
 commit = true

src/opentaskpy/cli/task_run.py

@@ -28,8 +28,15 @@ def main() -> None:
                                     OTF_NO_LOG - Prevent logging to any files, will log to stdout/err only
                                     OTF_LOG_DIRECTORY - Specify a particular log directory to write log files to
                                     OTF_LOG_LEVEL - Equivalent to using -v
+                                    OTF_LOG_INIT_EVENTS - Enable logging of log initialisation events. Set to 1 to enable
+                                    OTF_NO_THREAD_SLEEP - Disable the 1-second sleep between batch task thread creation. Set to 1 to disable
                                     OTF_SSH_KEY - Specify a particular SSH key to use for SSH/SFTP related transfers
+                                    OTF_STAGING_DIR - Staging base directory to place files before final location. Default is /tmp
+                                    OTF_BATCH_RESUME_LOG_DATE - Resume batch runs from a specific date in YYYYMMDD format
                                     OTF_VARIABLES_FILE - Override the default variables file location
+                                    OTF_PARAMIKO_ULTRA_DEBUG - Enable Paramiko ultra_debug for verbose SSH communications. Set to 1 to enable
+                                    OTF_LAZY_LOAD_VARIABLES - Only load variables used by the task definition. Set to 1 to enable
+                                    OTF_STALE_RUNNING_LOG_SECONDS - Resume using stale _running logs after this many inactive seconds
                                     OTF_NOOP - Equivalent to using --noop argument
 
                                 Task Definition Overrides:

src/opentaskpy/otflogging.py

@@ -167,6 +167,12 @@ def init_logging(
     # Set the log format
     formatter = logging.Formatter(OTF_LOG_FORMAT)
 
+    if os.environ.get("OTF_LOG_LEVEL") is not None:
+        # Only use env var if level is still at default (logging.INFO)
+        # This allows CLI args to override env vars
+        if level == logging.INFO:
+            level = os.environ["OTF_LOG_LEVEL"]
+
     # If the task_id isn't set yet, then use the env var
     if not task_id:
         task_id = os.getenv("OTF_TASK_ID")
@@ -207,9 +213,6 @@ def init_logging(
 
     # Set verbosity
     otf_logger.setLevel(logging.getLogger().getEffectiveLevel())
-    # Ensure the logger is at least at INFO level
-    if otf_logger.getEffectiveLevel() > logging.INFO:
-        otf_logger.setLevel(logging.INFO)
 
     # If the log level is set in the environment, then use that
     if os.environ.get("OTF_LOG_LEVEL") is not None:
@@ -232,7 +235,8 @@ def init_logging(
         otf_logger.addHandler(tfh)
         tfh.setFormatter(formatter)
 
-    otf_logger.debug("Logging initialised")
+    if os.environ.get("OTF_LOG_INIT_EVENTS", None) == "1":
+        otf_logger.debug("Logging initialised")
 
     return otf_logger
 

tests/test_logging.py

@@ -147,6 +147,41 @@ def test_init_logging(env_vars, top_level_root_dir):
     assert len(logger.handlers) == 0
 
 
+def test_init_logging_logs_init_event_when_enabled(env_vars, tmpdir, caplog):
+    os.environ["OTF_LOG_DIRECTORY"] = str(tmpdir)
+    os.environ["OTF_LOG_LEVEL"] = "DEBUG"
+    os.environ["OTF_LOG_INIT_EVENTS"] = "1"
+
+    with caplog.at_level(logging.DEBUG):
+        logger = opentaskpy.otflogging.init_logging(
+            "some.class.init_events", task_id="some_task_id", task_type="B"
+        )
+
+    assert any(
+        record.getMessage() == "Logging initialised" for record in caplog.records
+    )
+
+    opentaskpy.otflogging.close_log_file(logger, True)
+
+
+def test_init_logging_env_log_level_sets_root_debug(env_vars):
+    root_logger = logging.getLogger()
+    original_level = root_logger.level
+    original_handlers = list(root_logger.handlers)
+
+    os.environ["OTF_LOG_LEVEL"] = "DEBUG"
+    os.environ["OTF_NO_LOG"] = "1"
+
+    opentaskpy.otflogging.init_logging(
+        "some.class.root_logger", task_id="some_task_id", override_root_logger=True
+    )
+
+    assert logging.getLogger().getEffectiveLevel() == logging.DEBUG
+
+    root_logger.setLevel(original_level)
+    root_logger.handlers = original_handlers
+
+
 def test_get_latest_log_file(env_vars):
     # Setup some dummy log files
     log_path = "test/testLogs"