diff --git a/src/fudge/log.clj b/src/fudge/log.clj index 5e3059d..dec8daa 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,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! + "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: + 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" diff --git a/test/fudge/log_test.clj b/test/fudge/log_test.clj index 55710b2..782e2bf 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,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 @@ -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))))