From f6db3715c681af90511f5219252f16e57096a194 Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Sat, 11 Feb 2017 01:32:32 +1000 Subject: [PATCH] Initial prototype code --- README.md | 42 +++++++++- src/MicroLogging.jl | 167 +++++++++++++++++++++++++++++++++++++++- test/runtests.jl | 183 +++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 386 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index 581eff1..db74a62 100644 --- a/README.md +++ b/README.md @@ -2,6 +2,44 @@ [![Build Status](https://travis-ci.org/c42f/MicroLogging.jl.svg?branch=master)](https://travis-ci.org/c42f/MicroLogging.jl) -[![Coverage Status](https://coveralls.io/repos/c42f/MicroLogging.jl/badge.svg?branch=master&service=github)](https://coveralls.io/github/c42f/MicroLogging.jl?branch=master) - [![codecov.io](http://codecov.io/github/c42f/MicroLogging.jl/coverage.svg?branch=master)](http://codecov.io/github/c42f/MicroLogging.jl?branch=master) + + +## Design goals + +A prototype for a new logging frontend for `Base`. This isn't meant to be a +fully featured logging framework, just a simple API which allows an efficient +implementation. Logging should be unified so that logs from all packages can be +directed to a common handler in a simple and consistent way. + +### Minimalism of user-visible API + +Logging should be so simple that you reach for `@info` rather than `println()`. + +```julia +x = 42 +@info "my value is x = $x" +``` + +but it should be extensible in the backend. + + +### Efficiency aims - messages you don't see are "free" + +* Early-out to avoid formatting when the message will be filtered. With the + default of a per-module `Logger`, designed such that invisible messages cost + only a load, integer compare and branch. +* Ability to eliminate entire levels of verbose messages as dead code at compile + time (?) + +### Custom log formatters and backends + +* Module based log level control in a heirarchy for ease of use. +* Log pieces (module, message, file location, custom key/value pairs?) passed to + backend for custom formatting +* Non-Base logging frameworks should be able to define backends to send logs to: + stdout/stderr, files, the network, etc. +* The backend should be swappable, such that all packages using the frontend + logger get logs redirected there. + + diff --git a/src/MicroLogging.jl b/src/MicroLogging.jl index 6e6f635..838b5b4 100644 --- a/src/MicroLogging.jl +++ b/src/MicroLogging.jl @@ -1,5 +1,168 @@ module MicroLogging -# package code goes here +export Logger, + @debug, @info, @warn, @error, + @makelogger, + root_logger, configure_logging + + +#------------------------------------------------------------------------------- +immutable LogHandler + stream::IO + usecolor::Bool +end + +LogHandler(stream::IO) = LogHandler(stream, true) + +function logmsg(handler::LogHandler, loggername, level, location, msg) + if level == Debug ; color = :cyan ; levelstr = "DEBUG:" + elseif level == Info ; color = :blue ; levelstr = "INFO :" + elseif level == Warn ; color = :yellow ; levelstr = "WARN :" + elseif level == Error ; color = :red ; levelstr = "ERROR:" + else color = :dark_white ; levelstr = string(level) + end + if handler.usecolor + Base.print_with_color(color, handler.stream, levelstr) + else + print(handler.stream, levelstr) + end + fullmsg = " [($(loggername)) $(location[1]):$(location[2])]: $msg\n" + Base.print(handler.stream, fullmsg) +end + + + +#------------------------------------------------------------------------------- +abstract AbstractLogLevel + +immutable LogLevel <: AbstractLogLevel + level::Int +end +const Debug = LogLevel(-10) +const Info = LogLevel(0) +const Warn = LogLevel(10) +const Error = LogLevel(20) + +Base.:<=(l1::LogLevel, l2::LogLevel) = l1.level <= l2.level + + + +#------------------------------------------------------------------------------- +type Logger{L} + name::Symbol + min_level::L + handler + children::Vector{Logger} +end + +Logger{L}(name, parent::Logger{L}) = Logger{L}(Symbol(name), parent.min_level, + parent.handler, Vector{Module}()) +Logger(name, handler, level=Info) = Logger{typeof(level)}(Symbol(name), level, + handler, Vector{Module}()) +const _root_logger = Logger(:Main, LogHandler(STDERR)) + +Base.push!(parent::Logger, child) = push!(parent.children, child) + +const logger = _root_logger +root_logger() = _root_logger + +function configure_logging(; kwargs...) + configure_logging(root_logger(); kwargs...) +end + +function configure_logging(logger; level=nothing, handler=nothing) + if level !== nothing + logger.min_level = level + end + if handler !== nothing + logger.handler = handler + end + for child in logger.children + configure_logging(child; level=level, handler=handler) + end +end + +function configure_logging(m::Module; kwargs...) + mod = find_logger_module(m) + configure_logging(mod.logger; kwargs...) +end + + +shouldlog(logger::Logger, level) = logger.min_level <= level + +logmsg(logger::Logger, level, location, msg) = logmsg(logger.handler, logger.name, level, location, msg) + + +function find_logger_module(m::Module) + while module_name(m) !== :Main + if isdefined(m, :logger) + return m + end + m = module_parent(m) + end + return MicroLogging +end + + +# Logging macros +for (mname, level) in [(:debug, Debug), + (:info, Info), + (:warn, Warn), + (:error, Error)] + @eval macro $mname(exs...) + if length(exs) == 1 + mod = find_logger_module(current_module()) + logger_ex = :($mod.logger) + msg = esc(exs[1]) + elseif length(exs) == 2 + logger_ex = esc(exs[1]) + msg = esc(exs[2]) + else + error("@$mname must be called with one or two arguments") + end + quote + logger = $logger_ex + if shouldlog(logger, $($level)) + logmsg(logger, $($level), (@__FILE__, @__LINE__), $msg) + end + nothing + end + end +end + + +#------------------------------------------------------------------------------- +# Create per-module logger + + +""" +Create a logger for the current module +""" +macro makelogger() + modname = string(current_module()) + parent_logger = find_logger_module(module_parent(current_module())).logger + esc( + quote + const logger = Logger($modname, $parent_logger) + push!($parent_logger, logger) + end + ) +end + + +#= +macro logtrace(func) + assert(isa(func, Expr) && func.head == :function && func.args[2].head == :block) + enter_msg = "Enter $(func.args[1].args[1])" + exit_msg = "Exit $(func.args[1].args[1])" + unshift!(func.args[2].args, :(MicroLogging.@trace $enter_msg)) + push!(func.args[2].args, :(MicroLogging.@trace $exit_msg)) + esc(func) +end +=# + +end + + + -end # module diff --git a/test/runtests.jl b/test/runtests.jl index ef91de6..97b2561 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -1,5 +1,184 @@ using MicroLogging using Base.Test -# write your own tests here -@test 1 == 2 +import MicroLogging: Debug, Info, Warn, Error + +type TestHandler + messages::Vector{Any} +end + +TestHandler() = TestHandler(Vector{Any}()) + +MicroLogging.logmsg(handler::TestHandler, loggername, level, location, msg) = + push!(handler.messages, (loggername, level, msg)) + +function foo(x) + @debug "foo($x)" + @info "foo($x)" + @warn "foo($x)" + @error "foo($x)" +end + +#------------------------------------------------------------------------------- +@testset "Basic logging" begin + + handler = TestHandler() + configure_logging(handler=handler) + + configure_logging(level=Debug) + foo(1) + @test handler.messages == [(:Main, Debug, "foo(1)"), + (:Main, Info , "foo(1)"), + (:Main, Warn , "foo(1)"), + (:Main, Error, "foo(1)")] + empty!(handler.messages) + + configure_logging(level=MicroLogging.Info) + foo(2) + @test handler.messages == [(:Main, Info , "foo(2)"), + (:Main, Warn , "foo(2)"), + (:Main, Error, "foo(2)")] + empty!(handler.messages) + + configure_logging(level=MicroLogging.Warn) + foo(3) + @test handler.messages == [(:Main, Warn , "foo(3)"), + (:Main, Error, "foo(3)")] + empty!(handler.messages) + + configure_logging(level=MicroLogging.Error) + foo(4) + @test handler.messages == [(:Main, Error, "foo(4)")] + empty!(handler.messages) + +end + + +#------------------------------------------------------------------------------- +# Heirarchy +module A + using MicroLogging + @makelogger + + function a() + @debug "a" + @info "a" + @warn "a" + @error "a" + end + + module B + using MicroLogging + @makelogger + + function b() + @debug "b" + @info "b" + @warn "b" + @error "b" + end + + module C + using MicroLogging + @makelogger + + function c() + @debug "c" + @info "c" + @warn "c" + @error "c" + end + end + end +end + + +@testset "Logger heirarchy" begin + handler = TestHandler() + B_handler = TestHandler() + configure_logging(handler=handler) + configure_logging(A, level=Info) + configure_logging(A.B, level=Warn, handler=B_handler) + configure_logging(A.B.C, level=Error) + A.a() + @test handler.messages == [(:A, Info , "a"), + (:A, Warn , "a"), + (:A, Error, "a")] + empty!(handler.messages) + + A.B.b() + @test B_handler.messages == [(Symbol("A.B"), Warn , "b"), + (Symbol("A.B"), Error, "b")] + @test isempty(handler.messages) + empty!(B_handler.messages) + + A.B.C.c() + @test B_handler.messages == [(Symbol("A.B.C"), Error, "c")] + @test isempty(handler.messages) +end + + +#------------------------------------------------------------------------------- +#= + +function logger_macro_forms() + # Access logger + @info logger "bar()" + # Computation + @info begin + a = 0.5 + @sprintf("a = %.2f, a^2 = %.2f", a, a.^2) + end +end + + +function baz() + # Loggers as variables + handler = MicroLogging.LogHandler(STDOUT) + logger = Logger(:LocalLogger, handler, MicroLogging.Warn) + @debug logger "baz()" + @info logger "baz()" + @warn logger "baz()" + @error logger "baz()" +end + + +#= +function qux() + # Custom log levels ?? + @logmsg logger :mylevel "asdf" + @logmsg Debug2 "asdf" + @logmsg :level "asdf" +end +=# + + +type TestHandler + messages::Vector{Any} +end + +TestHandler() = TestHandler(Vector{Any}()) + +MicroLogging.logmsg(handler::TestHandler, loggername, level, location, msg) = + push!(handler.messages, (loggername, level, msg)) + + +@testset "Basic logging" + + handler = TestHandler() + configure_logging(Main, +configure_logging(Main, + level=MicroLogging.Debug, + handler=TestHandler() +) +Foo.foo(1) +Foo.foo(1) + +println() + +Foo.Bar.bar() + +println() +Foo.Bar.baz() + +=#