diff --git a/.changes/unreleased/Features-20230107-003157.yaml b/.changes/unreleased/Features-20230107-003157.yaml new file mode 100644 index 00000000000..27858b516be --- /dev/null +++ b/.changes/unreleased/Features-20230107-003157.yaml @@ -0,0 +1,6 @@ +kind: Features +body: Have dbt debug spit out structured json logs with flags enabled. +time: 2023-01-07T00:31:57.516063-08:00 +custom: + Author: versusfacit + Issue: "5353" diff --git a/core/dbt/compilation.py b/core/dbt/compilation.py index c0237b0a993..a89f36d9f31 100644 --- a/core/dbt/compilation.py +++ b/core/dbt/compilation.py @@ -1,11 +1,12 @@ -import os -from collections import defaultdict -from typing import List, Dict, Any, Tuple, Optional - +import argparse import networkx as nx # type: ignore +import os import pickle import sqlparse +from collections import defaultdict +from typing import List, Dict, Any, Tuple, Optional + from dbt import flags from dbt.adapters.factory import get_adapter from dbt.clients import jinja @@ -32,6 +33,7 @@ from dbt.node_types import NodeType, ModelLanguage from dbt.events.format import pluralize import dbt.tracking +import dbt.task.list as list_task graph_file_name = "graph.gpickle" @@ -473,7 +475,13 @@ def compile(self, manifest: Manifest, write=True, add_test_edges=False) -> Graph if write: self.write_graph_file(linker, manifest) - print_compile_stats(stats) + + # Do not print these for ListTask's + if not ( + self.config.args.__class__ == argparse.Namespace + and self.config.args.cls == list_task.ListTask + ): + print_compile_stats(stats) return Graph(linker.graph) diff --git a/core/dbt/events/proto_types.py b/core/dbt/events/proto_types.py index 3fb92eeda51..0bae4be273f 100644 --- a/core/dbt/events/proto_types.py +++ b/core/dbt/events/proto_types.py @@ -1,5 +1,5 @@ # Generated by the protocol buffer compiler. DO NOT EDIT! -# sources: types.proto +# sources: core/dbt/events/types.proto # plugin: python-betterproto from dataclasses import dataclass from datetime import datetime @@ -2847,6 +2847,45 @@ class RunResultWarningMessageMsg(betterproto.Message): data: "RunResultWarningMessage" = betterproto.message_field(2) +@dataclass +class DebugCmdOut(betterproto.Message): + """Z047""" + + msg: str = betterproto.string_field(1) + + +@dataclass +class DebugCmdOutMsg(betterproto.Message): + info: "EventInfo" = betterproto.message_field(1) + data: "DebugCmdOut" = betterproto.message_field(2) + + +@dataclass +class DebugCmdResult(betterproto.Message): + """Z048""" + + msg: str = betterproto.string_field(1) + + +@dataclass +class DebugCmdResultMsg(betterproto.Message): + info: "EventInfo" = betterproto.message_field(1) + data: "DebugCmdResult" = betterproto.message_field(2) + + +@dataclass +class ListCmdOut(betterproto.Message): + """Z049""" + + msg: str = betterproto.string_field(1) + + +@dataclass +class ListCmdOutMsg(betterproto.Message): + info: "EventInfo" = betterproto.message_field(1) + data: "ListCmdOut" = betterproto.message_field(2) + + @dataclass class IntegrationTestInfo(betterproto.Message): """T001""" diff --git a/core/dbt/events/types.proto b/core/dbt/events/types.proto index 87a10c19eda..fc251042005 100644 --- a/core/dbt/events/types.proto +++ b/core/dbt/events/types.proto @@ -2258,6 +2258,37 @@ message RunResultWarningMessageMsg { RunResultWarningMessage data = 2; } +// Z047 +message DebugCmdOut { + string msg = 1; +} + +message DebugCmdOutMsg { + EventInfo info = 1; + DebugCmdOut data = 2; +} + +// Z048 +message DebugCmdResult { + string msg = 1; +} + +message DebugCmdResultMsg { + EventInfo info = 1; + DebugCmdResult data = 2; +} + +// Z049 +message ListCmdOut { + string msg = 1; +} + +message ListCmdOutMsg { + EventInfo info = 1; + ListCmdOut data = 2; +} + + // T - Integration tests // T001 diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 043ed8d40ff..e74327be179 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -2345,3 +2345,30 @@ def code(self): def message(self) -> str: # This is the message on the result object, cannot be formatted in event return self.msg + + +@dataclass +class DebugCmdOut(InfoLevel, pt.DebugCmdOut): + def code(self): + return "Z047" + + def message(self) -> str: + return self.msg + + +@dataclass +class DebugCmdResult(InfoLevel, pt.DebugCmdResult): + def code(self): + return "Z048" + + def message(self) -> str: + return self.msg + + +@dataclass +class ListCmdOut(InfoLevel, pt.ListCmdOut): + def code(self): + return "Z049" + + def message(self) -> str: + return self.msg diff --git a/core/dbt/main.py b/core/dbt/main.py index a6c6f0b013d..429d823be52 100644 --- a/core/dbt/main.py +++ b/core/dbt/main.py @@ -229,15 +229,15 @@ 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") - fire_event(MainReportVersion(version=str(dbt.version.installed), log_version=LOG_VERSION)) - fire_event(MainReportArgs(args=args_to_dict(parsed))) + # For the ListTask, filter out system report logs to allow piping ls output to jq, etc + if not list_task.ListTask == parsed.cls: + fire_event(MainReportVersion(version=str(dbt.version.installed), log_version=LOG_VERSION)) + fire_event(MainReportArgs(args=args_to_dict(parsed))) - if dbt.tracking.active_user is not None: # mypy appeasement, always true - fire_event(MainTrackingUserState(user_state=dbt.tracking.active_user.state())) + if dbt.tracking.active_user is not None: # mypy appeasement, always true + fire_event(MainTrackingUserState(user_state=dbt.tracking.active_user.state())) results = None diff --git a/core/dbt/task/debug.py b/core/dbt/task/debug.py index 5f3e3854759..7460c08cc84 100644 --- a/core/dbt/task/debug.py +++ b/core/dbt/task/debug.py @@ -5,7 +5,11 @@ from typing import Optional, Dict, Any, List from dbt.events.functions import fire_event -from dbt.events.types import OpenCommand +from dbt.events.types import ( + OpenCommand, + DebugCmdOut, + DebugCmdResult, +) from dbt import flags import dbt.clients.system import dbt.exceptions @@ -99,25 +103,25 @@ def run(self): return not self.any_failure version = get_installed_version().to_version_string(skip_matcher=True) - print("dbt version: {}".format(version)) - print("python version: {}".format(sys.version.split()[0])) - print("python path: {}".format(sys.executable)) - print("os info: {}".format(platform.platform())) - print("Using profiles.yml file at {}".format(self.profile_path)) - print("Using dbt_project.yml file at {}".format(self.project_path)) - print("") + fire_event(DebugCmdOut(msg="dbt version: {}".format(version))) + fire_event(DebugCmdOut(msg="python version: {}".format(sys.version.split()[0]))) + fire_event(DebugCmdOut(msg="python path: {}".format(sys.executable))) + fire_event(DebugCmdOut(msg="os info: {}".format(platform.platform()))) + fire_event(DebugCmdOut(msg="Using profiles.yml file at {}".format(self.profile_path))) + fire_event(DebugCmdOut(msg="Using dbt_project.yml file at {}".format(self.project_path))) self.test_configuration() self.test_dependencies() self.test_connection() if self.any_failure: - print(red(f"{(pluralize(len(self.messages), 'check'))} failed:")) + fire_event( + DebugCmdResult(msg=red(f"{(pluralize(len(self.messages), 'check'))} failed:")) + ) else: - print(green("All checks passed!")) + fire_event(DebugCmdResult(msg=green("All checks passed!"))) for message in self.messages: - print(message) - print("") + fire_event(DebugCmdResult(msg=f"{message}\n")) return not self.any_failure @@ -273,21 +277,33 @@ def test_git(self): return green("OK found") def test_dependencies(self): - print("Required dependencies:") - print(" - git [{}]".format(self.test_git())) - print("") + fire_event(DebugCmdOut(msg="Required dependencies:")) + + logline_msg = self.test_git() + fire_event(DebugCmdResult(msg=f" - git [{logline_msg}]\n")) def test_configuration(self): + fire_event(DebugCmdOut(msg="Configuration:")) + profile_status = self._load_profile() + fire_event(DebugCmdOut(msg=f" profiles.yml file [{profile_status}]")) + project_status = self._load_project() - print("Configuration:") - print(" profiles.yml file [{}]".format(profile_status)) - print(" dbt_project.yml file [{}]".format(project_status)) + fire_event(DebugCmdOut(msg=f" dbt_project.yml file [{project_status}]")) + # skip profile stuff if we can't find a profile name if self.profile_name is not None: - print(" profile: {} [{}]".format(self.profile_name, self._profile_found())) - print(" target: {} [{}]".format(self.target_name, self._target_found())) - print("") + fire_event( + DebugCmdOut( + msg=" profile: {} [{}]\n".format(self.profile_name, self._profile_found()) + ) + ) + fire_event( + DebugCmdOut( + msg=" target: {} [{}]\n".format(self.target_name, self._target_found()) + ) + ) + self._log_project_fail() self._log_profile_fail() @@ -348,11 +364,12 @@ def _connection_result(self): def test_connection(self): if not self.profile: return - print("Connection:") + fire_event(DebugCmdOut(msg="Connection:")) for k, v in self.profile.credentials.connection_info(): - print(" {}: {}".format(k, v)) - print(" Connection test: [{}]".format(self._connection_result())) - print("") + fire_event(DebugCmdOut(msg=f" {k}: {v}")) + + res = self._connection_result() + fire_event(DebugCmdOut(msg=f" Connection test: [{res}]\n")) @classmethod def validate_connection(cls, target_dict): diff --git a/core/dbt/task/list.py b/core/dbt/task/list.py index fa8d3ccd8d2..411bed3da4c 100644 --- a/core/dbt/task/list.py +++ b/core/dbt/task/list.py @@ -1,15 +1,21 @@ import json +import dbt.flags + from dbt.contracts.graph.nodes import Exposure, SourceDefinition, Metric from dbt.graph import ResourceTypeSelector from dbt.task.runnable import GraphRunnableTask, ManifestTask from dbt.task.test import TestSelector from dbt.node_types import NodeType -from dbt.events.functions import warn_or_error -from dbt.events.types import NoNodesSelected +from dbt.events.functions import ( + fire_event, + warn_or_error, +) +from dbt.events.types import ( + NoNodesSelected, + ListCmdOut, +) from dbt.exceptions import DbtRuntimeError, DbtInternalError -from dbt.logger import log_manager -from dbt.events.eventmgr import EventLevel class ListTask(GraphRunnableTask): @@ -50,20 +56,6 @@ def __init__(self, args, config): '"models" and "resource_type" are mutually exclusive ' "arguments" ) - @classmethod - def pre_init_hook(cls, args): - """A hook called before the task is initialized.""" - # Filter out all INFO-level logging to allow piping ls output to jq, etc - # WARN level will still include all warnings + errors - # Do this by: - # - returning the log level so that we can pass it into the 'level_override' - # arg of events.functions.setup_event_logger() -- good! - # - mutating the initialized, not-yet-configured STDOUT event logger - # because it's being configured too late -- bad! TODO refactor! - log_manager.stderr_console() - super().pre_init_hook(args) - return EventLevel.WARN - def _iterate_selected_nodes(self): selector = self.get_node_selector() spec = self.get_selection_spec() @@ -148,9 +140,14 @@ def run(self): return self.output_results(generator()) def output_results(self, results): + """Log, or output a plain, newline-delimited, and ready-to-pipe list of nodes found.""" for result in results: self.node_results.append(result) - print(result) + if dbt.flags.LOG_FORMAT == "json": + fire_event(ListCmdOut(msg=result)) + else: + # Cleaner to leave as print than to mutate the logger not to print timestamps. + print(result) return self.node_results @property diff --git a/test/unit/test_graph.py b/test/unit/test_graph.py index 5534fe21f19..3f330717608 100644 --- a/test/unit/test_graph.py +++ b/test/unit/test_graph.py @@ -59,6 +59,7 @@ def setUp(self): # Create file filesystem searcher self.filesystem_search = patch('dbt.parser.read_files.filesystem_search') + def mock_filesystem_search(project, relative_dirs, extension, ignore_spec): if 'sql' not in extension: return [] @@ -72,6 +73,7 @@ def mock_filesystem_search(project, relative_dirs, extension, ignore_spec): self.hook_patcher = patch.object( dbt.parser.hooks.HookParser, '__new__' ) + def create_hook_patcher(cls, project, manifest, root_project): result = MagicMock(project=project, manifest=manifest, root_project=root_project) result.__iter__.side_effect = lambda: iter([]) @@ -82,7 +84,6 @@ def create_hook_patcher(cls, project, manifest, root_project): # Create the Manifest.state_check patcher @patch('dbt.parser.manifest.ManifestLoader.build_manifest_state_check') def _mock_state_check(self): - config = self.root_project all_projects = self.all_projects return ManifestStateCheck( project_env_vars_hash=FileHash.from_contents(''), @@ -98,6 +99,7 @@ def _mock_state_check(self): # Create the source file patcher self.load_source_file_patcher = patch('dbt.parser.read_files.load_source_file') self.mock_source_file = self.load_source_file_patcher.start() + def mock_load_source_file(path, parse_file_type, project_name, saved_files): for sf in self.mock_models: if sf.path == path: @@ -117,7 +119,6 @@ def _mock_hook_path(self): ) return path - def get_config(self, extra_cfg=None): if extra_cfg is None: extra_cfg = {} @@ -224,8 +225,6 @@ def test__model_materializations(self): config = self.get_config(cfg) manifest = self.load_manifest(config) - compiler = self.get_compiler(config) - linker = compiler.compile(manifest) expected_materialization = { "model_one": "table", diff --git a/tests/functional/profiles/test_profile_dir.py b/tests/functional/profiles/test_profile_dir.py index 7a4c8214a1d..75a30512dcb 100644 --- a/tests/functional/profiles/test_profile_dir.py +++ b/tests/functional/profiles/test_profile_dir.py @@ -1,13 +1,17 @@ -import io import os import pytest import yaml -from contextlib import contextmanager, redirect_stdout + +from contextlib import contextmanager from pathlib import Path -from typing import List import dbt.flags as flags -from dbt.tests.util import run_dbt, write_file, rm_file + +from dbt.tests.util import ( + run_dbt_and_capture, + write_file, + rm_file, +) @pytest.fixture(scope="class") @@ -84,16 +88,6 @@ def environ(env): os.environ[key] = value -# Use this if you need to capture the standard out in a test -def run_dbt_and_capture_stdout(args: List[str] = None, expect_pass=True): - stringbuf = io.StringIO() - with redirect_stdout(stringbuf): - res = run_dbt(args, expect_pass=expect_pass) - stdout = stringbuf.getvalue() - - return res, stdout - - class TestProfiles: def dbt_debug(self, project_dir_cli_arg=None, profiles_dir_cli_arg=None): # begin with no command-line args or user config (from profiles.yml) @@ -106,8 +100,8 @@ def dbt_debug(self, project_dir_cli_arg=None, profiles_dir_cli_arg=None): if profiles_dir_cli_arg: command.extend(["--profiles-dir", str(profiles_dir_cli_arg)]) - # get the output of `dbt debug` regarless of the exit code - return run_dbt_and_capture_stdout(command, expect_pass=None) + # get the output of `dbt debug` regardless of the exit code + return run_dbt_and_capture(command, expect_pass=None) @pytest.mark.parametrize( "project_dir_cli_arg, working_directory", diff --git a/tests/unit/test_events.py b/tests/unit/test_events.py index 5e412e34f33..7fa586cefa9 100644 --- a/tests/unit/test_events.py +++ b/tests/unit/test_events.py @@ -383,6 +383,9 @@ def test_event_codes(self): FlushEventsFailure(), TrackingInitializeFailure(), RunResultWarningMessage(), + DebugCmdOut(), + DebugCmdResult(), + ListCmdOut(), # T - tests ====================== IntegrationTestInfo(), IntegrationTestDebug(),