Repository: meltano/sdk
Pull request #2162 (2024-01-20 00:28:27)

feat: Expose metric dictionary to make logging metrics as JSON easier
<!-- readthedocs-preview meltano-sdk start -->
----
📚 Documentation preview 📚: https://meltano-sdk--2162.org.readthedocs.build/en/2162/

<!-- readthedocs-preview meltano-sdk end -->

## Summary by Sourcery

Expose metric dictionary to make logging metrics as JSON easier.

Enhancements:
- Adds a `to_dict` method to the `Point` class to convert a metric to a dictionary.
- Adds a `SingerMetricsFormatter` class to format metrics as JSON.
- Updates the default logging configuration to include a metrics formatter.
- Updates the `log` function to include the metric dictionary in the log record.
- Updates the documentation to include an example of how to log metrics as JSON.

codspeed-hq[bot]: ## [CodSpeed Performance Report](https://codspeed.io/meltano/sdk/branches/edgarrmondragon/refactor/metrics-json-logging)

### Merging #2162 will **not alter performance**

<sub>Comparing <code>edgarrmondragon/refactor/metrics-json-logging</code> (2c3ec58) with <code>main</code> (ac28095)</sub>



### Summary

`✅ 6` untouched benchmarks





codecov[bot]: ## [Codecov](https://app.codecov.io/gh/meltano/sdk/pull/2162?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano) Report
Attention: `1 lines` in your changes are missing coverage. Please review.
> Comparison is base [(`ac28095`)](https://app.codecov.io/gh/meltano/sdk/commit/ac28095376bd351b7fdaac2b3e9df78856042479?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano) 88.35% compared to head [(`815b748`)](https://app.codecov.io/gh/meltano/sdk/pull/2162?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano) 88.34%.

| [Files](https://app.codecov.io/gh/meltano/sdk/pull/2162?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano) | Patch % | Lines |
|---|---|---|
| [singer\_sdk/metrics.py](https://app.codecov.io/gh/meltano/sdk/pull/2162?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano#diff-c2luZ2VyX3Nkay9tZXRyaWNzLnB5) | 88.88% | [0 Missing and 1 partial :warning: ](https://app.codecov.io/gh/meltano/sdk/pull/2162?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano) |

<details><summary>Additional details and impacted files</summary>


```diff
@@            Coverage Diff             @@
##             main    #2162      +/-   ##
==========================================
- Coverage   88.35%   88.34%   -0.02%     
==========================================
  Files          54       54              
  Lines        4696     4700       +4     
  Branches      957      958       +1     
==========================================
+ Hits         4149     4152       +3     
  Misses        389      389              
- Partials      158      159       +1     
```



</details>

[:umbrella: View full report in Codecov by Sentry](https://app.codecov.io/gh/meltano/sdk/pull/2162?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano).   
:loudspeaker: Have feedback on the report? [Share it here](https://about.codecov.io/codecov-pr-comment-feedback/?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=meltano).

sourcery-ai[bot]: <!-- Generated by sourcery-ai[bot]: start review_guide -->

## Reviewer's Guide by Sourcery

This pull request introduces a new `SingerMetricsFormatter` class that formats metric log records as JSON. It also updates the `log` function to include the metric point in the log record's extra data, and adds a `to_dict` method to the `Point` class to convert a metric point to a dictionary. The default logging configuration and documentation are updated to reflect these changes.

#### Sequence diagram for logging a metric

```mermaid
sequenceDiagram
    participant Logger
    participant metrics.log
    participant Point
    Logger->>metrics.log: info("METRIC", extra={"point": point.to_dict()})
    activate metrics.log
    metrics.log->>Point: to_dict()
    activate Point
    Point-->>metrics.log: Returns dictionary
    deactivate Point
    metrics.log-->>Logger: Returns
    deactivate metrics.log
```

### File-Level Changes

| Change | Details | Files |
| ------ | ------- | ----- |
| Introduces a `SingerMetricsFormatter` class to format metric log records as JSON. | <ul><li>Creates a `SingerMetricsFormatter` class that inherits from `logging.Formatter`.</li><li>Implements a `format` method that adds a `metric_json` field to the log record, containing the JSON representation of the metric point.</li><li>If no point exists, the `metric_json` field will be an empty string.</li></ul> | `singer_sdk/metrics.py` |
| Updates the `log` function to include the metric point in the log record's extra data. | <ul><li>Modifies the `log` function to pass the metric point as part of the `extra` argument to the logger's `info` method.</li><li>The `extra` argument is a dictionary containing the metric point, which will be accessible to the formatter.</li></ul> | `singer_sdk/metrics.py` |
| Adds a `to_dict` method to the `Point` class to convert a metric point to a dictionary. | <ul><li>Adds a `to_dict` method to the `Point` class.</li><li>The `to_dict` method returns a dictionary representation of the metric point, including the metric type, metric name, value, and tags.</li></ul> | `singer_sdk/metrics.py` |
| Updates the default logging configuration to include the new `SingerMetricsFormatter` for the `singer_sdk.metrics` logger. | <ul><li>Adds a `metrics` formatter to the `formatters` section, using the `SingerMetricsFormatter` class.</li><li>Adds a `metrics` handler to the `handlers` section, using the `metrics` formatter.</li><li>Configures the `singer_sdk.metrics` logger to use the `metrics` handler and to not propagate logs to the root logger.</li></ul> | `singer_sdk/default_logging.yml` |
| Updates the documentation to reflect the changes in metric logging. | <ul><li>Updates the documentation to describe how to configure metric logging to output JSON format.</li><li>Provides an example of a logging configuration that sends metrics to a file in JSON format.</li></ul> | `docs/implementation/logging.md` |
| Updates tests to reflect the changes in metric logging. | <ul><li>Adds a test case for the `SingerMetricsFormatter` class.</li><li>Updates existing test cases to assert that the metric point is correctly logged as a dictionary.</li></ul> | `tests/core/test_metrics.py` |

---

<details>
<summary>Tips and commands</summary>

#### Interacting with Sourcery

- **Trigger a new review:** Comment `@sourcery-ai review` on the pull request.
- **Continue discussions:** Reply directly to Sourcery's review comments.
- **Generate a GitHub issue from a review comment:** Ask Sourcery to create an
  issue from a review comment by replying to it. You can also reply to a
  review comment with `@sourcery-ai issue` to create an issue from it.
- **Generate a pull request title:** Write `@sourcery-ai` anywhere in the pull
  request title to generate a title at any time. You can also comment
  `@sourcery-ai title` on the pull request to (re-)generate the title at any time.
- **Generate a pull request summary:** Write `@sourcery-ai summary` anywhere in
  the pull request body to generate a PR summary at any time exactly where you
  want it. You can also comment `@sourcery-ai summary` on the pull request to
  (re-)generate the summary at any time.
- **Generate reviewer's guide:** Comment `@sourcery-ai guide` on the pull
  request to (re-)generate the reviewer's guide at any time.
- **Resolve all Sourcery comments:** Comment `@sourcery-ai resolve` on the
  pull request to resolve all Sourcery comments. Useful if you've already
  addressed all the comments and don't want to see them anymore.
- **Dismiss all Sourcery reviews:** Comment `@sourcery-ai dismiss` on the pull
  request to dismiss all existing Sourcery reviews. Especially useful if you
  want to start fresh with a new review - don't forget to comment
  `@sourcery-ai review` to trigger a new review!
- **Generate a plan of action for an issue:** Comment `@sourcery-ai plan` on
  an issue to generate a plan of action for it.

#### Customizing Your Experience

Access your [dashboard](https://app.sourcery.ai) to:
- Enable or disable review features such as the Sourcery-generated pull request
  summary, the reviewer's guide, and others.
- Change the review language.
- Add, remove or edit custom review instructions.
- Adjust other review settings.

#### Getting Help

- [Contact our support team](mailto:support@sourcery.ai) for questions or feedback.
- Visit our [documentation](https://docs.sourcery.ai) for detailed guides and information.
- Keep in touch with the Sourcery team by following us on [X/Twitter](https://x.com/SourceryAI), [LinkedIn](https://www.linkedin.com/company/sourcery-ai/) or [GitHub](https://github.com/sourcery-ai).

</details>

<!-- Generated by sourcery-ai[bot]: end review_guide -->

Patch:
diff --git a/docs/implementation/logging.md b/docs/implementation/logging.md
index 828fcbc2..e15b2400 100644
--- a/docs/implementation/logging.md
+++ b/docs/implementation/logging.md
@@ -44,38 +44,43 @@ Users of a tap can configure the SDK logging by setting the `SINGER_SDK_LOG_CONF
 environment variable. The value of this variable should be a path to a YAML file in the
 [Python logging dict format](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details).
 
-For example, to send [metrics](./metrics.md) (with logger name `singer_sdk.metrics`) to a file, you could use the following config:
+### Metrics logging
+
+The Singer SDK provides a logger named `singer_sdk.metrics` for logging [Singer metrics](./metrics.md). Metric log records contain an extra field `point` which is a dictionary containing the metric data. The `point` field is formatted as JSON by default.
+
+To send metrics to a file in JSON format, you could use the following config:
 
 ```yaml
 version: 1
 disable_existing_loggers: false
 formatters:
   metrics:
-    format: "{asctime} {levelname} {message}"
+    (): pythonjsonlogger.jsonlogger.JsonFormatter
+    format: "{created} {message} {point}"
     style: "{"
 handlers:
   metrics:
     class: logging.FileHandler
     formatter: metrics
-    filename: metrics.log
+    filename: metrics.jsonl
 loggers:
   singer_sdk.metrics:
     level: INFO
     handlers: [ metrics ]
-    propagate: yes
+    propagate: no
 ```
 
-This will send metrics to a `metrics.log`:
-
-```
-2022-09-29 00:48:52,746 INFO METRIC: {"metric_type": "timer", "metric": "http_request_duration", "value": 0.501743, "tags": {"stream": "continents", "endpoint": "", "http_status_code": 200, "status": "succeeded"}}
-2022-09-29 00:48:52,775 INFO METRIC: {"metric_type": "counter", "metric": "http_request_count", "value": 1, "tags": {"stream": "continents", "endpoint": ""}}
-2022-09-29 00:48:52,776 INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.7397160530090332, "tags": {"stream": "continents", "context": {}, "status": "succeeded"}}
-2022-09-29 00:48:52,776 INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 7, "tags": {"stream": "continents", "context": {}}}
-2022-09-29 00:48:53,225 INFO METRIC: {"metric_type": "timer", "metric": "http_request_duration", "value": 0.392148, "tags": {"stream": "countries", "endpoint": "", "http_status_code": 200, "status": "succeeded"}}
-2022-09-29 00:48:53,302 INFO METRIC: {"metric_type": "counter", "metric": "http_request_count", "value": 1, "tags": {"stream": "countries", "endpoint": ""}}
-2022-09-29 00:48:53,302 INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.5258760452270508, "tags": {"stream": "countries", "context": {}, "status": "succeeded"}}
-2022-09-29 00:48:53,303 INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 250, "tags": {"stream": "countries", "context": {}}}
+This will send metrics to a `metrics.jsonl`:
+
+```json
+{"created": 1705709074.883021, "message": "METRIC", "point": {"type": "timer", "metric": "http_request_duration", "value": 0.501743, "tags": {"stream": "continents", "endpoint": "", "http_status_code": 200, "status": "succeeded"}}}
+{"created": 1705709074.897184, "message": "METRIC", "point": {"type": "counter", "metric": "http_request_count", "value": 1, "tags": {"stream": "continents", "endpoint": ""}}}
+{"created": 1705709074.897256, "message": "METRIC", "point": {"type": "timer", "metric": "sync_duration", "value": 0.7397160530090332, "tags": {"stream": "continents", "context": {}, "status": "succeeded"}}}
+{"created": 1705709074.897292, "message": "METRIC", "point": {"type": "counter", "metric": "record_count", "value": 7, "tags": {"stream": "continents", "context": {}}}}
+{"created": 1705709075.397254, "message": "METRIC", "point": {"type": "timer", "metric": "http_request_duration", "value": 0.392148, "tags": {"stream": "countries", "endpoint": "", "http_status_code": 200, "status": "succeeded"}}}
+{"created": 1705709075.421888, "message": "METRIC", "point": {"type": "counter", "metric": "http_request_count", "value": 1, "tags": {"stream": "countries", "endpoint": ""}}}
+{"created": 1705709075.422001, "message": "METRIC", "point": {"type": "timer", "metric": "sync_duration", "value": 0.5258760452270508, "tags": {"stream": "countries", "context": {}, "status": "succeeded"}}}
+{"created": 1705709075.422047, "message": "METRIC", "point": {"type": "counter", "metric": "record_count", "value": 250, "tags": {"stream": "countries", "context": {}}}}
 ```
 
 ## For package developers
diff --git a/singer_sdk/metrics.py b/singer_sdk/metrics.py
index 27222c7b..25102c03 100644
--- a/singer_sdk/metrics.py
+++ b/singer_sdk/metrics.py
@@ -68,29 +68,35 @@ class Point(t.Generic[_TVal]):
     value: _TVal
     tags: dict[str, t.Any] = field(default_factory=dict)
 
-    def __str__(self) -> str:
-        """Get string representation of this measurement.
+    def to_dict(self) -> dict[str, t.Any]:
+        """Convert this measure to a dictionary.
 
         Returns:
-            A string representation of this measurement.
+            A dictionary.
         """
-        return self.to_json()
+        return {
+            "type": self.metric_type,
+            "metric": self.metric.value,
+            "value": self.value,
+            "tags": self.tags,
+        }
 
-    def to_json(self) -> str:
-        """Convert this measure to a JSON object.
+
+class SingerMetricsFormatter(logging.Formatter):
+    """Logging formatter that adds a ``metric_json`` field to the log record."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        """Format a log record.
+
+        Args:
+            record: A log record.
 
         Returns:
-            A JSON object.
+            A formatted log record.
         """
-        return json.dumps(
-            {
-                "type": self.metric_type,
-                "metric": self.metric.value,
-                "value": self.value,
-                "tags": self.tags,
-            },
-            default=str,
-        )
+        point = record.__dict__.get("point")
+        record.__dict__["metric_json"] = json.dumps(point, default=str) if point else ""
+        return super().format(record)
 
 
 def log(logger: logging.Logger, point: Point) -> None:
@@ -100,7 +106,7 @@ def log(logger: logging.Logger, point: Point) -> None:
         logger: An logger instance.
         point: A measurement.
     """
-    logger.info("METRIC: %s", point)
+    logger.info("METRIC", extra={"point": point.to_dict()})
 
 
 class Meter(metaclass=abc.ABCMeta):
@@ -415,7 +421,12 @@ def _setup_logging(config: t.Mapping[str, t.Any]) -> None:
                 "console": {
                     "format": "{asctime:23s} | {levelname:8s} | {name:20s} | {message}",
                     "style": "{",
-                }
+                },
+                "metrics": {
+                    "()": SingerMetricsFormatter,
+                    "format": "{asctime:23s} | {levelname:8s} | {name:20s} | {message}: {metric_json}",  # noqa: E501
+                    "style": "{",
+                },
             },
             "handlers": {
                 "default": {
@@ -423,11 +434,23 @@ def _setup_logging(config: t.Mapping[str, t.Any]) -> None:
                     "formatter": "console",
                     "stream": sys.stderr,
                 },
+                "metrics": {
+                    "()": logging.StreamHandler,
+                    "formatter": "metrics",
+                    "stream": sys.stderr,
+                },
             },
             "root": {
                 "level": logging.INFO,
                 "handlers": ["default"],
             },
+            "loggers": {
+                "singer_sdk.metrics": {
+                    "level": logging.INFO,
+                    "handlers": ["metrics"],
+                    "propagate": False,
+                },
+            },
         },
     )
 


Test patch:
diff --git a/tests/core/test_metrics.py b/tests/core/test_metrics.py
index b0de4c9b..17d99033 100644
--- a/tests/core/test_metrics.py
+++ b/tests/core/test_metrics.py
@@ -1,5 +1,6 @@
 from __future__ import annotations
 
+import json
 import logging
 import os
 
@@ -18,6 +19,32 @@ class CustomObject:
         return f"{self.name}={self.value}"
 
 
+def test_singer_metrics_formatter():
+    formatter = metrics.SingerMetricsFormatter(fmt="{metric_json}", style="{")
+
+    record = logging.LogRecord(
+        name="test",
+        level=logging.INFO,
+        pathname="test.py",
+        lineno=1,
+        msg="METRIC",
+        args=(),
+        exc_info=None,
+    )
+
+    assert not formatter.format(record)
+
+    metric_dict = {
+        "type": "counter",
+        "metric": "test_metric",
+        "tags": {"test_tag": "test_value"},
+        "value": 1,
+    }
+    record.__dict__["point"] = metric_dict
+
+    assert formatter.format(record) == json.dumps(metric_dict)
+
+
 def test_meter():
     pid = os.getpid()
 
@@ -44,6 +71,9 @@ def test_meter():
 
 
 def test_record_counter(caplog: pytest.LogCaptureFixture):
+    metrics_logger = logging.getLogger(metrics.METRICS_LOGGER_NAME)
+    metrics_logger.propagate = True
+
     caplog.set_level(logging.INFO, logger=metrics.METRICS_LOGGER_NAME)
     pid = os.getpid()
     custom_object = CustomObject("test", 1)
@@ -63,16 +93,16 @@ def test_record_counter(caplog: pytest.LogCaptureFixture):
     total = 0
 
     assert len(caplog.records) == 100 + 1
+    # raise AssertionError
 
     for record in caplog.records:
         assert record.levelname == "INFO"
-        assert record.msg == "METRIC: %s"
-        assert "test=1" in record.message
+        assert record.msg.startswith("METRIC")
 
-        point: metrics.Point[int] = record.args[0]
-        assert point.metric_type == "counter"
-        assert point.metric == "record_count"
-        assert point.tags == {
+        point = record.__dict__["point"]
+        assert point["type"] == "counter"
+        assert point["metric"] == "record_count"
+        assert point["tags"] == {
             metrics.Tag.STREAM: "test_stream",
             metrics.Tag.ENDPOINT: "test_endpoint",
             metrics.Tag.PID: pid,
@@ -80,13 +110,17 @@ def test_record_counter(caplog: pytest.LogCaptureFixture):
             "custom_obj": custom_object,
         }
 
-        total += point.value
+        total += point["value"]
 
     assert total == 100
 
 
 def test_sync_timer(caplog: pytest.LogCaptureFixture):
+    metrics_logger = logging.getLogger(metrics.METRICS_LOGGER_NAME)
+    metrics_logger.propagate = True
+
     caplog.set_level(logging.INFO, logger=metrics.METRICS_LOGGER_NAME)
+
     pid = os.getpid()
     traveler = time_machine.travel(0, tick=False)
     traveler.start()
@@ -101,16 +135,16 @@ def test_sync_timer(caplog: pytest.LogCaptureFixture):
 
     record = caplog.records[0]
     assert record.levelname == "INFO"
-    assert record.msg == "METRIC: %s"
+    assert record.msg.startswith("METRIC")
 
-    point: metrics.Point[float] = record.args[0]
-    assert point.metric_type == "timer"
-    assert point.metric == "sync_duration"
-    assert point.tags == {
+    point = record.__dict__["point"]
+    assert point["type"] == "timer"
+    assert point["metric"] == "sync_duration"
+    assert point["tags"] == {
         metrics.Tag.STREAM: "test_stream",
         metrics.Tag.STATUS: "succeeded",
         metrics.Tag.PID: pid,
         "custom_tag": "pytest",
     }
 
-    assert pytest.approx(point.value, rel=0.001) == 10.0
+    assert pytest.approx(point["value"], rel=0.001) == 10.0