A more pure design

Project.toml

@@ -1,12 +1,10 @@
-authors = ["Lyndon White <[email protected]>"]
 name = "LoggingExtras"
 uuid = "bda5643c-bbc4-11e8-2bd7-9ffae705afc0"
-version = "0.1.0"
-
-[deps]
+authors = ["Lyndon White <[email protected]>"]
+version = "0.2.0"
 
 [compat]
-julia = "0.7"
+julia = "0.7, 1"
 
 [extras]
 Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"

README.md

@@ -6,8 +6,50 @@
 
 ![Diagram showing how loggers connect](diag.svg)
 
+# Discussion: Compositional Loggers
+
+LoggingExtras is designs around allowing you to build arbitrarily complicated 
+systems for "log plumbing". That is to say basically routing logged information to different places.
+It is built around the idea of simple parts which are composed together,
+to allow for powerful and flexible definition of your logging system.
+Without having to define any custom loggers by subtyping `AbstractLogger`.
+When we talk about composability we mean to say that the composition of any set of Loggers is itself a Logger.
+LoggingExtras is a composable logging system.
+
+Loggers can be broken down into 4 types:
+ - *Sinks*: Sinks are the final end point of a log messages journey. They write it to file, or display it on the console, or set off a red flashing light in the laboratory. A Sink should never decide what to accept, only what to do with it.
+ - *Filters*: Filters wrap around other loggers and decide wether or not to pass on a message. Thery can further be broken down by when that decision occurs (See `ActiveFilteredLogger` vs `EarlyFilteredLogger`).
+ - *Transformers*: Transformers modify the content of log messages, before passing them on. This includes the metadata like severity level. Unlike Filters they can't block a log message, but they could drop its level down to say `Debug` so that normally noone would see it.
+ - *Demux*: There is only one possible Demux Logger. and it is central to log routing. It acts as a hub that recieves 1 log message, and then sends copies of it to all its child loggers. Like iin the diagram above, it can be composed with Filters to control what goes where.
+
+This is a basically full taxonomy of all compositional loggers.
+Other than `Sinks`, this package implements the full set. So you shouldn't need to build your own routing components, just configure the ones included in this package.
+
+It is worth understanding the idea of logging purity.
+The loggers defined in this package are all pure.
+The Filters, only filter, the Sinks only sink, the transformers only Transform.
+
+We can contrast this to the the `ConsoleLogger` (the standard logger in the REPL).
+The `ConsoleLogger` is an in-pure sink.
+As well as displaying logs to the user (as a Sink);
+it uses the log content, in the form of the `max_log` kwarg to decide if a log should be displayed (Active Filtering);
+and it has a min_enabled_level setting, that controls if it will accept a message at all 
+(Early Filtering, in particular see `MinLevelLogger`).
+If it was to be defined in a compositional way,
+we would write;
+```
+
+ConsoleLogger(stream, min_level) = 
+	MinLevelLogger(
+		ActiveFilteredLogger(max_log_filter,
+			PureConsoleLogger(stream)
+		),
+		min_level
+	)
+```
 
-## Usage
+
+# Usage
 Load the package with `using LoggingExtras`.
 You likely also want to load the `Logging` standard lib.
 Loggers can be constructed and used like normal.
@@ -36,14 +78,19 @@ logger = global_logger()
 # Loggers introduced by this package:
 
 
-This package introduces 3 new loggers.
-The `DemuxLogger`, the `FilteredLogger` and the `FileLogger`.
+This package introduces 5 new loggers.
+The `DemuxLogger`, the `FileLogger`, and 3 types of filtered logger.
 All of them just wrap existing loggers.
-The `DemuxLogger` sends the logs to multiple different loggers.
-The `FilteredLogger` lets you add rules to cause a logger to ignore some inputs.
+ - The `DemuxLogger` sends the logs to multiple different loggers.
+ - The `TransformerLogger` applies a function to modify log messages before passing them on.
+ - The `FileLogger` is a simple logger sink that writes to file.
+ - The 3 filter loggers are used to control if a message is written or not
+     - The `MinLevelLogger` only allowes messages to pass that are above a given level of severity
+     - The `EarlyFilteredLogger` lets you write filter rules based on the `level`, `module`, `group` and `id` of the log message
+     - The `ActiveFilteredLogger` lets you filter based on the full content
 
 
-By combining `DemuxLogger` with `FilteredLogger`s you can arbitrarily route log messages, wherever you want.
+By combining `DemuxLogger` with filter loggers you can arbitrarily route log messages, wherever you want.
 
 The `FileLogger` is just a convience wrapper around the base julia `SimpleLogger`,
 to make it easier to pass in a filename, rather than a stream.
@@ -56,13 +103,15 @@ It takes a list of loggers.
 It also has the keyword argument `include_current_global`,
 to determine if you also want to log to the global logger.
 
-It is up to those loggers to determine if they will accept it.\
+It is up to those loggers to determine if they will accept it.
 Which they do using their methods for `shouldlog` and `min_enabled_level`.
-Or you can do, by wrapping them in a `FilteredLogger` as discussed below.
+Or you can do, by wrapping them in a filtered logger  as discussed below.
 
 The `FileLogger` does logging to file.
 It is really simple.
-It takes a filename; and the minimum level it should log.
+It takes a filename,
+ - a kwarg to check if should `always_flush` (default: `true`).
+ - a kwarg to `append` rather than overwrite (default `false`. i.e. overwrite by default)
 
 ### Demo
 We are going to log info and above to one file,
@@ -72,18 +121,18 @@ and warnings and above to another.
 julia> using Logging; using LoggingExtras;
 
 julia> demux_logger = DemuxLogger(
-		FileLogger("info.log", min_level=Logging.Info),
-		FileLogger("warn.log", min_level=Logging.Warn),
-		include_current_global=false
-		);
+	MinLevelLogger(FileLogger("info.log"), Logging.Info),
+	MinLevelLogger(FileLogger("warn.log"), Logging.Warn),
+	include_current_global=false
+);
 
 
 julia> with_logger(demux_logger) do
-		@warn("It is bad")
-		@info("normal stuff")
-		@error("THE WORSE THING")
-		@debug("it is chill")
-	end
+	@warn("It is bad")
+	@info("normal stuff")
+	@error("THE WORSE THING")
+	@debug("it is chill")
+end
 
 shell>  cat warn.log
 ┌ Warning: It is bad
@@ -100,51 +149,140 @@ shell>  cat info.log
 └ @ Main REPL[34]:4
 ```
 
-## `FilteredLogger`
+## `ActiveFilteredLogger`
 
-The `FilteredLogger` exists to give more control over which messages should be logged.
+The `ActiveFilteredLogger` exists to give more control over which messages should be logged.
 It warps any logger, and before sending messages to the logger to log,
 checks them against a filter function.
 The filter function takes the full set of parameters of the message.
-(See it's docstring with `?FilteredLogger` for more details.)
+(See it's docstring with `?ActiveFilteredLogger` for more details.)
 
 ### Demo
 We want to filter to only log strings staring with `"Yo Dawg!"`.
 
 ```
-julia> function yodawg_filter(level, message, _module, group, id, file, line; kwargs...)
-		startswith(msg, "Yo Dawg!")
+julia> function yodawg_filter(log_args)
+	startswith(log_args.message, "Yo Dawg!")
 end
  yodawg_filter (generic function with 1 method)                                                                                     
 
-julia> filtered_logger = FilteredLogger(yodawg_filter, global_logger());
+julia> filtered_logger = ActiveFilteredLogger(yodawg_filter, global_logger());
 
 julia> with_logger(filtered_logger) do
-		@info "Boring message"
-		@warn "Yo Dawg! it is bad"
-		@info "Another boring message"
-		@info "Yo Dawg! it is all good"
-	end
+	@info "Boring message"
+	@warn "Yo Dawg! it is bad"
+	@info "Another boring message"
+	@info "Yo Dawg! it is all good"
+end
 ┌ Warning: Yo Dawg! it is bad
 └ @ Main REPL[28]:3
 [ Info: Yo Dawg! it is all good
 ```
 
+## `EarlyFilteredLogger`
 
+The `EarlyFilteredLogger` is similar to the `ActiveFilteredLogger`,
+but it runs earlier in the logging pipeline.
+In particular it runs before the message is computed.
+It can be useful to filter things early if creating the log message is expensive.
+E.g. if it includes summary statistics of the error.
+The filter function for early filter logging only has access to the 
+`level`, `_module`, `id` and `group` fields of the log message.
+The most notable use of it is to filter based on modules,
+see the HTTP example below.
 
-# Examples
+Another example is using them to stop messages every being repeated within a given time period.
+
+```
+using Dates, Logging, LoggingExtras
+
+julia> function make_throttled_logger(period)
+         history = Dict{Symbol, DateTime}()
+         # We are going to use a closure
+         EarlyFilteredLogger(global_logger()) do log
+           if !haskey(history, log.id) || (period < now() - history[log.id])
+             # then we will log it, and update record of when we did
+             history[log.id] = now()
+             return true
+           else
+             return false
+           end
+         end
+       end
+make_throttled_logger (generic function with 1 method)
+
+julia> throttled_logger = make_throttled_logger(Second(3));
+
+julia> with_logger(throttled_logger) do
+         for ii in 1:10
+           sleep(1)
+           @info "It happen" ii
+         end
+       end
+┌ Info: It happen
+└   ii = 1
+┌ Info: It happen
+└   ii = 4
+┌ Info: It happen
+└   ii = 7
+┌ Info: It happen
+└   ii = 10
+```
+
+## `MinLevelLogger`
+This is basically a special case of the early filtered logger,
+that just checks if the level of the message is above the level specified when it was created.
+
+## `TransformerLogger`
+The transformer logger allows for the modification of log messages.
+This modification includes such things as its log level, and content,
+and all the other arguments passed to `handle_message`.
+
+When constructing a `TransformerLogger` you pass in a tranformation function,
+and a logger to be wrapped.
+The  transformation function takes a named tuple containing all the log message fields,
+and should return a new modified named tuple.
+
+A simple example of its use is truncating messages.
+
+```
+julia> using Logging, LoggingExtras
+
+julia> truncating_logger  = TransformerLogger(global_logger()) do log
+           if length(log.message) > 128
+               short_message = log.message[1:min(end, 125)] * "..."
+               return merge(log, (;message=short_message))
+           else
+               return log
+           end
+       end;
+
+julia> with_logger(truncating_logger) do
+           @info "the truncating logger only truncates long messages"
+           @info "Like this one that is this is a long and rambling message, it just keeps going and going and going,  and it seems like it will never end."
+           @info "Not like this one, that is is short"
+       end
+[ Info: the truncating logger only truncates long messages
+[ Info: Like this one that is this is a long and rambling message, it just keeps going and going and going,  and it seems like it wil...
+[ Info: Not like this one, that is is short
+```
+
+It can also be used to do things such as change the log level of messages from a particular module (see the example below).
+
+
+# More Examples
 
 ## Filter out any overly long messages
 
 ```
 using LoggingExtras
 using Logging
 
-function sensible_message_filter(level, message, _module, group, id, file, line; kwargs...)
-	length(message) < 1028
+function sensible_message_filter(log)
+	length(log.message) < 1028
 end
 
-global_logger(FilteredLogger(sensible_message_filter, global_logger()))
+global_logger(ActiveFilteredLogger(sensible_message_filter, global_logger()))
 ```
 
 
@@ -155,10 +293,31 @@ using LoggingExtras
 using Logging
 using HTTP
 
-function not_HTTP_message_filter(level, message, _module, group, id, file, line; kwargs...)
-	_module != HTTP
+function not_HTTP_message_filter(log)
+	log._module != HTTP
+end
+
+global_logger(EarlyFilteredLogger(not_HTTP_message_filter, global_logger()))
+```
+
+## Raising HTTP debug level errors to be Info level
+
+```
+using LoggingExtras
+using Logging
+using HTTP
+
+transformer_logger(global_logger()) do log
+	if log._module == HTTP && log.level=Logging.Debug
+		# Merge can be used to construct a new NamedTuple
+		# which effectively is the overwriting of fields of a NamedTuple
+		return merge(log, (; level=Logging.Info))
+	else
+		return log
+	end
 end
 
-global_logger(FilteredLogger(not_HTTP_message_filter, global_logger()))
+global_logger(transformer_logger)
 ```
 
+

src/LoggingExtras.jl

@@ -9,10 +9,34 @@ import Base.CoreLogging:
 	handle_message, shouldlog, min_enabled_level, catch_exceptions
 
 export demux_global_logger,
-    DemuxLogger, FilteredLogger, FileLogger
+    DemuxLogger, TransformerLogger, FileLogger,
+    ActiveFilteredLogger, EarlyFilteredLogger, MinLevelLogger
 
-include("demuxlogger.jl")
-include("filteredlogger.jl")
+
+######
+# Utilities for dealing with compositional loggers.
+# Since the logging system itself will not engage its checks
+# Once the first logger has started, any compositional logger needs to check
+# before passing anything on.
+
+# For checking child logger, need to check both `min_enabled_level` and `shouldlog`
+function comp_shouldlog(logger, args...)
+    level = first(args)
+    min_enabled_level(logger) <= level && shouldlog(logger, args...)
+end
+
+# For checking if child logger will take the message you are sending
+function comp_handle_message_check(logger, args...; kwargs...)
+    level, message, _module, group, id, file, line = args
+    return comp_shouldlog(logger, level, _module, group, id)
+end
+###############################
+
+include("demux.jl")
+include("transformer.jl")
+include("activefiltered.jl")
+include("earlyfiltered.jl")
+include("minlevelfiltered.jl")
 include("filelogger.jl")
 
 end # module