A few final logging touch-ups (#4388)

* Rm unused events, per #4104

* More structured ConcurrencyLine

* Replace \n prefixes with EmptyLine

* Reimplement ui.warning_tag to centralize logic

* Use warning_tag for deprecations too

* Rm more unused event types

* Exclude EmptyLine from json logs

* loglines are not always created by events (#4406)

Co-authored-by: Nathaniel May <nathaniel.may@fishtownanalytics.com>

core/dbt/deprecations.py

@@ -36,9 +36,9 @@ def show(self, *args, **kwargs) -> None:
         if self.name not in active_deprecations:
             desc = self.description.format(**kwargs)
             msg = ui.line_wrap_message(
-                desc, prefix='* Deprecation Warning:\n\n'
+                desc, prefix='Deprecated functionality\n\n'
             )
-            dbt.exceptions.warn_or_error(msg)
+            dbt.exceptions.warn_or_error(msg, log_fmt=ui.warning_tag('{}'))
             self.track_deprecation_warn()
             active_deprecations.add(self.name)
 
@@ -62,7 +62,7 @@ class PackageInstallPathDeprecation(DBTDeprecation):
 
 class ConfigPathDeprecation(DBTDeprecation):
     _description = '''\
-    The `{deprecated_path}` config has been deprecated in favor of `{exp_path}`.
+    The `{deprecated_path}` config has been renamed to `{exp_path}`.
     Please update your `dbt_project.yml` configuration to reflect this change.
     '''
 

core/dbt/events/functions.py

@@ -3,7 +3,7 @@
 from datetime import datetime
 import dbt.events.functions as this  # don't worry I hate it too.
 from dbt.events.base_types import Cli, Event, File, ShowException, NodeInfo, Cache
-from dbt.events.types import EventBufferFull, T_Event, MainReportVersion
+from dbt.events.types import EventBufferFull, T_Event, MainReportVersion, EmptyLine
 import dbt.flags as flags
 # TODO this will need to move eventually
 from dbt.logger import SECRET_ENV_PREFIX, make_log_dir_if_missing, GLOBAL_LOGGER
@@ -195,15 +195,21 @@ def create_file_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> s
 
 # translates an Event to a completely formatted json log line
 # you have to specify which message you want. (i.e. - e.message(), e.cli_msg(), e.file_msg())
-def create_json_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
+def create_json_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> Optional[str]:
+    if type(e) == EmptyLine:
+        return None  # will not be sent to logger
     # using preformatted string instead of formatting it here to be extra careful about timezone
     values = event_to_serializable_dict(e, lambda _: e.get_ts_rfc3339(), lambda x: msg_fn(x))
     raw_log_line = json.dumps(values, sort_keys=True)
     return scrub_secrets(raw_log_line, env_secrets())
 
 
 # calls create_stdout_text_log_line() or create_json_log_line() according to logger config
-def create_log_line(e: T_Event, msg_fn: Callable[[T_Event], str], file_output=False) -> str:
+def create_log_line(
+    e: T_Event,
+    msg_fn: Callable[[T_Event], str],
+    file_output=False
+) -> Optional[str]:
     if this.format_json:
         return create_json_log_line(e, msg_fn)  # json output, both console and file
     elif file_output is True:
@@ -215,6 +221,8 @@ def create_log_line(e: T_Event, msg_fn: Callable[[T_Event], str], file_output=Fa
 # allows for resuse of this obnoxious if else tree.
 # do not use for exceptions, it doesn't pass along exc_info, stack_info, or extra
 def send_to_logger(l: Union[Logger, logbook.Logger], level_tag: str, log_line: str):
+    if not log_line:
+        return
     if level_tag == 'test':
         # TODO after implmenting #3977 send to new test level
         l.debug(log_line)
@@ -303,15 +311,16 @@ def fire_event(e: Event) -> None:
         # using Event::message because the legacy logger didn't differentiate messages by
         # destination
         log_line = create_log_line(e, msg_fn=lambda x: x.message())
-
-        send_to_logger(GLOBAL_LOGGER, e.level_tag(), log_line)
+        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 isinstance(e, File):
         log_line = create_log_line(e, msg_fn=lambda x: x.file_msg(), file_output=True)
         # doesn't send exceptions to exception logger
-        send_to_logger(FILE_LOG, level_tag=e.level_tag(), log_line=log_line)
+        if log_line:
+            send_to_logger(FILE_LOG, level_tag=e.level_tag(), log_line=log_line)
 
     if isinstance(e, Cli):
         # explicitly checking the debug flag here so that potentially expensive-to-construct
@@ -320,18 +329,19 @@ def fire_event(e: Event) -> None:
             return  # eat the message in case it was one of the expensive ones
 
         log_line = create_log_line(e, msg_fn=lambda x: x.cli_msg())
-        if not isinstance(e, ShowException):
-            send_to_logger(STDOUT_LOG, level_tag=e.level_tag(), log_line=log_line)
-        # CliEventABC and ShowException
-        else:
-            send_exc_to_logger(
-                STDOUT_LOG,
-                level_tag=e.level_tag(),
-                log_line=log_line,
-                exc_info=e.exc_info,
-                stack_info=e.stack_info,
-                extra=e.extra
-            )
+        if log_line:
+            if not isinstance(e, ShowException):
+                send_to_logger(STDOUT_LOG, level_tag=e.level_tag(), log_line=log_line)
+            # CliEventABC and ShowException
+            else:
+                send_exc_to_logger(
+                    STDOUT_LOG,
+                    level_tag=e.level_tag(),
+                    log_line=log_line,
+                    exc_info=e.exc_info,
+                    stack_info=e.stack_info,
+                    extra=e.extra
+                )
 
 
 def get_invocation_id() -> str:

core/dbt/events/types.py

@@ -397,40 +397,6 @@ class SystemReportReturnCode(DebugLevel, Cli, File):
     def message(self) -> str:
         return f"command return code={self.returncode}"
 
-# TODO remove?? Not called outside of this file
-
-
-@dataclass
-class SelectorAlertUpto3UnusedNodes(InfoLevel, Cli, File):
-    node_names: List[str]
-    code: str = "I_NEED_A_CODE_5"
-
-    def message(self) -> str:
-        summary_nodes_str = ("\n  - ").join(self.node_names[:3])
-        and_more_str = (
-            f"\n  - and {len(self.node_names) - 3} more" if len(self.node_names) > 4 else ""
-        )
-        return (
-            f"\nSome tests were excluded because at least one parent is not selected. "
-            f"Use the --greedy flag to include them."
-            f"\n  - {summary_nodes_str}{and_more_str}"
-        )
-
-# TODO remove?? Not called outside of this file
-
-
-@dataclass
-class SelectorAlertAllUnusedNodes(DebugLevel, Cli, File):
-    node_names: List[str]
-    code: str = "I_NEED_A_CODE_6"
-
-    def message(self) -> str:
-        debug_nodes_str = ("\n  - ").join(self.node_names)
-        return (
-            f"Full list of tests that were excluded:"
-            f"\n  - {debug_nodes_str}"
-        )
-
 
 @dataclass
 class SelectorReportInvalidSelector(InfoLevel, Cli, File):
@@ -863,85 +829,7 @@ class InvalidVarsYAML(ErrorLevel, Cli, File):
     code: str = "A008"
 
     def message(self) -> str:
-        return "The YAML provided in the --vars argument is not valid.\n"
-
-
-# TODO: Remove? (appears to be uncalled)
-@dataclass
-class CatchRunException(ShowException, DebugLevel, Cli, File):
-    build_path: Any
-    exc: Exception
-    code: str = "I_NEED_A_CODE_1"
-
-    def message(self) -> str:
-        INTERNAL_ERROR_STRING = """This is an error in dbt. Please try again. If the \
-                            error persists, open an issue at https://github.com/dbt-labs/dbt-core
-                            """.strip()
-        prefix = f'Internal error executing {self.build_path}'
-        error = "{prefix}\n{error}\n\n{note}".format(
-                prefix=ui.red(prefix),
-                error=str(self.exc).strip(),
-                note=INTERNAL_ERROR_STRING
-        )
-        return error
-
-    def fields_to_json(self, val: Any) -> Any:
-        if val == self.exc:
-            return str(val)
-
-        return val
-
-
-# TODO: Remove? (appears to be uncalled)
-@dataclass
-class HandleInternalException(ShowException, DebugLevel, Cli, File):
-    exc: Exception
-    code: str = "I_NEED_A_CODE_2"
-
-    def message(self) -> str:
-        return str(self.exc)
-
-    def fields_to_json(self, val: Any) -> Any:
-        if val == self.exc:
-            return str(val)
-
-        return val
-
-# TODO: Remove? (appears to be uncalled)
-
-
-@dataclass
-class MessageHandleGenericException(ErrorLevel, Cli, File):
-    build_path: str
-    unique_id: str
-    exc: Exception
-    code: str = "I_NEED_A_CODE_3"
-
-    def message(self) -> str:
-        node_description = self.build_path
-        if node_description is None:
-            node_description = self.unique_id
-        prefix = "Unhandled error while executing {}".format(node_description)
-        return "{prefix}\n{error}".format(
-            prefix=ui.red(prefix),
-            error=str(self.exc).strip()
-        )
-
-    def fields_to_json(self, val: Any) -> Any:
-        if val == self.exc:
-            return str(val)
-
-        return val
-
-# TODO: Remove? (appears to be uncalled)
-
-
-@dataclass
-class DetailsHandleGenericException(ShowException, DebugLevel, Cli, File):
-    code: str = "I_NEED_A_CODE_4"
-
-    def message(self) -> str:
-        return ''
+        return "The YAML provided in the --vars argument is not valid."
 
 
 @dataclass
@@ -1639,7 +1527,7 @@ class DepsNotifyUpdatesAvailable(InfoLevel, Cli, File):
     code: str = "M019"
 
     def message(self) -> str:
-        return ('\nUpdates available for packages: {} \
+        return ('Updates available for packages: {} \
                 \nUpdate your versions in packages.yml, then run dbt deps'.format(self.packages))
 
 
@@ -1756,7 +1644,7 @@ class ServingDocsExitInfo(InfoLevel, Cli, File):
     code: str = "Z020"
 
     def message(self) -> str:
-        return "Press Ctrl+C to exit.\n\n"
+        return "Press Ctrl+C to exit."
 
 
 @dataclass
@@ -1807,7 +1695,7 @@ class StatsLine(InfoLevel, Cli, File):
     code: str = "Z023"
 
     def message(self) -> str:
-        stats_line = ("\nDone. PASS={pass} WARN={warn} ERROR={error} SKIP={skip} TOTAL={total}")
+        stats_line = ("Done. PASS={pass} WARN={warn} ERROR={error} SKIP={skip} TOTAL={total}")
         return stats_line.format(**self.stats)
 
 
@@ -2337,11 +2225,12 @@ def message(self) -> str:
 
 @dataclass
 class ConcurrencyLine(InfoLevel, Cli, File):
-    concurrency_line: str
+    num_threads: int
+    target_name: str
     code: str = "Q026"
 
     def message(self) -> str:
-        return self.concurrency_line
+        return f"Concurrency: {self.num_threads} threads (target='{self.target_name}')"
 
 
 @dataclass
@@ -2708,8 +2597,6 @@ def message(self) -> str:
     AdapterImportError(ModuleNotFoundError())
     PluginLoadError()
     SystemReportReturnCode(returncode=0)
-    SelectorAlertUpto3UnusedNodes(node_names=[])
-    SelectorAlertAllUnusedNodes(node_names=[])
     NewConnectionOpening(connection_state='')
     TimingInfoCollected()
     MergedFromState(nbr_merged=0, sample=[])
@@ -2755,8 +2642,6 @@ def message(self) -> str:
     PartialParsingDeletedExposure(unique_id='')
     InvalidDisabledSourceInTestNode(msg='')
     InvalidRefInTestNode(msg='')
-    MessageHandleGenericException(build_path='', unique_id='', exc=Exception(''))
-    DetailsHandleGenericException()
     RunningOperationCaughtError(exc=Exception(''))
     RunningOperationUncaughtError(exc=Exception(''))
     DbtProjectError()
@@ -2952,7 +2837,7 @@ def message(self) -> str:
     NodeStart(report_node_data=ParsedModelNode(), unique_id='')
     NodeFinished(report_node_data=ParsedModelNode(), unique_id='', run_result=RunResult())
     QueryCancelationUnsupported(type='')
-    ConcurrencyLine(concurrency_line='')
+    ConcurrencyLine(num_threads=0, target_name='')
     NodeCompiling(report_node_data=ParsedModelNode(), unique_id='')
     NodeExecuting(report_node_data=ParsedModelNode(), unique_id='')
     StarterProjectPath(dir='')

core/dbt/parser/schemas.py

@@ -960,10 +960,9 @@ def parse_patch(
         unique_id = f'macro.{patch.package_name}.{patch.name}'
         macro = self.manifest.macros.get(unique_id)
         if not macro:
-            warn_or_error(
-                f'WARNING: Found patch for macro "{patch.name}" '
-                f'which was not found'
-            )
+            msg = f'Found patch for macro "{patch.name}" ' \
+                  f'which was not found'
+            warn_or_error(msg, log_fmt=warning_tag('{}'))
             return
         if macro.patch_path:
             package_name, existing_file_path = macro.patch_path.split('://')

core/dbt/task/deps.py

@@ -10,7 +10,7 @@
 from dbt.events.functions import fire_event
 from dbt.events.types import (
     DepsNoPackagesFound, DepsStartPackageInstall, DepsUpdateAvailable, DepsUTD,
-    DepsInstallInfo, DepsListSubdirectory, DepsNotifyUpdatesAvailable
+    DepsInstallInfo, DepsListSubdirectory, DepsNotifyUpdatesAvailable, EmptyLine
 )
 from dbt.clients import system
 
@@ -81,6 +81,7 @@ def run(self):
                     source_type=source_type,
                     version=version)
             if packages_to_upgrade:
+                fire_event(EmptyLine())
                 fire_event(DepsNotifyUpdatesAvailable(packages=packages_to_upgrade))
 
     @classmethod

core/dbt/task/printer.py

@@ -65,6 +65,8 @@ def print_run_status_line(results) -> None:
         stats[result_type] += 1
         stats['total'] += 1
 
+    with TextOnly():
+        fire_event(EmptyLine())
     fire_event(StatsLine(stats=stats))
 
 

core/dbt/task/runnable.py

@@ -56,6 +56,7 @@
 import dbt.exceptions
 from dbt import flags
 import dbt.utils
+from dbt.ui import warning_tag
 
 RESULT_FILE_NAME = 'run_results.json'
 MANIFEST_FILE_NAME = 'manifest.json'
@@ -377,10 +378,8 @@ def execute_nodes(self):
         num_threads = self.config.threads
         target_name = self.config.target_name
 
-        text = "Concurrency: {} threads (target='{}')"
-        concurrency_line = text.format(num_threads, target_name)
         with NodeCount(self.num_nodes):
-            fire_event(ConcurrencyLine(concurrency_line=concurrency_line))
+            fire_event(ConcurrencyLine(num_threads=num_threads, target_name=target_name))
         with TextOnly():
             fire_event(EmptyLine())
 
@@ -461,8 +460,11 @@ def run(self):
             )
 
         if len(self._flattened_nodes) == 0:
-            warn_or_error("\nWARNING: Nothing to do. Try checking your model "
-                          "configs and model specification args")
+            with TextOnly():
+                fire_event(EmptyLine())
+            msg = "Nothing to do. Try checking your model " \
+                  "configs and model specification args"
+            warn_or_error(msg, log_fmt=warning_tag('{}'))
             result = self.get_result(
                 results=[],
                 generated_at=datetime.utcnow(),