CT-2049: Add CommandCompleted event (#7180)

* add protobuf message/class for new CommandCompleted event

For [CT-2049](#6878) we
concluded that we wanted a new event type, [CommandCompleted](#6878 (comment))
with [four (4) values](#6878 (comment)):
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](#6878 (comment)).

* 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](#7180 (comment))

.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"

core/dbt/cli/requires.py

@@ -5,15 +5,22 @@
 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
 from dbt.tracking import active_user, initialize_from_flags, track_run
 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)
 

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

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
 # =======================================================

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