From 69de15e8c7b8273ed9ede15440714ee3633e26c6 Mon Sep 17 00:00:00 2001 From: Peter Allen Webb Date: Tue, 24 Jan 2023 15:30:19 -0500 Subject: [PATCH 1/2] CT-1857: Event cleanup --- core/dbt/events/proto_types.py | 175 ++++++--------------------------- core/dbt/events/types.proto | 137 +++++--------------------- core/dbt/events/types.py | 145 ++++++--------------------- core/dbt/parser/models.py | 61 +++++++----- tests/unit/test_events.py | 13 +-- 5 files changed, 125 insertions(+), 406 deletions(-) diff --git a/core/dbt/events/proto_types.py b/core/dbt/events/proto_types.py index ee11e01d172..e2a001be763 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: core/dbt/events/types.proto +# sources: types.proto # plugin: python-betterproto from dataclasses import dataclass from datetime import datetime @@ -1083,123 +1083,6 @@ class ParsedFileLoadFailedMsg(betterproto.Message): data: "ParsedFileLoadFailed" = betterproto.message_field(2) -@dataclass -class StaticParserCausedJinjaRendering(betterproto.Message): - """I031""" - - path: str = betterproto.string_field(1) - - -@dataclass -class StaticParserCausedJinjaRenderingMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "StaticParserCausedJinjaRendering" = betterproto.message_field(2) - - -@dataclass -class UsingExperimentalParser(betterproto.Message): - """I032""" - - path: str = betterproto.string_field(1) - - -@dataclass -class UsingExperimentalParserMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "UsingExperimentalParser" = betterproto.message_field(2) - - -@dataclass -class SampleFullJinjaRendering(betterproto.Message): - """I033""" - - path: str = betterproto.string_field(1) - - -@dataclass -class SampleFullJinjaRenderingMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "SampleFullJinjaRendering" = betterproto.message_field(2) - - -@dataclass -class StaticParserFallbackJinjaRendering(betterproto.Message): - """I034""" - - path: str = betterproto.string_field(1) - - -@dataclass -class StaticParserFallbackJinjaRenderingMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "StaticParserFallbackJinjaRendering" = betterproto.message_field(2) - - -@dataclass -class StaticParsingMacroOverrideDetected(betterproto.Message): - """I035""" - - path: str = betterproto.string_field(1) - - -@dataclass -class StaticParsingMacroOverrideDetectedMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "StaticParsingMacroOverrideDetected" = betterproto.message_field(2) - - -@dataclass -class StaticParserSuccess(betterproto.Message): - """I036""" - - path: str = betterproto.string_field(1) - - -@dataclass -class StaticParserSuccessMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "StaticParserSuccess" = betterproto.message_field(2) - - -@dataclass -class StaticParserFailure(betterproto.Message): - """I037""" - - path: str = betterproto.string_field(1) - - -@dataclass -class StaticParserFailureMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "StaticParserFailure" = betterproto.message_field(2) - - -@dataclass -class ExperimentalParserSuccess(betterproto.Message): - """I038""" - - path: str = betterproto.string_field(1) - - -@dataclass -class ExperimentalParserSuccessMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "ExperimentalParserSuccess" = betterproto.message_field(2) - - -@dataclass -class ExperimentalParserFailure(betterproto.Message): - """I039""" - - path: str = betterproto.string_field(1) - - -@dataclass -class ExperimentalParserFailureMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "ExperimentalParserFailure" = betterproto.message_field(2) - - @dataclass class PartialParsingEnabled(betterproto.Message): """I040""" @@ -1408,6 +1291,34 @@ class JinjaLogWarningMsg(betterproto.Message): data: "JinjaLogWarning" = betterproto.message_field(2) +@dataclass +class JinjaLogInfo(betterproto.Message): + """I062""" + + node_info: "NodeInfo" = betterproto.message_field(1) + msg: str = betterproto.string_field(2) + + +@dataclass +class JinjaLogInfoMsg(betterproto.Message): + info: "EventInfo" = betterproto.message_field(1) + data: "JinjaLogInfo" = betterproto.message_field(2) + + +@dataclass +class JinjaLogDebug(betterproto.Message): + """I063""" + + node_info: "NodeInfo" = betterproto.message_field(1) + msg: str = betterproto.string_field(2) + + +@dataclass +class JinjaLogDebugMsg(betterproto.Message): + info: "EventInfo" = betterproto.message_field(1) + data: "JinjaLogDebug" = betterproto.message_field(2) + + @dataclass class GitSparseCheckoutSubdirectory(betterproto.Message): """M001""" @@ -1542,34 +1453,6 @@ class SelectorReportInvalidSelectorMsg(betterproto.Message): data: "SelectorReportInvalidSelector" = betterproto.message_field(2) -@dataclass -class JinjaLogInfo(betterproto.Message): - """M011""" - - node_info: "NodeInfo" = betterproto.message_field(1) - msg: str = betterproto.string_field(2) - - -@dataclass -class JinjaLogInfoMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "JinjaLogInfo" = betterproto.message_field(2) - - -@dataclass -class JinjaLogDebug(betterproto.Message): - """M012""" - - node_info: "NodeInfo" = betterproto.message_field(1) - msg: str = betterproto.string_field(2) - - -@dataclass -class JinjaLogDebugMsg(betterproto.Message): - info: "EventInfo" = betterproto.message_field(1) - data: "JinjaLogDebug" = betterproto.message_field(2) - - @dataclass class DepsNoPackagesFound(betterproto.Message): """M013""" diff --git a/core/dbt/events/types.proto b/core/dbt/events/types.proto index 2870b1bc610..8f49d5afd8f 100644 --- a/core/dbt/events/types.proto +++ b/core/dbt/events/types.proto @@ -863,98 +863,7 @@ message ParsedFileLoadFailedMsg { ParsedFileLoadFailed data = 2; } -// Skipping I030 - - -// I031 -message StaticParserCausedJinjaRendering { - string path = 1; -} - -message StaticParserCausedJinjaRenderingMsg { - EventInfo info = 1; - StaticParserCausedJinjaRendering data = 2; -} - -// I032 -message UsingExperimentalParser { - string path = 1; -} - -message UsingExperimentalParserMsg { - EventInfo info = 1; - UsingExperimentalParser data = 2; -} - -// I033 -message SampleFullJinjaRendering { - string path = 1; -} - -message SampleFullJinjaRenderingMsg { - EventInfo info = 1; - SampleFullJinjaRendering data = 2; -} - -// I034 -message StaticParserFallbackJinjaRendering { - string path = 1; -} - -message StaticParserFallbackJinjaRenderingMsg { - EventInfo info = 1; - StaticParserFallbackJinjaRendering data = 2; -} - -// I035 -message StaticParsingMacroOverrideDetected { - string path = 1; -} - -message StaticParsingMacroOverrideDetectedMsg { - EventInfo info = 1; - StaticParsingMacroOverrideDetected data = 2; -} - -// I036 -message StaticParserSuccess { - string path = 1; -} - -message StaticParserSuccessMsg { - EventInfo info = 1; - StaticParserSuccess data = 2; -} - -// I037 -message StaticParserFailure { - string path = 1; -} - -message StaticParserFailureMsg { - EventInfo info = 1; - StaticParserFailure data = 2; -} - -// I038 -message ExperimentalParserSuccess { - string path = 1; -} - -message ExperimentalParserSuccessMsg { - EventInfo info = 1; - ExperimentalParserSuccess data = 2; -} - -// I039 -message ExperimentalParserFailure { - string path = 1; -} - -message ExperimentalParserFailureMsg { - EventInfo info = 1; - ExperimentalParserFailure data = 2; -} +// Skipping I030 - I039 // I040 message PartialParsingEnabled { @@ -1124,6 +1033,28 @@ message JinjaLogWarningMsg { JinjaLogWarning data = 2; } +// I062 +message JinjaLogInfo { + NodeInfo node_info = 1; + string msg = 2; +} + +message JinjaLogInfoMsg { + EventInfo info = 1; + JinjaLogInfo data = 2; +} + +// I063 +message JinjaLogDebug { + NodeInfo node_info = 1; + string msg = 2; +} + +message JinjaLogDebugMsg { + EventInfo info = 1; + JinjaLogDebug data = 2; +} + // M - Deps generation // M001 @@ -1230,27 +1161,7 @@ message SelectorReportInvalidSelectorMsg { SelectorReportInvalidSelector data = 2; } -// M011 -message JinjaLogInfo { - NodeInfo node_info = 1; - string msg = 2; -} - -message JinjaLogInfoMsg { - EventInfo info = 1; - JinjaLogInfo data = 2; -} - -// M012 -message JinjaLogDebug { - NodeInfo node_info = 1; - string msg = 2; -} - -message JinjaLogDebugMsg { - EventInfo info = 1; - JinjaLogDebug data = 2; -} +// Skipped M011 and M012 // M013 message DepsNoPackagesFound { diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index ab2d090a93a..ab212a6c022 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -864,90 +864,7 @@ def message(self) -> str: return f"Failed to load parsed file from disk at {self.path}: {self.exc}" -# Skipped I030 - - -@dataclass -class StaticParserCausedJinjaRendering(DebugLevel, pt.StaticParserCausedJinjaRendering): - def code(self): - return "I031" - - def message(self) -> str: - return f"1605: jinja rendering because of STATIC_PARSER flag. file: {self.path}" - - -# TODO: Experimental/static parser uses these for testing and some may be a good use case for -# the `TestLevel` logger once we implement it. Some will probably stay `DebugLevel`. -@dataclass -class UsingExperimentalParser(DebugLevel, pt.UsingExperimentalParser): - def code(self): - return "I032" - - def message(self) -> str: - return f"1610: conducting experimental parser sample on {self.path}" - - -@dataclass -class SampleFullJinjaRendering(DebugLevel, pt.SampleFullJinjaRendering): - def code(self): - return "I033" - - def message(self) -> str: - return f"1611: conducting full jinja rendering sample on {self.path}" - - -@dataclass -class StaticParserFallbackJinjaRendering(DebugLevel, pt.StaticParserFallbackJinjaRendering): - def code(self): - return "I034" - - def message(self) -> str: - return f"1602: parser fallback to jinja rendering on {self.path}" - - -@dataclass -class StaticParsingMacroOverrideDetected(DebugLevel, pt.StaticParsingMacroOverrideDetected): - def code(self): - return "I035" - - def message(self) -> str: - return f"1601: detected macro override of ref/source/config in the scope of {self.path}" - - -@dataclass -class StaticParserSuccess(DebugLevel, pt.StaticParserSuccess): - def code(self): - return "I036" - - def message(self) -> str: - return f"1699: static parser successfully parsed {self.path}" - - -@dataclass -class StaticParserFailure(DebugLevel, pt.StaticParserFailure): - def code(self): - return "I037" - - def message(self) -> str: - return f"1603: static parser failed on {self.path}" - - -@dataclass -class ExperimentalParserSuccess(DebugLevel, pt.ExperimentalParserSuccess): - def code(self): - return "I038" - - def message(self) -> str: - return f"1698: experimental parser successfully parsed {self.path}" - - -@dataclass -class ExperimentalParserFailure(DebugLevel, pt.ExperimentalParserFailure): - def code(self): - return "I039" - - def message(self) -> str: - return f"1604: experimental parser failed on {self.path}" +# Skipped I030-I039 @dataclass @@ -1162,6 +1079,26 @@ def message(self) -> str: return self.msg +@dataclass +class JinjaLogInfo(InfoLevel, EventStringFunctor, pt.JinjaLogInfo): + def code(self): + return "I062" + + def message(self) -> str: + # This is for the log method used in macros so msg cannot be built here + return self.msg + + +@dataclass +class JinjaLogDebug(DebugLevel, EventStringFunctor, pt.JinjaLogDebug): + def code(self): + return "I063" + + def message(self) -> str: + # This is for the log method used in macros so msg cannot be built here + return self.msg + + # ======================================================= # M - Deps generation # ======================================================= @@ -1173,7 +1110,7 @@ def code(self): return "M001" def message(self) -> str: - return f" Subdirectory specified: {self.subdir}, using sparse checkout." + return f"Subdirectory specified: {self.subdir}, using sparse checkout." @dataclass @@ -1182,7 +1119,7 @@ def code(self): return "M002" def message(self) -> str: - return f" Checking out revision {self.revision}." + return f"Checking out revision {self.revision}." @dataclass @@ -1218,7 +1155,7 @@ def code(self): return "M006" def message(self) -> str: - return f" Updated checkout from {self.start_sha} to {self.end_sha}." + return f"Updated checkout from {self.start_sha} to {self.end_sha}." @dataclass @@ -1227,7 +1164,7 @@ def code(self): return "M007" def message(self) -> str: - return f" Checked out at {self.end_sha}." + return f"Checked out at {self.end_sha}." @dataclass @@ -1260,26 +1197,6 @@ def message(self) -> str: ) -@dataclass -class JinjaLogInfo(InfoLevel, EventStringFunctor, pt.JinjaLogInfo): - def code(self): - return "M011" - - def message(self) -> str: - # This is for the log method used in macros so msg cannot be built here - return self.msg - - -@dataclass -class JinjaLogDebug(DebugLevel, EventStringFunctor, pt.JinjaLogDebug): - def code(self): - return "M012" - - def message(self) -> str: - # This is for the log method used in macros so msg cannot be built here - return self.msg - - @dataclass class DepsNoPackagesFound(InfoLevel, pt.DepsNoPackagesFound): def code(self): @@ -1304,7 +1221,7 @@ def code(self): return "M015" def message(self) -> str: - return f" Installed from {self.version_name}" + return f"Installed from {self.version_name}" @dataclass @@ -1313,7 +1230,7 @@ def code(self): return "M016" def message(self) -> str: - return f" Updated version available: {self.version_latest}" + return f"Updated version available: {self.version_latest}" @dataclass @@ -1322,7 +1239,7 @@ def code(self): return "M017" def message(self) -> str: - return " Up to date!" + return "Up to date!" @dataclass @@ -1331,7 +1248,7 @@ def code(self): return "M018" def message(self) -> str: - return f" and subdirectory {self.subdirectory}" + return f"and subdirectory {self.subdirectory}" @dataclass @@ -2262,7 +2179,7 @@ def code(self): return "Z037" def message(self) -> str: - return " Creating symlink to local dependency." + return "Creating symlink to local dependency." @dataclass @@ -2271,7 +2188,7 @@ def code(self): return "Z038" def message(self) -> str: - return " Symlinks are not available on this OS, copying dependency." + return "Symlinks are not available on this OS, copying dependency." @dataclass diff --git a/core/dbt/parser/models.py b/core/dbt/parser/models.py index 597200abba5..710df10f145 100644 --- a/core/dbt/parser/models.py +++ b/core/dbt/parser/models.py @@ -1,19 +1,10 @@ from copy import deepcopy from dbt.context.context_config import ContextConfig from dbt.contracts.graph.nodes import ModelNode -import dbt.flags as flags +from dbt.events.base_types import EventLevel +from dbt.events.types import Note from dbt.events.functions import fire_event -from dbt.events.types import ( - StaticParserCausedJinjaRendering, - UsingExperimentalParser, - SampleFullJinjaRendering, - StaticParserFallbackJinjaRendering, - StaticParsingMacroOverrideDetected, - StaticParserSuccess, - StaticParserFailure, - ExperimentalParserSuccess, - ExperimentalParserFailure, -) +import dbt.flags as flags from dbt.node_types import NodeType, ModelLanguage from dbt.parser.base import SimpleSQLParser from dbt.parser.search import FileBlock @@ -261,7 +252,10 @@ def render_update(self, node: ModelNode, config: ContextConfig) -> None: elif not flags.STATIC_PARSER: # jinja rendering super().render_update(node, config) - fire_event(StaticParserCausedJinjaRendering(path=node.path)) + fire_event( + Note(f"1605: jinja rendering because of STATIC_PARSER flag. file: {node.path}"), + EventLevel.DEBUG, + ) return # only sample for experimental parser correctness on normal runs, @@ -295,7 +289,10 @@ def render_update(self, node: ModelNode, config: ContextConfig) -> None: # sample the experimental parser only during a normal run if exp_sample and not flags.USE_EXPERIMENTAL_PARSER: - fire_event(UsingExperimentalParser(path=node.path)) + fire_event( + Note(f"1610: conducting experimental parser sample on {node.path}"), + EventLevel.DEBUG, + ) experimental_sample = self.run_experimental_parser(node) # if the experimental parser succeeded, make a full copy of model parser # and populate _everything_ into it so it can be compared apples-to-apples @@ -325,7 +322,10 @@ def render_update(self, node: ModelNode, config: ContextConfig) -> None: # sampling rng here, but the effect would be the same since we would only roll # it 40% of the time. So I've opted to keep all the rng code colocated above. if stable_sample and not flags.USE_EXPERIMENTAL_PARSER: - fire_event(SampleFullJinjaRendering(path=node.path)) + fire_event( + Note(f"1611: conducting full jinja rendering sample on {node.path}"), + EventLevel.DEBUG, + ) # if this will _never_ mutate anything `self` we could avoid these deep copies, # but we can't really guarantee that going forward. model_parser_copy = self.partial_deepcopy() @@ -360,7 +360,9 @@ def render_update(self, node: ModelNode, config: ContextConfig) -> None: else: # jinja rendering super().render_update(node, config) - fire_event(StaticParserFallbackJinjaRendering(path=node.path)) + fire_event( + Note(f"1602: parser fallback to jinja rendering on {node.path}"), EventLevel.DEBUG + ) # if sampling, add the correct messages for tracking if exp_sample and isinstance(experimental_sample, str): @@ -396,19 +398,26 @@ def run_static_parser(self, node: ModelNode) -> Optional[Union[str, Dict[str, Li # this log line is used for integration testing. If you change # the code at the beginning of the line change the tests in # test/integration/072_experimental_parser_tests/test_all_experimental_parser.py - fire_event(StaticParsingMacroOverrideDetected(path=node.path)) + fire_event( + Note( + f"1601: detected macro override of ref/source/config in the scope of {node.path}" + ), + EventLevel.DEBUG, + ) return "has_banned_macro" # run the stable static parser and return the results try: statically_parsed = py_extract_from_source(node.raw_code) - fire_event(StaticParserSuccess(path=node.path)) + fire_event( + Note(f"1699: static parser successfully parsed {node.path}"), EventLevel.DEBUG + ) return _shift_sources(statically_parsed) # if we want information on what features are barring the static # parser from reading model files, this is where we would add that # since that information is stored in the `ExtractionError`. except ExtractionError: - fire_event(StaticParserFailure(path=node.path)) + fire_event(Note(f"1603: static parser failed on {node.path}"), EventLevel.DEBUG) return "cannot_parse" def run_experimental_parser( @@ -419,7 +428,12 @@ def run_experimental_parser( # this log line is used for integration testing. If you change # the code at the beginning of the line change the tests in # test/integration/072_experimental_parser_tests/test_all_experimental_parser.py - fire_event(StaticParsingMacroOverrideDetected(path=node.path)) + fire_event( + Note( + f"1601: detected macro override of ref/source/config in the scope of {node.path}" + ), + EventLevel.DEBUG, + ) return "has_banned_macro" # run the experimental parser and return the results @@ -428,13 +442,16 @@ def run_experimental_parser( # experimental features. Change `py_extract_from_source` to the new # experimental call when we add additional features. experimentally_parsed = py_extract_from_source(node.raw_code) - fire_event(ExperimentalParserSuccess(path=node.path)) + fire_event( + Note(f"1698: experimental parser successfully parsed {node.path}"), + EventLevel.DEBUG, + ) return _shift_sources(experimentally_parsed) # if we want information on what features are barring the experimental # parser from reading model files, this is where we would add that # since that information is stored in the `ExtractionError`. except ExtractionError: - fire_event(ExperimentalParserFailure(path=node.path)) + fire_event(Note(f"1604: experimental parser failed on {node.path}"), EventLevel.DEBUG) return "cannot_parse" # checks for banned macros diff --git a/tests/unit/test_events.py b/tests/unit/test_events.py index 529a11f5ed9..b8444184473 100644 --- a/tests/unit/test_events.py +++ b/tests/unit/test_events.py @@ -187,15 +187,6 @@ def test_event_codes(self): UnableToPartialParse(reason="something went wrong"), PartialParsingNotEnabled(), ParsedFileLoadFailed(path="", exc="", exc_info=""), - StaticParserCausedJinjaRendering(path=""), - UsingExperimentalParser(path=""), - SampleFullJinjaRendering(path=""), - StaticParserFallbackJinjaRendering(path=""), - StaticParsingMacroOverrideDetected(path=""), - StaticParserSuccess(path=""), - StaticParserFailure(path=""), - ExperimentalParserSuccess(path=""), - ExperimentalParserFailure(path=""), PartialParsingEnabled(deleted=0, added=0, changed=0), PartialParsingFile(file_id=""), InvalidDisabledTargetInTestNode( @@ -227,6 +218,8 @@ def test_event_codes(self): disabled="", ), JinjaLogWarning(), + JinjaLogInfo(msg=""), + JinjaLogDebug(msg=""), # M - Deps generation ====================== GitSparseCheckoutSubdirectory(subdir=""), GitProgressCheckoutRevision(revision=""), @@ -238,8 +231,6 @@ def test_event_codes(self): RegistryProgressGETRequest(url=""), RegistryProgressGETResponse(url="", resp_code=1234), SelectorReportInvalidSelector(valid_selectors="", spec_method="", raw_spec=""), - JinjaLogInfo(msg=""), - JinjaLogDebug(msg=""), DepsNoPackagesFound(), DepsStartPackageInstall(package_name=""), DepsInstallInfo(version_name=""), From 525e3d078ffefa8869d2e0c47c7b712c6f9d6d5d Mon Sep 17 00:00:00 2001 From: Peter Allen Webb Date: Tue, 24 Jan 2023 15:36:31 -0500 Subject: [PATCH 2/2] Add changelog entry. --- .changes/unreleased/Under the Hood-20230124-153553.yaml | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 .changes/unreleased/Under the Hood-20230124-153553.yaml diff --git a/.changes/unreleased/Under the Hood-20230124-153553.yaml b/.changes/unreleased/Under the Hood-20230124-153553.yaml new file mode 100644 index 00000000000..0a540d6da55 --- /dev/null +++ b/.changes/unreleased/Under the Hood-20230124-153553.yaml @@ -0,0 +1,6 @@ +kind: Under the Hood +body: Revised and simplified various structured logging events +time: 2023-01-24T15:35:53.065356-05:00 +custom: + Author: peterallenwebb + Issue: 6664 6665 6666