Should log to standard error out of the box?

[wiseman]

Do you think that timbre should log to standard error, as opposed to standard out, when used out of the box?

[ptaoussanis]

Hi John,

Sorry could you clarify: are you suggesting Timbre not log errors to standard error by default? (The default :standard-out appender does currently). Could you motivate that a little? Am not opposed to changing the behaviour if there's a reason to (?).

Cheers! :-)

[wiseman]

Sorry, didn't see your response earlier. I was proposing to change the default config so that all logging output goes to standard error, not just error-level messages.

I often find it convenient to consider program output separate from log messages, and sending logging output to console (standard error) makes this easier. For example, in the case of CLI tools that write their output to standard out, it can be convenient to redirect standard out (for further processing, etc.) and not have that output include log messages--and to still have the log messages be shown on the console.

Python's logging module works this way.

[ptaoussanis]

Hi John, no problem. Thanks for clarifying.

I don't think this'd make sense to do in the general case, though not sure what Python's rationale is - skimmed that page and couldn't find anything about always logging all output to standard error.

Anyway, it'd be quite easy for you to mod the default behaviour by replacing the default :standard-out appender:

{:doc "Prints to *out*/*err*. Enabled by default."
 :min-level nil :enabled? true :async? false :rate-limit nil
 :fn (fn [{:keys [error? output]}] ; Can use any appender args
       (binding [*out* (if error? *err* *out*)] ; Just mod the *out* here to your liking
         (str-println output)))}

Hope that helps?

Cheers! :-)

[wiseman]

Thanks, yes, that's what I'm currently doing and it's simple enough that it definitely speaks to the advantages of timbre's easy configuration.

But I'm curious to know why you think it doesn't makes sense to log to stderr?

For reference, this part of the Python doc talks about the stderr behavior:

By default, no destination is set for any logging messages. You can specify a destination
(such as console or file) by using basicConfig() as in the tutorial examples. If you call the
functions debug(), info(), warning(), error() and critical(), they will check to see if
no destination is set; and if one is not set, they will set a destination of the console (sys.stderr)
and a default format for the displayed message before delegating to the root logger to do the
actual message output.

[ptaoussanis]

For reference, this part of the Python doc talks about the stderr behavior

Ahh good, thanks - missed that. Do they give the rationale behind this choice anywhere?

But I'm curious to know why you think it doesn't makes sense to log to stderr?

I wouldn't say that in all cases, just that if we're talking about defaults I'd prefer the least surprising + most useful config.

My understanding is that most folks use stderr exclusively (or at least primarily) for errors, and generally make corresponding provisions for piping, storage, alerts, etc.

So there's the question of whether it's ideal/appropriate to be sending non-error output to stderr at all, and there's the separate question of whether we want to be mixing error/non-error output channels by default (whatever they are).

By keeping the channels separate by default, folks have the option of (for example) rebinding stdout/stderr as they like. If they happen to want them mixed, that's quite easy to do. It's a little trickier to unmix them if they come pre-mixed. Does that make sense?

Anyway, I'm far from a devops expert so may be off with my assessment. If you could find me a good argument for logging everything to stderr by default (Python's?), I'd definitely be open to it.

Cheers :-)

[wiseman]

I'm not totally sure what you mean by channels above--you're talking about non-error log messages output and error log messages? I guess I think of logging as being separate from a program's output in some sense. This mainly comes up in the unix pipeline workflow model: Logging to standard out breaks the model, because I can no longer use that program in a pipeline. E.g. sort /usr/dict/words | wc -l breaks if sort logs to stdout.

I see the potential downside of writing both error log messages and non-error log messages to the same output stream, but it seems like less of a problem to me than breaking the unix-style pipeline model by default.

[ptaoussanis]

Hi John,

I'm not totally sure what you mean by channels above--you're talking about non-error log messages output and error log messages?

That's right.

I see the potential downside of writing both error log messages and non-error log messages to the same output stream, but it seems like less of a problem to me than breaking the unix-style pipeline model by default.

Okay, I'm with you - and I think that's a very reasonable perspective. My first inclination is to suggest that the issue here is that we're assuming different default use cases, and each seems to have a different preference for how to handle output:

• For an application that produces output for use at/with a terminal, I think your unix-style pipeline argument is solid: logging should go to std-err to distinguish itself from program output.
• For an application server (e.g. web server) that isn't producing terminal output, it seems that it's useful for logging to go to std-err/std-out depending on whether the log output is error level or not.

Would you agree with the above assessment? If correct, then the question of where best to output std logging by default depends on the commonest use-case. Given (among other factors) the slow startup times, I might suggest that Clojure programs (in contrast to Python ones) are more often used for service-style applications than for terminal-output applications.

Would you agree there?

Instead of changing the default, what if we offered a simple config switch for terminal-output apps that'd change the behaviour of the default std appender? That way we can promote terminal apps from "write your own appender" to "flip this switch that's off by default".

What do you think?

[BTW Not sure why this was closed - wasn't intentional, sorry]

[pjlegato]

+1 to sending all log messages to STDERR. In my experience, wanting to separate "program output" (STDOUT) from "log messages" (STDERR) at the command line is by far the more common case. I can't think of any case where I've ever wanted to use STDOUT / STDERR to distinguish error-level logs from info-level logs. (That can be accomplished by sending everything to STDERR and grepping for the string "ERROR" in any case.)

[ptaoussanis]

Okay, just following up. So I don't think this is the kind of thing that has one obviously-correct approach. I don't feel strongly about it, but I do feel that Timbre's current approach is a little more semantically correct as a default (at least w/in the context of Clojure applications that are normally long-running processes rather than command-line utilities).

But I would definitely be happy to take a PR that added a simple config switch (something like :log-all-to-std-err?) for folks that prefer the Python-like behaviour.

Cheers! :-)

[pjlegato]

It's Unix behavior, not Python behavior. STDOUT is for output (hence the name).

[ptaoussanis]

Hi Paul,

Log output can be a program's primary/sole output. Calling Python's choice here "Unix behaviour" is a bit of a stretch I think. A quick Google will show that people have preferences one way or the other.

To recap, my rationale currently goes:

• Due to JVM startup time, Clojure programs are seldom used as command-line utils - so their primary output is often logging output.
• If nothing else is going to STDOUT anyway, it'd seem sensible to not unnecessarily flatten two forms of information into one stream by default when unflattening is much harder than flattening for folks that want it flat (again, we have Unix stream redirection for this).

Sending everything to STDERR is currently a 1 line change. With the switch proposed here, it'll be easier still - so even if there's disagreement about the default - should be easy enough for everyone to get the behaviour they'd like :-)

Cheers!

[ptaoussanis]

There's going to be a simple config flag for this in v4, closing.

[emlyn]

Just wondering if this config flag is available now that v4 is out?

[ptaoussanis]

Hi @emlyn, it is - you can see the println appender docstring for details

[emlyn]

Ah yes, thanks @ptaoussanis. How do :std-err / :std-out differ from :*err* / :*out*?

[ptaoussanis]

:std-err is Standard Error
:std-out is Standard Out
:*err* is whatever the value is of Clojure's *err* dynamic var (usu. Standard Error)
:*out* is whatever the value is of Clojure's *out* dynamic var (usu. Standard Out)

Does that make sense?

[emlyn]

Oh yes, of course, I forgot that out and err might be rebound. Thanks!