Logging works with Click

.changes/unreleased/Under the Hood-20221017-170500.yaml

@@ -0,0 +1,7 @@
+kind: Under the Hood
+body: Click CLI supports logging
+time: 2022-10-17T17:05:00.478948-05:00
+custom:
+  Author: iknox-fa
+  Issue: "5530"
+  PR: "6088"

core/dbt/cli/main.py

@@ -6,6 +6,7 @@
 from dbt.adapters.factory import adapter_management
 from dbt.cli import params as p
 from dbt.cli.flags import Flags
+from dbt.events.functions import setup_event_logger
 from dbt.profiler import profiler
 from dbt.tracking import initialize_from_flags, track_run
 
@@ -36,6 +37,7 @@ def cli_runner():
 @p.fail_fast
 @p.log_cache_events
 @p.log_format
+@p.log_path
 @p.macro_debugging
 @p.partial_parse
 @p.print
@@ -55,6 +57,14 @@ def cli(ctx, **kwargs):
     """
     flags = Flags()
 
+    # Logging
+    # N.B. Legacy logger is not supported
+    setup_event_logger(
+        flags.LOG_PATH,
+        flags.LOG_FORMAT,
+        flags.USE_COLORS,
+        flags.DEBUG,
+    )
     # Tracking
     initialize_from_flags(flags.ANONYMOUS_USAGE_STATS, flags.PROFILES_DIR)
     ctx.with_resource(track_run(run_command=ctx.invoked_subcommand))
@@ -82,7 +92,6 @@ def cli(ctx, **kwargs):
 @p.fail_fast
 @p.full_refresh
 @p.indirect_selection
-@p.log_path
 @p.models
 @p.profile
 @p.profiles_dir
@@ -129,7 +138,6 @@ def docs(ctx, **kwargs):
 @p.compile_docs
 @p.defer
 @p.exclude
-@p.log_path
 @p.models
 @p.profile
 @p.profiles_dir
@@ -169,7 +177,6 @@ def docs_serve(ctx, **kwargs):
 @p.defer
 @p.exclude
 @p.full_refresh
-@p.log_path
 @p.models
 @p.parse_only
 @p.profile
@@ -259,7 +266,6 @@ def list(ctx, **kwargs):
 @cli.command("parse")
 @click.pass_context
 @p.compile_parse
-@p.log_path
 @p.profile
 @p.profiles_dir
 @p.project_dir
@@ -282,7 +288,6 @@ def parse(ctx, **kwargs):
 @p.exclude
 @p.fail_fast
 @p.full_refresh
-@p.log_path
 @p.models
 @p.profile
 @p.profiles_dir
@@ -320,7 +325,6 @@ def run_operation(ctx, **kwargs):
 @click.pass_context
 @p.exclude
 @p.full_refresh
-@p.log_path
 @p.models
 @p.profile
 @p.profiles_dir
@@ -393,7 +397,6 @@ def freshness(ctx, **kwargs):
 @p.exclude
 @p.fail_fast
 @p.indirect_selection
-@p.log_path
 @p.models
 @p.profile
 @p.profiles_dir

core/dbt/cli/params.py

@@ -131,7 +131,8 @@
     "--log-path",
     envvar="DBT_LOG_PATH",
     help="Configure the 'log-path'. Only applies this setting for the current run. Overrides the 'DBT_LOG_PATH' if it is set.",
-    type=click.Path(),
+    default=Path.cwd() / "logs",
+    type=click.Path(resolve_path=True, path_type=Path),
 )
 
 macro_debugging = click.option(

core/dbt/clients/system.py

@@ -1,30 +1,32 @@
 import errno
-import functools
 import fnmatch
+import functools
 import json
 import os
 import os.path
 import re
 import shutil
+import stat
 import subprocess
 import sys
 import tarfile
-import requests
-import stat
-from typing import Type, NoReturn, List, Optional, Dict, Any, Tuple, Callable, Union
-from pathspec import PathSpec  # type: ignore
+from pathlib import Path
+from typing import Any, Callable, Dict, List, NoReturn, Optional, Tuple, Type, Union
 
+import dbt.exceptions
+import requests
 from dbt.events.functions import fire_event
 from dbt.events.types import (
-    SystemErrorRetrievingModTime,
     SystemCouldNotWrite,
+    SystemErrorRetrievingModTime,
     SystemExecutingCmd,
-    SystemStdOutMsg,
-    SystemStdErrMsg,
     SystemReportReturnCode,
+    SystemStdErrMsg,
+    SystemStdOutMsg,
 )
-import dbt.exceptions
+from dbt.exceptions import InternalException
 from dbt.utils import _connection_exception_retry as connection_exception_retry
+from pathspec import PathSpec  # type: ignore
 
 if sys.platform == "win32":
     from ctypes import WinDLL, c_bool
@@ -106,12 +108,18 @@ def load_file_contents(path: str, strip: bool = True) -> str:
     return to_return
 
 
-def make_directory(path: str) -> None:
+@functools.singledispatch
+def make_directory(path=None) -> None:
     """
     Make a directory and any intermediate directories that don't already
     exist. This function handles the case where two threads try to create
     a directory at once.
     """
+    raise InternalException(f"Can not create directory from {type(path)} ")
+
+
+@make_directory.register
+def _(path: str) -> None:
     path = convert_path(path)
     if not os.path.exists(path):
         # concurrent writes that try to create the same dir can fail
@@ -125,6 +133,11 @@ def make_directory(path: str) -> None:
                 raise e
 
 
+@make_directory.register
+def _(path: Path) -> None:
+    path.mkdir(parents=True, exist_ok=True)
+
+
 def make_file(path: str, contents: str = "", overwrite: bool = False) -> bool:
     """
     Make a file at `path` assuming that the directory it resides in already

core/dbt/events/functions.py

@@ -1,63 +1,55 @@
 import betterproto
-from colorama import Style
-from dbt.events.base_types import NoStdOut, BaseEvent, NoFile, Cache
-from dbt.events.types import EventBufferFull, MainReportVersion, EmptyLine
-import dbt.flags as flags
-from dbt.constants import SECRET_ENV_PREFIX, METADATA_ENV_PREFIX
-
-from dbt.logger import make_log_dir_if_missing, GLOBAL_LOGGER
-from datetime import datetime
-import json
 import io
-from io import StringIO, TextIOWrapper
-import logbook
+import json
 import logging
-from logging import Logger
-import sys
-from logging.handlers import RotatingFileHandler
 import os
-import uuid
+import sys
 import threading
-from typing import List, Optional, Union, Callable, Dict
+import uuid
 from collections import deque
+from datetime import datetime
+from io import StringIO, TextIOWrapper
+from logging import Logger
+from logging.handlers import RotatingFileHandler
+from typing import Callable, Dict, List, Optional, Union
+
+import dbt.flags as flags
+import logbook
+from colorama import Style
+from dbt.constants import METADATA_ENV_PREFIX, SECRET_ENV_PREFIX
+from dbt.events.base_types import BaseEvent, Cache, NoFile, NoStdOut
+from dbt.events.types import EmptyLine, EventBufferFull, MainReportVersion
+from dbt.logger import make_log_dir_if_missing
 
-LOG_VERSION = 3
+# create the module-globals
+LOG_VERSION = 2
 EVENT_HISTORY = None
 
-# create the global file logger with no configuration
-FILE_LOG = logging.getLogger("default_file")
-null_handler = logging.NullHandler()
-FILE_LOG.addHandler(null_handler)
-
-# set up logger to go to stdout with defaults
-# setup_event_logger will be called once args have been parsed
-STDOUT_LOG = logging.getLogger("default_stdout")
-STDOUT_LOG.setLevel(logging.INFO)
-stdout_handler = logging.StreamHandler(sys.stdout)
-stdout_handler.setLevel(logging.INFO)
-STDOUT_LOG.addHandler(stdout_handler)
-
-format_color = True
-format_json = False
+DEFAULT_FILE_LOGGER_NAME = "default_file"
+FILE_LOG = logging.getLogger(DEFAULT_FILE_LOGGER_NAME)
+
+DEFAULT_STDOUT_LOGGER_NAME = "default_std_out"
+STDOUT_LOG = logging.getLogger(DEFAULT_STDOUT_LOGGER_NAME)
+
 invocation_id: Optional[str] = None
 metadata_vars: Optional[Dict[str, str]] = None
 
 
-def setup_event_logger(log_path, level_override=None):
-    global format_json, format_color, STDOUT_LOG, FILE_LOG
+def setup_event_logger(log_path, log_format, use_colors, debug):
+    global FILE_LOG
+    global STDOUT_LOG
+
     make_log_dir_if_missing(log_path)
 
-    format_json = flags.LOG_FORMAT == "json"
-    # USE_COLORS can be None if the app just started and the cli flags
-    # havent been applied yet
-    format_color = True if flags.USE_COLORS else False
     # TODO this default should live somewhere better
     log_dest = os.path.join(log_path, "dbt.log")
-    level = level_override or (logging.DEBUG if flags.DEBUG else logging.INFO)
+    level = logging.DEBUG if debug else logging.INFO
 
     # overwrite the STDOUT_LOG logger with the configured one
     STDOUT_LOG = logging.getLogger("configured_std_out")
     STDOUT_LOG.setLevel(level)
+    setattr(STDOUT_LOG, "format_json", log_format == "json")
+    setattr(STDOUT_LOG, "format_color", True if use_colors else False)
 
     FORMAT = "%(message)s"
     stdout_passthrough_formatter = logging.Formatter(fmt=FORMAT)
@@ -76,6 +68,8 @@ def setup_event_logger(log_path, level_override=None):
     # overwrite the FILE_LOG logger with the configured one
     FILE_LOG = logging.getLogger("configured_file")
     FILE_LOG.setLevel(logging.DEBUG)  # always debug regardless of user input
+    setattr(FILE_LOG, "format_json", log_format == "json")
+    setattr(FILE_LOG, "format_color", True if use_colors else False)
 
     file_passthrough_formatter = logging.Formatter(fmt=FORMAT)
 
@@ -93,7 +87,7 @@ def capture_stdout_logs() -> StringIO:
     global STDOUT_LOG
     capture_buf = io.StringIO()
     stdout_capture_handler = logging.StreamHandler(capture_buf)
-    stdout_handler.setLevel(logging.DEBUG)
+    stdout_capture_handler.setLevel(logging.DEBUG)
     STDOUT_LOG.addHandler(stdout_capture_handler)
     return capture_buf
 
@@ -146,8 +140,7 @@ def event_to_dict(event: BaseEvent) -> dict:
 # translates an Event to a completely formatted text-based log line
 # type hinting everything as strings so we don't get any unintentional string conversions via str()
 def reset_color() -> str:
-    global format_color
-    return "" if not format_color else Style.RESET_ALL
+    return Style.RESET_ALL if getattr(STDOUT_LOG, "format_color", False) else ""
 
 
 def create_info_text_log_line(e: BaseEvent) -> str:
@@ -189,8 +182,27 @@ def create_json_log_line(e: BaseEvent) -> Optional[str]:
 
 # calls create_stdout_text_log_line() or create_json_log_line() according to logger config
 def create_log_line(e: BaseEvent, file_output=False) -> Optional[str]:
-    global format_json
-    if format_json:
+    global FILE_LOG
+    global STDOUT_LOG
+
+    if FILE_LOG.name == DEFAULT_FILE_LOGGER_NAME and STDOUT_LOG.name == DEFAULT_STDOUT_LOGGER_NAME:
+
+        # TODO: This is only necessary because our test framework doesn't correctly set up logging.
+        # This code should be moved to the test framework when we do CT-XXX (tix # needed)
+        null_handler = logging.NullHandler()
+        FILE_LOG.addHandler(null_handler)
+        setattr(FILE_LOG, "format_json", False)
+        setattr(FILE_LOG, "format_color", False)
+
+        stdout_handler = logging.StreamHandler(sys.stdout)
+        stdout_handler.setLevel(logging.INFO)
+        STDOUT_LOG.setLevel(logging.INFO)
+        STDOUT_LOG.addHandler(stdout_handler)
+        setattr(STDOUT_LOG, "format_json", False)
+        setattr(STDOUT_LOG, "format_color", False)
+
+    logger = FILE_LOG if file_output else STDOUT_LOG
+    if getattr(logger, "format_json"):
         return create_json_log_line(e)  # json output, both console and file
     elif file_output is True or flags.DEBUG:
         return create_debug_text_log_line(e)  # default file output
@@ -238,15 +250,6 @@ def fire_event(e: BaseEvent) -> None:
 
     add_to_event_history(e)
 
-    # backwards compatibility for plugins that require old logger (dbt-rpc)
-    if flags.ENABLE_LEGACY_LOGGER:
-        # using Event::message because the legacy logger didn't differentiate messages by
-        # destination
-        log_line = create_log_line(e)
-        if log_line:
-            send_to_logger(GLOBAL_LOGGER, e.level_tag(), log_line)
-        return  # exit the function to avoid using the current logger as well
-
     # always logs debug level regardless of user input
     if not isinstance(e, NoFile):
         log_line = create_log_line(e, file_output=True)

core/dbt/main.py

@@ -211,9 +211,7 @@ def run_from_args(parsed):
     if task.config is not None:
         log_path = getattr(task.config, "log_path", None)
     log_manager.set_path(log_path)
-    # if 'list' task: set stdout to WARN instead of INFO
-    level_override = parsed.cls.pre_init_hook(parsed)
-    setup_event_logger(log_path or "logs", level_override)
+    setup_event_logger(log_path or "logs", "json", False, True)
 
     fire_event(MainReportVersion(version=str(dbt.version.installed), log_version=LOG_VERSION))
     fire_event(MainReportArgs(args=args_to_dict(parsed)))

core/dbt/tests/fixtures/project.py

@@ -456,7 +456,7 @@ def project(
     # Logbook warnings are ignored so we don't have to fork logbook to support python 3.10.
     # This _only_ works for tests in `tests/` that use the project fixture.
     warnings.filterwarnings("ignore", category=DeprecationWarning, module="logbook")
-    setup_event_logger(logs_dir)
+    setup_event_logger(logs_dir, "json", False, False)
     orig_cwd = os.getcwd()
     os.chdir(project_root)
     # Return whatever is needed later in tests but can only come from fixtures, so we can keep

test/integration/base.py

@@ -313,7 +313,7 @@ def setUp(self):
         os.chdir(self.initial_dir)
         # before we go anywhere, collect the initial path info
         self._logs_dir = os.path.join(self.initial_dir, 'logs', self.prefix)
-        setup_event_logger(self._logs_dir)
+        setup_event_logger(self._logs_dir, None, False, True)
         _really_makedirs(self._logs_dir)
         self.test_original_source_path = _pytest_get_test_root()
         self.test_root_dir = self._generate_test_root_dir()

test/unit/test_system_client.py

@@ -53,6 +53,17 @@ def test__make_file_with_overwrite(self):
         self.assertTrue(written)
         self.assertEqual(self.get_profile_text(), 'NEW_TEXT')
 
+    def test__make_dir_from_str(self):
+        test_dir_str = self.tmp_dir + "/test_make_from_str/sub_dir"
+        dbt.clients.system.make_directory(test_dir_str)
+        self.assertTrue(Path(test_dir_str).is_dir())
+
+    def test__make_dir_from_pathobj(self):
+        test_dir_pathobj = Path(self.tmp_dir + "/test_make_from_pathobj/sub_dir")
+        dbt.clients.system.make_directory(test_dir_pathobj)
+        self.assertTrue(test_dir_pathobj.is_dir())
+
+
 
 class TestRunCmd(unittest.TestCase):
     """Test `run_cmd`.