Repository: dbt-labs/dbt-core
Pull request: CT-2049: Add CommandCompleted event
resolves #6878 

### Description

[CT-2049](https://github.com/dbt-labs/dbt-core/issues/6878) outlines a desire to have an event that is output on completion of any and every command. This PR adds that functionality. Below is a demo of the functionality in a loom video (clicking will redirect you to loom)

<a href="https://www.loom.com/share/661cb790b6524c4b87ecd90ca3520f00">
    <img style="max-width:300px;" src="https://cdn.loom.com/sessions/thumbnails/661cb790b6524c4b87ecd90ca3520f00-with-play.gif">
</a>

### Checklist

- [x] I have read [the contributing guide](https://github.com/dbt-labs/dbt-core/blob/main/CONTRIBUTING.md) and understand what's expected of me
- [x] I have signed the [CLA](https://docs.getdbt.com/docs/contributor-license-agreements)
- [x] I have run this code in development and it appears to resolve the stated issue
- [x] This PR includes tests, or tests are not required/relevant for this PR
- [x] I have [opened an issue to add/update docs](https://github.com/dbt-labs/docs.getdbt.com/issues/new/choose), or docs changes are not required/relevant for this PR
- [x] I have run `changie new` to [create a changelog entry](https://github.com/dbt-labs/dbt-core/blob/main/CONTRIBUTING.md#adding-a-changelog-entry)


[CT-2049]: https://dbtlabs.atlassian.net/browse/CT-2049?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ

Problem statement:
[CT-2049] Fire an event at the end of every command
On the `feature/click-cli` branch, each command explicitly returns a tuple of `success: bool, results: Any`. (The structure of `results` differs based on the command.)

We should additionally fire an event that can be used programmatically to determine:
- when the command completed
- if the command succeeded

Ideally, this event would be fired _always_, even in cases where the command was interrupted (`^C`) or cancelled itself (e.g. `--fail-fast`).

Hints from issue discussion:
Super agree with this. I suggest that we might want to have a CommandCompleted event that contains the data common to all commands, such as timing and success, and refer to an additional event that would contain more of the specific Result dump. We could do a "oneof" of all of the various Result objects, but the way they work in python protobufs is kind of kludgey and slow. We could even include the name of the Result event in the CommandCompleted event, if that would help.
Discussed during BLG: This event shouldn't include the full result that would be returned from the command if invoked programmatically, à la:
```python
results, success = dbt.invoke(['<command>'])
```
**Rationale:**
- those `results` can be different types (depending on the command), as Gerda mentioned above
- node-level results are already fired as events as soon as the node is finished
- we should already have events that "summarize" a graph-running command (how many nodes, how many succeeded, etc)

This event's `data` only needs to include:
- `which` command
- whether it succeeded (boolean)
- timestamp when it finished
- how long it took

(Plus standard metadata of course - `invocation_id` etc - which should already be present in the event's `info` dict, no specific plumbing needed)
Will need to connect with the Execution Team for where we should fire this event.  Possibly [here](https://github.com/dbt-labs/dbt-core/blob/main/core/dbt/tracking.py#L445-L461)?
Per BLG -- 2/13/23 we'd probably want to do this in the preflight decorator as a generator.  If the language team picks this ticket up feel free to ask for a pair from the Execution team, we'd be happy to show how/where that lives.

Commit message: add CommandCompleted event to event unit tests

Patch to review:
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)
 
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
 # =======================================================
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=""),


Code review comments:
diff_hunk: @@ -1827,6 +1827,16 @@ def message(self) -> str:
         return "No nodes selected!"
 
 
+@dataclass
+class CommandCompleted(InfoLevel, pt.CommandCompleted):
path: core/dbt/events/types.py
text: @user1:
This feels more `DebugLevel` than `InfoLevel` to me - do you feel strongly that it should be in the stdout logs?

@author:
I have no strong opinion. I'm fine with it being a debug 👍

diff_hunk: @@ -0,0 +1,6 @@
+kind: Under the Hood
+body: Add CommandComplete event, and fire it upon completion of every command
path: .changes/unreleased/Under the Hood-20230316-123305.yaml
text: @user1:
Nit: `CommandCompleted` (or just, matching whatever name you picked for the event!)