From f092b7db45e01b459aa899e8c0d076b97c137c16 Mon Sep 17 00:00:00 2001 From: Matthias Hecker Date: Tue, 31 Mar 2020 14:30:08 +0200 Subject: refactor: logger moved away from ircbot (exp.) This moves the logger management thread/queue to a seperate singleton. It removes the explicit stopping/restarting of the logging thread since the thread should behave like a daemon thread anyway. Still needs to be tested to work in daemonize. --- lib/rbot/ircbot.rb | 130 +++------------------------------------------------- lib/rbot/logger.rb | 128 +++++++++++++++++++++++++++++++++++++++++++++++++++ lib/rbot/plugins.rb | 6 ++- 3 files changed, 139 insertions(+), 125 deletions(-) create mode 100644 lib/rbot/logger.rb (limited to 'lib/rbot') diff --git a/lib/rbot/ircbot.rb b/lib/rbot/ircbot.rb index 2e808b9e..ddbc6eb6 100644 --- a/lib/rbot/ircbot.rb +++ b/lib/rbot/ircbot.rb @@ -9,20 +9,6 @@ require 'thread' require 'etc' require 'date' require 'fileutils' -require 'logger' - -$debug = false unless $debug -$daemonize = false unless $daemonize - -$dateformat = "%Y/%m/%d %H:%M:%S" -$logger = Logger.new(STDERR) -$logger.datetime_format = $dateformat -$logger.level = $cl_loglevel if defined? $cl_loglevel -$logger.level = 0 if $debug -$logger_stderr = $logger - -$log_queue = Queue.new -$log_thread = nil require 'pp' @@ -47,100 +33,14 @@ end class ServerError < RuntimeError end -def rawlog(level, message=nil, who_pos=1) - call_stack = caller - if call_stack.length > who_pos - who = call_stack[who_pos].sub(%r{(?:.+)/([^/]+):(\d+)(:in .*)?}) { "#{$1}:#{$2}#{$3}" } - else - who = "(unknown)" - end - # Output each line. To distinguish between separate messages and multi-line - # messages originating at the same time, we blank #{who} after the first message - # is output. - # Also, we output strings as-is but for other objects we use pretty_inspect - message = message.kind_of?(String) ? message : (message.pretty_inspect rescue '?') - qmsg = Array.new - message.each_line { |l| - qmsg.push [level, l.chomp, who] - who = ' ' * who.size - } - if level >= Logger::Severity::WARN and not $daemonize - qmsg.each do |l| - $logger_stderr.add(*l) - end - end - $log_queue.push qmsg -end - -def halt_logger - if $log_thread && $log_thread.alive? - $log_queue << nil - $log_thread.join - $log_thread = nil - end -end - -END { halt_logger } - -def restart_logger(newlogger = false) - halt_logger - - $logger = newlogger if newlogger - - $log_thread = Thread.new do - ls = nil - while ls = $log_queue.pop - ls.each { |l| $logger.add(*l) } - end - end -end - -restart_logger - -def log_session_start - $logger << "\n\n=== #{botclass} session started on #{Time.now.strftime($dateformat)} ===\n\n" - restart_logger -end - -def log_session_end - $logger << "\n\n=== #{botclass} session ended on #{Time.now.strftime($dateformat)} ===\n\n" - $log_queue << nil -end - -def debug(message=nil, who_pos=1) - rawlog(Logger::Severity::DEBUG, message, who_pos) -end - -def log(message=nil, who_pos=1) - rawlog(Logger::Severity::INFO, message, who_pos) -end - -def warning(message=nil, who_pos=1) - rawlog(Logger::Severity::WARN, message, who_pos) -end - -def error(message=nil, who_pos=1) - rawlog(Logger::Severity::ERROR, message, who_pos) -end - -def fatal(message=nil, who_pos=1) - rawlog(Logger::Severity::FATAL, message, who_pos) -end - # The following global is used for the improved signal handling. $interrupted = 0 # these first +require 'rbot/logger' require 'rbot/rbotconfig' -begin - require 'rubygems' -rescue LoadError - log "rubygems unavailable" -end - require 'rbot/load-gettext' require 'rbot/config' - require 'rbot/irc' require 'rbot/rfc2812' require 'rbot/ircsocket' @@ -362,7 +262,7 @@ class Bot :default => 1, :requires_restart => false, :validate => Proc.new { |v| (0..5).include?(v) }, :on_change => Proc.new { |bot, v| - $logger.level = v + LoggerManager.instance.set_level(v) }, :desc => "The minimum logging level (0=DEBUG,1=INFO,2=WARN,3=ERROR,4=FATAL) for console messages") Config.register Config::IntegerValue.new('log.keep', @@ -491,7 +391,6 @@ class Bot @config.bot_associate(self) rescue Exception => e fatal e - log_session_end exit 2 end @@ -503,7 +402,7 @@ class Bot @registry_factory.migrate_registry_folder(path) @logfile = @config['log.file'] - if @logfile.class!=String || @logfile.empty? + if @logfile.class != String || @logfile.empty? logfname = File.basename(botclass).gsub(/^\.+/,'') logfname << ".log" @logfile = File.join(botclass, logfname) @@ -528,19 +427,9 @@ class Bot # File.umask 0000 # Ensure sensible umask. Adjust as needed. end - unless $debug - logger = Logger.new(@logfile, - @config['log.keep'], - @config['log.max_size']*1024*1024) - logger.datetime_format= $dateformat - logger.level = @config['log.level'] - logger.level = $cl_loglevel if defined? $cl_loglevel - logger.level = 0 if $debug - - restart_logger(logger) - end - - log_session_start + # setup logger based on bot configuration + LoggerManager.instance.set_level(@config['log.level']) + LoggerManager.instance.set_logfile(@logfile, @config['log.keep'], @config['log.max_size']) if $daemonize log "Redirecting standard input/output/error" @@ -589,7 +478,6 @@ class Bot # @auth.load("#{botclass}/botusers.yaml") rescue Exception => e fatal e - log_session_end exit 2 end @auth.everyone.set_default_permission("*", true) @@ -952,7 +840,6 @@ class Bot debug "interrupted #{$interrupted} times" if $interrupted >= 3 debug "drastic!" - log_session_end exit 2 end end @@ -1027,7 +914,6 @@ class Bot connect rescue SystemExit - log_session_end exit 0 rescue Exception => e error e @@ -1068,7 +954,6 @@ class Bot # exceptions that ARENT SocketError's. How am I supposed to handle # that? rescue SystemExit - log_session_end exit 0 rescue Errno::ETIMEDOUT, Errno::ECONNABORTED, TimeoutError, SocketError => e error "network exception: #{e.pretty_inspect}" @@ -1112,7 +997,6 @@ class Bot quit_msg = e.to_s rescue => e fatal "unexpected exception: #{e.pretty_inspect}" - log_session_end exit 2 end end @@ -1381,11 +1265,9 @@ class Bot # now we re-exec # Note, this fails on Windows debug "going to exec #{$0} #{@argv.inspect} from #{@run_dir}" - log_session_end Dir.chdir(@run_dir) exec($0, *@argv) rescue Errno::ENOENT - log_session_end exec("ruby", *(@argv.unshift $0)) rescue Exception => e $interrupted += 1 diff --git a/lib/rbot/logger.rb b/lib/rbot/logger.rb new file mode 100644 index 00000000..1598f7bd --- /dev/null +++ b/lib/rbot/logger.rb @@ -0,0 +1,128 @@ +# encoding: UTF-8 +#-- vim:sw=2:et +#++ +# +# :title: rbot logger + +require 'logger' +require 'thread' +require 'singleton' + +module Irc +class Bot + + class LoggerManager + include Singleton + + def initialize + @dateformat = "%Y/%m/%d %H:%M:%S" + + @logger = Logger.new(STDERR) + @logger.datetime_format = @dateformat + @logger.level = Logger::Severity::DEBUG + @file_logger = nil + + @queue = Queue.new + @thread = start_thread + end + + def set_logfile(filename, keep, max_size) + @file_logger = Logger.new(filename, keep, max_size*1024*1024) + @file_logger.datetime_format = @dateformat + end + + def set_level(level) + @logger.level = level + if @file_logger + @file_logger.level = level + end + end + + def sync_log(severity, message = nil, progname = nil) + @logger.add(severity, message, progname) + if @file_logger + @file_logger.add(severity, message, progname) + end + end + + def async_log(severity, message=nil, who_pos=1) + unless @thread + STDERR.puts('logger thread already destroyed, cannot log message!') + end + + call_stack = caller + if call_stack.length > who_pos + who = call_stack[who_pos].sub(%r{(?:.+)/([^/]+):(\d+)(:in .*)?}) { "#{$1}:#{$2}#{$3}" } + else + who = "(unknown)" + end + # Output each line. To distinguish between separate messages and multi-line + # messages originating at the same time, we blank #{who} after the first message + # is output. + # Also, we output strings as-is but for other objects we use pretty_inspect + message = message.kind_of?(String) ? message : (message.pretty_inspect rescue '?') + qmsg = Array.new + message.each_line { |l| + qmsg.push [severity, l.chomp, who] + who = ' ' * who.size + } + @queue.push qmsg + end + + def log_session_start + if @file_logger + @file_logger << "\n\n=== session started on #{Time.now.strftime(@dateformat)} ===\n\n" + end + end + + def log_session_end + if @file_logger + @file_logger << "\n\n=== session ended on #{Time.now.strftime(@dateformat)} ===\n\n" + end + end + + def halt_logger + if @thread and @thread.alive? + @queue << nil + @thread.join + @thread = nil + end + end + + private + + def start_thread + Thread.new do + lines = nil + while lines = @queue.pop + lines.each { |line| + sync_log(*line) + } + end + end + end + + end + +end +end + +def debug(message=nil, who_pos=1) + Irc::Bot::LoggerManager.instance.async_log(Logger::Severity::DEBUG, message, who_pos) +end + +def log(message=nil, who_pos=1) + Irc::Bot::LoggerManager.instance.async_log(Logger::Severity::INFO, message, who_pos) +end + +def warning(message=nil, who_pos=1) + Irc::Bot::LoggerManager.instance.async_log(Logger::Severity::WARN, message, who_pos) +end + +def error(message=nil, who_pos=1) + Irc::Bot::LoggerManager.instance.async_log(Logger::Severity::ERROR, message, who_pos) +end + +def fatal(message=nil, who_pos=1) + Irc::Bot::LoggerManager.instance.async_log(Logger::Severity::FATAL, message, who_pos) +end diff --git a/lib/rbot/plugins.rb b/lib/rbot/plugins.rb index d231d7f2..9589b202 100644 --- a/lib/rbot/plugins.rb +++ b/lib/rbot/plugins.rb @@ -215,6 +215,7 @@ module Plugins @registry.flush end + # Method called to cleanup before the plugin is unloaded. If you overload # this method to handle additional cleanup tasks, remember to call super() # so that the default cleanup actions are taken care of as well. @@ -582,6 +583,10 @@ module Plugins ([str, err.inspect] + err.backtrace).join("\n") end + def get_plugin(name) + plugins.find { |plugin| plugin.name == name } + end + # This method is the one that actually loads a module from the # file _fname_ # @@ -653,7 +658,6 @@ module Plugins return newerr end end - private :load_botmodule_file # add one or more directories to the list of directories to # load core modules from -- cgit v1.2.3