Fixes #15874 - added logging of 'X_REQUEST_ID' http headers #475

dmitri-d · 2016-11-14T12:11:18Z

No description provided.

dmitri-d · 2016-11-14T12:14:43Z

Some notes:

for standard logger I replaced process id with request_id. I can restore the process id if it's important. Should I surround request id with <>'s (to help with parsing)?
I can return request id with smart-proxy responses if this would be useful

domcleal · 2016-11-15T13:14:30Z

lib/proxy/log.rb

+      Format = "%s, [%s%s] %5s -- %s: %s\n".freeze
+
+      def call(severity, time, progname, msg)
+        Format % [severity, format_datetime(time), request_id[0..5], severity, progname, msg2str(msg)]


The first severity field used to be a single letter (severity[0..0] in stdlib) so it's now duplicated and affects the indentation. Previously:

D, [2016-11-10T13:34:04.946305 #20953] DEBUG -- : require_ssl_client_verification: skipping, non-HTTPS request I, [2016-11-10T13:34:04.946767 #20953] INFO -- : 192.168.122.1 - - [10/Nov/2016 13:34:04] "GET /tftp/serverName HTTP/1.1" 200 30 0.0007

Now:

DEBUG, [2016-11-15T13:12:52.052872 ] DEBUG -- : Rack::Handler::WEBrick is mounted on /. INFO, [2016-11-15T13:12:52.052942 ] INFO -- : WEBrick::HTTPServer#start: pid=4326 port=8443

domcleal · 2016-11-15T13:16:53Z

lib/proxy/log.rb

+        time.strftime("%Y-%m-%dT%H:%M:%S.%6N ".freeze)
+      end
+
+      def msg2str(msg)


Should this inherit Logger::Formatter to avoid copying this implementation?

No point, as the methods that I need access to are private (grrr).

A subclass should be able to call the private method (without needing send).

You are indeed correct.

domcleal · 2016-11-15T13:18:10Z

modules/root/root_api.rb

@@ -14,6 +14,7 @@ class Proxy::RootApi < Sinatra::Base

  get "/version" do
    begin
+


Not needed?

domcleal · 2016-11-15T13:26:47Z

lib/proxy/request_id_middleware.rb

+    def call(env)
+      Thread.current.thread_variable_set(:request_id, env['HTTP_X_REQUEST_ID']) if env.has_key?('HTTP_X_REQUEST_ID')
+      to_ret = @app.call(env)
+      Thread.current.thread_variable_set(:request_id, nil)


This seems to break logging of the request ID in a default WEBrick configuration, I can't see the request ID at all in the logs.

It appears from adding debug that the thread var's being cleared by this line before the log formatter's called, so the thread variable is always nil. Commenting it out fixes the logging, but will obviously lead to data leaking between requests.

This isn't going to work for logging outside of rack app: the middleware is injected after webrick passes control to it, but before the controller code is invoked. There isn't much I can about this short of changing webrick, which I'd like to avoid.

What I could do however is to log the request (probably via additional middleware) and disable debug logging of requests in webrick/rack?

Yes, I think I see the issue now, that the Rack::CommonLogger defers logging until the very last minute by using a BodyProxy class. The CommonLogger middleware passes back a BodyProxy class wrapping the original body with a block that logs when the body is closed. By this point, this RequestIdMiddleware has long since completed.

While I'm not completely adverse to reimplementing request logging, it might be simpler to either:

Use Rack::BodyProxy here too - pass a BodyProxy with block back out of call that will wipe the thread variable, which should then be after CommonLogger.

Subclass Rack::CommonLogger, override log to wipe the thread variable.

Thanks for looking into this -- I didn't think to look into BodyProxy, but it explains why it's always one of the last thing to get logged. I also think using BodyProxy to clear the thread variable is probably the best approach.

domcleal · 2016-11-15T13:27:34Z

for standard logger I replaced process id with request_id. I can restore the process id if it's important. Should I surround request id with <>'s (to help with parsing)?

I don't think so, it seems fine to me as-is.

dmitri-d · 2016-11-16T11:24:03Z

LoggerFactory::LogFormatter now inherits from ::Logger::Formatter, which eliminated most of the code duplication
request_id thread variable is now cleared when request is closed (via Rack::BodyProxy)

Note: I should point out that only the first 6 digits of the request id are logged, the whole thing (64 digits) would take too much space.

domcleal · 2016-11-16T11:27:35Z

lib/proxy/log.rb

+      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..5], severity, progname, msg2str(msg)]


Could you use eight characters of the request ID? Mostly to match what Foreman currently logs - if the same ID is used then it'll be identical in both log files.

dmitri-d · 2016-11-16T12:37:06Z

Eight characters of the request id are now being logged. Rebased.

domcleal

Still using the first six rather than eight characters?

dmitri-d · 2016-11-16T12:48:24Z

Actually pushed the change now.

domcleal · 2016-11-16T12:56:48Z

Thanks, that's better

There's a comment on the ticket stating:

Make sure this gets recorded in structured format in logger buffer as well, so we can easily pull out logs (e.g. errors) via the API and show them.

Would you be able to add this?

dmitri-d · 2016-11-16T14:12:47Z

Make sure this gets recorded in structured format in logger buffer as well, so we can easily pull out logs (e.g. errors) via the API and show them.

Request_ids are now being stored when available in the log buffer.

domcleal · 2016-11-16T14:39:44Z

Thank you @witlessbird, merged.

theforeman-bot added Needs testing Not yet reviewed labels Nov 14, 2016

domcleal suggested changes Nov 15, 2016

View reviewed changes

theforeman-bot added Waiting on contributor and removed Not yet reviewed labels Nov 15, 2016

theforeman-bot added Needs re-review Needs testing and removed Waiting on contributor labels Nov 16, 2016

domcleal suggested changes Nov 16, 2016

View reviewed changes

theforeman-bot added Waiting on contributor Needs re-review Needs testing and removed Needs re-review Waiting on contributor labels Nov 16, 2016

domcleal approved these changes Nov 16, 2016

View reviewed changes

domcleal suggested changes Nov 16, 2016

View reviewed changes

theforeman-bot added Waiting on contributor Needs re-review Needs testing and removed Needs re-review Waiting on contributor labels Nov 16, 2016

domcleal approved these changes Nov 16, 2016

View reviewed changes

domcleal added Waiting on contributor and removed Needs re-review labels Nov 16, 2016

Fixes #15874 - added logging of 'X_REQUEST_ID' http headers

33d2de9

theforeman-bot added Needs re-review Needs testing and removed Waiting on contributor labels Nov 16, 2016

domcleal merged commit b39011e into theforeman:develop Nov 16, 2016

dmitri-d deleted the 15874-request-id-logging branch January 19, 2017 11:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fixes #15874 - added logging of 'X_REQUEST_ID' http headers #475

Fixes #15874 - added logging of 'X_REQUEST_ID' http headers #475

dmitri-d commented Nov 14, 2016

dmitri-d commented Nov 14, 2016

domcleal Nov 15, 2016

domcleal Nov 15, 2016

dmitri-d Nov 15, 2016

domcleal Nov 15, 2016

dmitri-d Nov 15, 2016

domcleal Nov 15, 2016

domcleal Nov 15, 2016

dmitri-d Nov 15, 2016

domcleal Nov 15, 2016

dmitri-d Nov 15, 2016

domcleal commented Nov 15, 2016

dmitri-d commented Nov 16, 2016

domcleal Nov 16, 2016

dmitri-d commented Nov 16, 2016

domcleal left a comment

dmitri-d commented Nov 16, 2016

domcleal commented Nov 16, 2016

dmitri-d commented Nov 16, 2016

domcleal commented Nov 16, 2016

		@@ -14,6 +14,7 @@ class Proxy::RootApi < Sinatra::Base

		get "/version" do
		begin

Fixes #15874 - added logging of 'X_REQUEST_ID' http headers #475

Fixes #15874 - added logging of 'X_REQUEST_ID' http headers #475

Conversation

dmitri-d commented Nov 14, 2016

dmitri-d commented Nov 14, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

domcleal commented Nov 15, 2016

dmitri-d commented Nov 16, 2016

Choose a reason for hiding this comment

dmitri-d commented Nov 16, 2016

domcleal left a comment

Choose a reason for hiding this comment

dmitri-d commented Nov 16, 2016

domcleal commented Nov 16, 2016

dmitri-d commented Nov 16, 2016

domcleal commented Nov 16, 2016