Fixes #26561 - logging stack replaced #61
Conversation
|
Inspiration at theforeman/smart-proxy#611 This is vaguely tested at the moment, also the code currently does not take advantage of the exception helper method at all and also no correlation id is taken into account. Help me to integrate this - the idea is that a request in Foreman gets UUID which is then passed to Foreman proxy and logged as well. We need to pass this UUID to Dynflow and log it along with all records. |
|
Smart proxy proxies requests to smart proxy dynflow core. The context needs to be extracted from the incoming request and passed into the outgoing request somewhere around here https://github.com/theforeman/smart_proxy_dynflow/blob/master/lib/smart_proxy_dynflow/callback.rb#L22 . This context the needs to be read from the incoming request in smart proxy dynflow core's API https://github.com/theforeman/smart_proxy_dynflow/blob/master/lib/smart_proxy_dynflow_core/api.rb , be used for sinatra's logging and then passed down into the action which is being triggered. Then we will need to introduce some kind of middleware to set/unset the correct logging context when an action is being run. Something like theforeman/foreman-tasks#383 should do the trick. @iNecas did I miss anything? |
|
If we would be ok with the API calls on smart-proxy-dynflow and smart-proxy-dynflow-core not using the correlation id, but just using it in the core dynflow tasks, the mechanism might be a bit simpler, as it would mean just passing it as input for the proxy tasks and restoring the mdc via middleware. |
lib/smart_proxy_dynflow_core/log.rb
Outdated
| def call(_severity, _datetime, _prog_name, message) | ||
| if message.is_a?(::Exception) | ||
| def format(message) | ||
| if message.is_a(Exception) |
lib/smart_proxy_dynflow_core/log.rb
Outdated
| @action_logger = apply_formatters(ProgNameWrapper.new(@logger, ' action'), [ProxyStructuredFormater]) | ||
| @dynflow_logger = apply_formatters(ProgNameWrapper.new(@logger, 'dynflow'), [ProxyStructuredFormater]) | ||
| end | ||
| end | ||
| end | ||
| end | ||
|
|
||
| class PryAction < ::Dynflow::Action |
There was a problem hiding this comment.
This should go away before merge
There was a problem hiding this comment.
Or we could turn it into something like SmartProxyDynflowCore::DummyAction with docs comments on how to use it: it might be quite nice debugging setup.
There was a problem hiding this comment.
Shouldn't this then live directly in Dynflow so it can be used anywhere?
|
So I have incorporated Adam's core (world) changes and it does seem to work to some degree. I rebased a WIP version, then I do Notice that there are some log entries before |
|
If I want to test this though proxy, what is the URL? The curl above is giving me 404 (spd is enabled and initialized). |
|
For testing through the proxy you need to have smart_proxy_dynflow plugin enabled there and |
|
Ok I think this is now ready for review and testing. This is how it works, smart proxy log: Those debug messages without any request id ( As you can see the the request ID is passed into the core and logged along with other structured info. However, there is still one issue described above - dynflow log lines do not contain the request id until the method |
|
So I tested this with STDOUT, JOURNAL and SYSLOG. All works fine, fixed all comments. Here is an example how an entry looks like, not many custom fields except REQUEST id and REMOTE_IP and SYSLOG_IDENTIFIER and PRIORITY (= logging level) for now, but it's a good start. I don't have rsyslog on my Fedora, however I tested this with journald which listens for syslog events as well. When testing this, note that there are no custom fields as syslog protocol is only PRIORITY + string message. That's the limitation of it. |
lzap
force-pushed
the
logging-26561
branch
2 times, most recently
from
1dc4097
to
cb4fa7f
Compare
|
Fixed rubocop issues |
|
This is needed to fix the tests lzap#2 |
|
This is a terrible test honestly: ;-) |
Your patch does not improve the code, why I think it's important is that users can disable debug level for tests (I do it quite often and only enable it when debugging something weird). The change can break behavior of tests. And I was not just complaining, I was going to fix it. But thanks, let's at least move forward with this. I am going to incorporate your PR into my one. :-) |
|
What is the status here? |
|
Depends on what we want. Currently, auto log rotating does not work in multithreaded environment correctly. By default, we use logrotate for production, so it's only issue for development environments. Several options: we can wait if TwP fixes the problem. Or we can remove file-logging feature completely from dynflow (and smart proxy and foreman?). I poked the maintainer once again to see if there are any plans short-term, let's see. |
|
Upstream released, packaging PR: theforeman/foreman-packaging#5783 |
|
While testing I am running into this when I do Ctrl-C: Is this a known issue? |
|
Anyway, I just repoduced this with 2.2.2 gem, then I updated to the new 2.3.0 release and |
There was a problem hiding this comment.
When running as external core I'm getting a blank line out of nowhere in the logs
2020-09-10T13:42:06 795a45de [I] Started GET /tasks/count
2020-09-10T13:42:06 795a45de [D] Headers: {"HTTP_ACCEPT_ENCODING"=>"gzip;q=1.0,deflate;q=0.6,identity;q=0.3", "HTTP_ACCEPT"=>"*/*, application/json,version=2", "HTTP_USER_AGENT"=>"Ruby", "HTTP_X_FORWARDED_FOR"=>"localhost:8000", "HTTP_X_REQUEST_ID"=>"795a45de-82fd-4813-b103-d50821352e33", "HTTP_CONNECTION"=>"close"
, "HTTP_HOST"=>"127.0.0.1:8008", "HTTP_VERSION"=>"HTTP/1.1"}
2020-09-10T13:42:06 795a45de [D]
2020-09-10T13:42:06 795a45de [D] require_ssl_client_verification: skipping, non-HTTPS request
2020-09-10T13:42:06 795a45de [I] Finished GET /tasks/count with 200 (1.05 ms)
2020-09-10T13:42:06 [D] close: 127.0.0.1:33212
If I run with dynflow core inside smart proxy (and external_core set to no, the debian way), I'm getting doubled outputs. Also note two request ids even though there was only one request
2020-09-10T13:43:24 5e3f7c2b [I] Started GET /tasks/count
2020-09-10T13:43:24 5e3f7c2b [I] Started GET /tasks/count
2020-09-10T13:43:24 5e3f7c2b [D] Headers: {"HTTP_HOST"=>"localhost:8000", "HTTP_USER_AGENT"=>"curl/7.66.0", "HTTP_ACCEPT"=>"*/*", "HTTP_VERSION"=>"HTTP/1.1"}
2020-09-10T13:43:24 5e3f7c2b [D] Headers: {"HTTP_HOST"=>"localhost:8000", "HTTP_USER_AGENT"=>"curl/7.66.0", "HTTP_ACCEPT"=>"*/*", "HTTP_VERSION"=>"HTTP/1.1"}
2020-09-10T13:43:24 5e3f7c2b [D]
2020-09-10T13:43:24 5e3f7c2b [D]
2020-09-10T13:43:24 4d345aae [I] Started GET /dynflow/tasks/count
2020-09-10T13:43:24 4d345aae [D] require_ssl_client_verification: skipping, non-HTTPS request
2020-09-10T13:43:24 4d345aae [D] require_ssl_client_verification: skipping, non-HTTPS request
2020-09-10T13:43:24 4d345aae [I] Finished GET /dynflow/tasks/count with 200 (3.64 ms)
2020-09-10T13:43:24 4d345aae [I] Finished GET /tasks/count with 200 (4.25 ms)
2020-09-10T13:43:24 4d345aae [I] Finished GET /tasks/count with 200 (4.25 ms)
|
Double lines problem solved, the middleware must not be included when running in standalone mode. Packaging PR still not merged but this should be ready: theforeman/foreman-packaging#5666 |
|
Dependency merged into nightly for the record. |
| module SmartProxyDynflowCore | ||
| class TestAction < ::Dynflow::Action | ||
| def run | ||
| state = 0 | ||
| while state < input[:debug_logs] | ||
| action_logger.debug("Test action counter at #{state}") | ||
| state += 1 | ||
| end | ||
| raise "test exception" if input[:exception] | ||
| end | ||
| end | ||
| end |
There was a problem hiding this comment.
Do you insist on getting this in?
There was a problem hiding this comment.
Uh I am not aware writing this or adding this hunk. Perhaps bad conflict resolution? I can delete this for sure if you think it's not valid.
Gemfile
Outdated
| @@ -32,6 +32,7 @@ else | |||
| gem 'rack', '>= 1.1' | |||
| gem 'sinatra' | |||
| end | |||
| gem 'logging-journald', '~> 2.0', :platforms => [:ruby] | |||
There was a problem hiding this comment.
Should this be added to gemspec?
There was a problem hiding this comment.
I could not find a way how to add a gemspec dependency only for a particular platform. This one won't work on JRuby or Ruby on Windows. Anyway, I am going to follow what smart-proxy does: https://github.com/theforeman/smart-proxy/blob/develop/smart_proxy.gemspec
Adding runtime dependency "logging" and keeping this line here as well.
| @logger.debug { 'Headers: ' + env.select { |k, v| k.start_with? 'HTTP_' }.inspect } | ||
| if @logger.debug? && env['rack.input'] | ||
| body = env['rack.input'].read | ||
| @logger.debug body.empty? ? '' : 'Body: ' + body |
There was a problem hiding this comment.
Is there's no body it logs an empty string. Shouldn't we skip it altogether if there's no body?
|
Rebased. |
|
We should be all good @adamruzicka ? Or did I miss some comment(s)? |
|
This should be fine, I was running with this for the past week or so. I just need to read it through once more and it will go in |
| @@ -3,6 +3,8 @@ | |||
| require 'smart_proxy_dynflow_core/settings' | |||
| require 'sd_notify' | |||
|
|
|||
| require 'smart_proxy_dynflow_core/test_action' | |||
There was a problem hiding this comment.
This file no longer exists
|
Rebased, I had a bunch of conflicts in gemspec/gemfiles so please re-review carefully. |
|
👮 is not happy |
|
Well. Ruby/Rubocop community is just swimming against current. It's |
|
Thank you @lzap ! |
This replaces the Ruby logging stack with logging gem which provides enhanced features including logging to journald via structured fields.