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=""),