Repository files navigation

μ/log(Pronounced: /mjuːlog/) is a micro-logging library that logs events and data, not words!

From the Greek letterμ,mu(Pronunciation: /mjuː/)
The twelfth letter of theGreek alphabet (Μ, μ), often used as a prefix formicro- which is10^-6 in the SI (System of Units). Lowercase letter "u" is oftensubstituted for "μ" when the Greek character is not typographicallyavailable.

(source:https://en.wikipedia.org/wiki/Mu_(letter))

Here some features and key design decisions that makeμ/log special:

• Effortlessly, logs events as data points.
• No need to construct strings that then need to be deconstructed later.
• Fast, extremely fast, under300 nanoseconds per log entry
• Memory bound; no unbounded use of memory
• All the processing and rendering happens asynchronously.
• Ability to add contextual logging.
• Adding publishers won't affect logging performances
• Extremely easy to createstateful publishers for new systems
• Wide range of publishers available (see available list)
• Event logs are useful, but not as important as process flow(therefore preferable to drop events rather than crashing theprocess)
• Because it is cheap to log events, you can freely log plenty.
• And events arejust data so can process, enrich, filter,aggregate, visualise the data with your own tools.

It is not the intention ofµ/log to be a logging system in thesense of Log4j et al. In any significant project I worked in the last15 years, logging text messages resulted in a large amount of stringswhich was hard to make sense of, thus mostly ignored.µ/log'sidea is to replace the "3 Pillars of Observability" with a morefundamental concept: "the event". Event-based data is easy toindex, search, augment, aggregate and visualise therefore can easilyreplace traditional logs, metrics and traces.

Existing logging libraries are based on a design from the 80s andearly 90s. Most of the systems at the time where developed instandalone servers where logging messages to console or file was thepredominant thing to do. Logging was mostly providing debugginginformation and system behavioural introspection.

Most of modern systems are distributed in virtualized machines thatlive in the cloud. These machines could disappear any time. In thiscontext logging on the local file system isn't useful as logs areeasily lost if virtual machines are destroyed. Therefore it is commonpractice to use log collectors and centralized log processors. The ELKstack it has been predominant in this space for years, but there are amultitude of other commercial and open-source products.

Most of these systems have to deal with non structured datarepresented as formatted strings in files. The process of extractinginformation out of these strings is very tedious, error prone, anddefinitely not fun. But the question is:why did we encode these asstrings in the first place? This is just because existing logframeworks, which have been redesigned in various decades follow thesame structure as when systems lived on the same single server fordecades.

I believe we need the break free of these anachronistic designs and useevent loggers,not message loggers, which are designed for dynamicdistributed systems living in cloud and using centralized logaggregators.So here isμ/log designed for this very purpose.

Watch my talk onμ/log at theLondon Clojurians Meetup:

• Features
• Motivation
• Table of contents
• Usage
  • Use of context
• Best practices
• μ/trace
• Publishers
• Additional topics
• Contributions
• Related projects
• License

In order to use the library add the dependency to yourproject.clj

;; Leiningen project[com.brunobonacci/mulog"0.9.0"];; deps.edn format{:deps { com.brunobonacci/mulog {:mvn/version"0.9.0"}}}

Current version:

Then require the namespace:

(nsyour-ns  (:require [com.brunobonacci.mulog:as μ]));; or for the more ASCII traditionalists(nsyour-ns  (:require [com.brunobonacci.mulog:as u]))

Check theonline documentation

Then instrument your code with the log you deem useful. The general structure is

(μ/log event-name, key1 value1, key2 value2, ... keyN valueN)

You can add as many key-value pairs as you deem useful to express the event in your system.

For example:

;; good to use namespaced keywords for the event-name(μ/log::hello:to"New World!")

However you will NOT be able to see any events until you add apublisher which will take your events and send them to a distributedlogger or your local console (if you are developing).

(μ/start-publisher! {:type:console})

At this point you should be able to see the previous event in yourREPL terminal and it will look as follows:

{:mulog/trace-id #mulog/flake"4VTBeu2scrIEMle9us8StnmvRrj9ThWP",:mulog/timestamp1587500402972,:mulog/event-name:your-ns/hello,:mulog/namespace"your-ns",:to"New World!"}

Here are some example of events you might want to log.

;; The general form is(μ/log::event-name,:key1"value1",:key2:value2,:keyN"valueN");; examples(μ/log::system-started:version"0.1.0":init-time32)(μ/log::user-logged:user-id"1234567":remote-ip"1.2.3.4":auth-method:password-login)(μ/log::http-request:path"/orders",:method:post,:remote-ip"1.2.3.4",:http-status201,:request-time129)(defx (RuntimeException."Boom!"))(μ/log::invalid-request:exception x,:user-id"123456789",:items-requested47)(μ/log::position-updated:poi"1234567":location {:lat51.4978128,:lng-0.1767122} )

All above are examples of events you might want to track, collect andaggregate on it in a specialized timeseries database.

Adding events which are rich in attributes and dimensions is extremelyuseful, however it is not easy to have all the attributes anddimensions at your disposal everywhere in the code. To get aroundthis problemμ/log supports the use of context.

There are two levels of context, a global level and a local one.

The global context allows you to define properties and values whichwill be added to all the events logged afterwards.

For example:

(μ/log::system-started:init-time32);; {:mulog/timestamp 1572709206048, :mulog/event-name :your-ns/system-started, :mulog/namespace "your-ns", :init-time 32};; set global context(μ/set-global-context! {:app-name"mulog-demo",:version"0.1.0",:env"local"})(μ/log::system-started:init-time32);; {:mulog/event-name :your-ns/system-started,;;  :mulog/timestamp  1587501375129,;;  :mulog/trace-id   #mulog/flake "4VTCYUcCs5KRbiRibgulnns3l6ZW_yxk",;;  :mulog/namespace  "your-ns",;;  :app-name         "mulog-demo",;;  :env              "local",;;  :init-time        32,;;  :version          "0.1.0"}

Typically, you will set the global context once in your main functionat the starting of your application with properties which are validfor all events emitted by the process. Useset-global-context! tospecify a given value, orupdate-global-context! with a updatefunction to change some of the values. Examples of properties youshould consider adding in the global context areapp-name,version,environment,process-id,host-ip,os-type,jvm-version etc etc

The second type of context is the (thread) local context. It can beused to inject information about the current processing and all theevents within the scope of the context will inherit the propertiesand their values.

For example the following line will contain all the properties of theglobal context, all the properties of thelocal context and allinline properties.

(μ/with-context {:order"abc123"}  (μ/log::item-processed:item-id"sku-123":qt2));; {:mulog/event-name :your-ns/item-processed,;;  :mulog/timestamp  1587501473472,;;  :mulog/trace-id   #mulog/flake "4VTCdCz6T_TTM9bS5LCwqMG0FhvSybkN",;;  :mulog/namespace  "your-ns",;;  :app-name         "mulog-demo",;;  :env              "local",;;  :item-id          "sku-123",;;  :order            "abc123",;;  :qt               2,;;  :version          "0.1.0"}

The local context can be nested:

(μ/with-context {:transaction-id"tx-098765"}  (μ/with-context {:order"abc123"}    (μ/log::item-processed:item-id"sku-123":qt2)));; {:mulog/event-name :your-ns/item-processed,;;  :mulog/timestamp  1587501492168,;;  :mulog/trace-id   #mulog/flake "4VTCeIc_FNzCjegzQ0cMSLI09RqqC2FR",;;  :mulog/namespace  "your-ns",;;  :app-name         "mulog-demo",;;  :env              "local",;;  :item-id          "sku-123",;;  :order            "abc123",;;  :qt               2,;;  :transaction-id   "tx-098765",;;  :version          "0.1.0"}

Local context works across function boundaries:

(defnprocess-item [sku quantity];; ... do something    (μ/log::item-processed:item-id sku:qt quantity);; ... do something    )(μ/with-context {:order"abc123"}    (process-item"sku-123"2));; {:mulog/event-name :your-ns/item-processed,;;  :mulog/timestamp  1587501555926,;;  :mulog/trace-id   #mulog/flake "4VTCi08XrCWQLrR8vS2nP8sG1zDTGuY_",;;  :mulog/namespace  "your-ns",;;  :app-name         "mulog-demo",;;  :env              "local",;;  :item-id          "sku-123",;;  :order            "abc123",;;  :qt               2,;;  :version          "0.1.0"}

Here some best practices to follow while logging events:

• Use namespaced keywords or qualified strings for theevent-name
• Log plain values, not opaque objects, objects will be turned into stringswhich diminishes their value
• Do not log mutable values, since rendering is done asynchronouslyyou could be logging a different state. If values are mutablecapture the current state (deref) and log it.
• Avoid logging deeply nested maps, they are hard to query.
• Log timestamps with milliseconds precision.
• Use global context to enrich events with application name(:app-name), version (:version), environment (:env), host,OS pid, and other useful information so that it is always possibleto determine the source of the event.Seeexample here.
• If you have to log an error/exception put the exception objectwith a:exception key. For example:

  (try  (something)  (catch Exception x    (μ/log::actionX:exception x:status:failed)))

  It will be easier to search for all the error in Elasticsearchjust by looking the presence of theexception key(Elasticsearch query exampleexception:*)

μ/trace(Pronounced: /mjuːtrace/) is a micro distributedtracing library with the focus on tracking data with custom attributes.

μ/trace is a subsystem ofμ/log and it relies heavily onit. While the objective ofμ/log is to record and publish aevent which happens in a single point in time, the objective ofμ/trace is to record and publish an event that spans over ashort period of time, and potentially, spans across multiple systems.

μ/trace can be used within a single system and it will provideaccurate data around instrumented operation of that system.μ/tracecan also be used in a distributed setup and in conjunction with otherdistributed tracers such asZipkin and participateinto distributed traces.

μ/trace data points are not confined to distributed tracers,but the data can be used and interpreted in Elasticsearch, in real-timestreaming system which use Apache Kafka etc.

Assume that you have a complex operation which you want to track therate, the outcome, the latency and have contextual information aboutthe call.

One example of such calls is the call to an external service or databaseto retrieve the current product availability.

Here an example of such call:

;; example call to external service(defnproduct-availability [product-id]  (http/get availability-service {:product-id product-id}))

We want to track how long this operation takes and if it fails, what'sthe reason. Withμ/trace we can instrument the request as follow:

;; same require as mulog;; (require '[com.brunobonacci.mulog :as μ]);; wrap the call to the `product-availability` function with μ/trace(μ/trace::availability  []  (product-availability product-id))

μ/trace will start a timer before calling(product-availability product-id) and when the execution completes it will log an eventusingμ/log. To the caller it will be like calling(product-availability product-id) directly as the caller will receive theevaluation result of the body. However,μ/log will publish the followingevent:

;; {:mulog/event-name :your-ns/availability,;;  :mulog/timestamp 1587504242983,;;  :mulog/trace-id #mulog/flake "4VTF9QBbnef57vxVy-b4uKzh7dG7r7y4",;;  :mulog/root-trace #mulog/flake "4VTF9QBbnef57vxVy-b4uKzh7dG7r7y4",;;  :mulog/duration 254402837,;;  :mulog/namespace "your-ns",;;  :mulog/outcome :ok,;;  :app-name "mulog-demo",;;  :env "local",;;  :version "0.1.0"}

There are a few things to notice here:

• Firstly, it inherited the global context which we set forμ/log (:app-name,:version and:env)
• Next, we have the same keys which are available inμ/logevents, such as::mulog/event-name,:mulog/timestamp,:mulog/namespace and:mulog/trace-id.
• In addition to the:mulog/trace-id, which identified thisparticular trace event, we have two more IDs. One called:mulog/root-trace and the second one called:mulog/parent-trace. The latter one is missing because thistrace doesn't have a parentμ/trace block. The:mulog/root-trace is the id of the originating trace which couldbe coming from another system. The:mulog/root-trace is thesame as the:mulog/trace-id because, in this example, this traceis the first one (and the only one) of the stack.
• Next, we have:mulog/duration which is the duration of the evaluation ofthe body ( theproduct-availability call) expressed innanoseconds
• Whether the call succeeded or failed, this is specified in:mulog/outcome which it can be:ok or:error. The latterwill be set in case an exception is raised, and in this case, anadditional:exception property will be added with the actualexception. In case of errors, the exception will be thrown back tothe caller for further handling.

In the above example we are missing some contextual information.For example, we know that someone is enquiring about product availabilitybut we don't know about which product. This information is availableat the point of call, it would be nice to be able to see this informationin the trace as well. That's easily done.

Likeμ/log events, we can add key/valuepairs to the trace as well:

(μ/trace::availability  [:product-id product-id]  (product-availability product-id))

Note that within square brackets we have added the info we need.But we can go one step further. Let's assume that we had theorder-idand theuser-id who is enquiring about the availability as local contextthen we would have the following trace event.

(defproduct-id"2345-23-545")(deforder-id"34896-34556")(defuser-id"709-6567567")(μ/with-context {:order order-id,:user user-id}  (μ/trace::availability    [:product-id product-id]    (product-availability product-id)));; {:mulog/event-name :your-ns/availability,;;  :mulog/timestamp 1587506497789,;;  :mulog/trace-id #mulog/flake "4VTHCez0rr3TpaBmUQrTb2DZaYmaWFkH",;;  :mulog/root-trace #mulog/flake "4VTHCez0rr3TpaBmUQrTb2DZaYmaWFkH",;;  :mulog/duration 280510026,;;  :mulog/namespace "your-ns",;;  :mulog/outcome :ok,;;  :app-name "mulog-demo",;;  :env "local",;;  :order "34896-34556",;;  :product-id "2345-23-545",;;  :user "709-6567567",;;  :version "0.1.0"}

One important difference betweenwith-context and theμ/tracepairs is thatwith-context willpropagate that information toall nested calls while theμ/trace pairs will be only added to thatspecific trace event and not the nested ones.

If we had the following set of nested calls:

(process-order)└── (availability)    ├── (warehouse-availability)    ├── (shopping-carts)    └── (availability-estimator)

Whereprocess-order check theavailability of each product, and tocheck the availability of each product you need to verify what isavailable in thewarehouse as well as how many items are locked inin-flight shopping carts and have this information provided to anestimator you would end-up with a trace which looks like thefollowing:

Publishers allow to send the events to external system where they canbe stored, indexed, transformed or visualised.

Most of the publishers are in separated modules to reduce the risk ofdependencies clash. Please see the specific publisher documentationfor the name of the module to add in your dependencies.

Modules can be started as follow:

(defpub (μ/start-publisher! {:type:console:pretty?true}))

The map contains the configuration which is specific to the publisher.

It returns a function with no arguments which when called stops thepublisher and flushes the records currently present in the buffer.Finally, if the publisher implements thejava.io.Closeable it willcall theclose method to release/close external resources.

Here the list of all available publishers:

• Publishers
  • Simple Console Publisher
  • Simple File Publisher
  • Advanced Console Publisher
  • Cloudwatch Logs Publisher
  • Elasticsearch Publisher
  • Jaeger Publisher
  • Kafka Publisher
  • Kinesis Publisher
  • Prometheus Publisher
  • Slack Publisher
  • Zipkin Publisher
• Special publishers
  • Inline Publishers
  • Custom Publishers
  • Multi Publisher
• Samplers
  • JVM Metrics Sampling
  • Filesystem Metrics Sampling

• Read aboutμ/log internals
• Check theFrequently Asked Questions
• How to write custom publishers
• How to transfer the local-context into a different thread.

I do consider the core pretty much feature complete, therefore I won'taccept changes in the core module. However, there is loads of workto be done on supporting libraries and publishers for various systems,Here your help if welcome, you can have a look at the list of open issuesmarked ashelp wanted.

PRs are welcome;-)

To contribute:

• pick an issue you would like to work on.
• drop a message to the issue so that I know someone else is working on it
• follow the guidelines in the ticket
• in doubt, just ask!

If you have questions or you need help please open an issue or postyour questions intoGithub Discussionsboard.

Alternatively you can post a question to the#mulog channel in the Clojurians Slack team.

Here there are some other open-source projects which are related toμ/log:

• slf4j-mulog - a SLF4j backend forμ/log.

  It enables you to send your traditional logs from your existingprojects viaμ/log and leverage allμ/log's capabilityto filter/transform/enrich events before publishing.

• μ/log hidden superpower, by Bruno Bonacci
• Structured logging with mulog, by Francesco Pischedda

Copyright © 2019-2021 Bruno Bonacci - Distributed under theApache License v2.0