From d59b5e5eb9ccf2255b5b1a0e90d947dabf3399c3 Mon Sep 17 00:00:00 2001 From: Art Wild Date: Tue, 28 Apr 2015 00:46:51 -0400 Subject: [PATCH 1/3] formatting output similar to log4j with a conversion pattern --- src/Logging.jl | 33 ++++++++++++--- src/formater.jl | 104 ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 132 insertions(+), 5 deletions(-) create mode 100644 src/formater.jl diff --git a/src/Logging.jl b/src/Logging.jl index efb0bb9e..6076511a 100644 --- a/src/Logging.jl +++ b/src/Logging.jl @@ -21,14 +21,34 @@ 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 %x: %m%n" +const DEFAULT_CONVERSION_PATTERN = "%m%n" +const SIMPLE_CONVERSION_PATTERN = "%p - %m%n" +const TTCC_CONVERSION_PATTERN = "%r [%t] %p %c %x - %m%n" + 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 + timestamp::Uint64 + + Logger(name::String, level::LogLevel, output::IO, parent::Logger, pattern::String) = + new(name, level, output, parent, pattern, time_ns()) + 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.timestamp = time_ns() + x + end end show(io::IO, logger::Logger) = print(io, "Logger(", join([logger.name, @@ -40,6 +60,8 @@ const _root = Logger("root", WARNING, STDERR) Logger(name::String;args...) = configure(Logger(name, WARNING, STDERR, _root); args...) Logger() = Logger("logger") +include("formater.jl") + for (fn,lvl,clr) in ((:debug, DEBUG, :cyan), (:info, INFO, :blue), (:warn, WARNING, :magenta), @@ -48,7 +70,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 @@ -70,12 +92,13 @@ function configure(logger=_root; args...) logger.output = parent.output 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/formater.jl b/src/formater.jl new file mode 100644 index 00000000..f091f3f9 --- /dev/null +++ b/src/formater.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('l', 'L', 'M', 'F') + +const SHORT_NAMES = @compat Dict{LogLevel,String}( + DEBUG => "DEBUG", + INFO => "INFO", + WARNING => "WARN", + ERROR => "ERROR", + CRITICAL => "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 parseint(m.captures[4][2:end]); catch 0 end : 0 + # minimum width + sym_minw = m.captures[3] != nothing ? try parseint(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) + logger.name + 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[level] + elseif sym == 'r' # time elapsed (milliseconds) + string(int((time_ns()-logger.timestamp)/10e5)) + 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 From f839724237cd57e18c8160f3a0eab5604e10587c Mon Sep 17 00:00:00 2001 From: Art Wild Date: Tue, 28 Apr 2015 01:09:21 -0400 Subject: [PATCH 2/3] fixing 0.4 compatibility --- src/Logging.jl | 2 +- src/formater.jl | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Logging.jl b/src/Logging.jl index 6076511a..fe25accd 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, diff --git a/src/formater.jl b/src/formater.jl index f091f3f9..15e80893 100644 --- a/src/formater.jl +++ b/src/formater.jl @@ -1,6 +1,6 @@ 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('l', 'L', 'M', 'F') +const BACKTRACE_CONVERSIONS = Set(Any['l', 'L', 'M', 'F']) const SHORT_NAMES = @compat Dict{LogLevel,String}( DEBUG => "DEBUG", @@ -41,9 +41,9 @@ function formatPattern(logger::Logger, level::LogLevel, msg...) append!(logstring, logger.pattern[s:(m.offset-1)].data) # maximum width - sym_maxw = m.captures[4] != nothing ? try parseint(m.captures[4][2:end]); catch 0 end : 0 + 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 parseint(m.captures[3]); catch 0 end : 0 + sym_minw = m.captures[3] != nothing ? try @compat parse(Int, m.captures[3]); catch 0 end : 0 # formating symbol sym = m.captures[5][1] @@ -77,7 +77,7 @@ function formatPattern(logger::Logger, level::LogLevel, msg...) elseif sym == 'p' # level SHORT_NAMES[level] elseif sym == 'r' # time elapsed (milliseconds) - string(int((time_ns()-logger.timestamp)/10e5)) + string(@compat round(Int, (time_ns()-logger.timestamp)/10e5)) elseif sym == 't' # thread or PID string(getpid()) else From 2c5c9d53cce0a928eb08fcdfc318be0f609ad884 Mon Sep 17 00:00:00 2001 From: Art Wild Date: Tue, 28 Apr 2015 14:12:59 -0400 Subject: [PATCH 3/3] added tests and documentatiton for `formatter` --- README.md | 49 +++++++++++++++++++++ REQUIRE | 2 +- src/Logging.jl | 12 +++--- src/{formater.jl => formatter.jl} | 20 ++++----- test/formatter.jl | 72 +++++++++++++++++++++++++++++++ test/runtests.jl | 1 + 6 files changed, 139 insertions(+), 17 deletions(-) rename src/{formater.jl => formatter.jl} (88%) create mode 100644 test/formatter.jl 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 fe25accd..c8c483de 100644 --- a/src/Logging.jl +++ b/src/Logging.jl @@ -22,10 +22,11 @@ catch end const OLD_CONVERSION_PATTERN = "%d{%d-%b %H:%M:%S}:%p:%t:%m%n" -const BASIC_CONVERSION_PATTERN = "%R %p %c %x: %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] %p %c %x - %m%n" +const TTCC_CONVERSION_PATTERN = "%r [%t] %-5p %c - %m%n" +const INITIALIZED_AT = time_ns() type Logger name::String @@ -33,10 +34,9 @@ type Logger output::IO parent::Logger pattern::String - timestamp::Uint64 Logger(name::String, level::LogLevel, output::IO, parent::Logger, pattern::String) = - new(name, level, output, parent, pattern, time_ns()) + 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) @@ -46,7 +46,6 @@ type Logger x.output=output x.parent=x x.pattern=DEFAULT_CONVERSION_PATTERN - x.timestamp = time_ns() x end end @@ -60,7 +59,7 @@ const _root = Logger("root", WARNING, STDERR) Logger(name::String;args...) = configure(Logger(name, WARNING, STDERR, _root); args...) Logger() = Logger("logger") -include("formater.jl") +include("formatter.jl") for (fn,lvl,clr) in ((:debug, DEBUG, :cyan), (:info, INFO, :blue), @@ -90,6 +89,7 @@ function configure(logger=_root; args...) logger.parent = parent = val::Logger logger.level = parent.level logger.output = parent.output + logger.pattern = parent.pattern end end diff --git a/src/formater.jl b/src/formatter.jl similarity index 88% rename from src/formater.jl rename to src/formatter.jl index 15e80893..1e336d5a 100644 --- a/src/formater.jl +++ b/src/formatter.jl @@ -2,13 +2,7 @@ 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 = @compat Dict{LogLevel,String}( - DEBUG => "DEBUG", - INFO => "INFO", - WARNING => "WARN", - ERROR => "ERROR", - CRITICAL => "FATAL" -) +const SHORT_NAMES = ["DEBUG", "INFO", "WARN", "ERROR", "FATAL"] function getbacktrace() btout = @compat Tuple{String,String,Int}[] @@ -59,7 +53,13 @@ function formatPattern(logger::Logger, level::LogLevel, msg...) push!(logstring, 0x25) else output = if sym == 'c' # category name (or logger name) - 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 @@ -75,9 +75,9 @@ function formatPattern(logger::Logger, level::LogLevel, msg...) elseif sym == 'M' # function bt != nothing ? string(bt[1]) : "NA" elseif sym == 'p' # level - SHORT_NAMES[level] + SHORT_NAMES[convert(Int, level)+1] elseif sym == 'r' # time elapsed (milliseconds) - string(@compat round(Int, (time_ns()-logger.timestamp)/10e5)) + string(@compat round(Int, (time_ns()-INITIALIZED_AT)/10e6)) elseif sym == 't' # thread or PID string(getpid()) else 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