12167: Improve request-id tracking in Workbench.
authorTom Clegg <tclegg@veritasgenetics.com>
Tue, 31 Oct 2017 03:07:52 +0000 (23:07 -0400)
committerTom Clegg <tclegg@veritasgenetics.com>
Tue, 31 Oct 2017 20:37:53 +0000 (16:37 -0400)
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 <tclegg@veritasgenetics.com>

apps/workbench/Gemfile.lock
apps/workbench/app/controllers/application_controller.rb
apps/workbench/app/models/arvados_api_client.rb
apps/workbench/config/initializers/lograge.rb
apps/workbench/test/controllers/application_controller_test.rb

index 34db9cd71c9ef61187b8593a111e76fa410538ea..8ffc1d33b50c8175fe3804f281390dc09f67d2f8 100644 (file)
@@ -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
index 5acf9a73513ecfa41b61ace597e2fda2059ecc7e..8d9e8578c529a618678f9a8136d8472ae81021ff 100644 (file)
@@ -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: '<timestamp>-<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
index 8638b0aa510b08cab457cf115fa9d42163ea6bd9..ac2fe3a97629f8ec957b6a99b21f779b9d363e63 100644 (file)
@@ -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
index 321bd037f98d58fd0fe9c860fc0c3f40ab771bc8..6e7f165c135b2132bcaef1e89ccac6890f585ed4 100644 (file)
@@ -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
index d38e88f2a60047545d2828664a45428ca4385e21..0bcf7a19fba5a7b22de2e5100098da1b1d2c189b 100644 (file)
@@ -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",