Fixes for Tribler logger

src/run_tribler.py

@@ -10,6 +10,7 @@
 
 from PyQt5.QtCore import QSettings
 
+from tribler_common.logger import load_logger_config
 from tribler_common.process_checker import ProcessChecker
 from tribler_common.sentry_reporter.sentry_reporter import SentryReporter, SentryStrategy
 from tribler_common.sentry_reporter.sentry_scrubber import SentryScrubber
@@ -83,12 +84,11 @@ def init_boot_logger():
 
     # Check whether we need to start the core or the user interface
     if parsed_args.mode in (RunMode.CORE_ONLY, RunMode.GUI_TEST_MODE):
-        from tribler_core.check_os import  should_kill_other_tribler_instances
+        from tribler_core.check_os import should_kill_other_tribler_instances
 
         should_kill_other_tribler_instances(root_state_dir)
         logger.info('Running in "core" mode')
-        import tribler_core
-        tribler_core.load_logger_config(root_state_dir)
+        load_logger_config('tribler-core', root_state_dir)
 
         # Check if we are already running a Tribler instance
         process_checker = ProcessChecker(root_state_dir)
@@ -117,7 +117,7 @@ def init_boot_logger():
             os.environ["QT_MAC_WANTS_LAYER"] = "1"
 
         # Set up logging
-        tribler_gui.load_logger_config(root_state_dir)
+        load_logger_config('tribler-gui', root_state_dir)
 
         from tribler_core.check_os import (
             check_and_enable_code_tracing,

src/tribler-common/tribler_common/logger.py

@@ -0,0 +1,67 @@
+import logging
+import logging.config
+import sys
+from pathlib import Path
+
+import yaml
+
+LOG_CONFIG_FILENAME = 'logger.yaml'
+
+
+logger = logging.getLogger(__name__)
+
+
+# note: this class is used by src/tribler-common/tribler_common/logger.yaml
+class StdoutFilter(logging.Filter):
+    def filter(self, record):
+        return record.levelno < logging.ERROR
+
+
+def load_logger_config(app_mode, log_dir):
+    """
+    Loads tribler-gui module logger configuration. Note that this function should be called explicitly to
+    enable GUI logs dump to a file in the log directory (default: inside state directory).
+    """
+    logger_config_path = get_logger_config_path()
+    setup_logging(app_mode, Path(log_dir), logger_config_path)
+
+
+def get_logger_config_path():
+    if not hasattr(sys, '_MEIPASS'):
+        dirname = Path(__file__).absolute().parent
+    else:
+        dirname = Path(getattr(sys, '_MEIPASS'), "tribler_source", "tribler_common")
+    return dirname / LOG_CONFIG_FILENAME
+
+
+def setup_logging(app_mode, log_dir: Path, config_path: Path):
+    """
+    Setup logging configuration with the given YAML file.
+    """
+    logger.info(f'Load logger config: app_mode={app_mode}, config_path={config_path}, dir={log_dir}')
+    if not config_path.exists():
+        print(f'Logger config not found in {config_path}. Using default configs.', file=sys.stderr)
+        logging.basicConfig(level=logging.INFO, stream=sys.stdout)
+        return
+
+    try:
+        # Update the log file paths in the config
+        module_info_log_file = log_dir.joinpath(f"{app_mode}-info.log")
+        module_error_log_file = log_dir.joinpath(f"{app_mode}-error.log")
+
+        with config_path.open() as f:
+            config_text = f.read()
+
+        config_text = config_text.replace('TRIBLER_INFO_LOG_FILE', str(module_info_log_file))
+        config_text = config_text.replace('TRIBLER_ERROR_LOG_FILE', str(module_error_log_file))
+
+        # Create log directory if it does not exist
+        if not log_dir.exists():
+            log_dir.mkdir(parents=True)
+
+        config = yaml.safe_load(config_text)
+        logging.config.dictConfig(config)
+        logger.info(f'Config loaded for app_mode={app_mode}')
+    except Exception as e:  # pylint: disable=broad-except
+        print('Error in loading logger config. Using default configs. Error:', e, file=sys.stderr)
+        logging.basicConfig(level=logging.INFO, stream=sys.stdout)

src/tribler-gui/tribler_gui/logger.yaml → src/tribler-common/tribler_common/logger.yaml

@@ -1,13 +1,10 @@
-# File: tribler_gui/logger.yaml
-# Look to tribler_common/logger/config.yaml for description and example configuration.
+# File: tribler_core/logger.yaml
 
 version: 1
 disable_existing_loggers: false
 filters:
-    info_filter:
-        () : tribler_common.logger.InfoFilter
-    error_filter:
-        (): tribler_common.logger.ErrorFilter
+    stdout_filter:
+        () : tribler_common.logger.StdoutFilter
 
 # Logging formatter
 formatters:
@@ -48,14 +45,14 @@ handlers:
         target: error_file_handler
         capacity: 1024
 
-    console:
+    stdout_handler:
         class: logging.StreamHandler
-        level: DEBUG
+        level: INFO
         formatter: standard
-        filters: [info_filter]
+        filters: [stdout_filter]
         stream: ext://sys.stdout
 
-    error_console:
+    stderr_handler:
         class: logging.StreamHandler
         level: ERROR
         formatter: error
@@ -64,12 +61,11 @@ handlers:
 # Root Logger Configuration
 root:
     level: NOTSET
-    handlers: [console, error_console, info_memory_handler, error_memory_handler]
-    propagate: yes
+    handlers: [stdout_handler, stderr_handler, info_memory_handler, error_memory_handler]
 
-# Module level configuration
-loggers:
-    TriblerGUI:
-        level: INFO
-        handlers: [console, error_console, info_memory_handler, error_memory_handler]
-        propagate: no
+# Module level configuration:
+# The following is an example of how you can reduce the verbosity of some specific loggers:
+#
+# loggers:
+#    TriblerTunnelCommunity:
+#        level: WARNING

src/tribler-common/tribler_common/tests/test_logger.py

@@ -0,0 +1,85 @@
+import logging
+from unittest.mock import MagicMock, Mock, call, patch
+
+from tribler_common.logger import get_logger_config_path, setup_logging
+
+
+@patch('tribler_common.logger.__file__', '/a/b/c/logger.py')
+def test_get_logger_config_path():
+    config_path = get_logger_config_path()
+    # take the last part of the path to ignore a drive name on Windows
+    assert config_path.parts[-4:] == ('a', 'b', 'c', 'logger.yaml')
+
+    with patch('sys._MEIPASS', '/x/y/z/', create=True):
+        config_path = get_logger_config_path()
+        assert config_path.parts[-6:] == ('x', 'y', 'z', 'tribler_source', 'tribler_common', 'logger.yaml')
+
+
+@patch('tribler_common.logger.logger')
+@patch('sys.stdout')
+@patch('sys.stderr')
+@patch('builtins.print')
+@patch('logging.basicConfig')
+def test_setup_logging_no_config(basic_config: Mock, print_: Mock, stderr: Mock, stdout: Mock, logger: Mock):
+    config_path = MagicMock()
+    config_path.exists.return_value = False
+    config_path.__str__.return_value = '<config-path>'
+
+    setup_logging('<app-mode>', '<log-dir>', config_path)
+
+    logger.info.assert_called_once_with("Load logger config: app_mode=<app-mode>, "
+                                        "config_path=<config-path>, dir=<log-dir>")
+    print_.assert_called_once_with("Logger config not found in <config-path>. Using default configs.", file=stderr)
+    basic_config.assert_called_once_with(level=logging.INFO, stream=stdout)
+
+
+@patch('yaml.safe_load')
+@patch('logging.config.dictConfig')
+@patch('tribler_common.logger.logger')
+def test_setup_logging(logger: Mock, dict_config: Mock, yaml_safe_load: Mock):
+    log_dir = MagicMock()
+    log_dir.__str__.return_value = '<log-dir>'
+    log_dir.exists.return_value = False
+
+    config_path = MagicMock()
+    config_path.__str__.return_value = '<config-path>'
+    config_path.exists.return_value = True
+    config_path.open().__enter__().read().replace().replace.return_value = '<config-text>'
+
+    yaml_safe_load.return_value = '<config>'
+
+    setup_logging('<app-mode>', log_dir, config_path)
+
+    log_dir.mkdir.assert_called_once_with(parents=True)
+
+    yaml_safe_load.assert_called_once_with('<config-text>')
+    dict_config.assert_called_once_with('<config>')
+    assert logger.info.call_count == 2
+    logger.info.assert_has_calls([
+        call('Load logger config: app_mode=<app-mode>, config_path=<config-path>, dir=<log-dir>'),
+        call("Config loaded for app_mode=<app-mode>")
+    ])
+
+@patch('tribler_common.logger.logger')
+@patch('sys.stdout')
+@patch('sys.stderr')
+@patch('builtins.print')
+@patch('logging.basicConfig')
+def test_setup_logging_exception(basic_config: Mock, print_: Mock, stderr: Mock, stdout: Mock, logger: Mock):
+    error = ZeroDivisionError()
+
+    log_dir = MagicMock()
+    log_dir.__str__.return_value = '<log-dir>'
+    log_dir.exists.return_value = True
+    log_dir.joinpath.side_effect = error
+
+    config_path = MagicMock()
+    config_path.__str__.return_value = '<config-path>'
+    config_path.exists.return_value = True
+
+    setup_logging('<app-mode>', log_dir, config_path)
+
+    logger.info.assert_called_once_with("Load logger config: app_mode=<app-mode>, "
+                                        "config_path=<config-path>, dir=<log-dir>")
+    print_.assert_called_once_with('Error in loading logger config. Using default configs. Error:', error, file=stderr)
+    basic_config.assert_called_once_with(level=logging.INFO, stream=stdout)