diff --git a/spec/compiler/crystal/tools/playground_spec.cr b/spec/compiler/crystal/tools/playground_spec.cr index dcff25b7e7ae..2e122ab8912c 100644 --- a/spec/compiler/crystal/tools/playground_spec.cr +++ b/spec/compiler/crystal/tools/playground_spec.cr @@ -576,7 +576,7 @@ describe Playground::AgentInstrumentorTransformer do end private def assert_compile(source) - sources = Playground::Session.instrument_and_prelude("", "", 0, source, Logger.new(nil)) + sources = Playground::Session.instrument_and_prelude("", "", 0, source) compiler = Compiler.new compiler.no_codegen = true result = compiler.compile sources, "fake-no-build" diff --git a/spec/std/logger_spec.cr b/spec/std/logger_spec.cr deleted file mode 100644 index d0b147032cb9..000000000000 --- a/spec/std/logger_spec.cr +++ /dev/null @@ -1,96 +0,0 @@ -require "spec" -require "logger" - -describe "Logger" do - it "logs messages" do - IO.pipe do |r, w| - logger = Logger.new(w) - logger.debug "debug:skip" - logger.info "info:show" - - logger.level = Logger::DEBUG - logger.debug "debug:show" - - logger.level = Logger::WARN - logger.debug "debug:skip:again" - logger.info "info:skip" - logger.error "error:show" - - r.gets.should match(/info:show/) - r.gets.should match(/debug:show/) - r.gets.should match(/error:show/) - end - end - - it "logs any object" do - IO.pipe do |r, w| - logger = Logger.new(w) - logger.info 12345 - - r.gets.should match(/12345/) - end - end - - it "formats message" do - IO.pipe do |r, w| - logger = Logger.new(w) - logger.progname = "crystal" - logger.warn "message" - - r.gets(chomp: false).should match(/W, \[.+? #\d+\] WARN -- crystal: message\n/) - end - end - - it "uses custom formatter" do - IO.pipe do |r, w| - logger = Logger.new(w) - logger.formatter = Logger::Formatter.new do |severity, datetime, progname, message, io| - io << severity.to_s[0] << ' ' << progname << ": " << message - end - logger.warn "message", "prog" - - r.gets(chomp: false).should eq("W prog: message\n") - end - end - - it "yields message" do - IO.pipe do |r, w| - logger = Logger.new(w) - logger.error { "message" } - logger.unknown { "another message" } - - r.gets(chomp: false).should match(/ERROR -- : message\n/) - r.gets(chomp: false).should match(/ ANY -- : another message\n/) - end - end - - it "yields message with progname" do - IO.pipe do |r, w| - logger = Logger.new(w) - logger.error("crystal") { "message" } - logger.unknown("shard") { "another message" } - - r.gets(chomp: false).should match(/ERROR -- crystal: message\n/) - r.gets(chomp: false).should match(/ ANY -- shard: another message\n/) - end - end - - it "can create a logger with nil (#3065)" do - logger = Logger.new(nil) - logger.error("ouch") - end - - it "doesn't yield to the block with nil" do - a = 0 - logger = Logger.new(nil) - logger.info { a = 1 } - a.should eq(0) - end - - it "closes" do - IO.pipe do |r, w| - Logger.new(w).close - w.closed?.should be_true - end - end -end diff --git a/src/compiler/crystal/command/playground.cr b/src/compiler/crystal/command/playground.cr index 9fb76acb59c5..3a4cd974e760 100644 --- a/src/compiler/crystal/command/playground.cr +++ b/src/compiler/crystal/command/playground.cr @@ -2,6 +2,7 @@ # # This is just the command-line part. The playground is # implemented in `crystal/tools/playground/` +require "logger" class Crystal::Command private def playground @@ -19,7 +20,7 @@ class Crystal::Command end opts.on("-v", "--verbose", "Display detailed information of executed code") do - server.logger.level = Logger::Severity::DEBUG + Logger.default_dispatcher.filter = Logger::DEBUG end opts.on("-h", "--help", "Show this message") do diff --git a/src/compiler/crystal/tools/playground/server.cr b/src/compiler/crystal/tools/playground/server.cr index 460c1ec19ed5..63885a05bb64 100644 --- a/src/compiler/crystal/tools/playground/server.cr +++ b/src/compiler/crystal/tools/playground/server.cr @@ -8,16 +8,18 @@ module Crystal::Playground class Session getter tag : Int32 - def initialize(@ws : HTTP::WebSocket, @session_key : Int32, @port : Int32, @logger : Logger) + @@logger = Logger.get(self) + + def initialize(@ws : HTTP::WebSocket, @session_key : Int32, @port : Int32) @running_process_filename = "" @tag = 0 end - def self.instrument_and_prelude(session_key, port, tag, source, logger) + def self.instrument_and_prelude(session_key, port, tag, source) ast = Parser.new(source).parse instrumented = Playground::AgentInstrumentorTransformer.transform(ast).to_s - logger.info "Code instrumentation (session=#{session_key}, tag=#{tag}).\n#{instrumented}" + @@logger.info "Code instrumentation (session=#{session_key}, tag=#{tag}).\n#{instrumented}" prelude = %( require "compiler/crystal/tools/playground/agent" @@ -42,11 +44,11 @@ module Crystal::Playground end def run(source, tag) - @logger.info "Request to run code (session=#{@session_key}, tag=#{tag}).\n#{source}" + @@logger.info "Request to run code (session=#{@session_key}, tag=#{tag}).\n#{source}" @tag = tag begin - sources = self.class.instrument_and_prelude(@session_key, @port, tag, source, @logger) + sources = self.class.instrument_and_prelude(@session_key, @port, tag, source) rescue ex : Crystal::Exception send_exception ex, tag return @@ -56,22 +58,22 @@ module Crystal::Playground compiler = Compiler.new compiler.color = false begin - @logger.info "Instrumented code compilation started (session=#{@session_key}, tag=#{tag})." + @@logger.info "Instrumented code compilation started (session=#{@session_key}, tag=#{tag})." result = compiler.compile sources, output_filename rescue ex - @logger.info "Instrumented code compilation failed (session=#{@session_key}, tag=#{tag})." + @@logger.info "Instrumented code compilation failed (session=#{@session_key}, tag=#{tag})." # due to instrumentation, we compile the original program begin - @logger.info "Original code compilation started (session=#{@session_key}, tag=#{tag})." + @@logger.info "Original code compilation started (session=#{@session_key}, tag=#{tag})." compiler.compile Compiler::Source.new("play", source), output_filename rescue ex - @logger.info "Original code compilation failed (session=#{@session_key}, tag=#{tag})." + @@logger.info "Original code compilation failed (session=#{@session_key}, tag=#{tag})." send_exception ex, tag return # if we don't exit here we've found a bug end - @logger.error "Instrumention bug found (session=#{@session_key}, tag=#{tag})." + @@logger.error "Instrumention bug found (session=#{@session_key}, tag=#{tag})." send_with_json_builder do |json| json.field "type", "bug" json.field "tag", tag @@ -93,7 +95,7 @@ module Crystal::Playground end def format(source, tag) - @logger.info "Request to format code (session=#{@session_key}, tag=#{tag}).\n#{source}" + @@logger.info "Request to format code (session=#{@session_key}, tag=#{tag}).\n#{source}" @tag = tag @@ -119,7 +121,7 @@ module Crystal::Playground begin @ws.send(message) rescue ex : IO::Error - @logger.warn "Unable to send message (session=#{@session_key})." + @@logger.warn "Unable to send message (session=#{@session_key})." end end @@ -158,7 +160,7 @@ module Crystal::Playground private def stop_process if process = @process - @logger.info "Code execution killed (session=#{@session_key}, filename=#{@running_process_filename})." + @@logger.info "Code execution killed (session=#{@session_key}, filename=#{@running_process_filename})." @process = nil File.delete @running_process_filename rescue nil process.kill rescue nil @@ -168,13 +170,13 @@ module Crystal::Playground private def execute(tag, output_filename) stop_process - @logger.info "Code execution started (session=#{@session_key}, tag=#{tag}, filename=#{output_filename})." + @@logger.info "Code execution started (session=#{@session_key}, tag=#{tag}, filename=#{output_filename})." process = @process = Process.new(output_filename, args: [] of String, input: Process::Redirect::Pipe, output: Process::Redirect::Pipe, error: Process::Redirect::Pipe) @running_process_filename = output_filename spawn do status = process.wait - @logger.info "Code execution ended (session=#{@session_key}, tag=#{tag}, filename=#{output_filename})." + @@logger.info "Code execution ended (session=#{@session_key}, tag=#{tag}, filename=#{output_filename})." exit_status = status.normal_exit? ? status.exit_code : status.exit_signal.value send_with_json_builder do |json| @@ -450,17 +452,16 @@ module Crystal::Playground @sessions = {} of Int32 => Session @sessions_key = 0 + @@logger = Logger.get(self) + property host : String? property port - property logger property source : Compiler::Source? def initialize @host = nil @port = 8080 @verbose = false - @logger = Logger.new(STDOUT) - @logger.level = Logger::Severity::WARN end def start @@ -472,7 +473,7 @@ module Crystal::Playground match_data = context.request.path.not_nil!.match(/\/(\d+)\/(\d+)$/).not_nil! session_key = match_data[1]?.try(&.to_i) tag = match_data[2]?.try(&.to_i) - @logger.info "#{context.request.path} WebSocket connected (session=#{session_key}, tag=#{tag})" + @@logger.info "#{context.request.path} WebSocket connected (session=#{session_key}, tag=#{tag})" session = @sessions[session_key] @@ -488,12 +489,12 @@ module Crystal::Playground client_ws = PathWebSocketHandler.new "/client" do |ws, context| origin = context.request.headers["Origin"] if !accept_request?(origin) - @logger.warn "Invalid Request Origin: #{origin}" + @@logger.warn "Invalid Request Origin: #{origin}" ws.close "Invalid Request Origin" else @sessions_key += 1 - @sessions[@sessions_key] = session = Session.new(ws, @sessions_key, @port, @logger) - @logger.info "/client WebSocket connected as session=#{@sessions_key}" + @sessions[@sessions_key] = session = Session.new(ws, @sessions_key, @port) + @@logger.info "/client WebSocket connected as session=#{@sessions_key}" ws.on_message do |message| json = JSON.parse(message) diff --git a/src/logger.cr b/src/logger.cr index 28103b89f9ee..b470c1e1b22f 100644 --- a/src/logger.cr +++ b/src/logger.cr @@ -1,178 +1,27 @@ -# The `Logger` class provides a simple but sophisticated logging utility that you can use to output messages. -# -# The messages have associated levels, such as `INFO` or `ERROR` that indicate their importance. -# You can then give the `Logger` a level, and only messages at that level of higher will be printed. -# -# For instance, in a production system, you may have your `Logger` set to `INFO` or even `WARN`. -# When you are developing the system, however, you probably want to know about the program’s internal state, -# and would set the `Logger` to `DEBUG`. -# -# If logging to multiple locations is required, an `IO::MultiWriter` can be -# used. -# -# ### Example -# -# ``` -# require "logger" -# -# log = Logger.new(STDOUT) -# log.level = Logger::WARN -# -# # or -# log = Logger.new(STDOUT, level: Logger::WARN) -# -# log.debug("Created logger") -# log.info("Program started") -# log.warn("Nothing to do!") -# -# begin -# File.each_line("/foo/bar.log") do |line| -# unless line =~ /^(\w+) = (.*)$/ -# log.error("Line in wrong format: #{line}") -# end -# end -# rescue err -# log.fatal("Caught exception; exiting") -# log.fatal(err) -# end -# ``` -class Logger - property level : Severity - property progname : String - - # Customizable `Proc` (with a reasonable default) - # which the `Logger` uses to format and print its entries. - # - # Use this setter to provide a custom formatter. - # The `Logger` will invoke it with the following arguments: - # - severity: a `Logger::Severity` - # - datetime: `Time`, the entry's timestamp - # - progname: `String`, the program name, if set when the logger was built - # - message: `String`, the body of a message - # - io: `IO`, the Logger's stream, to which you must write the final output - # - # Example: - # - # ``` - # require "logger" - # - # logger = Logger.new(STDOUT) - # logger.progname = "YodaBot" - # - # logger.formatter = Logger::Formatter.new do |severity, datetime, progname, message, io| - # label = severity.unknown? ? "ANY" : severity.to_s - # io << label[0] << ", [" << datetime << " #" << Process.pid << "] " - # io << label.rjust(5) << " -- " << progname << ": " << message - # end - # - # logger.warn("Fear leads to anger. Anger leads to hate. Hate leads to suffering.") - # - # # Prints to the console: - # # "W, [2017-05-06 18:00:41 -0300 #11927] WARN -- - # # YodaBot: Fear leads to anger. Anger leads to hate. Hate leads to suffering." - # ``` - property formatter - - # A logger severity level. - enum Severity - # Low-level information for developers - DEBUG - - # Generic (useful) information about system operation - INFO - - # A warning - WARN - - # A handleable error condition - ERROR - - # An unhandleable error that results in a program crash - FATAL - - UNKNOWN - end - - alias Formatter = Severity, Time, String, String, IO -> - - private DEFAULT_FORMATTER = Formatter.new do |severity, datetime, progname, message, io| - label = severity.unknown? ? "ANY" : severity.to_s - io << label[0] << ", [" << datetime << " #" << Process.pid << "] " - io << label.rjust(5) << " -- " << progname << ": " << message - end - - # :nodoc: - record Message, - severity : Severity, - datetime : Time, - progname : String, - message : String +require "logger/*" + +struct Logger + getter component : String + getter dispatcher : Dispatcher + + {% for level in Severity.constants %} + {% unless level == "SILENT" %} + def {{ level.downcase.id }}(message, *, time = Time.now, line_number = __LINE__, filename = __FILE__) + dispatcher.call Entry.new(message, Severity::{{ level }}, component, time, line_number, filename) + end + {% end %} + {% end %} - # Creates a new logger that will log to the given *io*. - # If *io* is `nil` then all log calls will be silently ignored. - def initialize(@io : IO?, @level = Severity::INFO, @formatter = DEFAULT_FORMATTER, @progname = "") - @closed = false - @mutex = Mutex.new + def initialize(@component, @dispatcher) end - # Calls the *close* method on the object passed to `initialize`. - def close - return if @closed - return unless io = @io - @closed = true + class_getter default_dispatcher = Dispatcher.new(nil, IOEmitter.new) - @mutex.synchronize do - io.close - end + def self.get(component) : Logger + default_dispatcher.get component end - {% for name in Severity.constants %} - {{name.id}} = Severity::{{name.id}} - - # Returns `true` if the logger's current severity is lower or equal to `{{name.id}}`. - def {{name.id.downcase}}? - level <= Severity::{{name.id}} - end - - # Logs *message* if the logger's current severity is lower or equal to `{{name.id}}`. - # *progname* overrides a default progname set in this logger. - def {{name.id.downcase}}(message, progname = nil) - log(Severity::{{name.id}}, message, progname) - end - - # Logs the message as returned from the given block if the logger's current severity - # is lower or equal to `{{name.id}}`. The block is not run if the severity is higher. - # *progname* overrides a default progname set in this logger. - def {{name.id.downcase}}(progname = nil) - log(Severity::{{name.id}}, progname) { yield } - end + {% for level in Severity.constants %} + {{ level }} = Severity::{{ level }} {% end %} - - # Logs *message* if *severity* is higher or equal with the logger's current - # severity. *progname* overrides a default progname set in this logger. - def log(severity, message, progname = nil) - return if severity < level || !@io - write(severity, Time.now, progname || @progname, message) - end - - # Logs the message as returned from the given block if *severity* - # is higher or equal with the loggers current severity. The block is not run - # if *severity* is lower. *progname* overrides a default progname set in this logger. - def log(severity, progname = nil) - return if severity < level || !@io - write(severity, Time.now, progname || @progname, yield) - end - - private def write(severity, datetime, progname, message) - io = @io - return unless io - - progname_to_s = progname.to_s - message_to_s = message.to_s - @mutex.synchronize do - formatter.call(severity, datetime, progname_to_s, message_to_s, io) - io.puts - io.flush - end - end end diff --git a/src/logger/dispatcher.cr b/src/logger/dispatcher.cr new file mode 100644 index 000000000000..6648c57ab089 --- /dev/null +++ b/src/logger/dispatcher.cr @@ -0,0 +1,34 @@ +require "./emitter" + +struct Logger + alias FilterType = Filter | Severity | (Entry -> Bool) + alias EmitterType = Emitter | (Entry -> Nil) + + class Dispatcher + include Emitter + + property filter : FilterType? + property emitters : Array(EmitterType) + + def initialize(@filter, @emitters) + end + + def self.new(filter, emitter : EmitterType) + new(filter, [emitter] of EmitterType) + end + + def call(entry : Entry) + case ff = filter + when Filter, Proc(Entry, Bool) + return unless ff.call(entry) + when Severity + return unless entry.severity >= ff + end + emitters.each &.call(entry) + end + + def get(component) : Logger + Logger.new(component.to_s, self) + end + end +end diff --git a/src/logger/emitter.cr b/src/logger/emitter.cr new file mode 100644 index 000000000000..8a2043200e9a --- /dev/null +++ b/src/logger/emitter.cr @@ -0,0 +1,24 @@ +require "./entry" + +struct Logger + module Emitter + abstract def call(entry : Entry) : Nil + end + + class IOEmitter + include Emitter + + DEFAULT_FORMATTER = ->(io : IO, entry : Entry) do + io << entry.time << ' ' << entry.severity.to_s.ljust(5) << " ::" + io << entry.component << " " << entry.message << '\n' + return nil + end + + def initialize(@io : IO = STDOUT, @formatter : Proc(IO, Entry, Nil) = DEFAULT_FORMATTER) + end + + def call(entry : Entry) : Nil + @formatter.call(@io, entry) + end + end +end diff --git a/src/logger/entry.cr b/src/logger/entry.cr new file mode 100644 index 000000000000..5146a767179d --- /dev/null +++ b/src/logger/entry.cr @@ -0,0 +1,15 @@ +require "./severity" + +struct Logger + struct Entry + getter message : String + getter severity : Severity + getter component : String + getter time : Time + getter line_number : Int32 + getter filename : String + + def initialize(@message, @severity, @component, @time, @line_number, @filename) + end + end +end diff --git a/src/logger/filter.cr b/src/logger/filter.cr new file mode 100644 index 000000000000..c4b908096510 --- /dev/null +++ b/src/logger/filter.cr @@ -0,0 +1,31 @@ +require "./entry" + +struct Logger + module Filter + abstract def call(entry : Entry) : Bool + end + + class HierarchyFilter + include Filter + + property levels : Hash(String, Severity) + + def initialize(@levels = {} of String => Severity) + end + + def call(entry : Entry) + component = entry.component + while true + if level = @levels[component]? + return entry.severity >= level + end + break if component.empty? + component = component[0...(component.rindex("::") || 0)] + end + + return true + end + + forward_missing_to @levels + end +end diff --git a/src/logger/severity.cr b/src/logger/severity.cr new file mode 100644 index 000000000000..506947b90e77 --- /dev/null +++ b/src/logger/severity.cr @@ -0,0 +1,17 @@ +struct Logger + # A logger severity level. + enum Severity + # Low-level information for developers + DEBUG + # Generic (useful) information about system operation + INFO + # A warning + WARN + # A handleable error condition + ERROR + # An unhandleable error that results in a program crash + FATAL + # A level that should never be used in messages but may be useful for setting thresholds + SILENT + end +end