Added async logging to handlers and reduced memory allocations some m…

…ore.

docs/src/man/records.md

@@ -22,16 +22,16 @@ type EC2Record <: Record
     public_ip::Attribute
     iam_user::Attribute
 
-    function EC2Record(args::Dict)
+    function EC2Record(name::AbstractString, level::AbstractString, msg)
         time = now()
         trace = Attribute(StackTrace, get_trace)
 
         EC2Record(
             Attribute(DateTime, () -> round(time, Base.Dates.Second)),
-            Attribute(args[:level]),
-            Attribute(args[:levelnum]),
-            Attribute(AbstractString, get_msg(args[:msg])),
-            Attribute(args[:name]),
+            Attribute(level),
+            Attribute(-1),
+            Attribute(AbstractString, get_msg(msg)),
+            Attribute(name),
             Attribute(myid()),
             Attribute(StackFrame, get_lookup(trace)),
             trace,

src/formatters.jl

@@ -58,19 +58,24 @@ function format(fmt::DefaultFormatter, rec::Record)
         if token.second
             tmp_val = rec[content]
 
-            value = if content === :lookup
-                # lookup is a StackFrame
-                name, file, line = tmp_val.func, tmp_val.file, tmp_val.line
-                "$(name)@$(basename(string(file))):$(line)"
+            if content === :lookup
+                name, file, line = if isa(tmp_val, StackFrame)
+                    # lookup is a StackFrame
+                    tmp_val.func, tmp_val.file, tmp_val.line
+                else
+                    "<nothing>", "", -1
+                end
+
+                value = "$(name)@$(basename(string(file))):$(line)"
             elseif content === :stacktrace
                 # stacktrace is a vector of StackFrames
                 str_frames = map(tmp_val) do frame
                     string(frame.func, "@", basename(string(frame.file)), ":", frame.line)
                 end
 
-                string(" stack:[", join(str_frames, ", "), "]")
+                value = string(" stack:[", join(str_frames, ", "), "]")
             else
-                tmp_val
+                value = tmp_val
             end
         end
 
@@ -112,16 +117,24 @@ function format(fmt::JsonFormatter, rec::Record)
     for (alias, key) in aliases
         tmp_val = rec[key]
 
-        value = if key === :date
-            string(tmp_val)
+        if key === :date
+            value = string(tmp_val)
         elseif key === :lookup
-            Dict(
-                :name => tmp_val.func,
-                :file => basename(string(tmp_val.file)),
-                :line => tmp_val.line
-            )
+            value = if isa(tmp_val, StackFrame)
+                Dict(
+                    :name => tmp_val.func,
+                    :file => basename(string(tmp_val.file)),
+                    :line => tmp_val.line
+                )
+            else
+                Dict(
+                    :name => "<nothing>",
+                    :file => "",
+                    :line => -1
+                )
+            end
         elseif key === :stacktrace
-            map(
+            value = map(
                 frame -> Dict(
                     :name => frame.func,
                     :file => basename(string(frame.file)),
@@ -130,7 +143,7 @@ function format(fmt::JsonFormatter, rec::Record)
                 tmp_val
             )
         else
-            tmp_val
+            value = tmp_val
         end
 
         dict[alias] = value

src/loggers.jl

@@ -66,7 +66,18 @@ end
 function Memento.Filter(l::Logger)
     function level_filter(rec::Record)
         level = rec[:level]
-        return l.levels[level] >= l.levels[l.level]
+
+        # NOTE: This is kind of a hack, but the logger can set the
+        # record.levelnum value if it is not set yet.
+        if haskey(l.levels, level)
+            if isnull(rec.levelnum) || get(rec.levelnum) < 0
+                rec.levelnum.x = Nullable(l.levels[level])
+            end
+
+            return l.levels[level] >= l.levels[l.level]
+        else
+            return false
+        end
     end
 
     Memento.Filter(level_filter)
@@ -266,26 +277,23 @@ and `args[:level]` is above the priority of `logger.level`.
 If this logger is not the root logger and `logger.propagate` is `true` then the
 parent logger is called.
 
+NOTE: This method calls all handlers asynchronously and is recursive, so you should call this
+method with a `@sync` in order to synchronize all handler tasks.
+
 # Arguments
 * `logger::Logger`: the logger to log `args` to.
 * `args::Dict`: a dict of msg fields and values that should be passed to `logger.record`.
 """
-function log(logger::Logger, args::Dict{Symbol, Any})
-    level = args[:level]
-    llevel = logger.level
-    levels = logger.levels
-
-    rec = logger.record(args)
-
+function log(logger::Logger, rec::Record)
     # If none of the `Filter`s return false we're good to log our record.
     if all(f -> f(rec), logger.filters)
         for (name, handler) in logger.handlers
-            log(handler, logger.record(args))
+            @async log(handler, rec)
         end
     end
 
     if !is_root(logger) && logger.propagate
-        log(get_parent(logger.name), args)
+        log(get_parent(logger.name), rec)
     end
 end
 
@@ -300,16 +308,14 @@ with the created `Dict`).
 * `logger::Logger`: the logger to log to.
 * `level::AbstractString`: the log level as a `String`
 * `msg::AbstractString`: the msg to log as a `String`
+
+# Throws
+* `CompositeException`: may be thrown if an error occurs in one of the handlers
+   (which are run with `@async`)
 """
 function log(logger::Logger, level::AbstractString, msg::AbstractString)
-    dict = Dict{Symbol, Any}(
-        :name => logger.name,
-        :level => level,
-        :levelnum => logger.levels[level],
-        :msg => msg
-    )
-
-    log(logger, dict)
+    rec = logger.record(logger.name, level, msg)
+    @sync log(logger, rec)
 end
 
 """
@@ -322,16 +328,14 @@ be a function that returns the log message string.
 * `msg::Function`: a function that returns a message `String`
 * `logger::Logger`: the logger to log to.
 * `level::AbstractString`: the log level as a `String`
+
+# Throws
+* `CompositeException`: may be thrown if an error occurs in one of the handlers
+   (which are run with `@async`)
 """
 function log(msg::Function, logger::Logger, level::AbstractString)
-    dict = Dict{Symbol, Any}(
-        :name => logger.name,
-        :level => level,
-        :levelnum => logger.levels[level],
-        :msg => msg
-    )
-
-    log(logger, dict)
+    rec = logger.record(logger.name, level, msg)
+    @sync log(logger, rec)
 end
 
 #=

src/records.jl

@@ -75,8 +75,8 @@ end
 Stores the most common logging event information.
 NOTE: if you'd like more logging attributes you can:
 
-1. You can add them to DefaultRecord and open a pull request if the new attributes are applicable to most applications.
-2. You can make a custom `Record` type.
+1. add them to DefaultRecord and open a pull request if the new attributes are applicable to most applications.
+2. make a custom `Record` type.
 
 # Fields
 * `date::Attribute{DateTime}`: timestamp of log event
@@ -100,25 +100,27 @@ immutable DefaultRecord <: Record
 end
 
 """
-    DefaultRecord(args::Dict{Symbol, Any})
+    DefaultRecord(name::AbstractString, level::AbstractString, msg::AbstractString)
 
-Takes a dict of initial log record arguments and creates the `DefaultRecord`.
+Takes a few initial log record arguments and creates a `DefaultRecord`.
 
 # Arguments
-* `args::Dict{Symbol, Any}`: takes a dict containing the log :level, :levelnum, :name and :msg
+* `name::AbstractString`: the name of the source logger.
+* `level::AbstractString`: the log level.
+* `msg::AbstractString`: the message being logged.
 """
-function DefaultRecord(args::Dict{Symbol, Any})
+function DefaultRecord(name::AbstractString, level::AbstractString, msg)
     time = now()
     trace = Attribute(StackTrace, get_trace)
 
     DefaultRecord(
         Attribute(DateTime, () -> round(time, Base.Dates.Second)),
-        Attribute(args[:level]),
-        Attribute(args[:levelnum]),
-        Attribute(AbstractString, get_msg(args[:msg])),
-        Attribute(args[:name]),
+        Attribute(level),
+        Attribute(-1),
+        Attribute(AbstractString, get_msg(msg)),
+        Attribute(name),
         Attribute(myid()),
-        Attribute(StackFrame, get_lookup(trace)),
+        Attribute(Union{StackFrame, Void}, get_lookup(trace)),
         trace,
     )
 end

test/formatters.jl

@@ -1,12 +1,8 @@
 import Memento: Attribute
 
 @testset "Formatters" begin
-    rec = DefaultRecord(Dict{Symbol, Any}(
-        :name => "Logger.example",
-        :level => :info,
-        :levelnum => 20,
-        :msg => "blah",
-    ))
+    rec = DefaultRecord("Logger.example", "info", "blah")
+
     @testset "DefaultFormatter" begin
         fmt = DefaultFormatter("{lookup}|{msg}|{stacktrace}")
         result = format(fmt, rec)

test/io.jl

@@ -76,7 +76,7 @@ using Base.Test
                                     `logger -t julia -p local0.$(sys_level) "$(level): Message"`
                                 )
                             else
-                                @test_throws ErrorException log(logger, "invalid", "Message")
+                                @test_throws CompositeException log(logger, "invalid", "Message")
                             end
                         end
                     end

test/records.jl

@@ -1,11 +1,6 @@
 @testset "Records" begin
     @testset "DefaultRecord" begin
-        rec = DefaultRecord(Dict{Symbol, Any}(
-            :name => "Logger.example",
-            :level => :info,
-            :levelnum => 20,
-            :msg => "blah",
-        ))
+        rec = DefaultRecord("Logger.example", "info", "blah")
 
         @test rec[:date] == get(rec.date)
         @test get(rec.date) == get(rec.date.x)