From: Tom Clegg Date: Tue, 31 Oct 2017 21:27:41 +0000 (-0400) Subject: 12167: Include a request ID in each API response and log entry. X-Git-Tag: 1.1.1~22^2 X-Git-Url: https://git.arvados.org/arvados.git/commitdiff_plain/5f46fe83d8a15048c4a5b90553c379803e99b135 12167: Include a request ID in each API response and log entry. Use the value of the X-Request-Id request header if given, otherwise generate one. Arvados-DCO-1.1-Signed-off-by: Tom Clegg --- diff --git a/services/api/Gemfile.lock b/services/api/Gemfile.lock index f1f03c3125..ebb594cb1e 100644 --- a/services/api/Gemfile.lock +++ b/services/api/Gemfile.lock @@ -85,6 +85,8 @@ GEM coffee-script-source execjs coffee-script-source (1.12.2) + concurrent-ruby (1.0.5) + crass (1.0.2) curb (0.9.3) database_cleaner (1.5.3) erubis (2.7.0) @@ -125,7 +127,8 @@ GEM hashie (3.5.5) highline (1.7.8) hike (1.2.3) - i18n (0.8.6) + i18n (0.9.0) + concurrent-ruby (~> 1.0) jquery-rails (4.2.2) rails-dom-testing (>= 1, < 3) railties (>= 4.2.0) @@ -139,12 +142,14 @@ GEM logging (2.2.2) little-plugger (~> 1.1) multi_json (~> 1.10) - lograge (0.4.1) - actionpack (>= 4, < 5.1) - activesupport (>= 4, < 5.1) - railties (>= 4, < 5.1) + 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) - loofah (2.0.3) + loofah (2.1.1) + crass (~> 1.0.2) nokogiri (>= 1.5.9) mail (2.6.4) mime-types (>= 1.16, < 4) @@ -153,7 +158,7 @@ GEM mime-types (3.1) mime-types-data (~> 3.2015) mime-types-data (3.2016.0521) - mini_portile2 (2.1.0) + mini_portile2 (2.3.0) minitest (5.10.3) mocha (1.2.1) metaclass (~> 0.0.1) @@ -167,8 +172,8 @@ GEM net-ssh (4.1.0) net-ssh-gateway (2.0.0) net-ssh (>= 4.0.0) - nokogiri (1.7.1) - mini_portile2 (~> 2.1.0) + nokogiri (1.8.1) + mini_portile2 (~> 2.3.0) oauth2 (1.3.1) faraday (>= 0.8, < 0.12) jwt (~> 1.0) @@ -193,7 +198,7 @@ GEM activemodel (>= 4.0.1, < 5.0) public_suffix (2.0.5) puma (2.16.0) - rack (1.6.5) + rack (1.6.8) rack-test (0.6.3) rack (>= 1.0) rails (4.2.5.2) @@ -222,8 +227,9 @@ GEM activesupport (= 4.2.5.2) rake (>= 0.8.7) thor (>= 0.18.1, < 2.0) - rake (12.0.0) + rake (12.2.1) ref (2.0.0) + request_store (1.3.2) responders (2.3.0) railties (>= 4.2.0, < 5.1) retriable (1.4.1) @@ -265,11 +271,11 @@ GEM therubyracer (0.12.3) libv8 (~> 3.16.14.15) ref - thor (0.19.4) + thor (0.20.0) thread_safe (0.3.6) tilt (1.4.1) trollop (2.1.2) - tzinfo (1.2.3) + tzinfo (1.2.4) thread_safe (~> 0.1) uglifier (2.7.2) execjs (>= 0.3.0) @@ -321,4 +327,4 @@ DEPENDENCIES uglifier (~> 2.0) BUNDLED WITH - 1.15.1 + 1.16.0 diff --git a/services/api/app/controllers/application_controller.rb b/services/api/app/controllers/application_controller.rb index d09283d928..56925a3f1f 100644 --- a/services/api/app/controllers/application_controller.rb +++ b/services/api/app/controllers/application_controller.rb @@ -32,6 +32,7 @@ class ApplicationController < ActionController::Base ERROR_ACTIONS = [:render_error, :render_not_found] + around_filter :set_current_request_id before_filter :disable_api_methods before_filter :set_cors_headers before_filter :respond_with_json_by_default @@ -372,6 +373,23 @@ class ApplicationController < ActionController::Base end end + def set_current_request_id + req_id = request.headers['X-Request-Id'] + if !req_id || req_id.length < 1 || req_id.length > 1024 + # Client-supplied ID is either missing or too long to be + # considered friendly. + req_id = "req-" + Random::DEFAULT.rand(2**128).to_s(36)[0..19] + end + response.headers['X-Request-Id'] = Thread.current[:request_id] = req_id + yield + Thread.current[:request_id] = nil + end + + def append_info_to_payload(payload) + super + payload[:request_id] = response.headers['X-Request-Id'] + end + def disable_api_methods if Rails.configuration.disable_api_methods. include?(controller_name + "." + action_name) diff --git a/services/api/config/initializers/lograge.rb b/services/api/config/initializers/lograge.rb index fa37ada24b..cc7150f03a 100644 --- a/services/api/config/initializers/lograge.rb +++ b/services/api/config/initializers/lograge.rb @@ -8,13 +8,17 @@ Server::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], + } exceptions = %w(controller action format id) params = event.payload[:params].except(*exceptions) params_s = SafeJSON.dump(params) if params_s.length > Rails.configuration.max_request_log_params_size - { params_truncated: params_s[0..Rails.configuration.max_request_log_params_size] + "[...]" } + payload[:params_truncated] = params_s[0..Rails.configuration.max_request_log_params_size] + "[...]" else - { params: params } + payload[:params] = params end + payload end end diff --git a/services/api/test/functional/application_controller_test.rb b/services/api/test/functional/application_controller_test.rb index af090f9536..27b046e3c2 100644 --- a/services/api/test/functional/application_controller_test.rb +++ b/services/api/test/functional/application_controller_test.rb @@ -51,6 +51,28 @@ class ApplicationControllerTest < ActionController::TestCase check_error_token end + test "X-Request-Id header" do + authorize_with :spectator + get(:index) + assert_match /^req-[0-9a-zA-Z]{20}$/, response.headers['X-Request-Id'] + end + + # The response header is the one that gets logged, so this test also + # ensures we log the ID supplied in the request, if any. + test "X-Request-Id given by client" do + authorize_with :spectator + @request.headers['X-Request-Id'] = 'abcdefG' + get(:index) + assert_equal 'abcdefG', response.headers['X-Request-Id'] + end + + test "X-Request-Id given by client is ignored if too long" do + authorize_with :spectator + @request.headers['X-Request-Id'] = 'abcdefG' * 1000 + get(:index) + assert_match /^req-[0-9a-zA-Z]{20}$/, response.headers['X-Request-Id'] + end + ['foo', '', 'FALSE', 'TRUE', nil, [true], {a:true}, '"true"'].each do |bogus| test "bogus boolean parameter #{bogus.inspect} returns error" do @controller = Arvados::V1::GroupsController.new