(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

@@ -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

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

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'

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

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

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
+# The method strip_hostnames_from_path (originally strip_ids_from_path) has been adapted
-# to replace with a single ":hostname" string to avoid proliferation of stat lines for
+# to add a match for hostnames in paths # to replace with a single ":hostname" string to
-# each new vm hostname deleted, modified or otherwise queried.
+# 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')

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

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)

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

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

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'
             }

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
 

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)

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)

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},

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],
       ]
 

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