Logging: restore previous (small) behaviors

CHANGELOG.md

@@ -9,6 +9,7 @@
 - Reorder logic for static parser sampling to speed up model parsing ([#4332](https:/dbt-labs/dbt-core/pull/4332))
 - Use more augmented assignment statements ([#4315](https:/dbt-labs/dbt-core/issues/4315)), ([#4311](https:/dbt-labs/dbt-core/pull/4331))
 - Adjust logic when finding approximate matches for models and tests ([#3835](https:/dbt-labs/dbt-core/issues/3835)), [#4076](https:/dbt-labs/dbt-core/pull/4076))
+- Restore small previous behaviors for logging: JSON formatting for first few events; `WARN`-level stdout for `list` task; include tracking events in `dbt.log` ([#4341](https:/dbt-labs/dbt-core/pull/4341))
 
 Contributors:
 - [@sarah-weatherbee](https:/sarah-weatherbee) ([#4331](https:/dbt-labs/dbt-core/pull/4331))

core/dbt/events/functions.py

@@ -40,15 +40,15 @@
 invocation_id: Optional[str] = None
 
 
-def setup_event_logger(log_path):
+def setup_event_logger(log_path, level_override=None):
  make_log_dir_if_missing(log_path)
  this.format_json = flags.LOG_FORMAT == 'json'
  # USE_COLORS can be None if the app just started and the cli flags
  # havent been applied yet
  this.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 = logging.DEBUG if flags.DEBUG else logging.INFO
+ level = level_override or (logging.DEBUG if flags.DEBUG else logging.INFO)
 
  # overwrite the STDOUT_LOG logger with the configured one
  this.STDOUT_LOG = logging.getLogger('configured_std_out')

core/dbt/events/types.py

@@ -137,7 +137,7 @@ def message(self):
 
 
 @dataclass
-class MainTrackingUserState(DebugLevel, Cli):
+class MainTrackingUserState(DebugLevel, Cli, File):
  user_state: str
  code: str = "A003"
 
@@ -2365,7 +2365,7 @@ def message(self) -> str:
 
 
 @dataclass
-class SendingEvent(DebugLevel, Cli):
+class SendingEvent(DebugLevel, Cli, File):
  kwargs: str
  code: str = "Z040"
 

core/dbt/main.py

@@ -223,7 +223,8 @@ def run_from_args(parsed):
 
  # we can now use the logger for stdout
  # set log_format in the logger
- parsed.cls.pre_init_hook(parsed)
+ # if 'list' task: set stdout to WARN instead of INFO
+ level_override = parsed.cls.pre_init_hook(parsed)
 
  fire_event(MainReportVersion(v=dbt.version.installed))
 
@@ -237,7 +238,7 @@ def run_from_args(parsed):
  log_path = getattr(task.config, 'log_path', None)
  # we can finally set the file logger up
  log_manager.set_path(log_path)
- setup_event_logger(log_path or 'logs')
+ setup_event_logger(log_path or 'logs', level_override)
  if dbt.tracking.active_user is not None: # mypy appeasement, always true
  fire_event(MainTrackingUserState(dbt.tracking.active_user.state()))
 

core/dbt/task/base.py

@@ -15,6 +15,7 @@
  InternalException
 )
 from dbt.logger import log_manager
+import dbt.events.functions as event_logger
 from dbt.events.functions import fire_event
 from dbt.events.types import (
  DbtProjectError, DbtProjectErrorException, DbtProfileError, DbtProfileErrorException,
@@ -64,13 +65,19 @@ def pre_init_hook(cls, args):
  """A hook called before the task is initialized."""
  if args.log_format == 'json':
  log_manager.format_json()
+ # we're mutating the initialized, but not-yet-configured event logger
+ # because it's being configured too late -- bad! TODO refactor!
+ event_logger.format_json = True
  else:
  log_manager.format_text()
 
  @classmethod
  def set_log_format(cls):
  if flags.LOG_FORMAT == 'json':
  log_manager.format_json()
+ # we're mutating the initialized, but not-yet-configured event logger
+ # because it's being configured too late -- bad! TODO refactor!
+ event_logger.format_json = True
  else:
  log_manager.format_text()
 

core/dbt/task/list.py

@@ -11,6 +11,8 @@
 from dbt.node_types import NodeType
 from dbt.exceptions import RuntimeException, InternalException, warn_or_error
 from dbt.logger import log_manager
+import logging
+import dbt.events.functions as event_logger
 
 
 class ListTask(GraphRunnableTask):
@@ -55,8 +57,17 @@ def __init__(self, args, config):
  @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()
+ event_logger.STDOUT_LOG.level = logging.WARN
  super().pre_init_hook(args)
+ return logging.WARN
 
  def _iterate_selected_nodes(self):
  selector = self.get_node_selector()