From 1f9f98cc57dbd64f9f012c7ead8615a26d38be77 Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Thu, 25 Nov 2021 13:40:21 +0100 Subject: [PATCH 1/9] Log formatting from flags earlier --- core/dbt/task/base.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/core/dbt/task/base.py b/core/dbt/task/base.py index 9bc6171dcda..45a75ed94d9 100644 --- a/core/dbt/task/base.py +++ b/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,6 +65,7 @@ def pre_init_hook(cls, args): """A hook called before the task is initialized.""" if args.log_format == 'json': log_manager.format_json() + event_logger.format_json = True else: log_manager.format_text() @@ -71,6 +73,7 @@ def pre_init_hook(cls, args): def set_log_format(cls): if flags.LOG_FORMAT == 'json': log_manager.format_json() + event_logger.format_json = True else: log_manager.format_text() From 88dbe5d536cb2c751691d477f6be1d746d2ea267 Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Thu, 25 Nov 2021 13:40:51 +0100 Subject: [PATCH 2/9] WARN-level stdout for list task --- core/dbt/events/functions.py | 2 +- core/dbt/task/list.py | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index dfc5b60b026..cf501239d61 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -48,7 +48,7 @@ def setup_event_logger(log_path): 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 = logging.DEBUG if flags.DEBUG else this.STDOUT_LOG.level # overwrite the STDOUT_LOG logger with the configured one this.STDOUT_LOG = logging.getLogger('configured_std_out') diff --git a/core/dbt/task/list.py b/core/dbt/task/list.py index 8d34d2da7c5..f3c8d6b15cd 100644 --- a/core/dbt/task/list.py +++ b/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): @@ -56,6 +58,7 @@ def __init__(self, args, config): def pre_init_hook(cls, args): """A hook called before the task is initialized.""" log_manager.stderr_console() + event_logger.STDOUT_LOG.level = logging.WARN super().pre_init_hook(args) def _iterate_selected_nodes(self): From 6cece1ca2be94182e4a6cd3ae6d0d3093ea0d640 Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Thu, 25 Nov 2021 14:29:34 +0100 Subject: [PATCH 3/9] Readd tracking events to File --- core/dbt/events/types.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 4ec722d2583..4d00bfaa590 100644 --- a/core/dbt/events/types.py +++ b/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" From 5508fa230b26f51c01ce0b9789f12111620ebd92 Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Mon, 29 Nov 2021 17:58:20 +0100 Subject: [PATCH 4/9] PR feedback, annotate hacks --- core/dbt/task/base.py | 7 +++++++ core/dbt/task/list.py | 9 +++++++-- 2 files changed, 14 insertions(+), 2 deletions(-) diff --git a/core/dbt/task/base.py b/core/dbt/task/base.py index 45a75ed94d9..c40d034bcc6 100644 --- a/core/dbt/task/base.py +++ b/core/dbt/task/base.py @@ -15,6 +15,7 @@ InternalException ) from dbt.logger import log_manager +import logging import dbt.events.functions as event_logger from dbt.events.functions import fire_event from dbt.events.types import ( @@ -63,6 +64,9 @@ def __init__(self, args, config): @classmethod def pre_init_hook(cls, args): """A hook called before the task is initialized.""" + # the event logger has been initialized, but it has not yet been configured + # TODO refactor + event_logger.STDOUT_LOG.level = logging.DEBUG if args.debug else logging.INFO if args.log_format == 'json': log_manager.format_json() event_logger.format_json = True @@ -71,6 +75,9 @@ def pre_init_hook(cls, args): @classmethod def set_log_format(cls): + # the event logger has been initialized, but it has not yet been configured + # TODO refactor + event_logger.STDOUT_LOG.level = logging.DEBUG if flags.DEBUG else logging.INFO if flags.LOG_FORMAT == 'json': log_manager.format_json() event_logger.format_json = True diff --git a/core/dbt/task/list.py b/core/dbt/task/list.py index f3c8d6b15cd..ce3ca13f54e 100644 --- a/core/dbt/task/list.py +++ b/core/dbt/task/list.py @@ -57,9 +57,14 @@ def __init__(self, args, config): @classmethod def pre_init_hook(cls, args): """A hook called before the task is initialized.""" - log_manager.stderr_console() - event_logger.STDOUT_LOG.level = logging.WARN super().pre_init_hook(args) + log_manager.stderr_console() + # filter out all INFO-level logging to allow piping ls output to jq, etc + # WARN level will still include all warnings + errors + # if user has specified DEBUG level (dbt --debug), don't override + # TODO refactor! + if event_logger.STDOUT_LOG.level == logging.INFO: + event_logger.STDOUT_LOG.level = logging.WARN def _iterate_selected_nodes(self): selector = self.get_node_selector() From 1799721ed74a7df026b61602a025d6df6aab659a Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Mon, 29 Nov 2021 18:13:34 +0100 Subject: [PATCH 5/9] Revert "PR feedback, annotate hacks" This reverts commit 5508fa230b26f51c01ce0b9789f12111620ebd92. --- core/dbt/task/base.py | 7 ------- core/dbt/task/list.py | 9 ++------- 2 files changed, 2 insertions(+), 14 deletions(-) diff --git a/core/dbt/task/base.py b/core/dbt/task/base.py index c40d034bcc6..45a75ed94d9 100644 --- a/core/dbt/task/base.py +++ b/core/dbt/task/base.py @@ -15,7 +15,6 @@ InternalException ) from dbt.logger import log_manager -import logging import dbt.events.functions as event_logger from dbt.events.functions import fire_event from dbt.events.types import ( @@ -64,9 +63,6 @@ def __init__(self, args, config): @classmethod def pre_init_hook(cls, args): """A hook called before the task is initialized.""" - # the event logger has been initialized, but it has not yet been configured - # TODO refactor - event_logger.STDOUT_LOG.level = logging.DEBUG if args.debug else logging.INFO if args.log_format == 'json': log_manager.format_json() event_logger.format_json = True @@ -75,9 +71,6 @@ def pre_init_hook(cls, args): @classmethod def set_log_format(cls): - # the event logger has been initialized, but it has not yet been configured - # TODO refactor - event_logger.STDOUT_LOG.level = logging.DEBUG if flags.DEBUG else logging.INFO if flags.LOG_FORMAT == 'json': log_manager.format_json() event_logger.format_json = True diff --git a/core/dbt/task/list.py b/core/dbt/task/list.py index ce3ca13f54e..f3c8d6b15cd 100644 --- a/core/dbt/task/list.py +++ b/core/dbt/task/list.py @@ -57,14 +57,9 @@ def __init__(self, args, config): @classmethod def pre_init_hook(cls, args): """A hook called before the task is initialized.""" - super().pre_init_hook(args) log_manager.stderr_console() - # filter out all INFO-level logging to allow piping ls output to jq, etc - # WARN level will still include all warnings + errors - # if user has specified DEBUG level (dbt --debug), don't override - # TODO refactor! - if event_logger.STDOUT_LOG.level == logging.INFO: - event_logger.STDOUT_LOG.level = logging.WARN + event_logger.STDOUT_LOG.level = logging.WARN + super().pre_init_hook(args) def _iterate_selected_nodes(self): selector = self.get_node_selector() From d9bcf34e70d4d26bbbe5072782e8954acba9196b Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Mon, 29 Nov 2021 18:21:22 +0100 Subject: [PATCH 6/9] This is maybe better --- core/dbt/events/functions.py | 4 ++-- core/dbt/main.py | 4 ++-- core/dbt/task/list.py | 8 ++++++++ 3 files changed, 12 insertions(+), 4 deletions(-) diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index cf501239d61..67cadef2cf2 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -40,7 +40,7 @@ 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 @@ -48,7 +48,7 @@ def setup_event_logger(log_path): 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 this.STDOUT_LOG.level + 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') diff --git a/core/dbt/main.py b/core/dbt/main.py index fac1eca64ab..ece452fef32 100644 --- a/core/dbt/main.py +++ b/core/dbt/main.py @@ -223,7 +223,7 @@ 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) + level_override = parsed.cls.pre_init_hook(parsed) fire_event(MainReportVersion(v=dbt.version.installed)) @@ -237,7 +237,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())) diff --git a/core/dbt/task/list.py b/core/dbt/task/list.py index f3c8d6b15cd..741022c8033 100644 --- a/core/dbt/task/list.py +++ b/core/dbt/task/list.py @@ -57,9 +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() From 9695a0575a43a954381371ad1a44f7a8927696a9 Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Mon, 29 Nov 2021 18:22:48 +0100 Subject: [PATCH 7/9] Annotate main.py --- core/dbt/main.py | 1 + 1 file changed, 1 insertion(+) diff --git a/core/dbt/main.py b/core/dbt/main.py index ece452fef32..00b4e70e804 100644 --- a/core/dbt/main.py +++ b/core/dbt/main.py @@ -223,6 +223,7 @@ def run_from_args(parsed): # we can now use the logger for stdout # set log_format in the logger + # 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)) From 291d68043dc27020d177114e403de485c998a6d9 Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Mon, 29 Nov 2021 18:27:48 +0100 Subject: [PATCH 8/9] One more comment in base.py --- core/dbt/task/base.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/core/dbt/task/base.py b/core/dbt/task/base.py index 45a75ed94d9..62406c677aa 100644 --- a/core/dbt/task/base.py +++ b/core/dbt/task/base.py @@ -65,6 +65,8 @@ 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() @@ -73,6 +75,8 @@ def pre_init_hook(cls, args): 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() From afd8201bc2397d8a8ac6f3ab47693fe7966ea10a Mon Sep 17 00:00:00 2001 From: Jeremy Cohen Date: Mon, 29 Nov 2021 18:38:15 +0100 Subject: [PATCH 9/9] Update changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index dd89e5d8dfe..a423535609e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ ### Under the hood - Change some CompilationExceptions to ParsingExceptions ([#4254](http://github.com/dbt-labs/dbt-core/issues/4254), [#4328](https://github.com/dbt-core/pull/4328)) - Reorder logic for static parser sampling to speed up model parsing ([#4332](https://github.com/dbt-labs/dbt-core/pull/4332)) +- 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://github.com/dbt-labs/dbt-core/pull/4341)) ## dbt-core 1.0.0rc2 (November 22, 2021)