Provide line number info to CLJS Chrome dev tools, etc.

[domkm]

In ClojureScript, Chrome Developer Tools shows that Timbre logs originate from a line within taoensso.timbre.appenders.core/console-?appender because that is where console.log|warn|error is called. It would be great if logs showed the correct line number. This could be achieved by using macros instead of functions.

[ptaoussanis]

Hi Dom!

Timbre logging calls are done via a macro, in part to capture available ns + line-number info. The appender call itself is intentionally a fn call for simplicity, flexibility, and expansion size. Expanding all appenders in place would balloon a ClojureScript source file quite quickly.

The ideal solution is to convey the line number from the macro call to the appender (fn) call. That way you can include the line number in the log output. That's what the ?line entry is at https://github.com/ptaoussanis/timbre#configuration.

As noted there though, support for this is unfortunately still waiting on http://dev.clojure.org/jira/browse/CLJ-865

If 865 gets resolved, we can update the default output-fn to include the line number.

Will keep this issue open. Haven't looked into this in a while so not sure if any other possibilities/hacks have since come up (esp. on the cljs side).

I've got my hands full atm, but would be happy to hear ideas if you felt like doing the digging yourself?

Cheers! :-)

[domkm]

Hi Peter :)

I missed that ?line comment in the README. Thanks for pointing it out.

However, even with CLJ-865 resolved, I don't think that this will really achieve what I'm looking for, though please correct me if I'm wrong. Even if logs include correct line numbers, source maps will still point to Timbre, right? Also, is macro expansion size a real issue since logging macros can be elided in production?

Though unrelated to the function vs. macro question, I prefer objects to be printed with console.log directly (instead of being pr-stred first) because I use cljs-devtools. I'd highly recommend it; I find it very helpful for ClojureScript development. Perhaps Timbre could provide something like this in the future.

[ptaoussanis]

Hey :-)

Even if logs include correct line numbers, source maps will still point to Timbre, right?

Source maps will still point to the appender, that's correct. Idea is if you have the line numbers in the log output, you don't need source maps. Actually, may be a way to support source maps too if we wanted that for convenience - haven't investigated. Would be happy if you wanted to dig.

Also, is macro expansion size a real issue since logging macros can be elided in production?

Well, you rarely elide everything in production- you'll normally elide specific levels. In any case, macro expansion size isn't the only reason to prefer functions here. Functions are just a lot more flexible + easier to work with. There'd need to be pretty compelling reasons to go the macro route with all you'd need to give up for it - if that makes sense?

I prefer objects to be printed with console.log directly (instead of being pr-stred first) because I use cljs-devtools

Sure, totally! You can just add your own little appender for this if you like and disable the default console appender. Would be happy to see a PR if you felt like including one?

Could add it to the bottom of https://github.com/ptaoussanis/timbre/blob/master/src/taoensso/timbre/appenders/core.cljx#L135 and add an alias at https://github.com/ptaoussanis/timbre/blob/master/src/taoensso/timbre.cljx#L51

I haven't used cljs-devtools myself, so would be awesome if you could handle that since you've experience with it.

Cheers! :-)

[ptaoussanis]

I prefer objects to be printed with console.log directly (instead of being pr-stred first) because I use cljs-devtools

Just took a quick look at cljs-devtools btw. Looks like you actually might not need/want a different appender at all?: Timbre already includes all raw logging args under the :vargs_ appender key. You're welcome to use that instead of the :output-fn if you prefer. (Or to mod your output fn to just return the raw logging args).

I'd suggest checking the config docstring at https://github.com/ptaoussanis/timbre#configuration to see what info your appenders are given to work with. Hope that helps? :-)

[domkm]

Hey Peter,

Sorry for my slow response. I don't know how you manage to always respond so quickly, politely, and thoroughly, but I truly admire you for it. :)

I'll take a look at the appender documentation that you included. Thanks for that. I'll also look into whether it's possible to fix line numbers without resorting to macros.

Thanks again for your help with this and for everything you do for the community. :)

[ptaoussanis]

No problem, you're very welcome! Thanks for saying so :-)

Feel free to ping if you have any follow-up Q's or if you turn up anything that Timbre could handle better. Like I say, it's quite possible- haven't looked into the line number situation for a while (and never looked on the cljs side).

Cheers! :-)

[domkm]

Using this I was able to create an appender that displayed the line number on which the appender was called instead of a line number from within the appender. That solved the biggest problem caused by appenders being functions. The problem now is that line numbers originate from within log1-fn because that is where appenders are called. Would you be open to a PR that inlines log1-fn into log1-macro? This would fix line numbers and source maps in ClojureScript without sacrificing the current data/function composition of configs and appenders.

[ptaoussanis]

Hey, sorry for the delay replying to this - have been crazy swamped.

Haven't had a chance to look at this in detail yet, but would be happy to see a PR with what you had in mind!

[ptaoussanis]

Hey Dom, any update on this?

[domkm]

Hey Peter, sorry, I've been swamped. I'll get around to this eventually but it probably won't be that soon so I'll close the issue for now. Thanks for your help!

[ptaoussanis]

Zero problem, please take your time. Do prefer to keep this open in the meanwhile though so that I don't forget about it :-)

[danskarda]

Hi Peter,
first - thanks for great Clojure and ClojureScript libraries!

I investigated the issue how to get correct file names with timbre and Chrome Dev Tools. It turns out that new Chrome Dev Tools has a feature called blackboxing. You can select files to be ignored by Chrome Dev Tools. For logging using timbre, you should blackbox:

• /timbre.js$
• /cljs/core.js$
• /path/to/your/custom/timbre/appender.js$

I used it today with cljs-devtools and it works great (including jump to the CLJS file with sourcemaps). Developer's heaven.

My setup:

(def devtools-level-to-fn
  {:fatal js/console.error,
   :error js/console.error,
   :warn  js/console.warn,
   :info  js/console.info,
   :debug js/console.debug,
   :trace js/console.trace})

(def devtools-appender
  "Simple js/console appender which avoids pr-str and uses cljs-devtools
  to format output"
  {:enabled?   true
   :async?     false
   :min-level  nil
   :rate-limit nil
   :output-fn  nil
   :fn
   (fn [data]
     (let [{:keys [level ?ns-str vargs_]} data
           vargs (list* (str ?ns-str ":") (force vargs_))
           f (devtools-level-to-fn level js/console.log)]
       (.apply f js/console (to-array vargs))))})

(when (= "Google Inc." js/navigator.vendor)
  (set! log/*config*
        (-> log/*config*
            (assoc-in [:appenders :console] devtools-appender))))

I am open to suggestions how to improve it and contribute it as a pull request.

[ptaoussanis]

@danskarda That's awesome, thank you Daniel!

May I ask for you to create a PR for a chrome-devtools appender as you have it here?

Please include a docstring mention of your https://developer.chrome.com/devtools/docs/blackboxing reference, and the vendor check as a comment block. (I'll bring that into the appender impl. myself).

Just focused on something else at the moment, but will clean up the PR + merge as soon as I have some time.

Edit: Oh, and you're very welcome re: the libs! :-)

[ptaoussanis]

Using this I was able to create an appender that displayed the line number on which the appender was called instead of a line number from within the appender.

Hey @domkm, any chance you could show me a snippet of what that appender looks like? Want to take a stab at getting this in on the next release. Thanks!

[domkm]

Hi @ptaoussanis,

I can't seem to find the code. Sorry. If memory serves, it was a direct JS-to-CLJS port of https://gist.github.com/bgrins/5108712#file-log-portable-js.

[ptaoussanis]

Hi Dom, thanks for the reply.

Do you happen to recall if some kind of a port of that code definitely solved the problem? I.e. when used as a Timbre appender, the appender was producing accurate line numbers w/o the need for any blackboxing?

Was fiddling with that Log-portable.js example yesterday and couldn't get anything to work outside of a similar trivial js/console.log wrapper. My understanding over what's actually causing the issue is limited though so I may be missing something obvious.

[domkm]

I remember modifying the built-in console-appender, but, if I actually had gotten it to work perfectly, I don't know why I wouldn't have also submitted a PR, so perhaps my memory is false. I'm really sorry I can't be more helpful.

[ptaoussanis]

No problem- if you happen to remember something, feel free to update here - otherwise have instructions in the v4.3 appender for enabling Chrome Blackboxing. CLJ-865 will also hopefully get resolved some time which should make this less important.

Cheers! :-)

[darwin]

I'm not a timbre user (yet), but I think OP's request can be implemented by a rather simple wrapper macro (in user code) and a modified console appender. For example we could take @danskarda's devtools-appender and instead of calling console.log in there we would store vargs into a global variable *last-vargs*. The wrapper macro would generate a line similar to this:

(do (set! *last-vargs* nil) (call-timbre-leading-to-devtools-appender-execution ...) (.apply js/console.log js/console *last-vargs*) nil)

This would work out-of-the-box without blackboxing setup. It relies on the fact that javascript has a single thread and nothing could step in between (assuming timbre does everything synchronously). Also the generated code at call sites would not balloon that much because possibly complex timbre code is still behind a function call. Of course it could be implemented less dirty using some kind of log queue or "service" instead of setting a global variable directly. But you get the idea.

[ptaoussanis]

@darwin Hi Antonin, would be happy to look over a PR if you have one - thanks!

[darwin]

I'm sorry I have a lot of other things on my plate right now. Don't expect a PR from me.