Skip to content

Commit

Permalink
Rework LoggingBackend and timestamps (#11)
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
willkg committed Oct 29, 2024
1 parent 4769017 commit f015254
Show file tree
Hide file tree
Showing 3 changed files with 102 additions and 23 deletions.
33 changes: 33 additions & 0 deletions HISTORY.rst
Original file line number Diff line number Diff line change
Expand Up @@ -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)
-----------------------
Expand Down
51 changes: 42 additions & 9 deletions src/markus/backends/logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,9 @@
from markus.backends import BackendBase


UTC = datetime.timezone.utc


class LoggingMetrics(BackendBase):
"""Metrics backend that publishes to Python logging.
Expand All @@ -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.
Expand All @@ -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):
Expand All @@ -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,
Expand Down
41 changes: 27 additions & 14 deletions tests/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand All @@ -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",
)
]

Expand All @@ -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",
)
]

Expand All @@ -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",
)
]

Expand All @@ -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")
]


Expand Down

0 comments on commit f015254

Please sign in to comment.