Add error to telemetry

Remove debug print

Remove debug print

Update test to cover error type

Add UUID to telemetry data based on the command execution flow

Update tests

Add flag to indicate if error is expected or not

Add result event and start, end time for command execution

Add duration time

Rename function name

src/snowflake/cli/api/commands/execution_metadata.py

@@ -0,0 +1,39 @@
+# Copyright (c) 2024 Snowflake Inc.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+import time
+from dataclasses import dataclass
+from enum import Enum
+
+
+class ExecutionStatus(Enum):
+    SUCCESS = "success"
+    FAILURE = "failure"
+
+
+@dataclass
+class ExecutionMetadata:
+    execution_id: str
+    start_time: float = 0
+    end_time: float = 0
+    status: ExecutionStatus = ExecutionStatus.SUCCESS
+
+    def __post_init__(self):
+        self.start_time = time.monotonic()
+
+    def complete(self, status: ExecutionStatus):
+        self.end_time = time.monotonic()
+        self.status = status
+
+    def duration(self):
+        return self.end_time - self.start_time

src/snowflake/cli/api/commands/snow_typer.py

@@ -16,6 +16,7 @@
 
 import dataclasses
 import logging
+import uuid
 from functools import wraps
 from typing import Any, Callable, Dict, List, Optional, Tuple
 
@@ -24,6 +25,10 @@
     global_options,
     global_options_with_connection,
 )
+from snowflake.cli.api.commands.execution_metadata import (
+    ExecutionMetadata,
+    ExecutionStatus,
+)
 from snowflake.cli.api.commands.flags import DEFAULT_CONTEXT_SETTINGS
 from snowflake.cli.api.commands.typer_pre_execute import run_pre_execute_commands
 from snowflake.cli.api.exceptions import CommandReturnTypeError
@@ -91,15 +96,18 @@ def custom_command(command_callable):
             @wraps(command_callable)
             def command_callable_decorator(*args, **kw):
                 """Wrapper around command callable. This is what happens at "runtime"."""
-                self.pre_execute()
+                execution = ExecutionMetadata(uuid.uuid4().hex)
+                self.pre_execute(execution)
                 try:
                     result = command_callable(*args, **kw)
-                    return self.process_result(result)
+                    self.process_result(result)
+                    execution.complete(ExecutionStatus.SUCCESS)
                 except Exception as err:
-                    self.exception_handler(err)
+                    execution.complete(ExecutionStatus.FAILURE)
+                    self.exception_handler(err, execution)
                     raise
                 finally:
-                    self.post_execute()
+                    self.post_execute(execution)
 
             return super(SnowTyper, self).command(name=name, **kwargs)(
                 command_callable_decorator
@@ -108,7 +116,7 @@ def command_callable_decorator(*args, **kw):
         return custom_command
 
     @staticmethod
-    def pre_execute():
+    def pre_execute(execution: ExecutionMetadata):
         """
         Callback executed before running any command callable (after context execution).
         Pay attention to make this method safe to use if performed operations are not necessary
@@ -118,7 +126,7 @@ def pre_execute():
 
         log.debug("Executing command pre execution callback")
         run_pre_execute_commands()
-        log_command_usage()
+        log_command_usage(execution)
 
     @staticmethod
     def process_result(result):
@@ -134,21 +142,25 @@ def process_result(result):
         print_result(result)
 
     @staticmethod
-    def exception_handler(exception: Exception):
+    def exception_handler(exception: Exception, execution: ExecutionMetadata):
         """
         Callback executed on command execution error.
         """
+        from snowflake.cli.app.telemetry import log_command_execution_error
+
         log.debug("Executing command exception callback")
+        log_command_execution_error(exception, execution)
 
     @staticmethod
-    def post_execute():
+    def post_execute(execution: ExecutionMetadata):
         """
         Callback executed after running any command callable. Pay attention to make this method safe to
         use if performed operations are not necessary for executing the command in proper way.
         """
-        from snowflake.cli.app.telemetry import flush_telemetry
+        from snowflake.cli.app.telemetry import flush_telemetry, log_command_result
 
         log.debug("Executing command post execution callback")
+        log_command_result(execution)
         flush_telemetry()
 
 

src/snowflake/cli/app/telemetry.py

@@ -23,6 +23,7 @@
 from snowflake.cli.__about__ import VERSION
 from snowflake.cli.api.cli_global_context import cli_context
 from snowflake.cli.api.config import get_feature_flags_section
+from snowflake.cli.api.execution_metadata import ExecutionMetadata
 from snowflake.cli.api.output.formats import OutputFormat
 from snowflake.cli.api.utils.error_handling import ignore_exceptions
 from snowflake.cli.app.constants import PARAM_APPLICATION_NAME
@@ -44,19 +45,25 @@ class CLITelemetryField(Enum):
     COMMAND = "command"
     COMMAND_GROUP = "command_group"
     COMMAND_FLAGS = "command_flags"
+    COMMAND_EXECUTION_ID = "command_execution_id"
+    COMMAND_RESULT_STATUS = "command_result_status"
     COMMAND_OUTPUT_TYPE = "command_output_type"
+    COMMAND_EXECUTION_TIME = "command_execution_time"
     # Configuration
     CONFIG_FEATURE_FLAGS = "config_feature_flags"
     # Information
     EVENT = "event"
     ERROR_MSG = "error_msg"
     ERROR_TYPE = "error_type"
+    IS_CLI_EXCEPTION = "is_cli_exception"
     # Project context
     PROJECT_DEFINITION_VERSION = "project_definition_version"
 
 
 class TelemetryEvent(Enum):
     CMD_EXECUTION = "executing_command"
+    CMD_EXECUTION_ERROR = "error_executing_command"
+    CMD_EXECUTION_RESULT = "result_executing_command"
 
 
 TelemetryDict = Dict[Union[CLITelemetryField, TelemetryField], Any]
@@ -141,8 +148,40 @@ def flush(self):
 
 
 @ignore_exceptions()
-def log_command_usage():
-    _telemetry.send({TelemetryField.KEY_TYPE: TelemetryEvent.CMD_EXECUTION.value})
+def log_command_usage(execution: ExecutionMetadata):
+    _telemetry.send(
+        {
+            TelemetryField.KEY_TYPE: TelemetryEvent.CMD_EXECUTION.value,
+            CLITelemetryField.COMMAND_EXECUTION_ID: execution.execution_id,
+        }
+    )
+
+
+@ignore_exceptions()
+def log_command_result(execution: ExecutionMetadata):
+    _telemetry.send(
+        {
+            TelemetryField.KEY_TYPE: TelemetryEvent.CMD_EXECUTION_RESULT.value,
+            CLITelemetryField.COMMAND_EXECUTION_ID: execution.execution_id,
+            CLITelemetryField.COMMAND_RESULT_STATUS: execution.status.value,
+            CLITelemetryField.COMMAND_EXECUTION_TIME: execution.duration(),
+        }
+    )
+
+
+@ignore_exceptions()
+def log_command_execution_error(exception: Exception, execution: ExecutionMetadata):
+    exception_type: str = type(exception).__name__
+    is_cli_exception: bool = issubclass(exception.__class__, click.ClickException)
+    _telemetry.send(
+        {
+            TelemetryField.KEY_TYPE: TelemetryEvent.CMD_EXECUTION_ERROR.value,
+            CLITelemetryField.COMMAND_EXECUTION_ID: execution.execution_id,
+            CLITelemetryField.ERROR_TYPE: exception_type,
+            CLITelemetryField.IS_CLI_EXCEPTION: is_cli_exception,
+            CLITelemetryField.COMMAND_EXECUTION_TIME: execution.duration(),
+        }
+    )
 
 
 @ignore_exceptions()

tests/api/commands/test_snow_typer.py

@@ -11,7 +11,6 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-
 from functools import partial
 from unittest import mock
 from unittest.mock import MagicMock
@@ -31,24 +30,24 @@ def class_factory(
 ):
     class _CustomTyper(SnowTyper):
         @staticmethod
-        def pre_execute():
+        def pre_execute(execution):
             if pre_execute:
-                pre_execute()
+                pre_execute(execution)
 
         @staticmethod
-        def post_execute():
+        def post_execute(execution):
             if post_execute:
-                post_execute()
+                post_execute(execution)
 
         @staticmethod
         def process_result(result):
             if result_handler:
                 result_handler(result)
 
         @staticmethod
-        def exception_handler(err):
+        def exception_handler(err, execution):
             if exception_handler:
-                exception_handler(err)
+                exception_handler(err, execution)
 
         def create_instance(self):
             return self
@@ -192,8 +191,9 @@ def test_enabled_command_is_not_visible(cli, os_agnostic_snapshot):
 @mock.patch("snowflake.cli.app.telemetry.log_command_usage")
 def test_snow_typer_pre_execute_sends_telemetry(mock_log_command_usage, cli):
     result = cli(app_factory(SnowTyperFactory))(["simple_cmd", "Norma"])
+
     assert result.exit_code == 0
-    mock_log_command_usage.assert_called_once_with()
+    mock_log_command_usage.assert_called_once_with(mock.ANY)
 
 
 @mock.patch("snowflake.cli.app.telemetry.flush_telemetry")

tests/app/test_telemetry.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 
 import os
+import uuid
 from unittest import mock
 
 from snowflake.connector.version import VERSION as DRIVER_VERSION
@@ -22,25 +23,30 @@
     "snowflake.cli.app.telemetry.python_version",
 )
 @mock.patch("snowflake.cli.app.telemetry.platform.platform")
+@mock.patch("uuid.uuid4")
 @mock.patch("snowflake.cli.app.telemetry.get_time_millis")
 @mock.patch("snowflake.connector.connect")
 @mock.patch("snowflake.cli.plugins.connection.commands.ObjectManager")
 @mock.patch.dict(os.environ, {"SNOWFLAKE_CLI_FEATURES_FOO": "False"})
-def test_executing_command_sends_telemetry_data(
-    _, mock_conn, mock_time, mock_platform, mock_version, runner
+def test_executing_command_sends_telemetry_usage_data(
+    _, mock_conn, mock_time, mock_uuid4, mock_platform, mock_version, runner
 ):
     mock_time.return_value = "123"
     mock_platform.return_value = "FancyOS"
     mock_version.return_value = "2.3.4"
-
+    mock_uuid4.return_value = uuid.UUID("8a2225b3800c4017a4a9eab941db58fa")
     result = runner.invoke(["connection", "test"], catch_exceptions=False)
     assert result.exit_code == 0, result.output
-
     # The method is called with a TelemetryData type, so we cast it to dict for simpler comparison
-    actual_call = mock_conn.return_value._telemetry.try_add_log_to_batch.call_args.args[  # noqa: SLF001
-        0
-    ].to_dict()
-    assert actual_call == {
+    usage_command_event = (
+        mock_conn.return_value._telemetry.try_add_log_to_batch.call_args_list[  # noqa: SLF001
+            0
+        ]
+        .args[0]
+        .to_dict()
+    )
+
+    assert usage_command_event == {
         "message": {
             "driver_type": "PythonConnector",
             "driver_version": ".".join(str(s) for s in DRIVER_VERSION[:3]),
@@ -50,6 +56,7 @@ def test_executing_command_sends_telemetry_data(
             "version_python": "2.3.4",
             "command": ["connection", "test"],
             "command_group": "connection",
+            "command_execution_id": "8a2225b3800c4017a4a9eab941db58fa",
             "command_flags": {"diag_log_path": "DEFAULT", "format": "DEFAULT"},
             "command_output_type": "TABLE",
             "type": "executing_command",
@@ -64,18 +71,78 @@ def test_executing_command_sends_telemetry_data(
     }
 
 
+@mock.patch(
+    "snowflake.cli.app.telemetry.python_version",
+)
+@mock.patch("snowflake.cli.app.telemetry.platform.platform")
+@mock.patch("uuid.uuid4")
+@mock.patch("snowflake.connector.time_util.get_time_millis")
+@mock.patch("snowflake.connector.connect")
+@mock.patch("snowflake.cli.plugins.connection.commands.ObjectManager")
+@mock.patch.dict(os.environ, {"SNOWFLAKE_CLI_FEATURES_FOO": "False"})
+def test_executing_command_sends_telemetry_result_data(
+    _, mock_conn, mock_time, mock_uuid4, mock_platform, mock_version, runner
+):
+    mock_time.return_value = "123"
+    mock_platform.return_value = "FancyOS"
+    mock_version.return_value = "2.3.4"
+    mock_uuid4.return_value = uuid.UUID("8a2225b3800c4017a4a9eab941db58fa")
+    result = runner.invoke(["connection", "test"], catch_exceptions=False)
+    assert result.exit_code == 0, result.output
+
+    # The method is called with a TelemetryData type, so we cast it to dict for simpler comparison
+    result_command_event = (
+        mock_conn.return_value._telemetry.try_add_log_to_batch.call_args_list[  # noqa: SLF001
+            1
+        ]
+        .args[0]
+        .to_dict()
+    )
+    assert (
+        result_command_event["message"]["type"] == "result_executing_command"
+        and result_command_event["message"]["command_result_status"] == "success"
+        and result_command_event["message"]["command_execution_time"]
+    )
+
+
 @mock.patch("snowflake.connector.connect")
 @mock.patch("snowflake.cli.plugins.streamlit.commands.StreamlitManager")
 def test_executing_command_sends_project_definition_in_telemetry_data(
     _, mock_conn, project_directory, runner
 ):
-
     with project_directory("streamlit_full_definition"):
-        result = runner.invoke(["streamlit", "deploy"], catch_exceptions=False)
+        result = runner.invoke(["streamlit", "deploy"])
     assert result.exit_code == 0, result.output
 
     # The method is called with a TelemetryData type, so we cast it to dict for simpler comparison
     actual_call = mock_conn.return_value._telemetry.try_add_log_to_batch.call_args.args[  # noqa: SLF001
         0
     ].to_dict()
     assert actual_call["message"]["project_definition_version"] == "1"
+
+
+@mock.patch("snowflake.connector.connect")
+@mock.patch("uuid.uuid4")
+@mock.patch("snowflake.cli.plugins.streamlit.commands.StreamlitManager")
+def test_failing_executing_command_sends_telemetry_data(
+    _, mock_uuid4, mock_conn, project_directory, runner
+):
+    mock_uuid4.return_value = uuid.UUID("8a2225b3800c4017a4a9eab941db58fa")
+    with project_directory("napp_post_deploy_missing_file"):
+        runner.invoke(["app", "run"], catch_exceptions=False)
+
+    # The method is called with a TelemetryData type, so we cast it to dict for simpler comparison
+    result_command_event = (
+        mock_conn.return_value._telemetry.try_add_log_to_batch.call_args_list[  # noqa: SLF001
+            1
+        ]
+        .args[0]
+        .to_dict()
+    )
+    assert (
+        result_command_event["message"]["type"] == "error_executing_command"
+        and result_command_event["message"]["error_type"] == "SourceNotFoundError"
+        and result_command_event["message"]["is_cli_exception"] == True
+        and result_command_event["message"]["command_execution_id"]
+        == "8a2225b3800c4017a4a9eab941db58fa"
+    )