Revision 9d460533
Added by Lukas Zapletal over 5 years ago
| bundler.d/journald.rb | ||
|---|---|---|
|
# disable to avoid journald native gem in development setup
|
||
|
group :journald do
|
||
|
gem 'logging-journald', '~> 2.0', :platforms => [:ruby]
|
||
|
end
|
||
| config/settings.yml.example | ||
|---|---|---|
|
# Uncomment and modify if you want to change the log level
|
||
|
# WARN, DEBUG, ERROR, FATAL, INFO, UNKNOWN
|
||
|
#:log_level: INFO
|
||
|
# The maximum size of a log file before it's rolled (in MiB)
|
||
|
#:file_rolling_size: 100
|
||
|
# The maximum age of a log file before it's rolled (in seconds). Also accepts 'daily', 'weekly', or 'monthly'.
|
||
|
#:file_rolling_age: weekly
|
||
|
# Number of log files to keep
|
||
|
#:file_rolling_keep: 6
|
||
|
# Logging pattern for file-based loging
|
||
|
#:file_logging_pattern: '%d %.8X{request} [%.1l] %m'
|
||
|
# Logging pattern for syslog or journal loging
|
||
|
#:system_logging_pattern: '%.8X{request} [%.1l] %m'
|
||
|
|
||
|
# Log buffer size and extra buffer size (for errors). Defaults to 3000 messages in total,
|
||
|
# which is about 500 kB request.
|
||
| lib/launcher.rb | ||
|---|---|---|
|
require 'proxy/sd_notify'
|
||
|
require 'proxy/settings'
|
||
|
require 'proxy/signal_handler'
|
||
|
require 'proxy/log_buffer/trace_decorator'
|
||
|
require 'thread'
|
||
|
|
||
|
module Proxy
|
||
| ... | ... | |
|
:server => :webrick,
|
||
|
:DoNotListen => true,
|
||
|
:Port => http_port, # only being used to correctly log http port being used
|
||
|
:Logger => ::Proxy::LogBuffer::Decorator.instance,
|
||
|
:Logger => ::Proxy::LogBuffer::TraceDecorator.instance,
|
||
|
:AccessLog => [],
|
||
|
:ServerSoftware => "foreman-proxy/#{Proxy::VERSION}",
|
||
|
:daemonize => false
|
||
|
}
|
||
| lib/proxy/log.rb | ||
|---|---|---|
|
require 'logger'
|
||
|
require 'logging'
|
||
|
require 'proxy/log_buffer/decorator'
|
||
|
|
||
|
# ::Rack::CommonLogger expects loggers to implement 'write' method
|
||
|
Logger.class_eval { alias_method :write, :info }
|
||
|
|
||
|
module Proxy
|
||
|
module Log
|
||
|
def logger
|
||
| ... | ... | |
|
end
|
||
|
|
||
|
class LoggerFactory
|
||
|
class LogFormatter < ::Logger::Formatter
|
||
|
Format = "%s, [%s%s] %5s -- %s: %s\n".freeze
|
||
|
|
||
|
def call(severity, time, progname, msg)
|
||
|
Format % [severity[0..0], format_datetime(time), request_id[0..7], severity, progname, msg2str(msg)]
|
||
|
end
|
||
|
|
||
|
def request_id
|
||
|
Thread.current.thread_variable_get(:request_id).to_s
|
||
|
end
|
||
|
end
|
||
|
BASE_LOG_SIZE = 1024 * 1024 # 1 MiB
|
||
|
|
||
|
begin
|
||
|
require 'syslog/logger'
|
||
|
::Syslog::Logger.class_eval { alias_method :write, :info }
|
||
|
|
||
|
class SyslogFormatter < Syslog::Logger::Formatter
|
||
|
Format = "<%s> %s\n".freeze
|
||
|
|
||
|
def call(severity, time, progname, msg)
|
||
|
request_id.empty? ? clean(msg) : Format % [request_id[0..7], clean(msg)]
|
||
|
end
|
||
|
|
||
|
def request_id
|
||
|
Thread.current.thread_variable_get(:request_id).to_s
|
||
|
end
|
||
|
end
|
||
|
|
||
|
@syslog_available = true
|
||
|
rescue LoadError
|
||
|
# ignore, syslog isn't available on this platform
|
||
|
@syslog_available = false
|
||
|
end
|
||
|
|
||
|
def self.logger
|
||
|
logger_name = 'foreman-proxy'
|
||
|
layout = Logging::Layouts.pattern(pattern: ::Proxy::SETTINGS.file_logging_pattern + "\n")
|
||
|
notime_layout = Logging::Layouts.pattern(pattern: ::Proxy::SETTINGS.system_logging_pattern + "\n")
|
||
|
logger = Logging.logger.root
|
||
|
if log_file.casecmp('STDOUT').zero?
|
||
|
if SETTINGS.daemon
|
||
|
puts "Settings log_file=STDOUT and daemon=true are incompatible, exiting..."
|
||
|
puts "Settings log_file=STDOUT and daemon=true cannot be used together"
|
||
|
exit(1)
|
||
|
end
|
||
|
logger = stdout_logger
|
||
|
logger.add_appenders(Logging.appenders.stdout(logger_name, layout: layout))
|
||
|
elsif log_file.casecmp('SYSLOG').zero?
|
||
|
unless syslog_available?
|
||
|
puts "'SYSLOG' logger is not supported on this platform, please use STDOUT or a file-based logger. Exiting..."
|
||
|
puts "Syslog is not supported on this platform, use STDOUT or a file"
|
||
|
exit(1)
|
||
|
end
|
||
|
logger = syslog_logger
|
||
|
logger.add_appenders(Logging.appenders.syslog(
|
||
|
logger_name, layout: notime_layout, facility: ::Syslog::Constants::LOG_LOCAL5))
|
||
|
elsif log_file.casecmp('JOURNAL').zero? || log_file.casecmp('JOURNALD').zero?
|
||
|
begin
|
||
|
logger.add_appenders(Logging.appenders.journald(
|
||
|
logger_name, logger_name: :proxy_logger, layout: notime_layout, facility: ::Syslog::Constants::LOG_LOCAL5))
|
||
|
rescue NoMethodError
|
||
|
logger.add_appenders(Logging.appenders.stdout(logger_name, layout: layout))
|
||
|
logger.warn "Journald is not available on this platform. Falling back to STDOUT."
|
||
|
end
|
||
|
else
|
||
|
logger = default_logger(log_file)
|
||
|
begin
|
||
|
keep = ::Proxy::SETTINGS.file_rolling_keep
|
||
|
size = BASE_LOG_SIZE * ::Proxy::SETTINGS.file_rolling_size
|
||
|
age = ::Proxy::SETTINGS.file_rolling_age
|
||
|
logger.add_appenders(Logging.appenders.rolling_file(
|
||
|
logger_name, layout: layout, filename: log_file, keep: keep, size: size, age: age, roll_by: 'date'))
|
||
|
rescue ArgumentError => ae
|
||
|
logger.add_appenders(Logging.appenders.stdout(logger_name, layout: layout))
|
||
|
logger.warn "Log file #{log_file} cannot be opened. Falling back to STDOUT: #{ae}"
|
||
|
end
|
||
|
end
|
||
|
logger.level = ::Logger.const_get(::Proxy::SETTINGS.log_level.upcase)
|
||
|
logger
|
||
|
end
|
||
|
|
||
|
def self.default_logger(log_file)
|
||
|
# We keep the last 6 10MB log files
|
||
|
logger = ::Logger.new(log_file, 6, 1024*1024*10)
|
||
|
logger.formatter = LogFormatter.new
|
||
|
logger
|
||
|
rescue Exception => e
|
||
|
puts "Unable to configure file-based logger: #{e.message}. Exiting..."
|
||
|
exit(1)
|
||
|
end
|
||
|
|
||
|
def self.stdout_logger
|
||
|
logger = ::Logger.new(STDOUT)
|
||
|
logger.formatter = LogFormatter.new
|
||
|
logger
|
||
|
end
|
||
|
|
||
|
def self.syslog_logger
|
||
|
logger = ::Syslog::Logger.new 'foreman-proxy'
|
||
|
logger.formatter = SyslogFormatter.new
|
||
|
logger.level = ::Logging.level_num(::Proxy::SETTINGS.log_level)
|
||
|
logger
|
||
|
end
|
||
|
|
||
| ... | ... | |
|
end
|
||
|
|
||
|
def self.log_file
|
||
|
::Proxy::SETTINGS.log_file
|
||
|
@log_file ||= ::Proxy::SETTINGS.log_file
|
||
|
end
|
||
|
end
|
||
|
|
||
| ... | ... | |
|
end
|
||
|
|
||
|
def call(env)
|
||
|
status = 500
|
||
|
env['rack.logger'] = logger
|
||
|
@app.call(env)
|
||
|
logger.info { "Started #{env['REQUEST_METHOD']} #{env['PATH_INFO']} #{env['QUERY_STRING']}" }
|
||
|
logger.trace { 'Headers: ' + env.select {|k,v| k.start_with? 'HTTP_'}.inspect }
|
||
|
logger.trace { (body = env['rack.input'].read).empty? ? '' : 'Body: ' + body }
|
||
|
before = Process.clock_gettime(Process::CLOCK_MONOTONIC)
|
||
|
status, _, _ = @app.call(env)
|
||
|
rescue Exception => e
|
||
|
logger.exception "Error processing request '#{::Logging.mdc['request']}", e
|
||
|
raise e
|
||
|
ensure
|
||
|
logger.info do
|
||
|
after = Process.clock_gettime(Process::CLOCK_MONOTONIC)
|
||
|
duration = (after - before) * 1000
|
||
|
"Finished #{env["REQUEST_METHOD"]} #{env["PATH_INFO"]} with #{status} (#{duration.round(2)} ms)"
|
||
|
end
|
||
|
end
|
||
|
end
|
||
|
end
|
||
| lib/proxy/log_buffer/decorator.rb | ||
|---|---|---|
|
message = progname
|
||
|
end
|
||
|
end
|
||
|
return if message == ''
|
||
|
# add to the logger first
|
||
|
@logger.add(severity, message)
|
||
|
@logger.add(::Logger::Severity::DEBUG, backtrace) if backtrace
|
||
| ... | ... | |
|
end
|
||
|
end
|
||
|
|
||
|
def debug(msg_or_progname, exception_or_backtrace = nil, &block)
|
||
|
def trace?
|
||
|
@trace ||= !!ENV['FOREMAN_PROXY_TRACE']
|
||
|
end
|
||
|
|
||
|
def trace(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
add(::Logger::Severity::DEBUG, nil, msg_or_progname, exception_or_backtrace, &block) if trace?
|
||
|
end
|
||
|
|
||
|
def debug(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
add(::Logger::Severity::DEBUG, nil, msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def info(msg_or_progname, exception_or_backtrace = nil, &block)
|
||
|
def info(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
add(::Logger::Severity::INFO, nil, msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
alias_method :write, :info
|
||
|
|
||
|
def warn(msg_or_progname, exception_or_backtrace = nil, &block)
|
||
|
def warn(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
add(::Logger::Severity::WARN, nil, msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
alias_method :warning, :warn
|
||
|
|
||
|
def error(msg_or_progname, exception_or_backtrace = nil, &block)
|
||
|
def error(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
add(::Logger::Severity::ERROR, nil, msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def fatal(msg_or_progname, exception_or_backtrace = nil, &block)
|
||
|
def fatal(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
add(::Logger::Severity::FATAL, nil, msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def request_id
|
||
|
(r = Thread.current.thread_variable_get(:request_id)).nil? ? r : r.to_s[0..7]
|
||
|
(r = ::Logging.mdc['request']).nil? ? r : r.to_s[0..7]
|
||
|
end
|
||
|
|
||
|
# Structured fields to log in addition to log messages. Every log line created within given block is enriched with these fields.
|
||
|
# Fields appear in joruand and/or JSON output (hash named 'ndc').
|
||
|
def with_fields(fields = {})
|
||
|
::Logging.ndc.push(fields) do
|
||
|
yield
|
||
|
end
|
||
|
end
|
||
|
|
||
|
# Standard way for logging exceptions to get the most data in the log. By default
|
||
|
# it logs via warn level, this can be changed via options[:level]
|
||
|
def exception(context_message, exception, options = {})
|
||
|
level = options[:level] || :warn
|
||
|
unless ::Logging::LEVELS.keys.include?(level.to_s)
|
||
|
raise "Unexpected log level #{level}, expected one of #{::Logging::LEVELS.keys}"
|
||
|
end
|
||
|
# send class, message and stack as structured fields in addition to message string
|
||
|
backtrace = exception.backtrace ? exception.backtrace : []
|
||
|
extra_fields = {
|
||
|
exception_class: exception.class.name,
|
||
|
exception_message: exception.message,
|
||
|
exception_backtrace: backtrace
|
||
|
}
|
||
|
extra_fields[:foreman_code] = exception.code if exception.respond_to?(:code)
|
||
|
with_fields(extra_fields) do
|
||
|
public_send(level) do
|
||
|
([context_message, "#{exception.class}: #{exception.message}"] + backtrace).join("\n")
|
||
|
end
|
||
|
end
|
||
|
end
|
||
|
|
||
|
def method_missing(symbol, *args);
|
||
| lib/proxy/log_buffer/trace_decorator.rb | ||
|---|---|---|
|
require 'proxy/log_buffer/buffer'
|
||
|
require 'thread'
|
||
|
|
||
|
module Proxy::LogBuffer
|
||
|
class TraceDecorator
|
||
|
def self.instance
|
||
|
@@instance ||= new(::Proxy::LogBuffer::Decorator.instance)
|
||
|
end
|
||
|
|
||
|
def initialize(logger)
|
||
|
@logger = logger
|
||
|
end
|
||
|
|
||
|
def debug(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
@logger.trace(msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def info(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
@logger.trace(msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def warn(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
@logger.trace(msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def error(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
@logger.trace(msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def fatal(msg_or_progname = nil, exception_or_backtrace = nil, &block)
|
||
|
@logger.trace(msg_or_progname, exception_or_backtrace, &block)
|
||
|
end
|
||
|
|
||
|
def method_missing(symbol, *args);
|
||
|
@logger.send(symbol, *args)
|
||
|
end
|
||
|
end
|
||
|
end
|
||
| lib/proxy/request_id_middleware.rb | ||
|---|---|---|
|
end
|
||
|
|
||
|
def call(env)
|
||
|
Thread.current.thread_variable_set(:request_id, env['HTTP_X_REQUEST_ID']) if env.has_key?('HTTP_X_REQUEST_ID')
|
||
|
::Logging.mdc['remote_ip'] = env['REMOTE_ADDR']
|
||
|
if env.has_key?('HTTP_X_REQUEST_ID')
|
||
|
::Logging.mdc['request'] = env['HTTP_X_REQUEST_ID']
|
||
|
else
|
||
|
::Logging.mdc['request'] = SecureRandom.uuid
|
||
|
end
|
||
|
status, header, body = @app.call(env)
|
||
|
[status, header, ::Rack::BodyProxy.new(body) { Thread.current.thread_variable_set(:request_id, nil) }]
|
||
|
[status, header, ::Rack::BodyProxy.new(body) { ::Logging.mdc.clear }]
|
||
|
end
|
||
|
end
|
||
|
end
|
||
| lib/proxy/settings/global.rb | ||
|---|---|---|
|
:settings_directory => Pathname.new(__FILE__).join("..","..","..","..","config","settings.d").expand_path.to_s,
|
||
|
:https_port => 8443,
|
||
|
:log_file => "/var/log/foreman-proxy/proxy.log",
|
||
|
:file_rolling_keep => 6,
|
||
|
:file_rolling_size => 100,
|
||
|
:file_rolling_age => 'weekly',
|
||
|
:file_logging_pattern => '%d %.8X{request} [%.1l] %m',
|
||
|
:system_logging_pattern => '%.8X{request} [%.1l] %m',
|
||
|
:log_level => "INFO",
|
||
|
:daemon => false,
|
||
|
:daemon_pid => "/var/run/foreman-proxy/foreman-proxy.pid",
|
||
| lib/smart_proxy_main.rb | ||
|---|---|---|
|
|
||
|
::Sinatra::Base.set :run, false
|
||
|
::Sinatra::Base.set :root, APP_ROOT
|
||
|
::Sinatra::Base.set :logging, false # we are not going to use Rack::Logger
|
||
|
::Sinatra::Base.set :logging, false
|
||
|
::Sinatra::Base.use ::Proxy::RequestIdMiddleware
|
||
|
::Sinatra::Base.use ::Proxy::LoggerMiddleware # instead, we have our own logging middleware
|
||
|
::Sinatra::Base.use ::Rack::CommonLogger, ::Proxy::LogBuffer::Decorator.instance
|
||
|
::Sinatra::Base.use ::Proxy::LoggerMiddleware
|
||
|
::Sinatra::Base.set :env, :production
|
||
|
::Sinatra::Base.register ::Sinatra::Authorization
|
||
|
|
||
| modules/dhcp_common/free_ips.rb | ||
|---|---|---|
|
require 'concurrent'
|
||
|
require 'logger'
|
||
|
require 'set'
|
||
|
require 'dhcp_common/pingable'
|
||
|
|
||
| smart_proxy.gemspec | ||
|---|---|---|
|
s.add_dependency 'json'
|
||
|
s.add_dependency 'rack', '>= 1.1'
|
||
|
s.add_dependency 'sinatra'
|
||
|
s.add_dependency 'logging'
|
||
|
s.description = <<EOF
|
||
|
Foreman Proxy is used via The Foreman Project, it allows Foreman to manage
|
||
|
Remote DHCP, DNS, TFTP and Puppet servers via a REST API
|
||
| test/bmc/bmc_api_test.rb | ||
|---|---|---|
|
assert_equal(expected, data["available_resources"])
|
||
|
end
|
||
|
|
||
|
def test_api_uses_default_smart_proxy_logger
|
||
|
Proxy::BMC::IPMI.logger = nil
|
||
|
Proxy::BMC::Plugin.load_test_settings(:provider_log_level => nil)
|
||
|
Proxy::BMC::IPMI.any_instance.stubs(:poweron?).returns(true)
|
||
|
get "/#{host}/chassis/power/on", args
|
||
|
assert_not_equal 'Rubyipmi', Proxy::BMC::IPMI.logger.progname
|
||
|
def test_api_can_use_default_smart_proxy_logger
|
||
|
Proxy::BMC::IPMI.logger = Proxy::LogBuffer::Decorator.instance
|
||
|
Proxy::BMC::IPMI.logger.error "TEST ERROR"
|
||
|
found = false
|
||
|
Proxy::LogBuffer::Buffer.instance.iterate_descending{|x| found = true if x.message == "TEST ERROR" }
|
||
|
assert found
|
||
|
end
|
||
|
|
||
|
def test_api_can_put_power_action
|
||
| test/bmc/bmc_test.rb | ||
|---|---|---|
|
require 'test_helper'
|
||
|
require 'bmc/ipmi'
|
||
|
require 'logger'
|
||
|
|
||
|
class BmcTest < Test::Unit::TestCase
|
||
|
|
||
| test/log_buffer/decorator_test.rb | ||
|---|---|---|
|
|
||
|
def test_should_keep_request_id_in_buffer_when_available
|
||
|
request_id = '12345678'
|
||
|
Thread.current.thread_variable_set(:request_id, request_id)
|
||
|
::Logging.mdc['request'] = request_id
|
||
|
@decorator.error('error message')
|
||
|
|
||
|
assert_false @buffer.to_a.empty?
|
||
|
assert_equal request_id, @buffer.to_a.first.request_id
|
||
|
ensure
|
||
|
Thread.current.thread_variable_set(:request_id, nil)
|
||
|
::Logging.mdc['request'] = nil
|
||
|
end
|
||
|
|
||
|
def test_should_not_roll_log_if_stdout_is_used
|
||
| test/log_buffer/logger_factory_test.rb | ||
|---|---|---|
|
require 'test_helper'
|
||
|
require 'tempfile'
|
||
|
require 'proxy/log'
|
||
|
|
||
|
class LoggerFactoryTest < Test::Unit::TestCase
|
||
|
def setup
|
||
|
@factory = ::Proxy::LoggerFactory
|
||
|
end
|
||
|
|
||
|
def test_should_configure_logger_when_stdout_is_used
|
||
|
@factory.stubs(:log_file).returns('STDOUT')
|
||
|
logger = @factory.logger
|
||
|
|
||
|
assert logger.is_a?(::Logger)
|
||
|
assert logger.formatter.is_a?(::Proxy::LoggerFactory::LogFormatter)
|
||
|
end
|
||
|
|
||
|
def test_should_configure_logger_by_default
|
||
|
tmp_logfile = Tempfile.new('logfactory-test').path
|
||
|
@factory.stubs(:log_file).returns(tmp_logfile)
|
||
|
logger = @factory.logger
|
||
|
|
||
|
assert logger.is_a?(::Logger)
|
||
|
assert logger.formatter.is_a?(::Proxy::LoggerFactory::LogFormatter)
|
||
|
end
|
||
|
|
||
|
def test_should_configure_syslog
|
||
|
@factory.stubs(:log_file).returns('SYSLOG')
|
||
|
@factory.expects(:syslog_available?).returns(true)
|
||
|
logger = @factory.logger
|
||
|
|
||
|
assert logger.is_a?(::Syslog::Logger)
|
||
|
assert logger.formatter.is_a?(::Proxy::LoggerFactory::SyslogFormatter)
|
||
|
end
|
||
|
end
|
||
Also available in: Unified diff
Fixes #25100 - Ruby logging stack replaced with logging gem