Make logging calls lighter

* Call set_lowest_log_level_by_opts with set_logging_options_dict

* Fix the _logging test with setting minimum logging level

* Fix test_deferred_stream_handler test

* Fix vt.Terminal failing test: test_log_sanitize

Fixes failing test added in a09b4f4

We can't assume tests are run at debug level, so this ensures the test
passes regardless of what logging level is currently set by capturing
the output in caplog at DEBUG which stream_stdout/stream_stderr uses by
default.

Signed-off-by: Joe Groocock <[email protected]>

---------

Signed-off-by: Joe Groocock <[email protected]>
Co-authored-by: Joe Groocock <[email protected]>

salt/_logging/impl.py

@@ -426,6 +426,7 @@ def set_logging_options_dict(opts):
     except AttributeError:
         pass
     set_logging_options_dict.__options_dict__ = opts
+    set_lowest_log_level_by_opts(opts)
 
 
 def freeze_logging_options_dict():

tests/pytests/integration/_logging/test_logging.py

@@ -0,0 +1,106 @@
+import logging
+import os
+
+import pytest
+
+import salt._logging.impl as log_impl
+from tests.support.mock import MagicMock, patch
+
+pytestmark = [
+    pytest.mark.skip_on_windows(reason="Temporarily skipped on the newer golden images")
+]
+
+
+log = logging.getLogger(__name__)
+
+
+@pytest.fixture
+def configure_loader_modules():
+    return {log_impl: {}}
+
+
+def log_nameToLevel(name):
+    """
+    Return the numeric representation of textual logging level
+    """
+    # log level values
+    CRITICAL = 50
+    FATAL = CRITICAL
+    ERROR = 40
+    WARNING = 30
+    WARN = WARNING
+    INFO = 20
+    DEBUG = 10
+    NOTSET = 0
+
+    _nameToLevel = {
+        "CRITICAL": CRITICAL,
+        "FATAL": FATAL,
+        "ERROR": ERROR,
+        "WARN": WARNING,
+        "WARNING": WARNING,
+        "INFO": INFO,
+        "DEBUG": DEBUG,
+        "NOTSET": NOTSET,
+    }
+    return _nameToLevel.get(name, None)
+
+
+def test_lowest_log_level():
+    ret = log_impl.get_lowest_log_level()
+    assert ret is not None
+
+    log_impl.set_lowest_log_level(log_nameToLevel("DEBUG"))
+    ret = log_impl.get_lowest_log_level()
+    assert ret is log_nameToLevel("DEBUG")
+
+    log_impl.set_lowest_log_level(log_nameToLevel("WARNING"))
+    ret = log_impl.get_lowest_log_level()
+    assert ret is log_nameToLevel("WARNING")
+
+    opts = {"log_level": "ERROR", "log_level_logfile": "INFO"}
+    log_impl.set_lowest_log_level_by_opts(opts)
+    ret = log_impl.get_lowest_log_level()
+    assert ret is log_nameToLevel("INFO")
+
+
+def test_get_logging_level_from_string(caplog):
+    ret = log_impl.get_logging_level_from_string(None)
+    assert ret is log_nameToLevel("WARNING")
+
+    ret = log_impl.get_logging_level_from_string(log_nameToLevel("DEBUG"))
+    assert ret is log_nameToLevel("DEBUG")
+
+    ret = log_impl.get_logging_level_from_string("CRITICAL")
+    assert ret is log_nameToLevel("CRITICAL")
+
+    caplog.clear()
+    with caplog.at_level(logging.WARNING):
+        msg = "Could not translate the logging level string 'BADLEVEL' into an actual logging level integer. Returning 'logging.ERROR'."
+        ret = log_impl.get_logging_level_from_string("BADLEVEL")
+        assert ret is log_nameToLevel("ERROR")
+        assert msg in caplog.text
+
+
+def test_logfile_handler(caplog):
+    caplog.clear()
+    with caplog.at_level(logging.WARNING):
+        ret = log_impl.is_logfile_handler_configured()
+        assert ret is False
+
+        msg = "log_path setting is set to `None`. Nothing else to do"
+        log_path = None
+        assert log_impl.setup_logfile_handler(log_path) is None
+        assert msg in caplog.text
+
+
+def test_in_mainprocess():
+    ret = log_impl.in_mainprocess()
+    assert ret is True
+
+    curr_pid = os.getpid()
+    with patch(
+        "os.getpid", MagicMock(side_effect=[AttributeError, curr_pid, curr_pid])
+    ):
+        ret = log_impl.in_mainprocess()
+        assert ret is True

tests/pytests/unit/_logging/handlers/test_deferred_stream_handler.py

@@ -9,6 +9,7 @@
 from pytestshellutils.utils.processes import terminate_process
 
 from salt._logging.handlers import DeferredStreamHandler
+from salt._logging.impl import set_lowest_log_level
 from salt.utils.nb_popen import NonBlockingPopen
 from tests.support.helpers import CaptureOutput, dedent
 from tests.support.runtests import RUNTIME_VARS
@@ -20,7 +21,7 @@ def _sync_with_handlers_proc_target():
 
     with CaptureOutput() as stds:
         handler = DeferredStreamHandler(sys.stderr)
-        handler.setLevel(logging.DEBUG)
+        set_lowest_log_level(logging.DEBUG)
         formatter = logging.Formatter("%(message)s")
         handler.setFormatter(formatter)
         logging.root.addHandler(handler)
@@ -45,7 +46,7 @@ def _deferred_write_on_flush_proc_target():
 
     with CaptureOutput() as stds:
         handler = DeferredStreamHandler(sys.stderr)
-        handler.setLevel(logging.DEBUG)
+        set_lowest_log_level(logging.DEBUG)
         formatter = logging.Formatter("%(message)s")
         handler.setFormatter(formatter)
         logging.root.addHandler(handler)
@@ -126,7 +127,7 @@ def test_deferred_write_on_atexit(tmp_path):
         # Just loop consuming output
         while True:
             if time.time() > max_time:
-                pytest.fail("Script didn't exit after {} second".format(execution_time))
+                pytest.fail(f"Script didn't exit after {execution_time} second")
 
             time.sleep(0.125)
             _out = proc.recv()
@@ -146,7 +147,7 @@ def test_deferred_write_on_atexit(tmp_path):
     finally:
         terminate_process(proc.pid, kill_children=True)
     if b"Foo" not in err:
-        pytest.fail("'Foo' should be in stderr and it's not: {}".format(err))
+        pytest.fail(f"'Foo' should be in stderr and it's not: {err}")
 
 
 @pytest.mark.skip_on_windows(reason="Windows does not support SIGINT")

tests/pytests/unit/utils/test_vt.py

@@ -1,3 +1,4 @@
+import logging
 import os
 import signal
 
@@ -43,10 +44,13 @@ def test_log_sanitize(test_cmd, caplog):
         cmd,
         log_stdout=True,
         log_stderr=True,
+        log_stdout_level="debug",
+        log_stderr_level="debug",
         log_sanitize=password,
         stream_stdout=False,
         stream_stderr=False,
     )
-    ret = term.recv()
+    with caplog.at_level(logging.DEBUG):
+        ret = term.recv()
     assert password not in caplog.text
     assert "******" in caplog.text