From ae93100d19874ea467e7304e97d62375632457bc Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Thu, 16 Mar 2023 11:27:55 -0700 Subject: [PATCH 1/6] add protobuf message/class for new CommandCompleted event For [CT-2049](https://github.com/dbt-labs/dbt-core/issues/6878) we concluded that we wanted a new event type, [CommandCompleted](https://github.com/dbt-labs/dbt-core/issues/6878#issuecomment-1419718606) with [four (4) values](https://github.com/dbt-labs/dbt-core/issues/6878#issuecomment-1426118283): which command was run, whether the command succeeded, the timestamp that the command finished, and how long the command took. This commit adds the new event proto defition, the auto generated proto_types, and the instantiatable even type. --- core/dbt/events/proto_types.py | 16 ++++++++++++++++ core/dbt/events/types.proto | 13 +++++++++++++ core/dbt/events/types.py | 10 ++++++++++ 3 files changed, 39 insertions(+) diff --git a/core/dbt/events/proto_types.py b/core/dbt/events/proto_types.py index 24d70ec9947..6ffb7a852cf 100644 --- a/core/dbt/events/proto_types.py +++ b/core/dbt/events/proto_types.py @@ -2184,6 +2184,22 @@ class NoNodesSelectedMsg(betterproto.Message): data: "NoNodesSelected" = betterproto.message_field(2) +@dataclass +class CommandCompleted(betterproto.Message): + """Q039""" + + command: str = betterproto.string_field(1) + success: bool = betterproto.bool_field(2) + completed_at: datetime = betterproto.message_field(3) + elapsed: float = betterproto.float_field(4) + + +@dataclass +class CommandCompletedMsg(betterproto.Message): + info: "EventInfo" = betterproto.message_field(1) + data: "CommandCompleted" = betterproto.message_field(2) + + @dataclass class CatchableExceptionOnRun(betterproto.Message): """W002""" diff --git a/core/dbt/events/types.proto b/core/dbt/events/types.proto index 39a53257e69..33bc6ef751b 100644 --- a/core/dbt/events/types.proto +++ b/core/dbt/events/types.proto @@ -1747,6 +1747,19 @@ message NoNodesSelectedMsg { NoNodesSelected data = 2; } +// Q039 +message CommandCompleted { + string command = 1; + bool success = 2; + google.protobuf.Timestamp completed_at = 3; + float elapsed = 4; +} + +message CommandCompletedMsg { + EventInfo info = 1; + CommandCompleted data = 2; +} + // W - Node testing // Skipped W001 diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 9ff34f84b52..1b3aa199642 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1827,6 +1827,16 @@ def message(self) -> str: return "No nodes selected!" +@dataclass +class CommandCompleted(InfoLevel, pt.CommandCompleted): + def code(self): + return "Q039" + + def message(self) -> str: + status = "succeeded" if self.success else "failed" + return f"Command `{self.command}` {status} at {self.completed_at} after {self.elapsed:0.2f} seconds" + + # ======================================================= # W - Node testing # ======================================================= From 73032780b9a389107f4946e38dd03199cb5246b3 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Thu, 16 Mar 2023 11:39:52 -0700 Subject: [PATCH 2/6] begin emitting CommandCompleted event in the preflight decorator The [preflight decorator](https://github.com/dbt-labs/dbt-core/blob/4186f99b742b47e0e95aca4f604cc09e5c67a449/core/dbt/cli/requires.py#L19) runs at the start of every CLI invocation. Thus is a perfect candidate for emitting the CommandCompleted event. This is noted in the [dicussion on CT-2049](https://github.com/dbt-labs/dbt-core/issues/6878#issuecomment-1428643539). --- core/dbt/cli/requires.py | 24 ++++++++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/core/dbt/cli/requires.py b/core/dbt/cli/requires.py index 57f0df82795..0867e17fe92 100644 --- a/core/dbt/cli/requires.py +++ b/core/dbt/cli/requires.py @@ -5,7 +5,12 @@ from dbt.config import RuntimeConfig from dbt.config.runtime import load_project, load_profile, UnsetProfile from dbt.events.functions import setup_event_logger, fire_event, LOG_VERSION -from dbt.events.types import MainReportVersion, MainReportArgs, MainTrackingUserState +from dbt.events.types import ( + CommandCompleted, + MainReportVersion, + MainReportArgs, + MainTrackingUserState, +) from dbt.exceptions import DbtProjectError from dbt.parser.manifest import ManifestLoader, write_manifest from dbt.profiler import profiler @@ -13,7 +18,9 @@ from dbt.utils import cast_dict_to_dict_of_strings from click import Context +import datetime from functools import update_wrapper +import time def preflight(func): @@ -53,7 +60,20 @@ def wrapper(*args, **kwargs): # Adapter management ctx.with_resource(adapter_management()) - return func(*args, **kwargs) + start_func = time.perf_counter() + + (results, success) = func(*args, **kwargs) + + fire_event( + CommandCompleted( + command=ctx.command_path, + success=success, + completed_at=datetime.datetime.utcnow(), + elapsed=time.perf_counter() - start_func, + ) + ) + + return (results, success) return update_wrapper(wrapper, func) From 0829ff7226c9aca855b24012065a78a8b696dd32 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Thu, 16 Mar 2023 12:09:18 -0700 Subject: [PATCH 3/6] add CommandCompleted event to event unit tests --- tests/unit/test_events.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/unit/test_events.py b/tests/unit/test_events.py index 01e9e576cd2..88441372a4c 100644 --- a/tests/unit/test_events.py +++ b/tests/unit/test_events.py @@ -1,6 +1,7 @@ import re from typing import TypeVar +from datetime import datetime from dbt.contracts.results import TimingInfo from dbt.events import AdapterLogger, test_types, types from dbt.events.base_types import ( @@ -326,6 +327,7 @@ def test_event_codes(self): types.NoNodesSelected(), types.DepsUnpinned(revision="", git=""), types.NoNodesForSelectionCriteria(spec_raw=""), + types.CommandCompleted(command="", success=True, elapsed=0.1, completed_at=datetime.utcnow()), # W - Node testing ====================== types.CatchableExceptionOnRun(exc=""), types.InternalErrorOnRun(build_path="", exc=""), From 9860e1130da9db2684c48b6ad4b9a8f363922998 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Thu, 16 Mar 2023 12:33:53 -0700 Subject: [PATCH 4/6] Add: changelog entry --- .changes/unreleased/Under the Hood-20230316-123305.yaml | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 .changes/unreleased/Under the Hood-20230316-123305.yaml diff --git a/.changes/unreleased/Under the Hood-20230316-123305.yaml b/.changes/unreleased/Under the Hood-20230316-123305.yaml new file mode 100644 index 00000000000..8aace685284 --- /dev/null +++ b/.changes/unreleased/Under the Hood-20230316-123305.yaml @@ -0,0 +1,6 @@ +kind: Under the Hood +body: Add CommandCompleted event, and fire it upon completion of every command +time: 2023-03-16T12:33:05.696752-07:00 +custom: + Author: QMalcolm + Issue: "6878" From 8f81ff8770c72990b99080787bfa166fc42a6f39 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Thu, 16 Mar 2023 13:03:46 -0700 Subject: [PATCH 5/6] fire CommandCompleted event reguardless of upstream exceptions Previously, if `--fail-fast` was specified and an issue was run into or an unhandled issue became an exception, the CommandCompleted event would not get fired because at this point in the stack we'd be in exception thrown handling mode. If an exception does reach this point, we want to still fire the event and also continue to propogate the exception. Hence the bare `raise` exists to reraise the caught exception --- core/dbt/cli/requires.py | 31 ++++++++++++++++++++++--------- 1 file changed, 22 insertions(+), 9 deletions(-) diff --git a/core/dbt/cli/requires.py b/core/dbt/cli/requires.py index 0867e17fe92..3b911a75fd7 100644 --- a/core/dbt/cli/requires.py +++ b/core/dbt/cli/requires.py @@ -62,16 +62,29 @@ def wrapper(*args, **kwargs): start_func = time.perf_counter() - (results, success) = func(*args, **kwargs) - - fire_event( - CommandCompleted( - command=ctx.command_path, - success=success, - completed_at=datetime.datetime.utcnow(), - elapsed=time.perf_counter() - start_func, + try: + (results, success) = func(*args, **kwargs) + + fire_event( + CommandCompleted( + command=ctx.command_path, + success=success, + completed_at=datetime.datetime.utcnow(), + elapsed=time.perf_counter() - start_func, + ) ) - ) + # Bare except because we really do want to catch ALL exceptions, + # i.e. we want to fire this event in ALL cases. + except: # noqa + fire_event( + CommandCompleted( + command=ctx.command_path, + success=False, + completed_at=datetime.datetime.utcnow(), + elapsed=time.perf_counter() - start_func, + ) + ) + raise return (results, success) From 92cec272ca70c276b892bdec412f46a73fe15ec0 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Thu, 16 Mar 2023 13:10:17 -0700 Subject: [PATCH 6/6] Update CommandCompleted event to be a `Debug` level event We don't actually "always" need this event to be logged. Thus we've updated it to `Debug` level. [Discussion Context](https://github.com/dbt-labs/dbt-core/pull/7180#discussion_r1139281963) --- core/dbt/events/types.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 1b3aa199642..f5bcc67fde2 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1828,7 +1828,7 @@ def message(self) -> str: @dataclass -class CommandCompleted(InfoLevel, pt.CommandCompleted): +class CommandCompleted(DebugLevel, pt.CommandCompleted): def code(self): return "Q039"