-
Notifications
You must be signed in to change notification settings - Fork 220
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Fixes #25100 - Ruby logging stack replaced with logging gem #611
Conversation
2fb3a23
to
37e62db
Compare
@@ -2,6 +2,7 @@ | |||
require 'proxy/sd_notify' | |||
require 'proxy/settings' | |||
require 'proxy/signal_handler' | |||
require 'proxy/log_buffer/trace_decorator' |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
did you forget to git add
this? ;)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Probably, let me check. It happened in the past :-)
lib/proxy/log_buffer/decorator.rb
Outdated
@@ -52,30 +53,68 @@ def add(severity, message = nil, progname = nil, backtrace = nil) | |||
end | |||
end | |||
|
|||
def debug(msg_or_progname, exception_or_backtrace = nil, &block) | |||
def trace? | |||
@trace ||= !!ENV['FOREMAN_TRACE'] |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
{C|Sh}ould this be FOREMAN_PROXY_TRACE
to distinguish?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sure.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I have more points that I have raised here that I would be happy for you to address :)
And also @mmoll points (that he raised them before me :D )
@syslog_available = false | ||
end | ||
|
||
def self.logger | ||
logger_name = 'foreman-proxy' |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
shouldn't it be a configuration, and that's just the default name?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
why would you change this from configuration?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
to have the ability to set up the log system you are using in a manner that easier for you to find things out.
For example "proxy_#xxx" so you can figure out from what proxy it arrived if you have more then one, and send it to tools such as graylog2 or other logging systems, rather then looking inside the machine at the log.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Both rsyslog and journad provides hostname
field for that. Can you give another example? This is just a process name actually, it should be set to application name according to logging
documentation, it sends this into syslog or system journal as well. This should not change.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
okay then, I have no additional examples :D
lib/proxy/log.rb
Outdated
@syslog_available = false | ||
end | ||
|
||
def self.logger | ||
logger_name = 'foreman-proxy' | ||
layout = Logging::Layouts.pattern(pattern: "%d %.8X{request} [%.1l] %m\n") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I know that the structure is "fixed", that is the pattern is used from "day one", but shouldn't that also be configured, with defaults?
The reason for it, is that if we can use tools such as jounald
(or syslog for that matter), there are tools that parse and display log information, and sometimes people wish to tweak them to specific format that easy to look for, and it can be useful for that.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I am gonna make rotation configurable, this is configurable in core and it's confusing (one pattern for file loggers, one pattern for syslog/journal). Proxy now support structured output, users can integrate nicely without need of parsing files.
lib/proxy/log.rb
Outdated
logger = default_logger(log_file) | ||
begin | ||
logger.add_appenders(Logging.appenders.rolling_file( | ||
logger_name, layout: layout, filename: log_file, keep: 6, size: 1024*1024*100, age: 'weekly', roll_by: 'date')) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
My own preferences is to use in such cases a constant for the size.
And also this part can be a configurable settings (the rotation part that is).
What do you think on that points?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sure, if you think that 104857600
is more readable :-)
Overall on the "make it configurable" topic, I think that going forward we should default to journald which handles all of retention, archival, rotation, indexing, throttling, integration and remote transport itself than building our own things. If I would need to pick whether to make configurable logging pattern or rotation, I'd go with rotation which can be sometimes useful since we still default to file logger.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Oh do you mean constant like SIZE = 1024*1024*100
? It's not needed, this is called only once as this is a singleton, therefore there is no performance benefit at all (technically it's even slower).
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Anyway this is now configurable and irrelevant :-)
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) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You cannot "skip" the first argument so I'm not sure that it can solve anything by adding nil
to the first element.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not sure what you mean, this is used in this patch on the following lines:
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).size > 0 ? 'Body: ' + body : '' }
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The example you provided is for "lazy" logging, that is, it is not written right away, and if some of the information was changed when the proc/block were executed, it will hold the new content.
Another way is to do something like this:
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).size > 0 ? 'Body: ' + body : ''
It is logging things right away, and even if the variable changes, it already logged things with the content that was used when executed at that time.
My exemple. uses arguments, rather then the block call, so each argument have it's own place.
If I need to access the second argument, but not the first, Ruby provides a different way of doing so:
def info(msg_or_progname: = nil, exception_or_backtrace: = nil, &block)
# ...
end
logger.info exception_or_backtrace: e
So the message or progname will be kept as nil
.
If you are using it the way your PR does it, your code will be like so:
logger.info nil, e
Does that make sense?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Does that make sense?
It does not.
Please be aware that proxy runs on Ruby 2.0 in production, I cannot use anything from modern Rubies at the moment, until we SCL it.
Also I want to use the same method definition as in the logging gem to stay consistent.
Rebased, added the missing file, renamed the env variable and made everything configurable. Now I need to add this into Puppet 🤦♂️ diff --git a/config/settings.yml.example b/config/settings.yml.example
index 3e635d4..187b674 100644
--- a/config/settings.yml.example
+++ b/config/settings.yml.example
@@ -64,6 +64,16 @@
# 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.
diff --git a/lib/proxy/log.rb b/lib/proxy/log.rb
index 578e284..2b3072a 100644
--- a/lib/proxy/log.rb
+++ b/lib/proxy/log.rb
@@ -18,8 +18,8 @@ module Proxy
def self.logger
logger_name = 'foreman-proxy'
- layout = Logging::Layouts.pattern(pattern: "%d %.8X{request} [%.1l] %m\n")
- notime_layout = Logging::Layouts.pattern(pattern: "%.8X{request} [%.1l] %m\n")
+ 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
@@ -44,8 +44,11 @@ module Proxy
end
else
begin
+ keep = ::Proxy::SETTINGS.file_rolling_keep
+ size = 1024 * 1024 * ::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: 6, size: 1024*1024*100, age: 'weekly', roll_by: 'date'))
+ 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}"
diff --git a/lib/proxy/log_buffer/decorator.rb b/lib/proxy/log_buffer/decorator.rb
index 71a73f5..21b6288 100644
--- a/lib/proxy/log_buffer/decorator.rb
+++ b/lib/proxy/log_buffer/decorator.rb
@@ -54,7 +54,7 @@ module Proxy::LogBuffer
end
def trace?
- @trace ||= !!ENV['FOREMAN_TRACE']
+ @trace ||= !!ENV['FOREMAN_PROXY_TRACE']
end
def trace(msg_or_progname = nil, exception_or_backtrace = nil, &block)
diff --git a/lib/proxy/settings/global.rb b/lib/proxy/settings/global.rb
index 479e64d..b2fe723 100644
--- a/lib/proxy/settings/global.rb
+++ b/lib/proxy/settings/global.rb
@@ -4,6 +4,11 @@ module ::Proxy::Settings
: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", |
37e62db
to
54cd7e2
Compare
lib/proxy/log.rb
Outdated
logger = default_logger(log_file) | ||
begin | ||
keep = ::Proxy::SETTINGS.file_rolling_keep | ||
size = 1024 * 1024 * ::Proxy::SETTINGS.file_rolling_size |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I still think that 1024 * 1024
should be some sort of constant.
I have two reasons for my way of thinking:
- It is easier to figure out that magic result -> more readable imo
- If needed, it is easier to change at a single location, even if at the moment it's on a single location.
I think that performance wise it is not that much of a difference if any.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Well I feel the opposite, it is standard practice to multiply 1024 for KiB, MiB etc. And changing that would mean an intrusive change for users (regressions), we need to agree on something (I propose MiB) and they stick with it.
Can you show a piece of code how you would like it?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Usually I'm in favor of constants to describe what's going on, but I agree with @lzap that 1024 has been a well established pattern.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The code I had in mind was something like this:
BASE_LOG_SIZE = 1024 * 1024 # 1 MiB
It's easier to figure this out (the usage) in my opinion. And if there is a bug (just for the sake of an argument), it is easier to figure out what was the expected result, or the type of usage.
Because 1024 * 1024
for me at least when I see such calculations, feels like "magic" at first glance, even with such code that is very readable and easy to understand.
But it's just how I learned programming, that created OCD on my side ;)
It's not something that is mandatory, but nice to have imo.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I can do this, won't hurt.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@ik5 I get that, but now I don't know that the size is in MBs unless I look at the constant. The use of a constant is to increase readability, not decrease it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@ekohl, that's true for any value that is not inline.
But let's say that MiB is not the right unit, but KiB is, in this specific location, it will be easy to figure this out, but add additional place that needs the same value, and then you are starting a possible bug,that you might forgot another place, you might add constantly comment that it must be the same as the log rotation size etc... so at the end a simple constant can solve this.
But it doesn't really matter, it's just my own OCD that I created myself after long period of pain from such things, and unlike a preparation for a might be feature, it is something a bit different imo.
54cd7e2
to
e57634e
Compare
Amended the constant. @tbrisker hey I'd like to get this into 1.20 is this fine? Only logging changes, low risk. |
Something's wrong [test] |
You need to explicitly tell Jenkins which one to run. For example [test rubocop] or core. |
Oh thanks, [test core] then please. |
bundler.d/journald.rb
Outdated
@@ -0,0 +1,4 @@ | |||
# disable to avoid journald native gem in development setup | |||
group :journald do | |||
gem 'logging-journald', '~> 1.0' |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks like this causes an issue on Ruby 2.0:
logging-journald (~> 1.0) was resolved to 1.0.0, which depends on
ruby (>= 2.1.0)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks for heads up, I filed PR upstream it is a small change.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So I removed Ruby 2.1 requirement in logging-journald and also pinned to journald-logger version 1.1.1 which still supports Ruby 2.0: lzap/logging-journald@a58235e
This will enable Jenkins/Travis to pass on Ruby 2.0. In RPM installations we don't use Bundler therefore the requirement for Ruby 2.1 in journald-logger 2.x does not matter as it's used in gemspec. It should work fine, the only reason for Ruby 2.1 is a method real_exception
which is not used at all by my gem and if needed, we can patch RPM version to support it. For Debian we don't care as it uses Ruby 2.1 and 2.3 already.
Tests seem to pass now, @ekohl ?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
journald-logger seems to have fixed this now?
e57634e
to
8d0b034
Compare
@lzap I'll try my best. BTW, was this already tested on MS Windows? |
It was not, there are no changes for Windows actually - it is assumed that journal bundler group should be disabled on that platform. I will test that. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Packaging PR has been merged, I am going to test on Windows later today and also on nightly tomorrow. |
I'm OK with the current code and also tested it on FreeBSD (which has no journald), but I'd like the situation of logging-journald and Ruby 2.0 to be fully resolved in order to start DEB packaging of the new dependencies. |
Also, there's one issue in my local rubocop run:
|
8d0b034
to
1b58b93
Compare
@mmoll fixed the Rubocop offence, I believe gem problems were sorted out the subdependency was pinned to a particular version. Go ahead and test this on Debian, I am currently installing Windows XP :-) |
While this might be OK for now, I'd have problems to upstream an old gem version to Debian. AFAICT, fixing all the builds of logging-journald and friends with Ruby 2.0-2.5 and then do gem releases would fix this, or am i wrong? |
I understand, luckily the original author of the gems actually accepted my proposal to put Ruby 2.0 back before he transferred to our org. We can actually go ahead and just use latest and greatest versions. That's what I just did, I bumped the gem to version 2.0 which now required Ruby 2.0 compatible latest versions: https://rubygems.org/gems/logging-journald I am gonna go ahead and create RPM/DEB packaging requests with the updated version. |
@mmoll FYI travis is now passing including 2.0: theforeman/journald-logger#5 |
@lzap so the |
1b58b93
to
de6d205
Compare
Oh good point, rebased. I am keeping 2.0 there but if you prefer this to be removed I can do this as well. Just latest and greatest is fine. |
Here are they:
|
@lzap I'll do the DEB dance soonish, I'm pretty sure there's stuff to do. ;) |
There were the following issues with the commit message:
If you don't have a ticket number, please create an issue in Redmine. More guidelines are available in Coding Standards or on the Foreman wiki. This message was auto-generated by Foreman's prprocessor |
48275f6
to
ee69bc4
Compare
I squashed, packaging PR is RTM and tested on nightly. @mmoll any chance of hitting 1.20 with this? :-) |
@lzap please see lzap/logging-journald@7e2c8ae#r30869732 |
Resolved the Debian problem with dependency. Try again please. |
merged, díky @lzap! |
Damn, sorry I should be more explicit. I haven't met Friday deadline and this was no longer a push for merge. It was quite opposite now, do not merge until @tbrisker branches off. Because of the RPM packaging part was not yet merged, this will break nightly: theforeman/foreman-packaging#3084 @tbrisker how do you want to proceed? Couple of options: from branching off one commit before this one to merging RPM packages and going all in with this (I have tested this but there still can be issues). |
for the record - @mmoll discussed it with me prior to merging, this is fine. |
Thanks folks you rock! |
This is continuation of improving logging for Foreman. This patch drops code which uses the simple Ruby logging and replaces it with logging gem which we also use in Foreman core. This brings new features for proxy, for example ability to send logs also to system journal with extended structured fields. I take advantage of this and send REQUEST id along with REMOTE_IP in the initial version of the patch. This is just for starters, in the future we can add more fields for example logs ORG/LOC NAME/ID but smart proxy doesn't have that available at the moment (Foreman would need to send these along with each request).
The patch does not change behavior of existing configuration values, everything stays as-is. There is new configuration option tho:
:log_file: JOURNAL
and when set, journald logger is enabled. This weird configuration syntax will need an overhaul but I don't wan to work on this since we are very close the branching date.Rolling file appender stays as-is, it should keep 6 files with maximum size of 100 MB (it used to be only 10 MB which was a bit too low and no huge risk - it's just extra 90 MB * 6). I have decided to change naming convention from
proxy.1.log
for old (rolled) files toproxy.181004.log
which is based on year, month and day. File rolling is based on weekly basis because by default on production instance logging level is at WARN level and log files for proxy are rather empty (only errors).I took the opportunity to improve logging in general.
I removed access log from stdout sent by webrick and moved logging of begin/end of requests into our own middleware logger which gives us more flexility (debug output, counting time spent in milliseconds similarly like Rails). Of course we also show request id for each individual line in log file (and syslog/journal). Example:
The patch also introduces
trace
logging call which is basically a DEBUG level but it is skipped unless environmental variableFOREMAN_TRACE
is provided. Both lines above headers and body are trace-level calls so they are only visible when needed (during extensive debugging). New TraceDecorator singleton is available and used for all Webrick log messages which are kinda useless most of the time. They can still be enabled usingFOREMAN_TRACE
if needed:The format of the log line is not changing in this patch, the four columns (date/time, request id, level and message) remains the same, I just dropped milliseconds from time that's the only change. But I removed Webrick's noisy AccessLog reporting on the STDOUT which was actually unused in production as far as I can tell.
I vastly simplified LoggerFactory, I removed unit tests for factory tho which I find not very useful.
Proxy log decorator (the main logger object used through the application) now also responds to blocks correctly for faster execution when higher level is set. It also skips logging if message is empty so one can decide in the lazy-evaluated block to skip creating a log entry actually. This is used in the LoggerMiddleware for fastest possible logging of all requests.
All the work goes hand-in-hand with our overall logging initiative - logs gathered via journald can be configured via rsyslog/elasticsearch module to be sent over to central place for archival and indexing. For more info:
I am trying to hit Foreman 1.20 with this patch, review needed. Silent period starts next Monday. @ares @mmoll @tbrisker @ik5 @ekohl