Add way to disable stringification step?

[jeroenvandijk]

I'm using socket-rocket, a timbre appender for Logstash, and log-config to send certain tagged log messages to Logstash. This is working nicely for simple log statements like:

(log/info "hello") ;=> {"message":"hello"}

With Logstash it can be useful to log nested structures, however, this doesn't seem to be possible in the current setup:

(log/info {:nested "hello"}) ;=> {"message":"{:nested \"hello\"}"}

In this case I would like to disable the formatting completely and just use identity for the log message. The socket-rocket appender would then generate proper JSON. It would require a third option to this part I presume.

Am I missing something and is this already possible? Or otherwise, do you think it is a good idea to have the ability to disable formatting?

Thanks,
Jeroen

[jeroenvandijk]

I'm looking into an implementation for this. Looking at clojure.tools.logging, it seems the log macro doesn't do any stringification [1]. logp [2] is equivalent to Timbre's log. Is there a specific reason why logp was deprecated [3]?

Also I wonder, what is the purpose of the msg-type :nil? When I do (timbre/log* {} :nil :info "some message") it will alway log nil.

[1] https://github.com/clojure/tools.logging/blob/master/src/main/clojure/clojure/tools/logging.clj#L81
[2] https://github.com/ptaoussanis/timbre/blob/master/src/taoensso/timbre.clj#L522
[3] https://github.com/clojure/tools.logging/blob/master/src/main/clojure/clojure/tools/logging.clj#L94

[ptaoussanis]

Hi Jeroen,

Sorry for the delay getting back to you - was away on vacation + intentionally trying to avoid non-critical work while the opportunity was there :-).

In this case I would like to disable the formatting completely and just use identity for the log message.

Understood. The formatting stuff is provided as a convenience since it's often what folks want, but it's entirely optional. Appenders will also receive all raw (unstringified) arguments under the :args key.

For future reference (for example, in case I'm not able to get back to you quickly) - this kind of stuff is (mostly) documented under the example-config docstring.

Looking at clojure.tools.logging, it seems the log macro doesn't do any stringification [1].

If I recall correctly, tools.logging actually does stringification only (i.e. no raw args are provided).

logp [2] is equivalent to Timbre's log.

To clarify:
logp => stringification with print (p) style stringification.
logf => stringification with fmt (f) style stringification.
log => whatever the default is, for brevity (usually equivalent to logp).

Is there a specific reason why logp was deprecated [3]?

Just to cut down on the unnecessary aliases: log is identical to logp.

Also I wonder, what is the purpose of the msg-type :nil? When I do (timbre/log* {} :nil :info "some message") it will alway log nil.

Good question. That's for when you don't want any auto stringification, for example because you're intending to use the raw :args (as in your case, as I understand it).

Does that help? Feel free to ping if you've got any other questions.

Cheers! :-)

[jeroenvandijk]

Sorry for the delay getting back to you - was away on vacation +
intentionally trying to avoid non-critical work while the opportunity was
there :-).

No worries! Thanks for giving this amount of support!

Also I wonder, what is the purpose of the msg-type :nil? When I do
(timbre/log* {} :nil :info "some message") it will alway log nil.

Good question. That's for when you don't want any auto stringification,
for example because you're intending to use the raw :args (as in your
case, as I understand it).

Sounds reasonable. I have two more questions. The code mentions
"implementation detail" next to log*, does that mean it is prone to change
and should not be used externally?

So I will :nil and use :args, but I'll have to write my own version of the
socket-rcoket appender to make it work for me since it is using :message
internally. I wonder what the normal use cases for :nil are?

Thanks again for the support!

[ptaoussanis]

"implementation detail" next to log*, does that mean it is prone to change
and should not be used externally?

Yes, that's right. You shouldn't need log* though, what are you thinking to use it for?

So I will :nil and use :args,

The :nil thing isn't important. Just use log/logf as you normally would. If the appender is configured to do the right thing with the :args that it receives, then any stringified arguments it does receive will just be ignored.

So only the appender needs a modification.

but I'll have to write my own version of the
socket-rcoket appender to make it work for me since it is using :message
internally.

Or I'd suggest contacting the author of socket-rocket. I'm not familiar with Logstash but if what you want to do is a common thing, it may be convenient to have it as a built-in option to socket-rocket.

I wonder what the normal use cases for :nil are?

I'd say just specialized cases where you have very high performance requirements and you want to avoid unnecessary auto-stringification. I wouldn't worry about this at all.

Cheers! :-)

[jeroenvandijk]

So I wasn't really clear indeed, the main reason I don't want the stringification is because I have very high performance requirements :-) I saw using log* with :nil as the only option to stop stringification in Timbre.

We're receiving more than 50k QPS and I only want to log a small sample of it. I'm using the rate-limiting feature to stop sending too many messages, but with the rate limiting the stringification is still applied. In my case it is a rather big clojure map, so it will definitely impact performance. Maybe I should wrap the log statement with my own sampling function so it doesn't matter. It feels though that the disabling of the auto-stringification wouldn't be a big addition, but you are a better judge.

I'll post a link to gist later to show you what I have done to get a better idea. I'll will also contact the socket-rocket author to discuss alternatives.

Thanks!

[ptaoussanis]

So I wasn't really clear indeed, the main reason I don't want the stringification is because I have very high performance requirements :-) I saw using log* with :nil as the only option to stop stringification in Timbre.

Okay, I'm with you. log* with :nil would indeed be the right approach then (though I'd benchmark to confirm that the difference is worth the effort).

Will look through this again next time I'm in the Timbre code. It may be possible, for example, to wrap the stringification stuff in a delay so that appenders don't need to pay the stringification cost when they don't need the stringification.

Maybe I should wrap the log statement with my own sampling function so it doesn't matter.

I guess that'd depend mostly on whether you want comprehensive or sampled logging though (i.e. aside from the performance concerns).

Note that there's a sometimes macro in the main Timbre ns to help with sampled logging:
(sometimes 0.3 (info "foo")) will log with 0.3 (30%) probability.

I'll post a link to gist later to show you what I have done to get a better idea. I'll will also contact the socket-rocket author to discuss alternatives.

Cool!

[ptaoussanis]

Okay, have added a note about delay-wrapping the stringified :message key in a future release of Timbre. This'll be a breaking change for appenders, so will need to wait for a v4 release unfortunately.

The approach you're taking in the meantime sounds good to me. Closing this, feel free to reopen if you have any further comments/questions. Cheers! :-)