Need some help/advice: No debug or info level logging, and duplicated message content

[PEZ]

I have a strange behaviour logging from ClojureScript. I get no logging when using debug or warn levels. I get logging with error and info. But then I get the log message duplicated. I’m pretty sure I am doing something wrong, but don’t know where to look for this. I don’t do any custom configuration from the ClojureScript side of things, but we use Timbre both for the backend and for the frontend. Using latest version, 6.1.0.

cljs꞉shadow-cljs.user꞉> 
(require '[taoensso.timbre :as log])
nil
cljs꞉shadow-cljs.user꞉> 
log/*config*
{:appenders {:console {:enabled? true, :fn #object [Function]}},
 :level :debug,
 :middleware [#object [Function]],
 :ns-blacklist ["key-frame.event-logger"]}
cljs꞉shadow-cljs.user꞉> 
(log/debug "foo") ; doesn't log anything
nil
cljs꞉shadow-cljs.user꞉> 
(log/info "foo") ; logs: 2023-05-09T12:24:21.046Z INFO [shadow-cljs.user:1] - foo foo
nil

Anyone seen something like this?

Originally from: #timbre at Clojurians Slack.

[ptaoussanis]

@PEZ Hi Peter! Can you please share a little more about your environment?
Where are you logging to? A browser console? If so, what browser?

[ptaoussanis]

A more thorough answer in the meantime.
I'd check the following:

1. Does your output destination do its own level filtering, etc.? That may be the case with browser consoles, for example.
2. Does the problem still present if you remove your middleware and ns-blacklist? (Good to rule these out to be safe).

Please let me know if you can rule out both of the above and you're still seeing the unexpected behaviour.

As an aside, please note that you have :level in your *config* - which was actually deprecated in Timbre v5. Please use :min-level instead.

The old :level is still supported though, so this won't be the cause of the behaviour you're seeing.

You can always find the latest *config* opts documented in detail here.

[PEZ]

@ptaoussanis Hi Peter! 😀 Thanks for your super speedy response. I'm logging in the browser, forgot to mention that!

Your clues were enough for me to find what I can disable in my code to get the logging levels back, as well as to get rid of the duplication of the logged data.

I'm not super clear if it was 2.. We have a copy of kee-frame in our codebase and disabling it's log init call gets rid of those strange things. We were sending :debug as the level which is what we saw in log/*debug*, but kee-frame (at least our copy) also has a default config with :info as the log level, so I don't know if maybe that was involved (I somehow doubt it).

I now have on my TODO to check out latest kee-frame and see if the problem is still there. Then I can create a minimal repro and maybe see what exactly was actually happening.

Anyway, I'm good now. Thanks again. You rock! 🎸🤘

[ptaoussanis]

You're very welcome 👍

I hadn't heard of kee-frame before, but from a quick skim of this version nothing obvious stands out as an issue.

Both the middleware and default {:level :info} there should be fine.

Ultimately what matters is the final value of timbre/*config*, and yours looks okay (assuming this is the middleware fn you have).

To confirm: after disabling some call to this init function, both issues go away (the duplication, and suppressed debug-level logs)?

[PEZ]

To confirm: after disabling some call to this init function, both issues go away (the duplication, and suppressed debug-level logs)?

Yes. Specifically, I commented out this call: https://github.com/ingesolvoll/kee-frame/blob/8907f615db446c20ed9054acd4b55995b8c6393f/src/kee_frame/core.cljc#L40

[ptaoussanis]

Yes. Specifically, I commented out this call: https://github.com/ingesolvoll/kee-frame/blob/8907f615db446c20ed9054acd4b55995b8c6393f/src/kee_frame/core.cljc#L40

I can't see any obvious reason why that should produce the behaviour you're seeing.
What's the value of (:log options) in your case?

The most common reason for folks not seeing debug output in a browser console is the browser suppressing low level output (for example, Chrome by default doesn't display debug-level).

But if both the duplicate logging and missing output are resolved by skipping this config call, then I guess something in the config must be causing issues.

Maybe try removing the middleware?:

(log/merge-config! {:middleware []})

Though I can't think why that would produce the observed behaviour.

[PEZ]

To shrink it down I tried with the kee-frame demo app. Forked it to here https://github.com/ingesolvoll/kee-frame-sample and insourced the kee-frame dependency.

Now I think you are right about that the two problems are not related.

And that it was the log filter in the browser that was in play for the log level issue. I don't understand how it didn't seem to be this when I fiddled with that setting in the browser... Maybe a caching issue somewhere in the chain of caches involved.

And you're suspicions about the middleware were on target as well. Removing that, removes the duplicated log content.

I couldn't immediately reproduce, but when I insourced kee-frame and added a dependency for latest Timbre it happened. So it seems that something changed in Timbre between 5.1.0 and 6.1.0 that made the middleware behave differently? According to SEMVER, that's OK. 😄

[ptaoussanis]

I don't understand how it didn't seem to be this when I fiddled with that setting in the browser

No problem, happy the missing debug-level problem is resolved 👍

And you're suspicions about the middleware were on target as well. Removing that, removes the duplicated log content.

Could you share a screenshot of what the duplicated log content looks like in your console?

Is it possible that what you're seeing is just the browser's view of the logged data?
The kee-frame middleware causes Timbre's console appender to use this path.

The purpose of that path is to log raw arguments directly to console, so that the console can offer its own type-specific inspection tools (e.g. to expand maps or arrays, etc.).

With the middleware disabled, Timbre's console appender uses this path which first produces a string from its arguments - thus preventing the console from offering any type-specific inspection tools.

[JagGunawardana]

I was having the double logging problem using Chrome (also using kee-frame). Adding :middleware with a value of nil to the logging config for kee frame start! fixed it.

(k/start! {:routes         routes-keys
             :initial-db     db/default-db
              :root-component [views/main-panel]
              :hash-routing?  true
              :log            {:min-level  (if debug :trace :debug)
                               :level      (if debug :debug :info)
                               :middleware nil
                               :ns-filter  {:allow #{"*"}
                                            :deny  #{"kee-frame.event-logger"
                                                     "kee-frame.fsm.alpha"}}}})

[ptaoussanis]

Closing - forthcoming release includes more console appender documentation about this, and makes it easier to control raw console logging without the need for middleware.