Skip to content

Add line numbers #1

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
dancmeyers wants to merge 3 commits into
base: master
Choose a base branch
from
Open

Add line numbers #1

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
bfcd9ea
Correct test function to run within 'testing'
Aug 3, 2017
aa7a898
Add metadata (file, namespace, line numbers)
Aug 11, 2017
4545f58
Add thread-first versions of the spy functions
Aug 11, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
72 changes: 53 additions & 19 deletions src/fudge/log.clj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,15 @@
[c k & args]
(apply (k c) c args))

(defmacro calling-meta
"Used by other macros to get the namespace, file and line of the log call.
Builds a def with a generated symbol to expand and evaluate for the info."
Copy link
Owner

@osfameron osfameron Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's an implementation detail so possibly doesn't need to be in docstring. Interesting though - is there any issue with having def's everywhere there's logging? And should it be a defonce to avoid being reevaluated in loops?

Copy link
Contributor Author

@dancmeyers dancmeyers Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

defonce would probably be better for loops, yes.

As for the defs everywhere where logging, I did spend quite a while in query console and writing extra output from the test file to check the current vars in (ns-publics (all-ns)) and anywhere else I could think to check. I couldn't find these defs cluttering up the namespace anywhere. The use of (gen-sym) also means that the defs are unique and won't clash with user defs, so even if they do stay around somewhere I don't think have one additional randomly named def with no value per log call is an issue.

Copy link
Contributor Author

@dancmeyers dancmeyers Oct 19, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done some testing with this. defonce requires a value, because it basically says "If the symbol has a value, leave it as-is. Otherwise set the symbol to arg #2". (def sym#) isn't actually setting the symbol to have a value, it's just defining the symbol as present. You can't do (defonce sym#).

[]
`(let [meta# (meta (def sym#))]
(-> meta#
(select-keys [:ns :file :line])
(update :ns str))))

;; # Log-levels

(defn set-valid-levels
Expand Down Expand Up @@ -52,12 +61,15 @@
{:message data}))

(defn prepare-data-for-logging
"Prepare the `data` structure being logged by setting the `:level`
and `:date` values"
[config data level]
"Prepare the `data` structure being logged by setting the `:level`,
`:date`, `:ns`, `:file` and `:line` values"
[config data level calling-meta]
(->> data
normalize-data
(merge {:date (call config :date-fn)
:ns (:ns calling-meta)
:file (:file calling-meta)
:line (:line calling-meta)
Copy link
Owner

@osfameron osfameron Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this could be (merge {:date... :level...} calling-meta) ?

I'm wondering if the calling-meta should be a) bundled in a sub-key, and/or b) passed within data.

Copy link
Contributor Author

@dancmeyers dancmeyers Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, good point r.e. the merge.

I was actually thinking that maybe data should be the sub key. That's the user provided bit, so that's the bit which might have clashing keys depending on what the user wants to output. data in a subkey stops anything like that.

:level level})))

;; # The logger configuration
Expand Down Expand Up @@ -118,40 +130,62 @@

;; # Main logging functions

(defn log
"Log a record with the config, level, and data provided"
[c level data]
(let [record (invoke c :prepare-fn data level)]
(defn log!
Copy link
Owner

@osfameron osfameron Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why the exclamation mark?

Copy link
Owner

@osfameron osfameron Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, if just to distinguish from the log macro, I've seen people use log-fn for the function implementation (though that's uncomfortable here, as we're using -fn for the callbacks already.) Perhaps separating macros into another namespace as I mentioned elsewhere is the thing.

Copy link
Contributor Author

@dancmeyers dancmeyers Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It was just to distinguish the macro from the function, yes.

Copy link

@ConorPFarrell ConorPFarrell Oct 18, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It shouldn't be called log! IMO as that goes against the Clojure standard. If I see ! at the end of a function, I expect it to be unsafe with respect to an STM transaction, not just impure.

Copy link
Owner

@osfameron osfameron Oct 18, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As in https://github.com/bbatsov/clojure-style-guide#changing-state-fns-with-exclamation-mark ?

That only says STM-unsafe should end with !, not that nothing else should. But yeah, as above, I don't love the name anyway.

Copy link
Contributor Author

@dancmeyers dancmeyers Oct 19, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm open to other suggestions. I basically nicked this pattern from timbre ( https://github.com/ptaoussanis/timbre ).

"Log a record with the config, level, form metadata and data provided"
[c calling-meta level data]
(let [record (invoke c :prepare-fn data level calling-meta)]
(when (invoke c :log?-fn record)
(->> record
(call c :format-fn)
(call c :output-fn)))))

(defn spy-with
(defmacro log
"Log a record with the config, level, and data provided."
[c level data]
`(log! ~c (calling-meta) ~level ~data))

(defmacro spy-with->>
Copy link
Owner

@osfameron osfameron Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good spot re ->>. I wonder if we want an alias without the punctuation noise though.

Also, why a macro?

Copy link
Contributor Author

@dancmeyers dancmeyers Aug 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So it can use the calling-meta macro correctly. With two macros like this, the whole lot expands into the caller's namespace, which means calling-meta gets the correct file, namespace and line. If this was a function, calling-meta would always return the file as fudge/log.clj, the namespace as fudge.log and the line as whatever line the call to calling-meta was on.

It's why I tried to leave all the complicated stuff in the log function, and have each macro do the minimum necessary to pass the function what it needs. Then there's minimal faffing with macro escaping.

"Log a record about a data value, first applying the transform
supplied. Returns the original, untransformed value. Designed
to be used in threaded pipelines. For example:
to be used in thread-last pipelines. For example:

(->> [1 2 3 4 5]
(map inc)
(spy-with->> logger #(str \"List contains \" (pr-str %)) :info)
(map inc))"
[c transform level data]
`(doto ~data
(->> (~transform)
(log ~c ~level))))

(defmacro spy-with->
"Log a record about a data value, first applying the transform
supplied. Returns the original, untransformed value. Designed
to be used in thread-first pipelines. For example:

(-> {:counter 1}
(update :counter inc)
(spy-with #(str \"The number is now \" (:counter %)))
(spy-with-> logger #(str \"The number is now \" (:counter %)) :info)
(update :counter inc))"
[c transform level data]
(doto data
(->> transform
(log c level))))
[data c transform level]
`(spy-with->> ~c ~transform ~level ~data))

(defn spy
"Log a record about a data value as per `spy-with`, but with no transformation."
(defmacro spy->>
"Log a record about a data value as per `spy-with->>`, but with no transformation."
[c level data]
(spy-with c identity level data))
`(spy-with->> ~c identity ~level ~data))

(defmacro spy->
"Log a record about a data value as per `spy-with->`, but with no transformation."
[data c level]
`(spy-with->> ~c identity ~level ~data))

;; # Common format configs

(defn format-plain
"Simple plain string formatter"
[{:keys [:date :level :message]}]
(str date " [" level "] " message))
[{:keys [:ns :line :date :level :message]}]
(str date " [" ns ":" line "] [" (name level) "] " message))

(def plain-config
"Config for a plain text log message format"
Expand Down
78 changes: 52 additions & 26 deletions test/fudge/log_test.clj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,9 @@
:fn
1))))

(deftest test-calling-meta
(is (= {:ns "fudge.log-test" :file "fudge/log_test.clj" :line 16} (calling-meta))))

(deftest test-valid-levels
(is (= #{:info :warn :error}
(-> {:level :info
Expand All @@ -34,11 +37,16 @@

(deftest test-prepare-data-for-logging
(let [config {:date-fn (constantly "2017-07-08")}
expected {:message "Hello World",
expected {:message "Hello World"
:ns "fudge.log_test"
:file "fudge/log_test.clj"
:line 30
:level :info
:date "2017-07-08"}]
(is (= expected (prepare-data-for-logging config "Hello World" :info)))
(is (= expected (prepare-data-for-logging config {:message "Hello World"} :info)))))
(is (= expected (prepare-data-for-logging config "Hello World" :info
{:ns "fudge.log_test" :file "fudge/log_test.clj" :line 30 :name "test"})))
(is (= expected (prepare-data-for-logging config {:message "Hello World"} :info
{:ns "fudge.log_test" :file "fudge/log_test.clj" :line 30 :name "test"})))))

(deftest test-get-logger
(let [logger (get-logger {:setup-config-fn #(assoc % :foo :foo)}
Expand All @@ -50,42 +58,60 @@
(testing "Config retained values from base config that weren't overridden"
(is (= identity (:format-fn logger))))))

(deftest test-log
(deftest test-log!
(testing "Log"
(let [logger {:prepare-fn (fn [c d l] (assoc d :level l))
(let [logger {:prepare-fn (fn [c d l m] (assoc d :level l))
:log?-fn (constantly true)
:format-fn (juxt :level :message)
:output-fn (partial clojure.string/join " ")}]
(is (= ":info MSG" (log logger :info {:message "MSG"})))))
(testing "Don't log")
(is (= ":info MSG" (log! logger {:file "path/to/file.clj" :line 30 :ns *ns*} :info {:message "MSG"})))))
(testing "Don't log"
(let [logger {:prepare-fn (constantly {})
:log?-fn (constantly false)}]
(is (= nil (log logger :info {:message "MSG"})))))
(is (= nil (log! logger {:file "path/to/file.clj" :line 30 :ns *ns*} :info {:message "MSG"}))))))

(deftest test-log
(let [logger {:prepare-fn (fn [c d l m] (assoc d :level l))
:log?-fn (constantly true)
:format-fn (juxt :level :message)
:output-fn (partial clojure.string/join " ")}]
(is (= ":info MSG" (log logger :info {:message "MSG"})))))

(deftest test-spy-and-spy-with
(let [out (atom "")
logger {:prepare-fn (fn [c d l] d)
logger {:prepare-fn (fn [c d l m] d)
:log?-fn (constantly true)
:format-fn identity
:output-fn (partial reset! out)}]
(testing "spy-with"
(let [result (spy-with logger count :info "Hello")]
(is (= "Hello" result))
(is (= 5 @out))))
(testing "spy"
(let [result (spy logger :info "Hello")]
(is (= "Hello" result))
(is (= "Hello" @out))))))
(testing "spy-with->>"
(let [result (spy-with->> logger count :info "Thread last")]
(is (= "Thread last" result))
(is (= 11 @out))))
(testing "spy-with->"
(let [result (spy-with-> "Thread first" logger count :info)]
(is (= "Thread first" result))
(is (= 12 @out))))
(testing "spy->>"
(let [result (spy->> logger :info "Thread last")]
(is (= "Thread last" result))
(is (= "Thread last" @out))))
(testing "spy->"
(let [result (spy-> "Thread first" logger :info)]
(is (= "Thread first" result))
(is (= "Thread first" @out))))))

(deftest test-formats
(let [record {:date "2017-07-08"
:ns "fudge.log-test"
:line 10
:file "fudge/log_test.clj"
:level :info
:message "Hello"}]
(testing "format-plain"
(is (= "2017-07-08 [:info] Hello"
(is (= "2017-07-08 [fudge.log-test:10] [info] Hello"
(format-plain record))))
(testing "format-aws-log"
(is (= "2017-07-08 {\"level\":\"info\",\"message\":\"Hello\"}"
(is (= "2017-07-08 {\"ns\":\"fudge.log-test\",\"line\":10,\"file\":\"fudge/log_test.clj\",\"level\":\"info\",\"message\":\"Hello\"}"
(format-aws-log record))))))

;; End to end tests
Expand All @@ -108,33 +134,33 @@
(let [logger (plain-logger)
result (with-out-str
(log logger :info "foo"))]
(is (= "2017-05-12T18:01 [:info] foo\n" result))))
(is (= "2017-05-12T18:01 [fudge.log-test:136] [info] foo\n" result))))

(testing "multiple lines output"
(let [logger (plain-logger)
result (with-out-str
(log logger :info "foo")
(log logger :error "bar"))]
(is (= "2017-05-12T18:01 [:info] foo\n2017-05-12T18:02 [:error] bar\n" result))))
(is (= "2017-05-12T18:01 [fudge.log-test:142] [info] foo\n2017-05-12T18:02 [fudge.log-test:143] [error] bar\n" result))))

(testing "pipeline"
(let [logger (plain-logger)
result (with-out-str
(->> 1
inc
(spy logger :info)
(spy->> logger :info)
inc
(spy-with logger #(* 10 %) :info)))]
(is (= "2017-05-12T18:01 [:info] 2\n2017-05-12T18:02 [:info] 30\n" result)))))
(spy-with->> logger #(* 10 %) :info)))]
(is (= "2017-05-12T18:01 [fudge.log-test:151] [info] 2\n2017-05-12T18:02 [fudge.log-test:153] [info] 30\n" result)))))

(deftest test-json-logger
(let [logger (json-logger)
result (with-out-str
(log logger :info "foo"))]
(is (= "{\"date\":\"2017-05-12T18:01\",\"level\":\"info\",\"message\":\"foo\"}\n" result))))
(is (= "{\"date\":\"2017-05-12T18:01\",\"ns\":\"fudge.log-test\",\"file\":\"fudge/log_test.clj\",\"line\":159,\"level\":\"info\",\"message\":\"foo\"}\n" result))))

(deftest test-aws-logger
(let [logger (aws-logger)
result (with-out-str
(log logger :info "foo"))]
(is (= "2017-05-12T18:01 {\"level\":\"info\",\"message\":\"foo\"}\n" result))))
(is (= "2017-05-12T18:01 {\"ns\":\"fudge.log-test\",\"file\":\"fudge/log_test.clj\",\"line\":165,\"level\":\"info\",\"message\":\"foo\"}\n" result))))