WIP: formatted output similar to log4j conversion patterns

README.md

@@ -195,6 +195,55 @@ Setting level=DEBUG
 30-Oct 23:26:16:DEBUG:root:So will this debug message!
 ```
 
+Formatting Output
+-----------------
+Logging messages can be formatter in a manner closely related to the pattern layout configuration of [log4j](http://logging.apache.org/log4j/2.x/manual/layouts.html#PatternLayout). The format of the result depends on the conversion pattern. A conversion pattern is composed of literal text and format control expressions called conversion specifiers.
+
+Note that any literal text, including **Special Character**s, may be included in the conversion pattern. **Special Characters** include \t, \n, \r, \f. Use \\\\ to insert a single backslash into the output.
+
+Each conversion specifier starts with a percent sign (%) and is followed by optional format modifiers and a conversion character. The conversion character specifies the type of data, e.g. category, priority, date, thread name. The format modifiers control such things as field width, padding, left and right justification. The following is a simple example.
+
+Let the conversion pattern be "%-5p [%c]: %m%n". Following calls
+
+```julia
+using Logging
+Logging.configure(format="%-5p [%c]: %m%n", level=DEBUG)
+debug("Message 1")
+warn("Message 2")
+```
+would yield the output
+```
+DEBUG [main]: Message 1
+WARN  [main]: Message 2
+```
+
+#### Conversion Patterns
+The conversions that are provided with `Logging` are:
+| Pattern | Description |
+|---------|-------------|
+|**c**| Outputs the name of the logger that published the logging event.|
+|**C**|Outputs the fully qualified module name of the caller issuing the logging request.|
+|**d**|Outputs the date of the logging event. The date conversion specifier may be followed by a set of braces containing a date and time pattern string in [`sprintf` format](http://www.cplusplus.com/reference/ctime/strftime/).|
+|**F**|Outputs the file name where the logging request was issued. *Generating the file information (location information) is an expensive operation and may impact performance. Use with caution.*|
+|**l**|Outputs location information of the caller which generated the logging event. *Generating location information is an expensive operation and may impact performance. Use with caution.*|
+|**L**|Outputs the line number from where the logging request was issued. *Generating line number information is an expensive operation and may impact performance. Use with caution.*|
+|**m**|Outputs the application supplied message associated with the logging event.|
+|**M**|Outputs the function name where the logging request was issued. *Generating the method name of the caller (location information) is an expensive operation and may impact performance. Use with caution.*|
+|**n**|Outputs the platform dependent line separator character or characters.|
+|**p**|Outputs the level of the logging event.|
+|**r**|Outputs the number of milliseconds elapsed since the Logging package was initialized until the creation of the logging event.|
+|**t**|Outputs the process identifier that generated the logging event.|
+|**%**|The sequence %% outputs a single percent sign.|
+
+#### Pattern Converters
+|Format modifier|left justify|minimum width|maximum width|comment|
+|:-------------:|:----------:|:-----------:|:-----------:|:------|
+|%20c|false|20|none|Left pad with spaces if the category name is less than 20 characters long.|
+|%-20c|true|20|none|Right pad with spaces if the category name is less than 20 characters long.|
+|%.30c|NA|none|30|Truncate from the beginning if the category name is longer than 30 characters.|
+|%20.30c|false|20|30|Left pad with spaces if the category name is shorter than 20 characters. However, if category name is longer than 30 characters, then truncate from the beginning.|
+|%-20.30c|true|20|30|Right pad with spaces if the category name is shorter than 20 characters. However, if category name is longer than 30 characters, then truncate from the beginning.|
+
 More advanced usage
 -------------------
 

REQUIRE

@@ -1,2 +1,2 @@
 julia v0.3
-Compat v0.3.6
+Compat

src/Logging.jl

@@ -2,7 +2,7 @@ module Logging
 
 using Compat
 
-import Base: show
+import Base: show, info, warn
 
 export debug, info, warn, err, critical, log,
        @debug, @info, @warn, @err, @error, @critical, @log,
@@ -21,14 +21,33 @@ catch
     Base.isless(x::LogLevel, y::LogLevel) = isless(x.val, y.val)
 end
 
+const OLD_CONVERSION_PATTERN     = "%d{%d-%b %H:%M:%S}:%p:%t:%m%n"
+const BASIC_CONVERSION_PATTERN   = "%r %p %c: %m%n"
+const DEFAULT_CONVERSION_PATTERN = "%m%n"
+const SIMPLE_CONVERSION_PATTERN  = "%p - %m%n"
+const TTCC_CONVERSION_PATTERN    = "%r [%t] %-5p %c - %m%n"
+const INITIALIZED_AT = time_ns()
+
 type Logger
     name::String
     level::LogLevel
     output::IO
     parent::Logger
-
-    Logger(name::String, level::LogLevel, output::IO, parent::Logger) = new(name, level, output, parent)
-    Logger(name::String, level::LogLevel, output::IO) = (x = new(); x.name = name; x.level=level; x.output=output; x.parent=x)
+    pattern::String
+
+    Logger(name::String, level::LogLevel, output::IO, parent::Logger, pattern::String) =
+        new(name, level, output, parent, pattern)
+    Logger(name::String, level::LogLevel, output::IO, parent::Logger) =
+        Logger(name, level, output, parent, DEFAULT_CONVERSION_PATTERN)
+    function Logger(name::String, level::LogLevel, output::IO)
+        x = new()
+        x.name = name
+        x.level=level
+        x.output=output
+        x.parent=x
+        x.pattern=DEFAULT_CONVERSION_PATTERN
+        x
+    end
 end
 
 show(io::IO, logger::Logger) = print(io, "Logger(", join([logger.name, 
@@ -40,6 +59,8 @@ const _root = Logger("root", WARNING, STDERR)
 Logger(name::String;args...) = configure(Logger(name, WARNING, STDERR, _root); args...)
 Logger() = Logger("logger")
 
+include("formatter.jl")
+
 for (fn,lvl,clr) in ((:debug,    DEBUG,    :cyan),
                      (:info,     INFO,     :blue),
                      (:warn,     WARNING,  :magenta),
@@ -48,7 +69,7 @@ for (fn,lvl,clr) in ((:debug,    DEBUG,    :cyan),
 
     @eval function $fn(logger::Logger, msg...)
         if $lvl >= logger.level
-            logstring = string(Libc.strftime("%d-%b %H:%M:%S",time()),":",$lvl, ":",logger.name,":", msg...,"\n")
+            logstring = formatPattern(logger, $lvl, msg...)
             if isa(logger.output, Base.TTY)
                 Base.print_with_color($(Expr(:quote, clr)), logger.output, logstring )
             else
@@ -68,14 +89,16 @@ function configure(logger=_root; args...)
             logger.parent = parent = val::Logger
             logger.level = parent.level
             logger.output = parent.output
+            logger.pattern = parent.pattern
         end
     end
-    
+
     for (tag, val) in args
         tag == :io            ? (logger.output = val::IO) :
         tag == :output        ? (logger.output = val::IO) :
         tag == :filename      ? (logger.output = open(val, "a")) :
         tag == :level         ? (logger.level  = val::LogLevel) :
+        tag == :format        ? (logger.pattern = val) :
         tag == :override_info ? nothing :  # handled below
         tag == :parent        ? nothing :  # handled above
                                 (Base.error("Logging: unknown configure argument \"$tag\""))

src/formatter.jl

@@ -0,0 +1,104 @@
+const CONVERSION_REGEXP = r"%(((-?\d+)?(.\d+)?)(c|C|F|l|L|m|M|n|p|r|t|x|X|%|d({.+})*))"
+const DEFAULT_TIMESTAMP_FORMAT = "%Y-%m-%d %H:%M:%S"
+const BACKTRACE_CONVERSIONS = Set(Any['l', 'L', 'M', 'F'])
+
+const SHORT_NAMES = ["DEBUG", "INFO", "WARN", "ERROR", "FATAL"]
+
+function getbacktrace()
+    btout = @compat Tuple{String,String,Int}[]
+    for b in backtrace()
+        code = ccall(:jl_lookup_code_address, Any, (Ptr{Void}, Cint), b, true)
+        #println(code)
+        if length(code) == 5 && !code[4]
+            push!(btout, (string(code[1]),string(code[2]),code[3]))
+        end
+    end
+    return btout
+end
+
+function formatPattern(logger::Logger, level::LogLevel, msg...)
+    btskip = 4
+    logstring = Uint8[]
+    matched = eachmatch(CONVERSION_REGEXP, logger.pattern) # match conversions params
+
+    # Check if backtrace is needed
+    needbacktrace = false
+    for m in matched
+        needbacktrace = m.captures[5][1] in BACKTRACE_CONVERSIONS
+        needbacktrace && break
+    end
+    bt = needbacktrace ? getbacktrace()[btskip] : nothing
+
+    # process conversion params
+    s = 1
+    for m in matched
+        append!(logstring, logger.pattern[s:(m.offset-1)].data)
+
+        # maximum width
+        sym_maxw = m.captures[4] != nothing ? try @compat parse(Int, m.captures[4][2:end]); catch 0 end : 0
+        # minimum width
+        sym_minw = m.captures[3] != nothing ? try @compat parse(Int, m.captures[3]); catch 0 end : 0
+        # formating symbol
+        sym = m.captures[5][1]
+
+        # process formating symbols
+        if sym == 'm' # message
+            for mp in msg
+                append!(logstring, string(mp).data)
+            end
+        elseif sym == 'n' # newline
+            @windows_only push!(logstring, 0x0d)
+            push!(logstring, 0x0a)
+        elseif sym == '%' # %
+            push!(logstring, 0x25)
+        else
+            output = if sym == 'c' # category name (or logger name)
+                category = logger.name
+                leaf = logger
+                while leaf != leaf.parent
+                    leaf = leaf.parent
+                    category = "$(leaf.name).$category"
+                end
+                category
+            elseif sym == 'C' # module
+                string(current_module())
+            elseif sym == 'd' # date
+                dformat = m.captures[end]
+                tformat = dformat != nothing ? dformat[2:end-1] : DEFAULT_TIMESTAMP_FORMAT
+                Libc.strftime(tformat,time())
+            elseif sym == 'F' # file
+                bt != nothing ? basename(bt[2]) : "NA"
+            elseif sym == 'l' # module(func:line)
+                bt != nothing ? "$(current_module())($(bt[1]):$(bt[3]))" : "NA"
+            elseif sym == 'L' # line
+                bt != nothing ? string(bt[3]) : "NA"
+            elseif sym == 'M' # function
+                bt != nothing ? string(bt[1]) : "NA"
+            elseif sym == 'p' # level
+                SHORT_NAMES[convert(Int, level)+1]
+            elseif sym == 'r' # time elapsed (milliseconds)
+                string(@compat round(Int, (time_ns()-INITIALIZED_AT)/10e6))
+            elseif sym == 't' # thread or PID
+                string(getpid())
+            else
+                ""
+            end
+
+            # adjust output
+            lout = length(output)
+            if lout > sym_maxw && sym_maxw != 0
+                output = output[(lout-sym_maxw+1):end]
+                lout = sym_maxw
+            end
+            if lout < abs(sym_minw) && sym_minw != 0
+                output = sym_minw > 0 ? lpad(output, sym_minw, ' ') : rpad(output, -sym_minw, ' ')
+            end
+            append!(logstring, output.data)
+        end
+        s = m.offset+length(m.match)
+    end
+    if s < length(logger.pattern)
+        append!(logstring, logger.pattern[s:end].data)
+    end
+    return bytestring(logstring)
+end

test/formatter.jl

@@ -0,0 +1,72 @@
+module TestFormater
+    using Logging
+    using Base.Test
+    using Compat
+
+    # configre root logger
+    Logging.configure(level=DEBUG, format=Logging.BASIC_CONVERSION_PATTERN)
+
+    # setup test data
+    logger = Logging._root
+    loggerName   = logger.name
+    testMessage1 = "TEST1"
+    testMessage2 = "TEST2"
+    testLevel    = DEBUG
+    testTFormat  = "%Y-%m-%d"
+    newline = @windows? "\r\n" : "\n"
+
+    # BASIC_CONVERSION_PATTERN   = "%r %p %c: %m%n"
+    msg = split(Logging.formatPattern(logger, testLevel, testMessage1), ' ')
+    @test @compat parse(Int, msg[1]) > 0
+    @test msg[2] == string(testLevel)
+    @test msg[3] == "$loggerName:"
+    @test msg[4] == "$testMessage1$newline"
+
+    # multiple parameters
+    msg = split(Logging.formatPattern(logger, testLevel, testMessage1, testMessage2), ' ')
+    @test msg[4] == "$testMessage1$testMessage2$newline"
+
+    # all patterns
+    Logging.configure(logger, format="%c %C %d{$testTFormat} %F %l %L %M %p %r %t %% %m %n")
+    msg = split(Logging.formatPattern(logger, testLevel, testMessage1), ' ')
+    @test msg[1] == "$loggerName"
+    @test msg[2] == string(current_module())
+    @test msg[3] == strftime(testTFormat,time())
+    @test msg[8] == string(testLevel)
+    @test @compat parse(Int, msg[9]) > 0
+    @test msg[10] == string(getpid())
+    @test msg[11] == "%"
+    @test msg[12] == testMessage1
+    @test msg[13] == newline
+
+    # logger hierarchy
+    Logging.configure(logger, format="%c")
+    msg = Logging.formatPattern(logger, testLevel, testMessage1)
+    @test msg == logger.name
+
+    nameL1 = "level1"
+    loggerL1 = Logger(nameL1, format = logger.pattern) # TODO remove pattern setup
+    msg = Logging.formatPattern(loggerL1, testLevel, testMessage1)
+    @test msg == "$(logger.name).$nameL1"
+
+    nameL2 = "level2"
+    loggerL2 = Logger(nameL2, parent = loggerL1)
+    msg = Logging.formatPattern(loggerL2, testLevel, testMessage1)
+    loggerL2Name = "$(logger.name).$nameL1.$nameL2"
+    @test msg == loggerL2Name
+
+    # format modifiers
+    Logging.configure(loggerL2, format= "%50c#%-50c#%.5c#%10.5c#%-10.5c#%20.10c")
+    msg = split(Logging.formatPattern(loggerL2, testLevel, testMessage1), '#')
+    trimed = loggerL2Name[(length(loggerL2Name)-4):end]
+    @test msg[1] == lpad(loggerL2Name, 50, ' ')
+    @test msg[2] == rpad(loggerL2Name, 50, ' ')
+    @test msg[3] == trimed
+    @test msg[4] == lpad(trimed, 10, ' ')
+    @test msg[5] == rpad(trimed, 10, ' ')
+
+    Logging.configure(logger, format= "%-10.15c")
+    Logging.configure(loggerL2, format= "%-10.15c")
+    @test Logging.formatPattern(logger, testLevel, testMessage1) == rpad(loggerName, 10, ' ')
+    @test Logging.formatPattern(loggerL2, testLevel, testMessage1) == loggerL2Name[(length(loggerL2Name)-14):end]
+end

test/runtests.jl

@@ -2,3 +2,4 @@ include("log_test.jl")
 include("macro_test1.jl")
 include("macro_test2.jl")
 include("macro_test3.jl")
+include("formatter.jl")