diff --git a/README.md b/README.md index f0ac7a2f..1ee45bc5 100644 --- a/README.md +++ b/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 ------------------- diff --git a/REQUIRE b/REQUIRE index 75fdd5ea..525335c6 100644 --- a/REQUIRE +++ b/REQUIRE @@ -1,2 +1,2 @@ julia v0.3 -Compat v0.3.6 +Compat diff --git a/src/Logging.jl b/src/Logging.jl index efb0bb9e..c8c483de 100644 --- a/src/Logging.jl +++ b/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\"")) diff --git a/src/formatter.jl b/src/formatter.jl new file mode 100644 index 00000000..1e336d5a --- /dev/null +++ b/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 \ No newline at end of file diff --git a/test/formatter.jl b/test/formatter.jl new file mode 100644 index 00000000..a8d5c391 --- /dev/null +++ b/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 \ No newline at end of file diff --git a/test/runtests.jl b/test/runtests.jl index 3c8e2652..47b21559 100644 --- a/test/runtests.jl +++ b/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") \ No newline at end of file