Misc logging cleanup + commentary

core/dbt/deps/git.py

@@ -94,7 +94,7 @@ def _fetch_metadata(self, project, renderer) -> ProjectPackageMetadata:
  'The git package "{}" \n\tis {}.\n\tThis can introduce '
  'breaking changes into your project without warning!\n\nSee {}'
  .format(self.git, self.unpinned_msg(), PIN_PACKAGE_URL),
- log_fmt=ui.yellow('WARNING: {}')
+ log_fmt=ui.warning_tag('{}')
  )
  loaded = Project.from_project_root(path, renderer)
  return ProjectPackageMetadata.from_project(loaded)

core/dbt/events/functions.py

@@ -3,6 +3,7 @@
 import dbt.events.functions as this # don't worry I hate it too.
 from dbt.events.base_types import Cli, Event, File, ShowException
 import dbt.flags as flags
+import dbt.ui as ui
 # TODO this will need to move eventually
 from dbt.logger import SECRET_ENV_PREFIX, make_log_dir_if_missing, GLOBAL_LOGGER
 import io
@@ -110,14 +111,27 @@ def scrub_secrets(msg: str, secrets: List[str]) -> str:
 T_Event = TypeVar('T_Event', bound=Event)
 
 
+def format_level(level):
+ fixed_width = level.ljust(5)
+ # TODO turn off all color everwhere for file + JSON
+ if not this.format_color:
+ return fixed_width
+ elif level == 'warn':
+ return ui.yellow(fixed_width)
+ elif level == 'error':
+ return ui.red(fixed_width)
+ else:
+ return fixed_width
+
+
 # translates an Event to a completely formatted text-based log line
 # you have to specify which message you want. (i.e. - e.message, e.cli_msg(), e.file_msg())
 # type hinting everything as strings so we don't get any unintentional string conversions via str()
 def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
  color_tag: str = '' if this.format_color else Style.RESET_ALL
  ts: str = e.ts.strftime("%H:%M:%S")
  scrubbed_msg: str = scrub_secrets(msg_fn(e), env_secrets())
- level: str = e.level_tag()
+ level: str = format_level(e.level_tag())
  log_line: str = f"{color_tag}{ts} | [ {level} ] | {scrubbed_msg}"
  return log_line
 
@@ -223,7 +237,11 @@ def fire_event(e: Event) -> None:
 
  # always logs debug level regardless of user input
  if isinstance(e, File):
- log_line = create_json_log_line(e, msg_fn=lambda x: x.file_msg())
+ log_line = (
+ create_json_log_line(e, msg_fn=lambda x: x.file_msg())
+ if this.format_json else
+ create_text_log_line(e, msg_fn=lambda x: x.file_msg())
+ )
  # doesn't send exceptions to exception logger
  send_to_logger(FILE_LOG, level_tag=e.level_tag(), log_line=log_line)
 
@@ -233,7 +251,11 @@ def fire_event(e: Event) -> None:
  if e.level_tag() == 'debug' and not flags.DEBUG:
  return # eat the message in case it was one of the expensive ones
 
- log_line = create_json_log_line(e, msg_fn=lambda x: x.cli_msg())
+ log_line = (
+ create_json_log_line(e, msg_fn=lambda x: x.cli_msg())
+ if this.format_json else
+ create_text_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

core/dbt/events/types.py

@@ -282,34 +282,6 @@ def message(self) -> str:
  return f"command return code={self.code}"
 
 
-@dataclass
-class SelectorAlertUpto3UnusedNodes(InfoLevel, Cli, File):
- node_names: List[str]
-
- 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}"
- )
-
-
-@dataclass
-class SelectorAlertAllUnusedNodes(DebugLevel, Cli, File):
- node_names: List[str]
-
- 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):
  selector_methods: dict
@@ -680,7 +652,7 @@ def message(self) -> str:
 
 class InvalidVarsYAML(ErrorLevel, Cli, File):
  def message(self) -> str:
- return "The YAML provided in the --vars argument is not valid.\n"
+ return "The YAML provided in the --vars argument is not valid."
 
 
 @dataclass
@@ -1265,7 +1237,7 @@ class DepsNotifyUpdatesAvailable(InfoLevel, Cli, File):
  packages: List[str]
 
  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))
 
 
@@ -1277,7 +1249,9 @@ def message(self) -> str:
  return f"Database error while running {self.hook_type}"
 
 
-class EmptyLine(InfoLevel, Cli, File):
+class EmptyLine(InfoLevel, Cli):
+ # ignore in file
+ # TODO: ignore if JSON formatted?
  def message(self) -> str:
  return ''
 
@@ -1357,7 +1331,7 @@ def message(self) -> str:
 
 class ServingDocsExitInfo(InfoLevel, Cli, File):
  def message(self) -> str:
- return "Press Ctrl+C to exit.\n\n"
+ return "Press Ctrl+C to exit."
 
 
 @dataclass
@@ -1403,7 +1377,7 @@ class StatsLine(InfoLevel, Cli, File):
  stats: Dict
 
  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)
 
 
@@ -1869,10 +1843,11 @@ def message(self) -> str:
 
 @dataclass
 class ConcurrencyLine(InfoLevel, Cli, File):
- concurrency_line: str
+ num_threads: int
+ target_name: str
 
  def message(self) -> str:
- return self.concurrency_line
+ return f"Concurrency: {self.num_threads} threads (target='{self.target_name}')"
 
 
 @dataclass
@@ -2176,8 +2151,6 @@ def dump_callable():
  SystemStdOutMsg(bmsg=b'')
  SystemStdErrMsg(bmsg=b'')
  SystemReportReturnCode(code=0)
- SelectorAlertUpto3UnusedNodes(node_names=[])
- SelectorAlertAllUnusedNodes(node_names=[])
  SelectorReportInvalidSelector(selector_methods={'': ''}, spec_method='', raw_spec='')
  MacroEventInfo(msg='')
  MacroEventDebug(msg='')
@@ -2306,7 +2279,7 @@ def dump_callable():
  NodeStart(unique_id='')
  NodeFinished(unique_id='')
  QueryCancelationUnsupported(type='')
- ConcurrencyLine(concurrency_line='')
+ ConcurrencyLine(num_threads=0, target_name='')
  StarterProjectPath(dir='')
  ConfigFolderDirectory(dir='')
  NoSampleProfileFound(adapter='')

core/dbt/parser/schemas.py

@@ -961,7 +961,7 @@ def parse_patch(
  macro = self.manifest.macros.get(unique_id)
  if not macro:
  warn_or_error(
- f'WARNING: Found patch for macro "{patch.name}" '
+ f'Found patch for macro "{patch.name}" '
  f'which was not found'
  )
  return

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

@@ -353,10 +353,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())
 

core/dbt/task/serve.py

@@ -6,7 +6,7 @@
 from http.server import SimpleHTTPRequestHandler
 from socketserver import TCPServer
 from dbt.events.functions import fire_event
-from dbt.events.types import ServingDocsPort, ServingDocsAccessInfo, ServingDocsExitInfo
+from dbt.events.types import ServingDocsPort, ServingDocsAccessInfo, ServingDocsExitInfo, EmptyLine
 
 from dbt.task.base import ConfiguredTask
 
@@ -22,6 +22,8 @@ def run(self):
 
  fire_event(ServingDocsPort(address=address, port=port))
  fire_event(ServingDocsAccessInfo(port=port))
+ fire_event(EmptyLine())
+ fire_event(EmptyLine())
  fire_event(ServingDocsExitInfo())
 
  # mypy doesn't think SimpleHTTPRequestHandler is ok here, but it is

core/dbt/ui.py

@@ -66,4 +66,6 @@ def line_wrap_message(
 
 
 def warning_tag(msg: str) -> str:
- return f'[{yellow("WARNING")}]: {msg}'
+ # duplicative now that new structured logs include levels
+ # return f'[{yellow("WARNING")}]: {msg}'
+ return msg