From 85ff3f7022e52465b24a0e8ca34f74b15b6e2ac5 Mon Sep 17 00:00:00 2001 From: John O'Connor Date: Fri, 26 Jun 2020 20:49:17 +0100 Subject: [PATCH] (MAINT) Add optional API Request Logging This was partially an exercise to use middleware, but also to enable basic logging for the API by logging all the API calls to the logger. --- bin/vmpooler | 4 +-- docs/configuration.md | 7 ++++ lib/vmpooler.rb | 1 + lib/vmpooler/api.rb | 5 ++- lib/vmpooler/api/request_logger.rb | 20 ++++++++++++ .../metrics/promstats/collector_middleware.rb | 14 ++++---- spec/integration/api/v1/config_spec.rb | 2 +- spec/integration/api/v1/ondemandvm_spec.rb | 2 +- spec/integration/api/v1/poolreset.rb | 2 +- spec/integration/api/v1/status_spec.rb | 2 +- spec/integration/api/v1/token_spec.rb | 32 +++++++++++++++---- spec/integration/api/v1/vm_hostname_spec.rb | 2 +- spec/integration/api/v1/vm_spec.rb | 2 +- spec/integration/api/v1/vm_template_spec.rb | 2 +- spec/integration/dashboard_spec.rb | 5 ++- spec/unit/env_config.rb | 1 + vmpooler.yaml.example | 6 ++++ 17 files changed, 85 insertions(+), 24 deletions(-) create mode 100644 lib/vmpooler/api/request_logger.rb diff --git a/bin/vmpooler b/bin/vmpooler index 44922ab..139d79c 100755 --- a/bin/vmpooler +++ b/bin/vmpooler @@ -27,13 +27,13 @@ end if torun.include? :api api = Thread.new do redis = Vmpooler.new_redis(redis_host, redis_port, redis_password) - Vmpooler::API.execute(torun, config, redis, metrics) + Vmpooler::API.execute(torun, config, redis, metrics, logger) end torun_threads << api elsif metrics.respond_to?(:setup_prometheus_metrics) # Run the cut down API - Prometheus Metrics only. prometheus_only_api = Thread.new do - Vmpooler::API.execute(torun, config, nil, metrics) + Vmpooler::API.execute(torun, config, nil, metrics, logger) end torun_threads << prometheus_only_api end diff --git a/docs/configuration.md b/docs/configuration.md index 4846b94..d49debb 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -191,6 +191,13 @@ https://jenkins.example.com/job/platform\_puppet-agent-extra\_puppet-agent-integ Expects a boolean value (optional; default: false) +### REQUEST\_LOGGER + +Enable API request logging to the logger +When enabled all requests to the API are written to the standard logger. +Expects a boolean value +(optional; default: false) + ### EXTRA\_CONFIG Specify additional application configuration files diff --git a/lib/vmpooler.rb b/lib/vmpooler.rb index 20eb26b..276bfa7 100644 --- a/lib/vmpooler.rb +++ b/lib/vmpooler.rb @@ -84,6 +84,7 @@ module Vmpooler parsed_config[:config]['experimental_features'] = ENV['EXPERIMENTAL_FEATURES'] if ENV['EXPERIMENTAL_FEATURES'] parsed_config[:config]['purge_unconfigured_folders'] = ENV['PURGE_UNCONFIGURED_FOLDERS'] if ENV['PURGE_UNCONFIGURED_FOLDERS'] parsed_config[:config]['usage_stats'] = ENV['USAGE_STATS'] if ENV['USAGE_STATS'] + parsed_config[:config]['request_logger'] = ENV['REQUEST_LOGGER'] if ENV['REQUEST_LOGGER'] parsed_config[:redis] = parsed_config[:redis] || {} parsed_config[:redis]['server'] = ENV['REDIS_SERVER'] || parsed_config[:redis]['server'] || 'localhost' diff --git a/lib/vmpooler/api.rb b/lib/vmpooler/api.rb index dd527ac..9ffe386 100644 --- a/lib/vmpooler/api.rb +++ b/lib/vmpooler/api.rb @@ -9,7 +9,7 @@ module Vmpooler # Load dashboard components require 'vmpooler/dashboard' - def self.execute(torun, config, redis, metrics) + def self.execute(torun, config, redis, metrics, logger) self.settings.set :config, config self.settings.set :redis, redis unless redis.nil? self.settings.set :metrics, metrics @@ -43,6 +43,9 @@ module Vmpooler end if torun.include? :api + # Enable API request logging only if required + use Vmpooler::API::RequestLogger, logger: logger if config[:config]['request_logger'] + use Vmpooler::Dashboard use Vmpooler::API::Dashboard use Vmpooler::API::Reroute diff --git a/lib/vmpooler/api/request_logger.rb b/lib/vmpooler/api/request_logger.rb new file mode 100644 index 0000000..d31c190 --- /dev/null +++ b/lib/vmpooler/api/request_logger.rb @@ -0,0 +1,20 @@ +# frozen_string_literal: true + +module Vmpooler + class API + class RequestLogger + attr_reader :app + + def initialize(app, options = {}) + @app = app + @logger = options[:logger] + end + + def call(env) + status, headers, body = @app.call(env) + @logger.log('s', "[ ] API: Method: #{env['REQUEST_METHOD']}, Status: #{status}, Path: #{env['PATH_INFO']}, Body: #{body}") + [status, headers, body] + end + end + end +end diff --git a/lib/vmpooler/metrics/promstats/collector_middleware.rb b/lib/vmpooler/metrics/promstats/collector_middleware.rb index c05c866..bfaa7a0 100644 --- a/lib/vmpooler/metrics/promstats/collector_middleware.rb +++ b/lib/vmpooler/metrics/promstats/collector_middleware.rb @@ -6,9 +6,10 @@ # # The code was also failing Rubocop on PR check, so have addressed all the offenses. # -# The method strip_ids_from_path has been adapted to add a match for hostnames in paths -# to replace with a single ":hostname" string to avoid proliferation of stat lines for -# each new vm hostname deleted, modified or otherwise queried. +# The method strip_hostnames_from_path (originally strip_ids_from_path) has been adapted +# to add a match for hostnames in paths # to replace with a single ":hostname" string to +# avoid # proliferation of stat lines for # each new vm hostname deleted, modified or +# otherwise queried. require 'benchmark' require 'prometheus/client' @@ -91,12 +92,12 @@ module Vmpooler counter_labels = { code: code, method: env['REQUEST_METHOD'].downcase, - path: strip_ids_from_path(env['PATH_INFO']) + path: strip_hostnames_from_path(env['PATH_INFO']) } duration_labels = { method: env['REQUEST_METHOD'].downcase, - path: strip_ids_from_path(env['PATH_INFO']) + path: strip_hostnames_from_path(env['PATH_INFO']) } @requests.increment(labels: counter_labels) @@ -105,10 +106,11 @@ module Vmpooler nil end - def strip_ids_from_path(path) + def strip_hostnames_from_path(path) # Custom for /vm path - so we just collect aggrate stats for all usage along this one # path. Custom counters are then added more specific endpoints in v1.rb # Since we aren't parsing UID/GIDs as in the original example, these are removed. + # Similarly, request IDs are also stripped from the /ondemand path. path .gsub(%r{/vm/.+$}, '/vm') .gsub(%r{/ondemand/.+$}, '/ondemand') diff --git a/spec/integration/api/v1/config_spec.rb b/spec/integration/api/v1/config_spec.rb index 6bcd385..79874c8 100644 --- a/spec/integration/api/v1/config_spec.rb +++ b/spec/integration/api/v1/config_spec.rb @@ -40,7 +40,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, metrics) + app.execute([:api], config, redis, metrics, nil) app.settings.set :config, auth: false create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) end diff --git a/spec/integration/api/v1/ondemandvm_spec.rb b/spec/integration/api/v1/ondemandvm_spec.rb index 0af5bb1..37b315c 100644 --- a/spec/integration/api/v1/ondemandvm_spec.rb +++ b/spec/integration/api/v1/ondemandvm_spec.rb @@ -43,7 +43,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, metrics) + app.execute([:api], config, redis, metrics, nil) app.settings.set :config, auth: false app.settings.set :checkoutlock, checkoutlock create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) diff --git a/spec/integration/api/v1/poolreset.rb b/spec/integration/api/v1/poolreset.rb index c393138..dfb7f18 100644 --- a/spec/integration/api/v1/poolreset.rb +++ b/spec/integration/api/v1/poolreset.rb @@ -37,7 +37,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, metrics) + app.execute([:api], config, redis, metrics, nil) app.settings.set :config, auth: false create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) end diff --git a/spec/integration/api/v1/status_spec.rb b/spec/integration/api/v1/status_spec.rb index 7c22ebf..76e65df 100644 --- a/spec/integration/api/v1/status_spec.rb +++ b/spec/integration/api/v1/status_spec.rb @@ -40,7 +40,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, nil) + app.execute([:api], config, redis, nil, nil) app.settings.set :config, auth: false create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) end diff --git a/spec/integration/api/v1/token_spec.rb b/spec/integration/api/v1/token_spec.rb index d4f33f4..72ab060 100644 --- a/spec/integration/api/v1/token_spec.rb +++ b/spec/integration/api/v1/token_spec.rb @@ -18,16 +18,21 @@ describe Vmpooler::API::V1 do describe '/token' do let(:prefix) { '/api/v1' } let(:current_time) { Time.now } - let(:config) { { } } + let(:config) { { + config: {} + } } before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, nil) + app.execute([:api], config, redis, nil, nil) end describe 'GET /token' do context '(auth not configured)' do - let(:config) { { auth: false } } + let(:config) { { + config: {}, + auth: false + } } it 'returns a 404' do get "#{prefix}/token" @@ -38,6 +43,7 @@ describe Vmpooler::API::V1 do context '(auth configured)' do let(:config) { { + config: {}, auth: { 'provider' => 'dummy' } @@ -65,7 +71,10 @@ describe Vmpooler::API::V1 do describe 'POST /token' do context '(auth not configured)' do - let(:config) { { auth: false } } + let(:config) { { + config: {}, + auth: false + } } it 'returns a 404' do post "#{prefix}/token" @@ -76,6 +85,7 @@ describe Vmpooler::API::V1 do context '(auth configured)' do let(:config) { { + config: {}, auth: { 'provider' => 'dummy' } @@ -106,7 +116,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, nil) + app.execute([:api], config, redis, nil, nil) app.settings.set :config, config app.settings.set :redis, redis end @@ -118,7 +128,10 @@ describe Vmpooler::API::V1 do describe 'GET /token/:token' do context '(auth not configured)' do - let(:config) { { auth: false } } + let(:config) { { + config: {}, + auth: false + } } it 'returns a 404' do get "#{prefix}/token/this" @@ -128,6 +141,7 @@ describe Vmpooler::API::V1 do context '(auth configured)' do let(:config) { { + config: {}, auth: true, pools: [ {'name' => 'pool1', 'size' => 5} @@ -150,7 +164,10 @@ describe Vmpooler::API::V1 do describe 'DELETE /token/:token' do context '(auth not configured)' do - let(:config) { { auth: false } } + let(:config) { { + config: {}, + auth: false + } } it 'returns a 404' do delete "#{prefix}/token/this" @@ -161,6 +178,7 @@ describe Vmpooler::API::V1 do context '(auth configured)' do let(:config) { { + config: {}, auth: { 'provider' => 'dummy' } diff --git a/spec/integration/api/v1/vm_hostname_spec.rb b/spec/integration/api/v1/vm_hostname_spec.rb index ba2b460..ff5f7a3 100644 --- a/spec/integration/api/v1/vm_hostname_spec.rb +++ b/spec/integration/api/v1/vm_hostname_spec.rb @@ -43,7 +43,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, metrics) + app.execute([:api], config, redis, metrics, nil) create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) end diff --git a/spec/integration/api/v1/vm_spec.rb b/spec/integration/api/v1/vm_spec.rb index f6b2cc9..0d06585 100644 --- a/spec/integration/api/v1/vm_spec.rb +++ b/spec/integration/api/v1/vm_spec.rb @@ -40,7 +40,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, metrics) + app.execute([:api], config, redis, metrics, nil) app.settings.set :config, auth: false app.settings.set :checkoutlock, checkoutlock create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) diff --git a/spec/integration/api/v1/vm_template_spec.rb b/spec/integration/api/v1/vm_template_spec.rb index a306d87..25c0fbd 100644 --- a/spec/integration/api/v1/vm_template_spec.rb +++ b/spec/integration/api/v1/vm_template_spec.rb @@ -41,7 +41,7 @@ describe Vmpooler::API::V1 do before(:each) do expect(app).to receive(:run!).once - app.execute([:api], config, redis, metrics) + app.execute([:api], config, redis, metrics, nil) app.settings.set :config, auth: false app.settings.set :checkoutlock, checkoutlock create_token('abcdefghijklmnopqrstuvwxyz012345', 'jdoe', current_time) diff --git a/spec/integration/dashboard_spec.rb b/spec/integration/dashboard_spec.rb index 8d87ac4..b0abbea 100644 --- a/spec/integration/dashboard_spec.rb +++ b/spec/integration/dashboard_spec.rb @@ -18,6 +18,7 @@ describe Vmpooler::API do describe 'Dashboard' do let(:config) { { + config: {}, pools: [ {'name' => 'pool1', 'size' => 5} ], @@ -26,7 +27,7 @@ describe Vmpooler::API do before(:each) do expect(app).to receive(:run!) - app.execute([:api], config, redis, nil) + app.execute([:api], config, redis, nil, nil) app.settings.set :config, auth: false end @@ -64,6 +65,7 @@ describe Vmpooler::API do describe '/dashboard/stats/vmpooler/pool' do let(:config) { { + config: {}, pools: [ {'name' => 'pool1', 'size' => 5}, {'name' => 'pool2', 'size' => 1} @@ -134,6 +136,7 @@ describe Vmpooler::API do describe '/dashboard/stats/vmpooler/running' do let(:config) { { + config: {}, pools: [ {'name' => 'pool-1', 'size' => 5}, {'name' => 'pool-2', 'size' => 1}, diff --git a/spec/unit/env_config.rb b/spec/unit/env_config.rb index 91d79f6..0eba2fb 100644 --- a/spec/unit/env_config.rb +++ b/spec/unit/env_config.rb @@ -30,6 +30,7 @@ describe 'Vmpooler' do ['experimental_features', test_bool, nil], ['purge_unconfigured_folders', test_bool, nil], ['usage_stats', test_bool, nil], + ['request_logger', test_bool, nil], ['extra_config', test_string, nil], ] diff --git a/vmpooler.yaml.example b/vmpooler.yaml.example index d596724..6120c50 100644 --- a/vmpooler.yaml.example +++ b/vmpooler.yaml.example @@ -509,6 +509,12 @@ # Expects a boolean value # (optional; default: false) # +# - request_logger +# Enable API Request logging to the logger +# When enabled all requests to the API are written to the standard logger. +# Expects a boolean value +# (optional; default: false) +# # - max_lifetime_upper_limit # Sets a lifetime upper limit (in hours) for how long the vm lifetime can be set via the API. Lifetime can be set and extended # so this configuration is used to enforce an upper limit to both the initial lifetime request and/or the extended