/active-logger

Clojure library with utilities and a DSL for logging on top of Timbre with support for Riemann.

Primary LanguageClojureEclipse Public License 2.0EPL-2.0

active-logger

Utilities and DSL for logging on top of Timbre with support for Riemann, Logstash, and more.

Currently active-logger supports hijacking log messages from Log4j, java.util.logging (JUL), and Apache Commons Logging (JCL).

https://img.shields.io/clojars/v/de.active-group/active-logger.svg

Breaking changes

Breaking changes in version 0.10.0:

  • We removed active.clojure.logger.timbre/timbre-config-section; the client should choose its section key for the configuration itself and the library should be called with a configuration object of schema active.clojure.logger.timbre/timbre-config-schema.

Breaking changes in version 0.8.0:

  • We revamped the Metrics implementation: You need to adjust all your calls to log-metric in your code. Details see below.

0.7.0

  • A call to redirect-log4j! isn’t necessary anymore. You have to remove the active.clojure.logger.log4j namespace from your :require statements. You also have to remove the calls to redirect-log4j! without substitution.

TL;DR

If you just want to get going, here is a minimal working example on how to start logging events.

  1. Add active-logger and active-clojure to your deps.edn: 
    {:deps {de.active-group/active-clojure {:mvn/version "0.42.0"}
        de.active-group/active-logger  {:mvn/version "0.13.0"}}}
  2. Start logging some events: 
    (ns my.app
  (:require ...
            [active.clojure.logger.event :as event-logger]))

(event-logger/log-event! :info "We are live!")

    The default configuration logs via println to stdout.

    See examples/ for example projects.

Change configuration

To adjust the configuration you can provide a Timbre configuration map:

(ns my.app
  (:require [active.clojure.logger.event :as event-logger]))

(def timbre-config-map
  {:min-level :debug  ;; Log everything that is at least a :debug message.
   :appenders
   {;; Print messages to stdout/stderr.
    :println '(println)
    ;; Write messages to a file.
    :spit '(spit "/tmp/my-app.log")
    ;; Submit messages to a logstash instance.
    :logstash '(logstash "localhost" 4660)}})

(event-logger/set-global-log-events-config-from-map! timbre-config-map)

Or use active-clojure’s active.clojure.config facilities:

(ns my.app
  (:require [active.clojure.config :as active-config]
            [active.clojure.logger.event :as event-logger]
            [active.clojure.logger.timbre :as timbre]))

(def config-map
  {:min-level :debug  ;; Log everything that is at least a :debug message.
   :appenders
   {;; Print messages to stdout/stderr.
    :println '(println)
    ;; Write messages to a file.
    :spit '(spit "/tmp/my-app.log")
    ;; Submit messages to a logstash instance.
    :logstash '(logstash "localhost" 4660)}})

(def configuration (active-config/make-configuration timbre/timbre-config-schema [] config-map))

;; Initialize the event-logger.
(-> configuration
    timbre/configuration->timbre-config
    event-logger/set-global-log-events-config!)

Prerequisites

For active-logger to work as expected, please make sure to exclude any direct or transitive dependencies on org.slf4j/slf4j-log4j12 and other slf4j bindings.

You compiler should give you a warning along these lines if you still depend on it:

SLF4J: Class path contains multiple SLF4J bindings.

Usage

active-logger is intended to be used alongside active-clojure and follows the same naming scheme (all active-logger namespaces can be found under active.clojure.logger).

There are two basic ways to do logging with active-logger: Effectful and monadic. In general, both of theses options are available for each logging function in active-logger.

Effectful

Effectful logging refers to logging functions that immediately execute. Usually they are signified by a bang (!) at the end of the var’s name (i. e. active.clojure.logger.event/log-event!). In any non-monadic execution context, use these functions for logging, metrics, etc.

Monadic

Monadic logging refers to logging functions that can be used to formulate the intent on logging at this location when executing a monadic program. The log function will only be executed when the monadic program is run.

Monadic in this context means programs defined using active.clojure.monad.

Example for effectful and monadic logging

(ns my.ns
  (:require [active.clojure.config :as active-config]
            [active.clojure.logger.timbre :as timbre]
            [active.clojure.logger.event :as event-logger]
            [active.clojure.monad :as monad :refer [monadic]]))

;; NOTE: Initialize as shown in TL;DR section.

;; Effectful logging
(let [res (+ 2 2)]
  (event-logger/log-event! :trace (str "res =" res))
  res)
;; 2020-07-11 15:19:02.659 host INFO [my.ns] TRACE - res = 4
;; => 4


;; Monadic logging
(def prog (monadic [res (monad/return 4)]
                   (event-logger/log-event :trace (str "res =" res))
                   (monad/return 4)))

(monad/run-free-reader-state-exception
 event-logger/log-events-command-config
 prog)
;; 2020-07-11 15:19:02.659 host INFO [my.ns] TRACE - res = 4
;; => 4

Components

active-logger includes several different entities that can be logged.

Event

Events are reports of things that the system did that may be of interest for later perusal by system administrators in case of failures or by developers. Each event carries a namespace saying where the event came from, and a level that specifies how “important” the event is. Functions to log events can be found in active.clojure.logger.event.

Metrics

Metrics can be used to log metrics for specified parts of your system. Functions to log events can be found in active.clojure.logger.metric.

Metrics use Prometheus-style metric types, for more details see https://prometheus.io/docs/concepts/metric_types/.

As for Events described above, we have an effectful logging and an monadic login. The command config for monadic logging is active.clojure.logger.metric/monad-command-config. We currently implement:

  • Counters with log-counter-metric! and the monadic log-counter-metric,
  • Gauges with log-gauge-metric! and the monadic log-gauge-metric, and
  • Histograms with log-histogram-metric! and the monadic log-histogram-metric that supports an arbitrary number of buckets.

Counters and histograms are state-based, which means that their next value depends on previous values and that they accumulate over time and need to be stored. The metric store is internal to the implementation and there are functions for (re-)setting the store, most useful is active.clojure.logger.metric-accumulator/reset-global-metric-store!. This resets the store for both the effectful and monadic implementation as both implementations can be used concurrently and share the same store.

Since the existence of metrics, respectively the absence of metrics may hold important information about the health of a system, the library comes with functionality to prune stale metrics, that is to clean the metric store from metrics that have not been updated in a while. Without pruning old metrics, they will still be in the store and may be cause wrong conclusions about the system. You can use active.clojure.logger.metric-accumulator/prune-stale-metrics! or as a convenience start a thread that prunes stale metrics periodically with active.clojure.logger.metric-accumulator/start-prune-stale-metrics-thread!.

(We also implement set-counter-metric! and the monadic set-counter-metric for metrics that represent counters but can be used by gauges by setting the value instead of incrementing the value. Use this only if you know what you are doing.)

Emitter

Metrics can be emitted

  • as Events and use the events configuration. This is the default and by default it logs the events with log level :info. This can be changed to :debug for example:
(active.clojure.logger.metric-emitter/set-global-log-metrics-config!
  active.clojure.logger.metric-emitter/configure-metrics-loging :events :debug)
  • to Riemann by passing the result of (active.clojure.logger.metric-emitter/configure-metrics-logging riemann-config :riemann) to active.clojure.logger.metric-emitter/set-global-log-metrics-config; riemann-config is a Riemann configuration object, see below.
  • not at all – this can be set with (active.clojure.logger.metric-emitter/set-global-log-metrics-config! :no-push)

Not emitting metrics at all is the recommended configuration when using Prometheus, see next section.

Integrate with Prometheus

Prometheus scrapes metrics from its targets from their HTTP endpoints. The namespace active.clojure.logger.metric-prometheus provides functionality for providing such an endpoint, the most important functions are:

  • (render-metrics!) that returns the Prometheus-parseable string of all metrics in the store, and
  • (wrap-prometheus-metrics-ring-handler handler) which is a ring handler that returns the rendered page on the endpoint /metrics. This is a convenient way to hook the route into your already existing webserver.

Example webserver

Here is an example on how to add a webserver that serves the metrics to your application using the HTTP Kit webserver:

(ns example.webserver
  (:require [org.httpkit.server :as http]
            [active.clojure.config :as config]
            [active.clojure.logger.metric-prometheus :as metric-prometheus]
            [active.clojure.logger.metric :as metrics]
            [active.clojure.logger.event :as events]))

(def webserver-host
  (config/setting
   :host
   "Where the webserver is hosted."
   (config/default-string-range "0.0.0.0")))

(def webserver-port
  (config/setting
   :port
   "The port the webserver is listening on."
   (config/integer-between-range 1024 49151 8002)))

(def webserver-section
  (config/section
   :webserver
   (config/schema "Configuration for the webserver."
                  webserver-host
                  webserver-port)))

(defn record-http-requests-total-handler
  [handler]
  (fn [req]
    (let [res (handler req)]
      (metrics/log-counter-metric! "http_requests_total"
                                  (merge
                                    {:uri (:uri req)}
                                    (when-let [status (:status res)]
                                      {:status status}))
                                  1)
      res)))

(def app
  (record-http-requests-total-handler
    (metric-prometheus/wrap-prometheus-metrics-ring-handler
     (fn [_req]
       {:status 404 :headers {"Content-Type" "text/plain"} :body "not found"}))))

(defn start-webserver!
  ([webserver-config]
   (let [host (config/access webserver-config webserver-host)
         port (config/access webserver-config webserver-port)]
     (start-webserver! host port)))
  ([host port]
   (events/log-event :info (str "Starting webserver on " host ":" port))
   (let [stop-server! (http/run-server app {:ip host :port port})]
     (fn []
       (stop-server! :timeout 100)
       (events/log-event :info "Stopped webserver.")))))

This example uses active.clojure.config to configure the host and port of the webserver, you can hook the webserver-section into your already existing active.clojure.config setup.

It also records a metric that counts all the HTTP requests that reach the webserver. An example output when pointing a browser to the endpoint might look like:

# HELP http_requests_total http_requests_total
# TYPE http_requests_total counter
http_requests_total{uri="/metrics",status="200"} 5 1662025543973

Timed Metrics

Timed metrics can be used to log timing characteristics specified parts of your system. Functions to log events can be found in active.clojure.logger.timed-metric. Basically syntactic sugar around active.clojure.logger.metric – setup and configuration of Metrics applies to Timed metrics as well.

State Change

State changes are for monitoring the live operation of a system. They announce for a certain system component its state, its service. Functions to log events can be found in active.clojure.logger.state-change.

Configuration

active-logger comes with two basic configuration sections: Timbre and Riemann. For more information on active.clojure.config, refer to active-clojure’s documentation on the topic.

In general, to provide a configuration means to supply a map that contains only keys and values according to some schema defined as a active.clojure.config/schema and consumed by active.clojure.config/make-configuration.

Timbre

There are lots of configuration options to define how the event logger should behave. For a full list of options, refer to the respective sources.

Here, we will cover the most important options:

:min-level

default: :debug

The minimum level a message must have to be printed. Possible values are #{:trace :debug :info :warn :error :fatal :report}.

There is syntax for advanced settings for levels for namespaces: [[#{\"taoensso.*\"} :error] ... [#{\"*\"} :debug]]

:appenders

default: {:println (println)}

Defines how messages are printed (stdout, to a file, …). An appender spec is a list starting with one of {spit, rotor, logstash, println}, followed by keyword parameters corresponding to the respective appender.

Multiple appenders can be configured and active at the same time. A full example of an appender configuration might looks like this:

{:appenders {:spit    (spit {:fname "/tmp/app.log"})
             :riemann (riemann {:host "localhost"
                                :port 5555})
             :println (println)}}

Appender: spit

Specifies an appender that writes to a file, specified via the :fname setting. Example: {:spit (spit {:fname "my.log"})}

Appender: rotor

Specifies an appender that writes to a file and rotates the file when it reaches a given file size. It accepts the following settings:

optiondescriptiondefault
:pathPath to log file. Historical versions are suffixed with a 3-digit index.=”./timbre-rotor.log”=
:max-sizeMaximum size of a log file in bytes. Log files are rotated when they exceed this size.1.048.576 bytes (1~MB)
:backlogNumber of rotated logs to keep.5

Example:

{:rotor (rotor {:path "/tmp/project.log"
                :max-size 1073741824
                :backlog 999})}

Appender: println

Specifies an appender that will print regular log entries to stdout, errors to stderr. Example: {:println (println)}

Appender: logstash

Specifies an appender that writes to a Logstash instance. It takes two arguments: the host name, and the port number of the Logstash instance. Example: {:logstash (logstash "localhost" 4660)}

Appender: riemann

Specifies an appender that writes to a Riemann instance. It accepts the following settings:

optiondescriptiondefault
:hostThe host Riemann is served on.“localhost”
:portThe port Riemann is listening on.5555

Example

{:riemann (riemann {:host "localhost"
                    :port 5555})}

:ns-filter:

It is possible to filter specific namespaces in the log-output. You can give a map with keys `:allow` and `:deny` with set values that contain namespace pattern. Example: {:ns-filter {:allow #{"*"} :deny #{"taoensso.*"}}}

:timestamp-opts

Section containing three settings related to how timestamps are formatted in logs:

optiondescription
:patternPattern for the timestamp (see SimpleDateFormat)
:localeThis is an IETF BCP 47 language tag string specifying the locale such as =”de-DE”= or =”en-US”= or :jvm-default.
:timezoneThis is an ID for the time zone relative to which log entry dates should formatted. This can be a full name such as =”Germany/Berlin”=, or a custom ID such as =”GMT-8:00”. The value may also be =:jvm-default for the default time zone, and :utc for UTC.

Riemann

Here are the configuration settings for Riemann. They happen in the :riemann section:

optiondescriptiondefault
:hostString specifying the host where Riemann runs.=”127.0.0.1=
:portPort where Riemann runs.5555
:tls?Specifies whether the communication with Riemann should use TLS. It can be true or false.false
:keyIf :tls? is true, use the specified TLS key-file.-
:certIf :tls? is true, use the specified TLS cert-file.-
:ca-certIf :tls? is true, use the specified TLS CA cert-file.-

Troubleshooting/Bad Players

Certain libraries and frameworks are notorious for emitting log messages as soon as their namespaces are included. This will happen before any configuration for active-logger can be applied. Therefore, you need to handle each such scenario differently. Refer to the Jetty example below to get an idea on how such problems might be fixed.

Jetty

Jetty is one example of a bad player. It will, as soon as any of it’s namespaces are included, emit an ‘announcement’ message that will be printed to stdout as soon as your ns-declaration is evaluated:

Logging to org.slf4j.impl.Log4jLoggerAdapter(org.eclipse.jetty.util.log) via org.eclipse.jetty.util.log.Slf4jLog
Logging initialized @18641ms to org.eclipse.jetty.util.log.Slf4jLog

The solution to disable the message is to

  • create a namespace, i.e. my-project.disable-jetty-logs that turns off this message in particular
  • include that namespace in the namespace that will be called first (usually the one that contains your -main function, likely core.clj) as the very first dependency

Example:

;; disable_jetty_logs.clj
(ns my-project.disable-jetty-logs)

(.setProperty (org.eclipse.jetty.util.log.Log/getProperties) "org.eclipse.jetty.util.log.announce" "false")

;; core.clj
(ns my-project.core
  (:require [my-project.disable-jetty-logs]
            ...))  ; more imports

This answer on StackOverflow led to this solution.

License

Copyright © 2022 Active Group GmbH

This program and the accompanying materials are made available under the terms of the Eclipse Public License 2.0 which is available at http://www.eclipse.org/legal/epl-2.0.

This Source Code may also be made available under the following Secondary Licenses when the conditions for such availability set forth in the Eclipse Public License, v. 2.0 are satisfied: GNU General Public License as published by the Free Software Foundation, either version 2 of the License, or (at your option) any later version, with the GNU Classpath Exception which is available at https://www.gnu.org/software/classpath/license.html.