From f0152548f88ba7ac75976a28bc66cfd812574d0a Mon Sep 17 00:00:00 2001 From: Will Kahn-Greene Date: Tue, 29 Oct 2024 18:47:53 -0400 Subject: [PATCH] Rework LoggingBackend and timestamps (#11) This adds a new "timestamp_mode" which changes the behavior of the timestamp in the logged output. * "utc": inserts a UTC timestamp * "local": inserts a local timezone timestamp * anything: doesn't insert a timestamp at all In the cases where I'm using Markus in a local dev environment for service development, the logging framework is already configured with a timestamp, so having Markus' LoggingBackend also include a timestamp is redundant and not wildly helpful. Thus I wanted to include a "no timestamp" option. For when the user wants a timestamp, it seemed prudent to support both UTC and local timezone timestamps. Also, timestamps are now emitted in isoformat. --- HISTORY.rst | 33 ++++++++++++++++++++++ src/markus/backends/logging.py | 51 ++++++++++++++++++++++++++++------ tests/test_logging.py | 41 +++++++++++++++++---------- 3 files changed, 102 insertions(+), 23 deletions(-) diff --git a/HISTORY.rst b/HISTORY.rst index daf9239..1658bbd 100644 --- a/HISTORY.rst +++ b/HISTORY.rst @@ -12,6 +12,39 @@ History * Dropped support for Python 3.8 (#160) +* Changed timestamp field in LoggingBackend. The LoggingBackend now defaults to + not emitting a timestamp at all. If you would like a timestamp, you can + provide the ``"timestamp_mode"`` option with either ``"utc"`` for UTC + timestamps or ``"local"`` for local timezone timestamps. + + No timestamp example:: + + LoggingBackend() + + emits lines like:: + + METRICS|histogram|foo|4321|#key1:val + + ``"utc"`` timestamp mode example:: + + LoggingBackend(options={"timestamp_mode": "utc"}) + + emits lines like:: + + METRICS|2017-03-06T11:30:00+00:00:00|histogram|foo|4321|#key1:val + + ``"local"`` timestamp mode example:: + + LoggingBackend(options={"timestamp_mode": "local"}) + + emits lines like:: + + METRICS|2017-03-06T11:30:00|histogram|foo|4321|#key1:val + + If you want the original behavior, add set ``timestamp_mode`` to ``local``. + (#11) + + 5.0.0 (June 24th, 2024) ----------------------- diff --git a/src/markus/backends/logging.py b/src/markus/backends/logging.py index 8ba82ad..1002b68 100644 --- a/src/markus/backends/logging.py +++ b/src/markus/backends/logging.py @@ -11,6 +11,9 @@ from markus.backends import BackendBase +UTC = datetime.timezone.utc + + class LoggingMetrics(BackendBase): """Metrics backend that publishes to Python logging. @@ -24,16 +27,24 @@ class LoggingMetrics(BackendBase): } } - The :py:class:`markus.backends.logging.LoggingMetrics` backend generates - logging messages in this format:: - - leader|timestamp|metric_type|stat|value|#tags + By default the :py:class:`markus.backends.logging.LoggingMetrics` backend + generates logging messages in this format:: + leader|metric_type|stat|value|#tags For example:: - METRICS|2017-03-06 11:30:00|histogram|foo|4321|#key1:val + METRICS|histogram|foo|4321|#key1:val + + If you set the ``"timestamp_mode"`` option to ``"utc"`` for a UTC timestamp + or ``"local"`` for a local timezone timestamp, then it'll have this + format:: + + leader|timestamp|metric_type|stat|value|#tags + + For example:: + METRICS|2017-03-06T11:30:00|histogram|foo|4321|#key1:val This will log at the ``logging.INFO`` level. @@ -50,6 +61,14 @@ class LoggingMetrics(BackendBase): Defaults to ``"METRICS"``. + * ``timestamp_mode``: mode for timestamp + + * ``"utc"``: UTC timestamp + * ``"local"``: local timezone timestamp + * anything else: no timestamp + + Defaults to no timestamp. + """ def __init__(self, options=None, filters=None): @@ -58,15 +77,29 @@ def __init__(self, options=None, filters=None): self.logger_name = options.get("logger_name", "markus") self.logger = logging.getLogger(self.logger_name) self.leader = options.get("leader", "METRICS") + self.timestamp_mode = options.get("timestamp_mode", None) + + tmpl = [ + "%(leader)s", + "%(kind)s", + "%(stat)s", + "%(value)s", + "%(tags)s", + ] + if self.timestamp_mode == "utc": + tmpl.insert(1, "%(utc_timestamp)s") + elif self.timestamp_mode == "local": + tmpl.insert(1, "%(local_timestamp)s") + + self.tmpl = "|".join(tmpl) def emit(self, record): self.logger.info( - "%(leader)s|%(timestamp)s|%(kind)s|%(stat)s|%(value)s|%(tags)s" + self.tmpl % { "leader": self.leader, - # NOTE(willkg): This is a tz-naive datetstamp so it'll be in - # local time. - "timestamp": datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S"), + "local_timestamp": datetime.datetime.now().isoformat(), + "utc_timestamp": datetime.datetime.now(tz=UTC).isoformat(), "kind": record.stat_type, "stat": record.key, "value": record.value, diff --git a/tests/test_logging.py b/tests/test_logging.py index c9c2e5c..658a1a4 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -4,27 +4,18 @@ import datetime -import pytest - from markus.backends.logging import LoggingMetrics, LoggingRollupMetrics from markus.main import MetricsFilter, MetricsRecord class TestLoggingMetrics: - @pytest.fixture(autouse=True) - def set_time(self, time_machine): - # NOTE(willkg): this takes advantage of a bug in time_machine where if - # you use string parsing and don't provide a timezone, it uses the - # local timezone - time_machine.move_to("2017-03-06 16:30:00", tick=False) - def test_incr(self, caplog): caplog.set_level("DEBUG") rec = MetricsRecord("incr", key="foo", value=10, tags=["key1:val", "key2:val"]) lm = LoggingMetrics() lm.emit_to_backend(rec) assert caplog.record_tuples == [ - ("markus", 20, "METRICS|2017-03-06 16:30:00|incr|foo|10|#key1:val,key2:val") + ("markus", 20, "METRICS|incr|foo|10|#key1:val,key2:val") ] def test_gauge(self, caplog): @@ -38,7 +29,7 @@ def test_gauge(self, caplog): ( "markus", 20, - "METRICS|2017-03-06 16:30:00|gauge|foo|100|#key1:val,key2:val", + "METRICS|gauge|foo|100|#key1:val,key2:val", ) ] @@ -53,7 +44,7 @@ def test_timing(self, caplog): ( "markus", 20, - "METRICS|2017-03-06 16:30:00|timing|foo|1234|#key1:val,key2:val", + "METRICS|timing|foo|1234|#key1:val,key2:val", ) ] @@ -68,7 +59,7 @@ def test_histogram(self, caplog): ( "markus", 20, - "METRICS|2017-03-06 16:30:00|histogram|foo|4321|#key1:val,key2:val", + "METRICS|histogram|foo|4321|#key1:val,key2:val", ) ] @@ -83,8 +74,30 @@ def filter(self, record): lm = LoggingMetrics(filters=[BlueFilter()]) lm.emit_to_backend(MetricsRecord("incr", key="foo", value=1, tags=[])) lm.emit_to_backend(MetricsRecord("incr", key="foo.blue", value=2, tags=[])) + assert caplog.record_tuples == [("markus", 20, "METRICS|incr|foo.blue|2|")] + + def test_utc_timezone_incr(self, caplog, time_machine): + time_machine.move_to("2017-03-06 16:30:00 +0000", tick=False) + caplog.set_level("DEBUG") + rec = MetricsRecord("incr", key="foo", value=10, tags=["key1:val", "key2:val"]) + lm = LoggingMetrics(options={"timestamp_mode": "utc"}) + lm.emit_to_backend(rec) + assert caplog.record_tuples == [ + ( + "markus", + 20, + "METRICS|2017-03-06T16:30:00+00:00|incr|foo|10|#key1:val,key2:val", + ) + ] + + def test_local_timezone_incr(self, caplog, time_machine): + time_machine.move_to("2017-03-06 16:30:00", tick=False) + caplog.set_level("DEBUG") + rec = MetricsRecord("incr", key="foo", value=10, tags=["key1:val", "key2:val"]) + lm = LoggingMetrics(options={"timestamp_mode": "local"}) + lm.emit_to_backend(rec) assert caplog.record_tuples == [ - ("markus", 20, "METRICS|2017-03-06 16:30:00|incr|foo.blue|2|") + ("markus", 20, "METRICS|2017-03-06T16:30:00|incr|foo|10|#key1:val,key2:val") ]