From: Tom Clegg Date: Tue, 31 Oct 2017 03:07:52 +0000 (-0400) Subject: 12167: Improve request-id tracking in Workbench. X-Git-Tag: 1.1.1~22^2~1 X-Git-Url: https://git.arvados.org/arvados.git/commitdiff_plain/0e12d049716003b08c4fc881343ebf14c3522b99?ds=sidebyside 12167: Improve request-id tracking in Workbench. Include current request ID in API requests via X-Request-Id header instead of a form parameter. (Also move Arvados API token from form to Authorization request header.) Always log request ID as its own field, instead of adding it to params (where it might get truncated before being logged). Use new request ID format: "req-" + 20-random-alphanum-chars. Use an around_filter to set/clear the current request ID in one place, instead of setting it in controller code and clearing it in logging code. Return request ID to browser via X-Request-Id header. Arvados-DCO-1.1-Signed-off-by: Tom Clegg --- diff --git a/apps/workbench/Gemfile.lock b/apps/workbench/Gemfile.lock index 34db9cd71c..8ffc1d33b5 100644 --- a/apps/workbench/Gemfile.lock +++ b/apps/workbench/Gemfile.lock @@ -58,7 +58,7 @@ GEM railties (>= 3.1) bootstrap-x-editable-rails (1.5.1.1) railties (>= 3.0) - builder (3.2.2) + builder (3.2.3) byebug (3.5.1) columnize (~> 0.8) debugger-linecache (~> 1.2) @@ -87,6 +87,7 @@ GEM coffee-script-source (1.8.0) columnize (0.9.0) commonjs (0.2.7) + concurrent-ruby (1.0.5) daemon_controller (1.2.0) debugger-linecache (1.2.0) deep_merge (1.0.1) @@ -124,11 +125,12 @@ GEM headless (1.0.2) highline (1.6.21) httpclient (2.8.2.4) - i18n (0.7.0) + i18n (0.9.0) + concurrent-ruby (~> 1.0) jquery-rails (3.1.2) railties (>= 3.0, < 5.0) thor (>= 0.14, < 2.0) - json (1.8.3) + json (1.8.6) jwt (1.5.4) launchy (2.4.3) addressable (~> 2.3) @@ -142,10 +144,11 @@ GEM logging (2.1.0) little-plugger (~> 1.1) multi_json (~> 1.10) - lograge (0.3.6) - actionpack (>= 3) - activesupport (>= 3) - railties (>= 3) + lograge (0.7.1) + actionpack (>= 4, < 5.2) + activesupport (>= 4, < 5.2) + railties (>= 4, < 5.2) + request_store (~> 1.0) logstash-event (1.2.02) mail (2.6.3) mime-types (>= 1.16, < 3) @@ -153,7 +156,7 @@ GEM metaclass (0.0.4) mime-types (2.99) mini_portile (0.6.2) - minitest (5.8.4) + minitest (5.10.3) mocha (1.1.0) metaclass (~> 0.0.1) morrisjs-rails (0.5.1) @@ -207,11 +210,12 @@ GEM activesupport (= 4.1.12) rake (>= 0.8.7) thor (>= 0.18.1, < 2.0) - rake (10.4.2) + rake (12.2.1) rake-compiler (0.9.5) rake raphael-rails (2.1.2) ref (1.0.5) + request_store (1.3.2) retriable (1.4.1) ruby-debug-passenger (0.2.0) ruby-prof (0.15.2) @@ -254,10 +258,10 @@ GEM therubyracer (0.12.1) libv8 (~> 3.16.14.0) ref - thor (0.19.1) - thread_safe (0.3.5) + thor (0.20.0) + thread_safe (0.3.6) tilt (1.4.1) - tzinfo (1.2.2) + tzinfo (1.2.4) thread_safe (~> 0.1) uglifier (2.7.2) execjs (>= 0.3.0) @@ -323,4 +327,4 @@ DEPENDENCIES wiselinks BUNDLED WITH - 1.15.1 + 1.16.0 diff --git a/apps/workbench/app/controllers/application_controller.rb b/apps/workbench/app/controllers/application_controller.rb index 5acf9a7351..8d9e8578c5 100644 --- a/apps/workbench/app/controllers/application_controller.rb +++ b/apps/workbench/app/controllers/application_controller.rb @@ -11,8 +11,8 @@ class ApplicationController < ActionController::Base ERROR_ACTIONS = [:render_error, :render_not_found] - prepend_before_filter :set_current_request_id, except: ERROR_ACTIONS around_filter :thread_clear + around_filter :set_current_request_id around_filter :set_thread_api_token # Methods that don't require login should # skip_around_filter :require_thread_api_token @@ -573,6 +573,19 @@ class ApplicationController < ActionController::Base Rails.cache.delete_matched(/^request_#{Thread.current.object_id}_/) end + def set_current_request_id + response.headers['X-Request-Id'] = + Thread.current[:request_id] = + "req-" + Random::DEFAULT.rand(2**128).to_s(36)[0..19] + yield + Thread.current[:request_id] = nil + end + + def append_info_to_payload(payload) + super + payload[:request_id] = response.headers['X-Request-Id'] + end + # Set up the thread with the given API token and associated user object. def load_api_token(new_token) Thread.current[:arvados_api_token] = new_token @@ -1307,10 +1320,4 @@ class ApplicationController < ActionController::Base def wiselinks_layout 'body' end - - def set_current_request_id - # Request ID format: '-<9_digits_random_number>' - current_request_id = "#{Time.new.to_i}-#{sprintf('%09d', rand(0..10**9-1))}" - Thread.current[:current_request_id] = current_request_id - end end diff --git a/apps/workbench/app/models/arvados_api_client.rb b/apps/workbench/app/models/arvados_api_client.rb index 8638b0aa51..ac2fe3a976 100644 --- a/apps/workbench/app/models/arvados_api_client.rb +++ b/apps/workbench/app/models/arvados_api_client.rb @@ -114,14 +114,10 @@ class ArvadosApiClient url.sub! '/arvados/v1/../../', '/' query = { - 'api_token' => (tokens[:arvados_api_token] || - Thread.current[:arvados_api_token] || - ''), 'reader_tokens' => ((tokens[:reader_tokens] || Thread.current[:reader_tokens] || []) + [Rails.configuration.anonymous_user_token]).to_json, - 'current_request_id' => (Thread.current[:current_request_id] || ''), } if !data.nil? data.each do |k,v| @@ -143,12 +139,19 @@ class ArvadosApiClient query["_profile"] = "true" end - header = {"Accept" => "application/json"} + headers = { + "Accept" => "application/json", + "Authorization" => "OAuth2 " + + (tokens[:arvados_api_token] || + Thread.current[:arvados_api_token] || + ''), + "X-Request-Id" => Thread.current[:request_id] || '', + } profile_checkpoint { "Prepare request #{query["_method"] or "POST"} #{url} #{query[:uuid]} #{query.inspect[0,256]}" } msg = @client_mtx.synchronize do begin - @api_client.post(url, query, header: header) + @api_client.post(url, query, headers) rescue => exception raise NoApiResponseException.new(url, exception) end diff --git a/apps/workbench/config/initializers/lograge.rb b/apps/workbench/config/initializers/lograge.rb index 321bd037f9..6e7f165c13 100644 --- a/apps/workbench/config/initializers/lograge.rb +++ b/apps/workbench/config/initializers/lograge.rb @@ -6,15 +6,20 @@ ArvadosWorkbench::Application.configure do config.lograge.enabled = true config.lograge.formatter = Lograge::Formatters::Logstash.new config.lograge.custom_options = lambda do |event| + payload = { + request_id: event.payload[:request_id], + } + # Also log params (minus the pseudo-params added by Rails). But if + # params is huge, don't log the whole thing, just hope we get the + # most useful bits in truncate(json(params)). exceptions = %w(controller action format id) - params = {current_request_id: Thread.current[:current_request_id]}. - merge(event.payload[:params].except(*exceptions)) + params = event.payload[:params].except(*exceptions) params_s = Oj.dump(params) - Thread.current[:current_request_id] = nil # Clear for next request if params_s.length > 1000 - { params_truncated: params_s[0..1000] + "[...]" } + payload[:params_truncated] = params_s[0..1000] + "[...]" else - { params: params } + payload[:params] = params end + payload end end diff --git a/apps/workbench/test/controllers/application_controller_test.rb b/apps/workbench/test/controllers/application_controller_test.rb index d38e88f2a6..0bcf7a19fb 100644 --- a/apps/workbench/test/controllers/application_controller_test.rb +++ b/apps/workbench/test/controllers/application_controller_test.rb @@ -338,11 +338,11 @@ class ApplicationControllerTest < ActionController::TestCase assert_response 404 end - test "requesting to the API server includes client_session_id param" do - got_query = nil + test "requesting to the API server includes X-Request-Id header" do + got_header = nil stub_api_calls - stub_api_client.stubs(:post).with do |url, query, opts={}| - got_query = query + stub_api_client.stubs(:post).with do |url, query, header={}| + got_header = header true end.returns fake_api_response('{}', 200, {}) @@ -352,14 +352,21 @@ class ApplicationControllerTest < ActionController::TestCase test_uuid = "zzzzz-j7d0g-zzzzzzzzzzzzzzz" get(:show, {id: test_uuid}) - assert_includes got_query, 'current_request_id' - assert_match /\d{10}-\d{9}/, got_query['current_request_id'] + assert_not_nil got_header + assert_includes got_header, 'X-Request-Id' + assert_match /^req-[0-9a-zA-Z]{20}$/, got_header["X-Request-Id"] end - test "current_request_id is nil after a request" do + test "current request_id is nil after a request" do @controller = NodesController.new get(:index, {}, session_for(:active)) - assert_nil Thread.current[:current_request_id] + assert_nil Thread.current[:request_id] + end + + test "X-Request-Id header" do + @controller = NodesController.new + get(:index, {}, session_for(:active)) + assert_match /^req-[0-9a-zA-Z]{20}$/, response.headers['X-Request-Id'] end [".navbar .login-menu a",