fix: split cold start metric from application metrics to prevent duplicate app metrics

CHANGELOG.md

@@ -6,6 +6,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Fixed
+- **Metrics**: Cold start metric is now completely separate from application metrics dimensions, making it easier and cheaper to visualize.
+    - This is a breaking change if you were graphing/alerting on both application metrics with the same name to compensate this previous malfunctioning
+    - Marked as bugfix as this is the intended behaviour since the beginning, as you shouldn't have the same application metric with different dimensions
+
 ## [1.3.1] - 2020-08-22
 ### Fixed
 - **Tracer**: capture_method decorator did not properly handle nested context managers
@@ -44,7 +49,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [1.0.1] - 2020-07-06
 ### Fixed
-- **Logger**: Fix a bug with `inject_lambda_context` causing existing an Logger keys to be overriden if `structure_logs` was called before
+- **Logger**: Fix a bug with `inject_lambda_context` causing existing Logger keys to be overridden if `structure_logs` was called before
 
 ## [1.0.0] - 2020-06-18
 ### Added
@@ -114,7 +119,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [0.8.0] - 2020-04-24
 ### Added
-- **Logger**: Introduced `Logger` class for stuctured logging as a replacement for `logger_setup`
+- **Logger**: Introduced `Logger` class for structured logging as a replacement for `logger_setup`
 - **Logger**: Introduced `Logger.inject_lambda_context` decorator as a replacement for `logger_inject_lambda_context`
 
 ### Removed

aws_lambda_powertools/metrics/base.py

@@ -177,7 +177,7 @@ def serialize_metric_set(self, metrics: Dict = None, dimensions: Dict = None, me
         if self.service and not self.dimension_set.get("service"):
             self.dimension_set["service"] = self.service
 
-        logger.debug("Serializing...", {"metrics": metrics, "dimensions": dimensions})
+        logger.debug({"details": "Serializing metrics", "metrics": metrics, "dimensions": dimensions})
 
         metric_names_and_units: List[Dict[str, str]] = []  # [ { "Name": "metric_name", "Unit": "Count" } ]
         metric_names_and_values: Dict[str, str] = {}  # { "metric_name": 1.0 }
@@ -207,7 +207,7 @@ def serialize_metric_set(self, metrics: Dict = None, dimensions: Dict = None, me
         }
 
         try:
-            logger.debug("Validating serialized metrics against CloudWatch EMF schema", embedded_metrics_object)
+            logger.debug("Validating serialized metrics against CloudWatch EMF schema")
             fastjsonschema.validate(definition=CLOUDWATCH_EMF_SCHEMA, data=embedded_metrics_object)
         except fastjsonschema.JsonSchemaException as e:
             message = f"Invalid format. Error: {e.message}, Invalid item: {e.name}"  # noqa: B306, E501

aws_lambda_powertools/metrics/metric.py

@@ -110,8 +110,6 @@ def single_metric(name: str, unit: MetricUnit, value: float, namespace: str = No
         metric: SingleMetric = SingleMetric(namespace=namespace)
         metric.add_metric(name=name, unit=unit, value=value)
         yield metric
-        logger.debug("Serializing single metric")
         metric_set: Dict = metric.serialize_metric_set()
     finally:
-        logger.debug("Publishing single metric", {"metric": metric})
         print(json.dumps(metric_set))

aws_lambda_powertools/metrics/metrics.py

@@ -4,7 +4,8 @@
 import warnings
 from typing import Any, Callable
 
-from .base import MetricManager
+from .base import MetricManager, MetricUnit
+from .metric import single_metric
 
 logger = logging.getLogger(__name__)
 
@@ -149,7 +150,6 @@ def decorate(event, context):
                 else:
                     metrics = self.serialize_metric_set()
                     self.clear_metrics()
-                    logger.debug("Publishing metrics", {"metrics": metrics})
                     print(json.dumps(metrics))
 
             return response
@@ -167,6 +167,7 @@ def __add_cold_start_metric(self, context: Any):
         global is_cold_start
         if is_cold_start:
             logger.debug("Adding cold start metric and function_name dimension")
-            self.add_metric(name="ColdStart", value=1, unit="Count")
-            self.add_dimension(name="function_name", value=context.function_name)
-            is_cold_start = False
+            with single_metric(name="ColdStart", unit=MetricUnit.Count, value=1, namespace=self.namespace) as metric:
+                metric.add_dimension(name="function_name", value=context.function_name)
+                metric.add_dimension(name="service", value=self.service)
+                is_cold_start = False

docs/content/core/metrics.mdx

@@ -238,7 +238,12 @@ def lambda_handler(evt, ctx):
     ...
 ```
 
-If it's a cold start, this feature will add a metric named `ColdStart` and a dimension named `function_name`.
+If it's a cold start invocation, this feature will:
+
+* Create a separate EMF blob solely containing a metric named `ColdStart`
+* Add `function_name` and `service` dimensions
+
+This has the advantage of keeping cold start metric separate from your application metrics.
 
 ## Testing your code
 

tests/functional/test_metrics.py

@@ -7,13 +7,15 @@
 
 from aws_lambda_powertools import Metrics, single_metric
 from aws_lambda_powertools.metrics import MetricUnit, MetricUnitError, MetricValueError, SchemaValidationError
+from aws_lambda_powertools.metrics import metrics as metrics_global
 from aws_lambda_powertools.metrics.base import MetricManager
 
 
 @pytest.fixture(scope="function", autouse=True)
 def reset_metric_set():
     metrics = Metrics()
     metrics.clear_metrics()
+    metrics_global.is_cold_start = True  # ensure each test has cold start
     yield
 
 
@@ -112,6 +114,10 @@ def capture_metrics_output(capsys):
     return json.loads(capsys.readouterr().out.strip())
 
 
+def capture_metrics_output_multiple_emf_objects(capsys):
+    return [json.loads(line.strip()) for line in capsys.readouterr().out.split("\n") if line]
+
+
 def test_single_metric_logs_one_metric_only(capsys, metric, dimension, namespace):
     # GIVEN we try adding more than one metric
     # WHEN using single_metric context manager
@@ -495,7 +501,7 @@ def lambda_handler(evt, context):
 
     LambdaContext = namedtuple("LambdaContext", "function_name")
     lambda_handler({}, LambdaContext("example_fn"))
-    _ = capture_metrics_output(capsys)  # ignore first stdout captured
+    _, _ = capture_metrics_output_multiple_emf_objects(capsys)  # ignore first stdout captured
 
     # THEN ColdStart metric and function_name dimension should be logged once
     lambda_handler({}, LambdaContext("example_fn"))
@@ -630,3 +636,38 @@ def test_serialize_metric_set_metric_definition(metric, dimension, namespace, se
     assert "Timestamp" in metric_definition_output["_aws"]
     remove_timestamp(metrics=[metric_definition_output, expected_metric_definition])
     assert metric_definition_output == expected_metric_definition
+
+
+def test_log_metrics_capture_cold_start_metric_separately(capsys, namespace, service, metric, dimension):
+    # GIVEN Metrics is initialized
+    my_metrics = Metrics(service=service, namespace=namespace)
+
+    # WHEN log_metrics is used with capture_cold_start_metric
+    @my_metrics.log_metrics(capture_cold_start_metric=True)
+    def lambda_handler(evt, context):
+        my_metrics.add_metric(**metric)
+        my_metrics.add_dimension(**dimension)
+
+    LambdaContext = namedtuple("LambdaContext", "function_name")
+    lambda_handler({}, LambdaContext("example_fn"))
+
+    cold_start_blob, custom_metrics_blob = capture_metrics_output_multiple_emf_objects(capsys)
+
+    # THEN ColdStart metric and function_name dimension should be logged
+    # in a separate EMF blob than the application metrics
+    assert cold_start_blob["ColdStart"] == 1
+    assert cold_start_blob["function_name"] == "example_fn"
+    assert cold_start_blob["service"] == service
+
+    # and that application metrics dimensions are not part of ColdStart EMF blob
+    assert "test_dimension" not in cold_start_blob
+
+    # THEN application metrics EMF blob should not have
+    # ColdStart metric nor function_name dimension
+    assert "function_name" not in custom_metrics_blob
+    assert "ColdStart" not in custom_metrics_blob
+
+    # and that application metrics are recorded as normal
+    assert custom_metrics_blob["service"] == service
+    assert custom_metrics_blob["single_metric"] == metric["value"]
+    assert custom_metrics_blob["test_dimension"] == dimension["value"]