From bfcd9ea5e92a012f00351462bc58eaffcb6ffd6d Mon Sep 17 00:00:00 2001 From: Dan Meyers Date: Thu, 3 Aug 2017 13:05:44 +0100 Subject: [PATCH 1/3] Correct test function to run within 'testing' To match all the other tests. --- test/fudge/log_test.clj | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/fudge/log_test.clj b/test/fudge/log_test.clj index 55710b2..373c618 100644 --- a/test/fudge/log_test.clj +++ b/test/fudge/log_test.clj @@ -57,10 +57,10 @@ :format-fn (juxt :level :message) :output-fn (partial clojure.string/join " ")}] (is (= ":info MSG" (log logger :info {:message "MSG"}))))) - (testing "Don't log") + (testing "Don't log" (let [logger {:prepare-fn (constantly {}) :log?-fn (constantly false)}] - (is (= nil (log logger :info {:message "MSG"}))))) + (is (= nil (log logger :info {:message "MSG"})))))) (deftest test-spy-and-spy-with (let [out (atom "") From aa7a898c80fc69c2da887f625210e2bb0fd5fb7f Mon Sep 17 00:00:00 2001 From: Dan Meyers Date: Fri, 11 Aug 2017 23:35:33 +0100 Subject: [PATCH 2/3] Add metadata (file, namespace, line numbers) Getting metadata about the file, namespace and line the log function was called from requires the use of macros. So convert the log functions users would call (log, spy, spy-with) to macros to get this information. The output functions have also been modified to include the namespace and line number (and filename, for json output) in the default case. A slight downside to this is that the end-to-end tests include the line number in the output, so adding or removing lines from the test file causes those tests to fail... Any better ideas for how to test this much appreciated. --- src/fudge/log.clj | 55 +++++++++++++++++++++++++++-------------- test/fudge/log_test.clj | 48 ++++++++++++++++++++++++----------- 2 files changed, 69 insertions(+), 34 deletions(-) diff --git a/src/fudge/log.clj b/src/fudge/log.clj index 5e3059d..01ebcd0 100644 --- a/src/fudge/log.clj +++ b/src/fudge/log.clj @@ -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." + [] + `(let [meta# (meta (def sym#))] + (-> meta# + (select-keys [:ns :file :line]) + (update :ns str)))) + ;; # Log-levels (defn set-valid-levels @@ -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) :level level}))) ;; # The logger configuration @@ -118,40 +130,45 @@ ;; # 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! + "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 "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: - (-> {:counter 1} - (update :counter inc) - (spy-with #(str \"The number is now \" (:counter %))) - (update :counter inc))" + (->> {:counter 1} + (update :counter inc) + (spy-with #(str \"The number is now \" (:counter %))) + (update :counter inc))" [c transform level data] - (doto data - (->> transform - (log c level)))) + `(doto ~data + (->> (~transform) + (log ~c ~level)))) -(defn spy +(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)) ;; # 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" diff --git a/test/fudge/log_test.clj b/test/fudge/log_test.clj index 373c618..4369e74 100644 --- a/test/fudge/log_test.clj +++ b/test/fudge/log_test.clj @@ -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 @@ -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)} @@ -50,21 +58,28 @@ (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"}))))) + (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)}] @@ -79,13 +94,16 @@ (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 @@ -108,14 +126,14 @@ (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:128] [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:134] [info] foo\n2017-05-12T18:02 [fudge.log-test:135] [error] bar\n" result)))) (testing "pipeline" (let [logger (plain-logger) @@ -125,16 +143,16 @@ (spy logger :info) inc (spy-with logger #(* 10 %) :info)))] - (is (= "2017-05-12T18:01 [:info] 2\n2017-05-12T18:02 [:info] 30\n" result))))) + (is (= "2017-05-12T18:01 [fudge.log-test:143] [info] 2\n2017-05-12T18:02 [fudge.log-test:145] [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\":151,\"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\":157,\"level\":\"info\",\"message\":\"foo\"}\n" result)))) From 4545f58c4fa522fe618fd5afb2964c4e04499191 Mon Sep 17 00:00:00 2001 From: Dan Meyers Date: Sat, 12 Aug 2017 00:32:53 +0100 Subject: [PATCH 3/3] Add thread-first versions of the spy functions spy and spy-with were specifically thread-last due to the argument order. This renames them to spy->> and spy-with->> to make that explicit, and also adds a thread-first variant of each. Also updated the doc for each case to actually be correct, i.e. called in a thread-first or -last way, with data strctures that are manipulated in thread-first or -last context. --- src/fudge/log.clj | 37 +++++++++++++++++++++++++++---------- test/fudge/log_test.clj | 38 +++++++++++++++++++++++--------------- 2 files changed, 50 insertions(+), 25 deletions(-) diff --git a/src/fudge/log.clj b/src/fudge/log.clj index 01ebcd0..dec8daa 100644 --- a/src/fudge/log.clj +++ b/src/fudge/log.clj @@ -140,28 +140,45 @@ (call c :output-fn))))) (defmacro log - "Log a record with the config, level, and data provided" + "Log a record with the config, level, and data provided." [c level data] `(log! ~c (calling-meta) ~level ~data)) -(defmacro spy-with +(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 threaded pipelines. For example: + to be used in thread-last pipelines. For example: - (->> {:counter 1} - (update :counter inc) - (spy-with #(str \"The number is now \" (:counter %))) - (update :counter inc))" + (->> [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 - "Log a record about a data value as per `spy-with`, but with no transformation." +(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-> logger #(str \"The number is now \" (:counter %)) :info) + (update :counter inc))" + [data c transform level] + `(spy-with->> ~c ~transform ~level ~data)) + +(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 diff --git a/test/fudge/log_test.clj b/test/fudge/log_test.clj index 4369e74..782e2bf 100644 --- a/test/fudge/log_test.clj +++ b/test/fudge/log_test.clj @@ -83,14 +83,22 @@ :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" @@ -126,33 +134,33 @@ (let [logger (plain-logger) result (with-out-str (log logger :info "foo"))] - (is (= "2017-05-12T18:01 [fudge.log-test:128] [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 [fudge.log-test:134] [info] foo\n2017-05-12T18:02 [fudge.log-test:135] [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 [fudge.log-test:143] [info] 2\n2017-05-12T18:02 [fudge.log-test:145] [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\",\"ns\":\"fudge.log-test\",\"file\":\"fudge/log_test.clj\",\"line\":151,\"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 {\"ns\":\"fudge.log-test\",\"file\":\"fudge/log_test.clj\",\"line\":157,\"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))))