From 9a7305d43fe908005a61519b3be232916b9251e9 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Wed, 22 Mar 2023 08:45:11 -0700 Subject: [PATCH] CT-2049: Add CommandCompleted event (#7180) * 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. * 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). * add CommandCompleted event to event unit tests * Add: changelog entry * 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 * 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) --- .../Under the Hood-20230316-123305.yaml | 6 +++ core/dbt/cli/requires.py | 37 ++++++++++++++++++- core/dbt/events/proto_types.py | 16 ++++++++ core/dbt/events/types.proto | 13 +++++++ core/dbt/events/types.py | 10 +++++ tests/unit/test_events.py | 2 + 6 files changed, 82 insertions(+), 2 deletions(-) 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" diff --git a/core/dbt/cli/requires.py b/core/dbt/cli/requires.py index adeeb0b485a..5915187ce22 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,33 @@ def wrapper(*args, **kwargs): # Adapter management ctx.with_resource(adapter_management()) - return func(*args, **kwargs) + start_func = time.perf_counter() + + 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) return update_wrapper(wrapper, func) diff --git a/core/dbt/events/proto_types.py b/core/dbt/events/proto_types.py index acb968c2654..a00ab8b9de2 100644 --- a/core/dbt/events/proto_types.py +++ b/core/dbt/events/proto_types.py @@ -2210,6 +2210,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 f7ced23f1d5..41dc8432af5 100644 --- a/core/dbt/events/types.proto +++ b/core/dbt/events/types.proto @@ -1767,6 +1767,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 91c60996226..dd56136b8b4 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1863,6 +1863,16 @@ def message(self) -> str: return "No nodes selected!" +@dataclass +class CommandCompleted(DebugLevel, 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 # ======================================================= diff --git a/tests/unit/test_events.py b/tests/unit/test_events.py index 2b4f8126eea..1d70ebed81d 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 ( @@ -328,6 +329,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=""),