Example: otplike Logging System

[pwhittin]

Here's some code to implement a simple otplike logging system:

(ns otplike-log.log
  (:require [clj-time.core :as t]
            [clj-time.local :as l]
            [otplike.process :as process :refer [!]]))

(defn pad0
  [field-width n]
  (let [s (pr-str n)
        pad-count (- field-width (count s))
        pad-string (apply str (repeat pad-count "0"))]
    (str pad-string s)))

(def pad00 (partial pad0 2))

(def pad000 (partial pad0 3))

(defn get-now-str
  []
  (let [now (l/local-now)]
    (str
      (pad00 (t/year now)) "-" (pad00 (t/month now)) "-" (pad00 (t/day now))
      " "
      (pad00 (t/hour now)) ":" (pad00 (t/minute now)) ":" (pad00 (t/second now))
      "." (pad000 (t/milli now)))))

(defn get-space-delimited-values-string
  [values]
  (apply str (interpose " " values)))

(defn get-log-line
  [values]
  (str (get-now-str) ": " (get-space-delimited-values-string values) "\n"))

(process/proc-defn
  log-proc
  [log-line-fn]
  (process/receive!
    msg (do (log-line-fn msg)
          (recur log-line-fn))))

(defn create-log
  [log-fn]
  (let [log (process/spawn log-proc [(comp log-fn get-log-line)])]
    (fn
      [& values]
      (! log values))))

and here's a demo of using it:

(ns otplike-log.core
  (:require [otplike-log.log :as l])
  (:gen-class))

(defn doit
  [this-many-times moniker sleep-ms log]
  (doall (for [n (range this-many-times)]
           (do
             (log moniker n)
             (Thread/sleep sleep-ms)))))

(def doit-slow (partial doit 10 "slow" 1000))

(def doit-fast (partial doit 20 "fast" 500))

(defn log-to-file
  [log-file-spec]
  (fn
    [log-line]
    (spit log-file-spec log-line :append true)))

(defn example-1
  [log]
  (log
    "one"
    (+ 1 2)
    (apply str (interpose "," "three")))
  (doseq [log-message (range 10)]
    (log log-message)))

(defn example-2
  [log]
  (future (doit-fast log))
  (doit-slow log))

(defn -main
  [& args]
  (let [log (l/create-log (log-to-file "log.txt"))]
    (example-1 log)
    (example-2 log)))

Running "-main" produces something like:

2017-09-08 15:18:15.799: one 3 t,h,r,e,e
2017-09-08 15:18:15.801: 0
2017-09-08 15:18:15.801: 1
2017-09-08 15:18:15.802: 2
2017-09-08 15:18:15.803: 3
2017-09-08 15:18:15.803: 4
2017-09-08 15:18:15.804: 5
2017-09-08 15:18:15.804: 6
2017-09-08 15:18:15.805: 7
2017-09-08 15:18:15.806: 8
2017-09-08 15:18:15.806: 9
2017-09-08 15:18:15.807: fast 0
2017-09-08 15:18:15.807: slow 0
2017-09-08 15:18:16.301: fast 1
2017-09-08 15:18:16.801: slow 1
2017-09-08 15:18:16.802: fast 2
2017-09-08 15:18:17.302: fast 3
2017-09-08 15:18:17.801: slow 2
2017-09-08 15:18:17.803: fast 4
2017-09-08 15:18:18.303: fast 5
2017-09-08 15:18:18.802: slow 3
2017-09-08 15:18:18.803: fast 6
2017-09-08 15:18:19.304: fast 7
2017-09-08 15:18:19.803: slow 4
2017-09-08 15:18:19.804: fast 8
2017-09-08 15:18:20.305: fast 9
2017-09-08 15:18:20.803: slow 5
2017-09-08 15:18:20.805: fast 10
2017-09-08 15:18:21.305: fast 11
2017-09-08 15:18:21.804: slow 6
2017-09-08 15:18:21.806: fast 12
2017-09-08 15:18:22.307: fast 13
2017-09-08 15:18:22.804: slow 7
2017-09-08 15:18:22.807: fast 14
2017-09-08 15:18:23.307: fast 15
2017-09-08 15:18:23.805: slow 8
2017-09-08 15:18:23.808: fast 16
2017-09-08 15:18:24.308: fast 17
2017-09-08 15:18:24.805: slow 9
2017-09-08 15:18:24.809: fast 18
2017-09-08 15:18:25.309: fast 19

[pwhittin]

Added "supervised" logging that restarts the logger if it crashes:

(ns otplike-log.log
  (:require [clj-time.core :as t]
            [clj-time.local :as l]
            [otplike.process :as op :refer [!]]))

(defn pad0
  [field-width n]
  (let [s (pr-str n)
        pad-count (- field-width (count s))
        pad-string (apply str (repeat pad-count "0"))]
    (str pad-string s)))

(def pad00 (partial pad0 2))

(def pad000 (partial pad0 3))

(defn get-now-str
  []
  (let [now (l/local-now)]
    (str
      (pad00 (t/year now)) "-" (pad00 (t/month now)) "-" (pad00 (t/day now))
      " "
      (pad00 (t/hour now)) ":" (pad00 (t/minute now)) ":" (pad00 (t/second now))
      "." (pad000 (t/milli now)))))

(defn get-space-delimited-values-string
  [values]
  (apply str (interpose " " values)))

(defn get-log-line
  [values]
  (str (get-now-str) ": " (get-space-delimited-values-string values) "\n"))

(op/proc-defn
  log-proc
  [log-line-fn]
  (op/receive!
    msg (do
          (log-line-fn msg)
          (recur log-line-fn))))

(op/proc-defn
  supervised-log-proc
  [log-line-fn]
  (op/flag :trap-exit true)
  (loop [log (op/spawn-link log-proc [log-line-fn])]
    (recur
      (op/receive!
        [:EXIT _ reason]
        (let [new-log (op/spawn-link log-proc [log-line-fn])]
          (! new-log [(str "log-monitor-proc: log died - " reason)])
          new-log)
        msg
        (do
          (! log msg)
          log)))))

(defn create-log
  [log-fn]
  (let [log (op/spawn log-proc [(comp log-fn get-log-line)])]
    (fn
      [& values]
      (! log values))))

(defn create-supervised-log
  [log-fn]
  (let [supervised-log (op/spawn supervised-log-proc
                                 [(comp log-fn get-log-line)])]
    (fn
      [& values]
      (! supervised-log values))))

and here's a demo of using it:

(ns otplike-log.core
  (:require [otplike-log.log :as l])
  (:gen-class))

(defn doit
  [this-many-times moniker sleep-ms log]
  (doseq [n (range this-many-times)]
    (do
      (log moniker n)
      (Thread/sleep sleep-ms))))

(def doit-slow (partial doit 10 "slow" 1000))

(def doit-fast (partial doit 20 "fast" 500))

(defn log-to-file
  [log-file-spec]
  (fn
    [log-line]
    (spit log-file-spec log-line :append true)))

(defn log-to-file-or-die
  [log-file-spec]
  (fn
    [log-line]
    (if (re-find #".*: die" log-line)
      (/ 11 0) ;; Division by Zero Exception
      (spit log-file-spec log-line :append true))))

(defn example-1
  [log]
  (log
    "one"
    (+ 1 2)
    (apply str (interpose "," "three")))
  (doseq [log-message (range 10)]
    (log log-message)))

(defn example-2
  [log]
  (future (doit-fast log))
  (doit-slow log))

(defn example-3
  [log]
  (log "example-3: 1")
  (log "die")
  (log "example-3: 2")
  (Thread/sleep 1000)
  (log "example-3: 3"))

(defn -main
  [& args]
  (let [log (l/create-log (log-to-file "log.txt"))]
    (log "=================================================================")
    (log "== create-log")
    (log "=================================================================")
    (example-1 log)
    (example-2 log))
  (let [log (l/create-supervised-log (log-to-file-or-die "log.txt"))]
    (log "=================================================================")
    (log "== create-supervised-log")
    (log "=================================================================")
    (example-3 log)))

Running "-main" produces something like:

2017-09-13 16:15:14.361: =================================================================
2017-09-13 16:15:14.365: == create-log
2017-09-13 16:15:14.366: =================================================================
2017-09-13 16:15:14.366: one 3 t,h,r,e,e
2017-09-13 16:15:14.367: 0
2017-09-13 16:15:14.367: 1
2017-09-13 16:15:14.368: 2
2017-09-13 16:15:14.368: 3
2017-09-13 16:15:14.368: 4
2017-09-13 16:15:14.369: 5
2017-09-13 16:15:14.369: 6
2017-09-13 16:15:14.370: 7
2017-09-13 16:15:14.371: 8
2017-09-13 16:15:14.372: 9
2017-09-13 16:15:14.372: fast 0
2017-09-13 16:15:14.373: slow 0
2017-09-13 16:15:14.851: fast 1
2017-09-13 16:15:15.350: slow 1
2017-09-13 16:15:15.352: fast 2
2017-09-13 16:15:15.852: fast 3
2017-09-13 16:15:16.351: slow 2
2017-09-13 16:15:16.353: fast 4
2017-09-13 16:15:16.852: fast 5
2017-09-13 16:15:17.352: slow 3
2017-09-13 16:15:17.354: fast 6
2017-09-13 16:15:17.854: fast 7
2017-09-13 16:15:18.353: slow 4
2017-09-13 16:15:18.354: fast 8
2017-09-13 16:15:18.855: fast 9
2017-09-13 16:15:19.353: slow 5
2017-09-13 16:15:19.356: fast 10
2017-09-13 16:15:19.856: fast 11
2017-09-13 16:15:20.354: slow 6
2017-09-13 16:15:20.357: fast 12
2017-09-13 16:15:20.858: fast 13
2017-09-13 16:15:21.355: slow 7
2017-09-13 16:15:21.358: fast 14
2017-09-13 16:15:21.859: fast 15
2017-09-13 16:15:22.355: slow 8
2017-09-13 16:15:22.359: fast 16
2017-09-13 16:15:22.860: fast 17
2017-09-13 16:15:23.356: slow 9
2017-09-13 16:15:23.361: fast 18
2017-09-13 16:15:23.862: fast 19
2017-09-13 16:15:24.379: =================================================================
2017-09-13 16:15:24.383: == create-supervised-log
2017-09-13 16:15:24.385: =================================================================
2017-09-13 16:15:24.387: example-3: 1
2017-09-13 16:15:24.424: log-monitor-proc: log died - [:exception {:message "Divide by zero", :class "java.lang.ArithmeticException", :stack-trace ["clojure.lang.Numbers.divide(Numbers.java:158)" "clojure.lang.Numbers.divide(Numbers.java:3808)" "otplike_log.core$log_to_file_or_die$fn__13374.invoke(core.clj:27)" "clojure.core$comp$fn__4727.invoke(core.clj:2460)" "otplike_log.log$eval13053$log_proc__13055$fn__13092$state_machine__6737__auto____13097$fn__13101.invoke(log.clj:34)" "otplike_log.log$eval13053$log_proc__13055$fn__13092$state_machine__6737__auto____13097.invoke(log.clj:34)" "clojure.core.async.impl.ioc_macros$run_state_machine.invokeStatic(ioc_macros.clj:973)" "clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:972)" "clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:977)" "clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:975)" "clojure.core.async.impl.ioc_macros$take_BANG_$fn__6753.invoke(ioc_macros.clj:986)" "clojure.core.async.impl.channels.ManyToManyChannel$fn__1608$fn__1609.invoke(channels.clj:95)" "clojure.lang.AFn.run(AFn.java:22)" "java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)" "java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)" "java.lang.Thread.run(Thread.java:748)"]}]
2017-09-13 16:15:25.365: example-3: 3

Notice that there is no log line "example-3: 2". This is because the message to log this line was sent to the log-proc process, but the log-proc process died before processing it. Later, when a new log-proc process was started by the supervisor, the log line "example-3: 3" was logged.

[pwhittin]

Did I implement "supervised-log-proc" in a sensible way?