Exploring the idea: `statsd` integration drain.

[dpc]

Since all these logging statements are placed all over the code already (at least that's the idea), someone might want to log some logging statements as events for statsd. Might be useful, especially for libraries

There could be a drain, that would allow to do so: user would pick the logging events that it's interested with, and possibly even use use the values associated with them.

Some thinking:

• what's the best way to reliably pick a logging statement
  • what if code changes and so do logging statements
  • would logging statements be consider an API that must not be broken?
    • maybe some special logging statements could have "hooks/tags" that would be like a pluggable A PI
    • "target" that is not used current could be used for that purpose?
      • would have to add it to all macros (not a big deal, info!(tag: ...) would be backward compatibile)
• how to match logging statements in a performant way
  • reuse the "hook/tag" idea?
• what about the logging level; some logging levels are not even compiled in...
  • "hook" events would have to be at least info?

[dpc]

@56quarters @tshlabs ; Hi, sorry for bothering you out of the blue, but since I've seen you're working on cadence, I wonder if you have any opinions about it: do you think logging statements could be practically a source for stats metrics? Would it make sense?

Eg. in the code:

info!(req.log, "req_finished": "request finished", "time" => req.start - req.end);

and then, there'd be a drain in the app itself with something like:

.on_event("req_finished", |statsd, event| {
               statsd.time("server.request_time", event.value_u64("time"));
               statsd.incr("server.requests");
           })

[aomader]

I myself find this idea quite interesting, not particularly with statsd but with other endpoints as well.

[56quarters]

@dpc Sorry for my lack of response, I just noticed this. Offhand this seems like a really neat idea! I'll have to spend a little time thinking about it, but you seem to have enumerated most of the open questions.

Some prior art that I'm aware of that uses logging hooks to emit metrics to statsd is the Gunicorn server in Python. I'm not super familiar with how they implemented this (plus, it's an application not a general purpose library) but it may be of some use: https://github.com/benoitc/gunicorn/blob/4a04195975563d2f4ec28ffaa70d138beda76da4/gunicorn/instrument/statsd.py

Cheers!

[56quarters]

Looking at the design of Slog a bit (very cool lib, BTW), it seems like writing metrics based on logging statements would be pretty unobtrusive. The only part of the application that would even have to be concerned with Statsd or metrics would be wherever the metrics Drain gets configured. This seems like it would make it easy to use a variety of metrics clients or completely different backends.

I'm :+1:

[dpc]

Let's keep it open. I (or someone) can start prototyping on that at some point.

[56quarters]

Hey @dpc,

I'm thinking about attempting to create a Drain implementation for Cadence in the next few weeks. Do you think this should be a crate that lives along side Cadence or do you imagine it as a repo living under the slog-rs organization? Thanks!

[dpc]

Awesome.

If you're the author, you're free to decide about all these things. :)

Having said that it seems to me that since it's a Drain for slog that provides integration with Cadence, it is more of a slog part. Similarly the Drain that logs to journald is slog-journal. So slog-cadene seems to be natural candidate.

I'd be happy to create a repo for you under https://github.com/slog-rs/cadence and make you the owner of it it.

[56quarters]

The separate repo sounds great, thanks.

[dpc]

slogv2 added notion of tags. One of the use cases I had in mind was this.

[CAD97]

Thought about design a bit; might or might not play with an implementation some time down the road. (Feel free to ninja me, anyone!)

Sketch:

crate slog-metrics, provides two new macros for logging of metrics: slog_metric_start! and slog_metric_stop!. Uses chrono for tracking time.

macro_rules slog_metric_start {
    ($log:expr, $task:expr) => (slog_metric_start!($log, $task;));
    ($log:expr, $task:expr; $($kvs:tt)*) => {
        info!($log, #"slog-metric-start", "Starting task {task}", "task"=$task; "time" => %$crate::chrono::Local::now(), $($kvs)*);
    }
}
macro_rules slog_metric_stop {
    ($log:expr, $task:expr) => (slog_metric_stop!($log, $task;));
    ($log:expr, $task:expr; $($kvs:tt)*) => {
        info!($log, #"slog-metric-stop", "Finished task {task}", "task"=$task; "time" => %$crate::chrono::Local::now(), $($kvs)*);
    }
}

The info! logging statements above were chosen subjectively to present a decent log to other drain implementations. The info! level was chosen as the best fit, but it might mean losing metrics in release builds; maybe it can be started higher but the drain rewrites the level lower?

Provides a pass-through drain wrapper that listens for the tags #"slog-metric-start" and #"slog-metric-stop". Maintains an atomic mapping from running task names to the instant that they started. When seeing a task start, clones the time it started and records it in the backing map. When seeing a task stop, removes the start time, calculates the duration elapsed, and gives that duration along with the task name to a callback. If no start was provided, logs an error!. Provides an option on creation to filter out the tagged records.

---

(Sorry for stream-of-consciousness explanation but wanted to share it before going to sleep)

[dpc]

About the "loosing metrics in release" - you don't have to use info! or anything else - you could just use a similiar macro with the static logging level check removed. We could even land it in core slog crate.