Is there a way to get Timbre to just print its messages once, even when using a custom appender?

This is a follow up to the previous issue I raised: #5

I want to stop the built in Timbre output, I want to only use my custom function. I had assumed this would be automatic, but I guess not?

I have this in my code:

(timbre/set-config!
[:appenders :my-appender]
{:doc "The i-love-timbre-but-i-need-pretty-print appender"
:min-level :debug
:enabled? true
:async? true
:max-message-per-msecs nil ; No rate limiting
:fn (fn [{:keys [error? prefix message more]}](binding [out %28if error? err out%29]
%28let [output %28with-out-str %28pp/pprint prefix%29 %28pp/pprint message%29 %28pp/pprint more%29%29]
%28print output%29
%28flush%29%29))})

And now each messages appears twice in the terminal output:

2013-Mar-26 14:07:30 -0400 DEBUG [kiosks-clojure.update-model] - return value from get-from-initial-config -- :events-called-when-the-app-starts-that-run-in-their-own-threads #{{:order-of-events 3, :event-name "persist-interactions-to-database"} {:order-of-events 1, :event-name "delete-old-sessions"}}

2013-Mar-26 14:07:30 -0400 DEBUG [kiosks-clojure.update-model] - return value from get-from-model -- :sessions {}

"2013-Mar-26 14:07:30 -0400 DEBUG [kiosks-clojure.update-model]"
" return value from get-from-initial-config -- :events-called-when-the-app-starts-that-run-in-their-own-threads"
[#{{:order-of-events 3, :event-name "persist-interactions-to-database"}
{:order-of-events 1, :event-name "delete-old-sessions"}}]

"2013-Mar-26 14:07:30 -0400 DEBUG [kiosks-clojure.update-model]"
" return value from get-from-model -- :sessions"
[{}]

It looks like the first 2 messages are from the built-in functionality of Timbre, and the next 2 are from the custom function that I am using. Is there a way to surpress those first 2 messages? I find it difficult to read the terminal output, and decipher what is going on, when there are so many duplicate messages.

It looks like the same SimpleDateFormat instance is shared between all log writers. I think that can cause some concurrency issues, because SimpleDateFormat is not thread safe.

If I profile nested function calls, the time for the outer is the time for the inner + outer call. It would be nice to be able to tell p to subtract out the inner time.

I added timbre 1.5.1 to my project.clj; [com.taoensso/timbre "1.5.1"]

Then, in the repl:

user=> (use '[taoensso.timbre :as timbre :only (trace debug info warn error fatal spy)])
nil
user=> (warn "hello")
UnknownHostException linux-r2d6: Name or service not known  java.net.Inet6AddressImpl.lookupAllHostAddr (Inet6AddressImpl.java:-2)

user=> (.printStackTrace *e)
java.net.UnknownHostException: linux-r2d6: linux-r2d6: Name or service not known
nil
user=>  at java.net.InetAddress.getLocalHost(InetAddress.java:1438)
    at taoensso.timbre$fn__1323.invoke(timbre.clj:189)
    at clojure.lang.AFn.applyToHelper(AFn.java:159)
    at clojure.lang.AFn.applyTo(AFn.java:151)
    at clojure.core$apply.invoke(core.clj:601)
    at taoensso.timbre.utils$memoize_ttl$fn__1237$fn__1239.invoke(utils.clj:24)
    at clojure.lang.Delay.deref(Delay.java:33)
    at clojure.core$deref.invoke(core.clj:2080)
    at taoensso.timbre.utils$memoize_ttl$fn__1237.doInvoke(utils.clj:24)
    at clojure.lang.RestFn.invoke(RestFn.java:397)
    at taoensso.timbre$wrap_appender_juxt$fn__1325$fn__1328.invoke(timbre.clj:219)
    at user$eval1468.invoke(NO_SOURCE_FILE:1)
    at clojure.lang.Compiler.eval(Compiler.java:6511)
    at clojure.lang.Compiler.eval(Compiler.java:6477)
    at clojure.core$eval.invoke(core.clj:2797)
    at clojure.main$repl$read_eval_print__6405.invoke(main.clj:245)
    at clojure.main$repl$fn__6410.invoke(main.clj:266)
    at clojure.main$repl.doInvoke(main.clj:266)
    at clojure.lang.RestFn.invoke(RestFn.java:1096)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate$fn__544.invoke(interruptible_eval.clj:56)
    at clojure.lang.AFn.applyToHelper(AFn.java:159)
    at clojure.lang.AFn.applyTo(AFn.java:151)
    at clojure.core$apply.invoke(core.clj:601)
    at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1771)
    at clojure.lang.RestFn.invoke(RestFn.java:425)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate.invoke(interruptible_eval.clj:41)
    at clojure.tools.nrepl.middleware.interruptible_eval$interruptible_eval$fn__585$fn__587.invoke(interruptible_eval.clj:171)
    at clojure.core$comp$fn__4034.invoke(core.clj:2278)
    at clojure.tools.nrepl.middleware.interruptible_eval$run_next$fn__578.invoke(interruptible_eval.clj:138)
    at clojure.lang.AFn.run(AFn.java:24)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:722)
Caused by: java.net.UnknownHostException: linux-r2d6: Name or service not known
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
    at java.net.InetAddress$1.lookupAllHostAddr(InetAddress.java:866)
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1258)
    at java.net.InetAddress.getLocalHost(InetAddress.java:1434)
    ... 32 more

Don't know if I'm doing something wrong (i.e. I should configure something), but I think it would be nice anyway if it was possible to do it like that "out of the box".

A beginner level question: I have some messages I'd like logged no matter what the logging level (unless it's off). I imagine log4j's level ALL acts like this. Is there anything like this in timbre? Any workarounds?

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

Hello! When I've started hacking #42 I found that timbre are broken :)

taoensso.timbre> (def level-compile-time :warn)
#'taoensso.timbre/level-compile-time
taoensso.timbre> (info "hello!")
CompilerException java.lang.Exception: Invalid logging level: level__5490__auto__, compiling:(/private/var/folders/mq/b8drc2px3gj486d1hj75w8800000gn/T/form-init934025151497129718.clj:1)

So let's look at macroexpansion:

(clojure.core/let [s1__5487__auto__ :info
                   default-config?__5488__auto__ (clojure.core/or
                                                  (clojure.core/keyword?
                                                   s1__5487__auto__)
                                                  (clojure.core/nil?
                                                   s1__5487__auto__))
                   config__5489__auto__ (if
                                            default-config?__5488__auto__
                                          @taoensso.timbre/config
                                          s1__5487__auto__)
                   level__5490__auto__ (if
                                           default-config?__5488__auto__
                                         s1__5487__auto__
                                         "hello!")]
  (clojure.core/when (taoensso.timbre/logging-enabled?
                      level__5490__auto__
                      config__5489__auto__)
    (clojure.core/when-let [juxt-fn__5491__auto__ (clojure.core/get-in
                                                   (taoensso.timbre/compile-config
                                                    config__5489__auto__)
                                                   [:appenders-juxt
                                                    level__5490__auto__])]
      (clojure.core/let [[x1__5492__auto__
                          &
                          xn__5493__auto__
                          :as
                          xs__5494__auto__] (if
                          default-config?__5488__auto__
                          (clojure.core/vector
                           "hello!")
                          (clojure.core/vector))
                          has-throwable?__5495__auto__ (clojure.core/instance?
                                                        java.lang.Throwable
                                                        x1__5492__auto__)
                          log-vargs__5496__auto__ (clojure.core/vec
                                                   (if
                                                       has-throwable?__5495__auto__
                                                     xn__5493__auto__
                                                     xs__5494__auto__))]
        (taoensso.timbre/send-to-appenders!
         level__5490__auto__
         {}
         log-vargs__5496__auto__
         "taoensso.timbre"
         (clojure.core/when has-throwable?__5495__auto__
           x1__5492__auto__)
         nil
         juxt-fn__5491__auto__
         :print-str
         (clojure.core/let [file__5497__auto__ "/private/var/folders/mq/b8drc2px3gj486d1hj75w8800000gn/T/form-init934025151497129718.clj"]
           (clojure.core/when (clojure.core/not=
                               file__5497__auto__
                               "NO_SOURCE_PATH")
             file__5497__auto__))
         1)))))

You can see here:

(taoensso.timbre/logging-enabled?
                      level__5490__auto__
                      config__5489__auto__)

But logging-enabled? itself is macro

(defmacro logging-enabled?
  "Returns true iff current logging level is sufficient and current namespace
  unfiltered. The namespace test is runtime, the logging-level test compile-time
  iff a compile-time logging level was specified."
  [level & [config]]
  (if level-compile-time
    (when (level-sufficient? level)
      `(let [ns-filter# (:ns-filter (compile-config (or ~config @config)))]
         (ns-filter# ~(str *ns*))))
    `(and (level-sufficient? ~level)
          (let [ns-filter# (:ns-filter (compile-config (or ~config @config)))]
            (ns-filter# ~(str *ns*))))))

And its trying to use level (actually level__5490__auto__ symbol from macroexpanstion). It's wrong.

I thing mistake is somewhere :) May be first let should not be quouted.

Something like:

(gen-logger {:config ...}) => timbre-fn

(timbre-fn :info "My log message")

Wanted to start the conversation on this.

Good performance testing relies on lazy sequences being evaluated where they are created, in order to ensure accurate numbers. It would be handy to have a p macro that incorporates a dorun/doall to automatically force resolution of lazy sequences.

What do you think about providing equivalents to the standard logging-level fns that automatically do formatting?

At least SOME kind of interpolation would be useful. Right now, I have a bunch of logging expressions in a codebase that are all like (debug (format …message and values to record…)).

Trivial little Carmine appender with index & expiring ks for a synchronized, distributed, query-able rotating log.

mmcgrana/clj-stacktrace#27 (comment)

Thoughts welcome!

https://github.com/AvisoNovate/pretty

When a log contains credentials, esp :password or "password" as key in a map, replace the corresponding value with "******". This can also be extended to patterns in text being logged.

Some way of customizing the prefix on a per-appender basis would be useful (e.g. some appenders may already include a timestamp).

Hello,

I tried create a pull request that would enable adding source-code line numbers to log output, but my macro-fu failed me. I just could not figure out where I should add (:line (meta &form)).

So I'm calling better programmers for the task. Would it be possible to add line number to the map that is passed to :prefix-fn function?

-jarppe

The time that a labeled section of code takes during profiling is stored in a vector of times in *pdata*. Currently, all of the times are accumulated first, and the summary statistics (min, max, mean, etc) are computed after the code has finished.

This approach works but can lead to OutOfMemory errors for code that is repeated heavily, e.g. the function being mapped over a large sequence.

An alternate approach is to compute the stats using a "streaming" (or "one-pass") approach, in which the times themselves are not saved, but are used merely to update the current values of the summary statistics. The stats are amenable to such an approach—even the MAD, so long as M stands for "mean" and not "median". One problem that could be introduced by this approach is a loss of precision, unless fractions and big-int math were used, which could get unwieldy after millions of iterations.

Another approach, suggested by @ptaoussanis, is to let the times accumulate to a point, then summarize them into the statistics. For example, for the first 10,000 times, simply accumulate them in the vector. Then, use the next time as a trigger point for summarizing the first 10k times, and add the 10,001st time as the first time in a new accumulator vector. At the 20,001st time, times 10,001 through 20,000 are folded into the summary statistics, and the accumulator vector is emptied.

A significant challenge faced by both approaches is how to do the calculation apart from the profiled code. In other words, how can you prevent the statistics calculations from falsely inflating the amount of time reported on the 10,001st time? I don't have a good solution to this obstacle. If this is a deal-breaker, I suggest documenting the limitation somewhere.

I often find myself writing something like the following:
(timbre/info (color-str :green "something good happened"))
or
(timbre/error (color-str :red "something unexpected has happened")) so as to differentiate the messages in the log.

What would be really cool is if it were possible to set the color-str based upon the log level in set-config!

Something along the lines of:

(timbre/set-config! [:appenders :debug-color-str] :cyan)
(timbre/set-config! [:appenders :info-color-str] :green)
(timbre/set-config! [:appenders :error-color-str] :red)

Hi there,

I'm trying to get Timbre to not rate limit my appender when calling error in a tight loop

(I tweeted about this here): https://twitter.com/t_crayford/status/498479067365396480 and https://twitter.com/t_crayford/status/498479149951242240, you asked me to file an issue.

Here's that issue:

How do I get timbre to not rate limit appenders at all? Here's roughly the code I'm using:

(do
  (require '[taoensso.timbre :as timbre])
  (require '[yeller-timbre-appender :reload true])
  (timbre/set-config! [:appenders :yeller]
    (yeller-timbre-appender/make-yeller-appender
      {:token "YOUR TOKEN"
       :environment "timebre-test"}))
  (dotimes [_ 100] (timbre/error (ex-info "lol" {:foo 1}))))

make-yeller-appender just returns a normal appender with a map, it doesn't set rate limit (and I've tried with :rate-limit nil as well). I put a println in there and it only logged 10 times, despite the 100 times I called the error macro.

Hi,

I am not sure if it is appropriate to put question here, please close it if it not.

The question is what is the reason to make the def-loggers private, I want to use timbre as logging tool, but I would like to wrap it so it is flexible for me.

I make a poor workaround by copying def-loggers and so on into the logging.clj file in my personal project.

Thanks

Julius

Would there be a way to profile a form/fn without explicitly wrapping it in p? Code starts to look more difficult to read if you leave the profiling in the code, lots of p's wrapping fn's. To make things cleaner, and separate concerns a bit, it'd be nice to have some way to have a list of fn's to wrap with profiling, maybe in a config block or similar.

Maybe something like this?

(profile-fns ["get-db-user", "send-api-request", "load-xml"])

This would wrap the listed fns in profiling without cluttering the code.

I'm kind of new to Clojure, so I'm not sure how doable or easy this would be.

Hello.

How about support of MDC-like (https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html) log's contexts? It's especially useful with structural log-appenders (like Graylog or Logstash).

Hi!

I'm having peculiar problem with Timbre. My problem is two-fold. First - all the log messages get written to stdout as well as to file via :spit appender. In stdout there are linebreaks after each log-message. However in actual logfile there isn't (it's just one big blob of text).

Most probably it's just my config which is listed here:

(timbre/set-level! (:level (:logging cfg/appconfig)))
(timbre/set-config! [:appenders :spit :enabled?] true)
(timbre/set-config! [:shared-appender-config :spit-filename] (str (:logname (:logging cfg/appconfig))))

So should the log messages be displayed in stdout with this configuration? And what might cause the newlines be missing from log file?

Trying to upgrade from 2.x to 3.x. When I try to compile my project (with lein compile) I'm getting a compilation error:

Exception in thread "main" java.lang.RuntimeException: 
No such var: encore/simple-date-format, compiling:(taoensso/timbre.clj:278:27)

It could be that I'm missing something obvious, but I don't see a straightforward way of removing appenders, apart from modifying the config map with swap! and dissoc. I want to disable logging to standard-out.

I am writing clojure on android and want to use timbre rather than calling android's log functions directly. I've made an android appender which does this and works just fine.

The issue comes with the style of compilation. Android needs to be aot compiled and a number of issues arise when aot compiling timbre. First the clj-stacktrace dependency has an undeclared leiningen dependency which when everything is aot compiled will fail and so I have to manually exclude that namespace from the top level. I also have to manually exclude all the appenders which have external dependencies which results in a very long list of exclusions which I'll need to update if you add new appenders.

It would be much better (for me at least) if the appenders were packaged separately (then they could actually depend on the appropriate packages for mail/irc etc). It would also be good if the clj-stacktrace dependency could be removed, or possibly I should be asking upstream whether clj-stacktrace would consider splitting out their leiningen plugin from the basic stacktrace formatting code.

There is one more issue I have found, and that's that the get-hostname implementation explodes on android if you try and log something from the main thread because it sees it as network access on the main thread. I'm currently working around it by doing an alter-var-root which sets the get-hostname to always return Unknown. If this could be implemented in a different way (future + promise on load?) or made optional then timbre would work by default with clojure-android.

Hello,
I am using the defnp macro from taoensso.timbre.profiling v3.1.6. When I run in through eastwood, I get a warning:

{:linter :unused-ret-vals,
 :msg
 "Constant value is discarded inside null: nil (nil value is returned by comment and gen-class expressions)",
 :line nil,
 :column nil}

I tried to examine what was happening. So I did a macroexpand on a simple function:

(macroexpand '(defnp foo [x] (* x x)))

The result is:

(def foo (clojure.core/fn ([x] nil (taoensso.timbre.profiling/pspy "foo" (* x x)))))

I am guessing the nil generated is what is tripping eastwood.

Currently pspy is a macro, which makes it hard to incorporate into a generalised function. For example, I can't write:

(pspy (var-name v) (test-var v))

To profile my tests.

To fix this, please consider a refactor along the following lines:

(defn pspy* [name func]
  (if-not *pdata*
    (func)
    (let [name (utils/fq-keyword name)
          start-time (System/nanoTime)]
      (try (func)
           (finally
             (let [elapsed (- (System/nanoTime) start-time)]
               (swap! *pdata* #(assoc % name (conj (% name []) elapsed)))))))))

(defmacro pspy [name & body]
  `(pspy* ~name (fn [] ~@body))

I wanted the output from Timbre to be formatted the way pprint formats output, so I wrote this function:

(defn set-the-current-debugging-level [level-of-debugging]
;; 2013-03-01 - called when the app starts. level-of-debugging should be passed in as a
;; command line argument. If set to 'production', then all debugging and output to the
;; terminal is surpressed. Otherwise, we are in debugging mode, and a lot gets printed
;; to the terminal, mostly via timbre.
;;
;; 2013-03-08 - i love timbre, but i need the objects pretty printed to the terminal.
(timbre/set-config!
[:appenders :my-appender]
{:doc "The i-love-timbre-but-i-need-pretty-print appender"
:min-level :debug
:enabled? true
:async? false
:max-message-per-msecs nil ; No rate limiting
:fn (fn [{:keys [error? prefix message more]}](binding [out %28if error? err out%29]
%28pp/pprint prefix%29
%28pp/pprint message%29
%28pp/pprint more%29))})
(swap! is-this-development-or-production (fn [current-environment-as-string](if %28= level-of-debugging)
"production"
"development")))
(if (= @is-this-development-or-production "production")
(timbre/set-level! :error)
(timbre/set-level! :debug)))

I use Timbre in a lot of functions, running in different threads.

Suddenly, the output I get at the terminal became mangled garbage:

on -data-to-datab"as<eop,t "io ouarnt cvtpaluhu eea =nsd'tt athrehtar teoeafrd 'd>eTlh eetaete-uro<l/do-pssteioans>s"iogns
, eour c pu alnd thoreado usagke losoks l liikeke this:t "his
: ""
< option value='music'>Music"(debug/thread-top))
(debug/thread-top)
)
[" at the[ start o"f ade"lAolulr ki ndcsp</to pttihone> "]s]ta
rt of peu2013-Mar-12 23:03:21 -0400 MacBook-Pro.local DEBUG [kiosks-clojure.core] - in get-options-for-select-box: ["<option v
alue='dance'>Dance" "Theater" "Music" "
All kinds"]
r sainstd- thsreesasdi ouns-adgaet al-o"to2ok0-s1d 3l-iMkaer a-tt1ah2ib sa2:s3 e:[,03 31o:u42412 7-7r00 40000 c "pLua wDarenesdnt crteohs
yr-JeMaaavcdaB ouVosMka"ge 2l2o o#k<-TPhrroe.aldo s clailk eD EtBhUiGs :[ k[i3o1s4k4Ts2h-7rce7la0od0j[uDrees.tcrooryeJ]a"va
VM,05 ,"maiDne]s>t]ro[4y7J"a3i1vna6V0 0Mg0"e t"- 2o2p t#i<oTnhsr-efaodrT -hTsrheerlaedc-t1-1b"ox: 1"9

<Thea[dr[[eDaeds tTrhoryeJa"da[<vToaphrtVeiMoa,nd5- ,1vm1aa,luien=]'>d]a[n4c6e0'21>0D0a0n c"e1"1" 19 #<Thr5e,maadin]> ]\

T[h3r0e8a9d4[0T0h0r e"ad-T1h1r,ead-12" 20 #<Thread Thread[Th
r ead-12,5,main]>][51,3m4a2i7n0]0>0] [3"0894000 "Thread-12""<Tohread- 1230" #< 2Th1 re#<aTd hTrehared aTdh[rTehad[Tread-12,5,main]>][
13400000 "hread-13,5,maiTnh]r>e]a[960000 d"-13q"tp5 2211 8#8<9pT0thi0or5ne-a1 dv1a lTuSehe=rl'teehaceadtt[oerTr'h>rTheeaadte-r1<3/,op5
t,imona>i"n]>
] [960000"0 "q t1p15 2#1<8T8h9r0e0a5d- 1T1h rSeealde[cqtotrp052"18 81910 0#5<-T1h1r Seealde Tchtroera0d,[5q,tpm5a2i1n8]8>9]0[0854-9101
0S0e l"ectqort0p,55,main]>][849000 "qtp52121889080859-01035 -A1c3ce pAtcocre0pt oSer0l ecSteClehcatnCnehalnConnenleCoctnnore@c0t".<oo0r
[email protected] 0:v.a3l00u.e00=0':1m3u"s0i0c0'1>M"usic <1/3o pt# ih" r#e<a

I posted about this on the Clojure mailist, and folks could only suggest that concurrency was the problem, which seems obvious, but not helpful:

https://groups.google.com/forum/?fromgroups=#!topic/clojure/Vd0Px2v8V2I

I would like to use pprint with Timbre. Is this possible? Can you suggest why it causes such problems when called from multiple threads?

If I add timbre to my project, and run lein deps :tree the branch concerning timbre looks like that:

[com.taoensso/timbre "3.3.0"]
  [com.taoensso/encore "1.7.3"]
    [com.keminglabs/cljx "0.4.0"]
      [com.cemerick/piggieback "0.1.3"]
        [org.clojure/clojurescript "0.0-2080"]
          [com.google.javascript/closure-compiler "v20130603"]
            [args4j "2.0.16"]
            [com.google.code.findbugs/jsr305 "1.3.9"]
            [com.google.guava/guava "14.0.1"]
            [com.google.protobuf/protobuf-java "2.4.1"]
            [org.json/json "20090211"]
          [org.clojure/data.json "0.2.3"]
          [org.clojure/google-closure-library "0.0-20130212-95c19e7f0f5f"]
            [org.clojure/google-closure-library-third-party "0.0-20130212-95c19e7f0f5f"]
          [org.mozilla/rhino "1.7R4"]
      [org.clojars.trptcolin/sjacket "0.1.0.6"]
        [net.cgrand/parsley "0.9.1"]
        [net.cgrand/regex "1.1.0"]
      [org.clojure/core.match "0.2.0"]
      [watchtower "0.1.1"]
    [org.clojure/tools.reader "0.8.7"]
  [io.aviso/pretty "0.1.12"]

It seems that excluding cljx does not have an impact (as far as I can tell). Would it be worth excluding this by default so that timbre can truly be an "all-Clojure library" as advertised?

Hey,

Is it possible to profile across multiple namespaces?
I replaced a bunch of defns in a namespace extra with defnps and then called a function in my core namespace that at some point calls functions from the extra namespace as well. I thought they'd show up in the logs but they dont.

Is this not meant to work or did I miss something like setting a log level?

I have a large sequence that cannot fit in memory. I also have a function that takes this sequence as an argument and reduces it to a value. So, with names changed to protect the innocent, my code looks like:

(defn process [items]
  (reduce (fn [count item] (inc count)) 0 items))

This version works fine because reduce consumes the sequence without retaining the head. (This claim is not obvious, but it is true, at least in my case.)

The problem is, if I replace defn with defnp as defined by taoensso.timbre.profiling, I now have a function that retains the head of the sequence, with expanded code equivalent to the following:

(defn process [items]
  (pspy* "process"
         (fn []
           (reduce (fn [count item] (inc count)) 0 items))))

In this version, the reduce starts consuming the sequence, but the enclosing process function retains the head. As a result, I get an OutOfMemoryError instead of an answer.

For more on head retention, see this thread and this SO question.

Regarding a solution, my best guess would be to change pspy so that it used Clojure metadata instead of wrapping code in a function. I'm not sure this would be compatible with the other features of taoensso.timbre.profiling, but my guess is that there's some way to make that work.

(defn laggy []
  (Thread/sleep 200)
  (throw (Exception. "Done")))

(defn profiled []
  (try
    (p :laggy (laggy))
    (catch Exception e :fail)))

(profile :info :lag (profiled))


;;          Name  Calls       Min        Max       MAD      Mean   Time% Time
;;  [Clock] Time                                                     100 200ms
;;Accounted Time                                                       0 0ns

All the time is actually spent under (p :laggy), but the thrown exception causes it to be ignored.

This is more of an issue in a real usage scenario where the function would only fail sometimes, but do so expensively. Then the result for

(defn profiled []
  (p :profiled
    (try
      (p :slow-function (slow-function))
    (catch Exception e
      (p :recover (recover)))))

would say that only very low part of the time spent in :profiled was spent in :slow-function and :recover, because all slow runs of :slow-function were ignored.

I like Timbre. I want to use it in my current project. However, it uses tools.nrepl as a dependency. tools.nrepl uses tools.logging. I want it to use timbre. Is it possible to set tools.logging up to redirect to timbre?

Do you have a sample configuration for logging to a specified file you can share? Would be great to add this to the readme. I'm new to log4j and logging in clojure in general so it's not obvious to me how logging to file works.

Hi Peter,

I note that syslog support was never mentioned before.

Hipsters may cling on to logging frameworks and façades like they would to skinny jeans, but there is a venerable protocol on UNIX systems called Syslog that is a trusted option when deploying daemons on production servers. Call me old-fashioned.

There is an existing implementation in Clojure.

More rationale (excerpt from LinuxJournal):

As the number and complexity of applications on a system grows, so, too, does the complexity of the system administrator's job. Applications and their messages vary widely in their significance to certain audiences. If a number of applications are considered “critical” and their status is the system administrator's responsibility, he does not want to search to find out where and how every critical application logs its status. That's where syslogd comes in.

Hi,

I updated a project to use the latest timbre and noticed that running lein do drop, migrate suddenly took 9 times more time than earlier.

I worked my way downwards and found out that this behavior starts occurring from version 2.7.0. With 2.6.x things work just fine. I did reproduce this behavior multiple times.

For some reason when a task is done and it prints its last message on screen it takes ages for the process to end (about 2 minutes). Any ideas what could be wrong?

Using [com.taoensso/timbre "3.1.6"] (from clojars as of Fri Mar 14 22:48:34 PDT 2014), running (require '[taoensso.timbre :as timbre]) gives me the below error (expanded with pst).

CompilerException java.lang.RuntimeException: No such var: encore/simple-date-format, compiling:(taoensso/timbre.clj:278:27)
        clojure.lang.Compiler.analyze (Compiler.java:6380)
        clojure.lang.Compiler.analyze (Compiler.java:6322)
        clojure.lang.Compiler$InvokeExpr.parse (Compiler.java:3573)
        clojure.lang.Compiler.analyzeSeq (Compiler.java:6562)
        clojure.lang.Compiler.analyze (Compiler.java:6361)
        clojure.lang.Compiler.analyze (Compiler.java:6322)
        clojure.lang.Compiler$HostExpr$Parser.parse (Compiler.java:915)
        clojure.lang.Compiler.analyzeSeq (Compiler.java:6560)
        clojure.lang.Compiler.analyze (Compiler.java:6361)
        clojure.lang.Compiler.analyzeSeq (Compiler.java:6548)
        clojure.lang.Compiler.analyze (Compiler.java:6361)
        clojure.lang.Compiler.analyze (Compiler.java:6322)
Caused by:
RuntimeException No such var: encore/simple-date-format
        clojure.lang.Util.runtimeException (Util.java:219)
        clojure.lang.Compiler.resolveIn (Compiler.java:6848)
        clojure.lang.Compiler.resolve (Compiler.java:6818)
        clojure.lang.Compiler.analyzeSymbol (Compiler.java:6779)
        clojure.lang.Compiler.analyze (Compiler.java:6343)
        clojure.lang.Compiler.analyze (Compiler.java:6322)
nil

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

Did you consider checking the log level in the log* macro to be done at compile time? I'm talking about this line, here https://github.com/ptaoussanis/timbre/blob/master/src/taoensso/timbre.clj#L333

My current project is very performance sensitive and I would be more confident putting log statements everywhere if I would know that it would not affect performance at all at runtime. Even if it doesn't matter that much, I don't see the benefit of having the option to change the log level at runtime, for production at least. Am I wrong?

What do you think?

Thanks for this library!

Best,
Jeroen

All fns using defnp macro are shown to have an Id in the :user namespace when the results are printed. So the ids are something like :user/process. Would it be possible to show their original namespace name?

cheers!

The v3.0.0 Carmine and Postal appenders have adopted a new style that I'd like to see carried over into 3rd party appenders. Basically each appender ns now exposes a make-<X>-appender (ƒ [& [appender-opts make-opts]]) that'll return a ready-to-use Timbre appender.

appender-opts are any general opts like {:enabled? true :min-level :error}. The appender creator fn will supply defaults, override-able with appender-opts.

make-opts are any opts specific to this appender - e.g. database connections, special formatting options, etc. The options exposed here will be up to the appender author.

If anyone feels like helping out (esp. if you're the author of a v2.x appender), please consider a PR to bring the old appenders in line with the new, more flexible style. You can see the taoensso.timbre.appenders.postal or taoensso.timbre.appenders.carmine namespaces for examples.

Thanks a ton! Feel free to ping me with questions, etc.

I am using timbre to output log messages from several threads, e.g. from a future call. This has worked fine until I changed the root binding of *read-eval* to (constantly false) (as recommended for security reason). Suddenly, I keep getting an exception saying EvalReader not allowed when *read-eval* is false whenever I call a logging command from within a future or a function sent to an agent.

For example, the following code triggers the exception (Clojure 1.5):

(ns test.core
  (:gen-class)
  (:use [taoensso.timbre :only (warn)]))

(defn -main [& args]
  (alter-var-root #'*read-eval* (constantly false))
  (future (warn "Test"))
  (Thread/sleep 1000)
  (shutdown-agents))

The exception goes away when either the alter-var form is removed or the future form is converted to a do form.

Is this a bug or am I doing something wrong?

I just wish to ask, why is there a possibility to override level-atom atom with *level-dynamic*, but there is no possibility to override config atom with a thread-local setting. I want to be able to use a different combination of appenders on a per thread basis, but there seems to be no way to do that with timbre.

I "fixed" this by writing my own logging macros that use a dynamic config and pass it explicitly to the log function, however this solution feels very ugly. Could try to make a generic patch to timbre, but I want to ask if there's some reason behind the current behaviour before wasting any time.

When trying to wrap a multiple arity function with defnp, an error is returned, e.g:

(defnp hi 
  ([] "hi") 
  ([name] (str "hi" name)))

IllegalArgumentException 
Invalid signature {} should be a list 
clojure.core/assert-valid-fdecl/fn--6503 (core.clj:6726)

user=> (pst)
nil
IllegalArgumentException Invalid signature {} should be a list
    clojure.core/assert-valid-fdecl/fn--6503 (core.clj:6726)
    clojure.core/map/fn--4215 (core.clj:2487)
    clojure.lang.LazySeq.sval (LazySeq.java:42)
    clojure.lang.LazySeq.seq (LazySeq.java:60)
    clojure.lang.RT.seq (RT.java:484)
    clojure.core/seq (core.clj:133)
    clojure.core/filter/fn--4234 (core.clj:2523)
    clojure.lang.LazySeq.sval (LazySeq.java:42)
    clojure.lang.LazySeq.seq (LazySeq.java:67)
    clojure.lang.RT.seq (RT.java:484)
    clojure.core/seq (core.clj:133)
    clojure.core/assert-valid-fdecl (core.clj:6730)

More information:

user=> (macroexpand-1 '(defnp hi
                         ([] "hi")
                         ([name] (str "hi" name))))
(clojure.core/defn hi 
  ([] "hi") {} 
  (taoensso.timbre.profiling/pspy "hi" ([name] (str "hi" name))))

Please see this stackoverflow item
http://stackoverflow.com/questions/23333029/clojure-timbre-and-clojure-test-namespaces
This may be my problem (namespace mgt can be tricky), but I'm bringing it to your attention in case it is not my problem.

When max-count number of logs is reached, the active log file isn't getting rotated out, and continues to grow in size.