diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index cd117b1931d..a96045d341f 100644 --- a/core/dbt/events/functions.py +++ b/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 +from dbt.events.types import EventBufferFull, T_Event, MainReportVersion 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 @@ -17,6 +17,7 @@ from logging.handlers import RotatingFileHandler import os import uuid +import threading from typing import Any, Callable, Dict, List, Optional, Union import dataclasses from collections import deque @@ -164,12 +165,31 @@ def event_to_serializable_dict( # 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: +def create_stdout_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.get_ts().strftime("%H:%M:%S") scrubbed_msg: str = scrub_secrets(msg_fn(e), env_secrets()) + log_line: str = f"{color_tag}{ts} {scrubbed_msg}" + return log_line + + +def create_file_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str: + log_line: str = '' + # Create a separator if this is the beginning of an invocation + if type(e) == MainReportVersion: + separator = 30 * '=' + log_line = f'\n\n{separator} {e.get_ts()} | {get_invocation_id()} {separator}\n' + color_tag: str = '' if this.format_color else Style.RESET_ALL + ts: str = e.get_ts().strftime("%H:%M:%S.%f") + scrubbed_msg: str = scrub_secrets(msg_fn(e), env_secrets()) level: str = e.level_tag() if len(e.level_tag()) == 5 else f"{e.level_tag()} " - log_line: str = f"{color_tag}{ts} | [ {level} ] | {scrubbed_msg}" + thread = '' + if threading.current_thread().getName(): + thread_name = threading.current_thread().getName() + thread_name = thread_name[:10] + thread_name = thread_name.ljust(10, ' ') + thread = f' [{thread_name}]:' + log_line = log_line + f"{color_tag}{ts} [{level}]{thread} {scrubbed_msg}" return log_line @@ -181,13 +201,14 @@ def create_json_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str: return scrub_secrets(raw_log_line, env_secrets()) -# calls create_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]) -> str: - return ( - create_json_log_line(e, msg_fn) - if this.format_json else - create_text_log_line(e, msg_fn) - ) +# 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: + if this.format_json: + return create_json_log_line(e, msg_fn) # json output, both console and file + elif file_output is True: + return create_file_text_log_line(e, msg_fn) # default file output + else: + return create_stdout_text_log_line(e, msg_fn) # console output # allows for resuse of this obnoxious if else tree. @@ -287,7 +308,7 @@ def fire_event(e: Event) -> None: # 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()) + 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) diff --git a/core/dbt/main.py b/core/dbt/main.py index d82a3bea7c7..befca2fe3f7 100644 --- a/core/dbt/main.py +++ b/core/dbt/main.py @@ -221,24 +221,22 @@ def track_run(task): def run_from_args(parsed): log_cache_events(getattr(parsed, 'log_cache_events', False)) - # 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=str(dbt.version.installed))) - # this will convert DbtConfigErrors into RuntimeExceptions # task could be any one of the task objects task = parsed.cls.from_args(args=parsed) - fire_event(MainReportArgs(args=parsed)) + # Set up logging log_path = None if task.config is not None: log_path = getattr(task.config, 'log_path', None) - # we can finally set the file logger up log_manager.set_path(log_path) + # if 'list' task: set stdout to WARN instead of INFO + level_override = parsed.cls.pre_init_hook(parsed) setup_event_logger(log_path or 'logs', level_override) + + fire_event(MainReportVersion(v=str(dbt.version.installed))) + fire_event(MainReportArgs(args=parsed)) + if dbt.tracking.active_user is not None: # mypy appeasement, always true fire_event(MainTrackingUserState(dbt.tracking.active_user.state()))