Merge pull request #400 from puppetlabs/extra-atributes

Add additional data to spans in api/v1.rb

lib/vmpooler/api/helpers.rb

@@ -6,17 +6,24 @@ module Vmpooler
 
     module Helpers
 
+      def tracer
+        @tracer ||= OpenTelemetry.tracer_provider.tracer('api', Vmpooler::VERSION)
+      end
+
       def has_token?
         request.env['HTTP_X_AUTH_TOKEN'].nil? ? false : true
       end
 
       def valid_token?(backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           return false unless has_token?
 
           backend.exists?("vmpooler__token__#{request.env['HTTP_X_AUTH_TOKEN']}") ? true : false
         end
+      end
 
       def validate_token(backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           if valid_token?(backend)
             backend.hset("vmpooler__token__#{request.env['HTTP_X_AUTH_TOKEN']}", 'last', Time.now)
 
@@ -30,8 +37,10 @@ module Vmpooler
           headers['WWW-Authenticate'] = 'Basic realm="Authentication required"'
           halt 401, JSON.pretty_generate(result)
         end
+      end
 
       def validate_auth(backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           return if authorized?
 
           content_type :json
@@ -41,8 +50,10 @@ module Vmpooler
           headers['WWW-Authenticate'] = 'Basic realm="Authentication required"'
           halt 401, JSON.pretty_generate(result)
         end
+      end
 
       def authorized?
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           @auth ||= Rack::Auth::Basic::Request.new(request.env)
 
           if @auth.provided? and @auth.basic? and @auth.credentials
@@ -55,8 +66,19 @@ module Vmpooler
 
           return false
         end
+      end
 
       def authenticate_ldap(port, host, encryption_hash, user_object, base, username_str, password_str)
+        tracer.in_span(
+          "Vmpooler::API::Helpers.#{__method__}",
+          attributes: {
+            'net.peer.name' => host,
+            'net.peer.port' => port,
+            'net.transport' => 'ip_tcp',
+            'enduser.id' => username_str
+          },
+          kind: :client
+        ) do
           ldap = Net::LDAP.new(
             :host => host,
             :port => port,
@@ -73,8 +95,15 @@ module Vmpooler
 
           return false
         end
+      end
 
       def authenticate(auth, username_str, password_str)
+        tracer.in_span(
+          "Vmpooler::API::Helpers.#{__method__}",
+          attributes: {
+            'enduser.id' => username_str
+          }
+        ) do
           case auth['provider']
           when 'dummy'
             return (username_str != password_str)
@@ -114,8 +143,10 @@ module Vmpooler
             return false
           end
         end
+      end
 
       def export_tags(backend, hostname, tags)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           backend.pipelined do
             tags.each_pair do |tag, value|
               next if value.nil? or value.empty?
@@ -125,8 +156,10 @@ module Vmpooler
             end
           end
         end
+      end
 
       def filter_tags(tags)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           return unless Vmpooler::API.settings.config[:tagfilter]
 
           tags.each_pair do |tag, value|
@@ -137,6 +170,7 @@ module Vmpooler
 
           tags
         end
+      end
 
       def mean(list)
         s = list.map(&:to_f).reduce(:+).to_f
@@ -156,12 +190,15 @@ module Vmpooler
       end
 
       def get_task_times(backend, task, date_str)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           backend.hvals("vmpooler__#{task}__" + date_str).map(&:to_f)
         end
+      end
 
       # Takes the pools and a key to run scard on
       # returns an integer for the total count
       def get_total_across_pools_redis_scard(pools, key, backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           # using pipelined is much faster than querying each of the pools and adding them
           # as we get the result.
           res = backend.pipelined do
@@ -171,10 +208,12 @@ module Vmpooler
           end
           res.inject(0) { |m, x| m + x }.to_i
         end
+      end
 
       # Takes the pools and a key to run scard on
       # returns a hash with each pool name as key and the value being the count as integer
       def get_list_across_pools_redis_scard(pools, key, backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           # using pipelined is much faster than querying each of the pools and adding them
           # as we get the result.
           temp_hash = {}
@@ -188,10 +227,12 @@ module Vmpooler
           end
           temp_hash
         end
+      end
 
       # Takes the pools and a key to run hget on
       # returns a hash with each pool name as key and the value as string
       def get_list_across_pools_redis_hget(pools, key, backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           # using pipelined is much faster than querying each of the pools and adding them
           # as we get the result.
           temp_hash = {}
@@ -205,8 +246,10 @@ module Vmpooler
           end
           temp_hash
         end
+      end
 
       def get_capacity_metrics(pools, backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           capacity = {
               current: 0,
               total: 0,
@@ -225,8 +268,10 @@ module Vmpooler
 
           capacity
         end
+      end
 
       def get_queue_metrics(pools, backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           queue = {
               pending: 0,
               cloning: 0,
@@ -249,8 +294,10 @@ module Vmpooler
 
           queue
         end
+      end
 
       def get_tag_metrics(backend, date_str, opts = {})
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           opts = {:only => false}.merge(opts)
 
           tags = {}
@@ -275,8 +322,10 @@ module Vmpooler
 
           tags
         end
+      end
 
       def get_tag_summary(backend, from_date, to_date, opts = {})
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           opts = {:only => false}.merge(opts)
 
           result = {
@@ -305,8 +354,10 @@ module Vmpooler
 
           result
         end
+      end
 
       def get_task_metrics(backend, task_str, date_str, opts = {})
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           opts = {:bypool => false, :only => false}.merge(opts)
 
           task = {
@@ -371,8 +422,10 @@ module Vmpooler
 
           task
         end
+      end
 
       def get_task_summary(backend, task_str, from_date, to_date, opts = {})
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           opts = {:bypool => false, :only => false}.merge(opts)
 
           task_sym = task_str.to_sym
@@ -452,6 +505,7 @@ module Vmpooler
 
           result
         end
+      end
 
       def pool_index(pools)
         pools_hash = {}
@@ -464,12 +518,14 @@ module Vmpooler
       end
 
       def template_ready?(pool, backend)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           prepared_template = backend.hget('vmpooler__template__prepared', pool['name'])
           return false if prepared_template.nil?
           return true if pool['template'] == prepared_template
 
           return false
         end
+      end
 
       def is_integer?(x)
         Integer(x)
@@ -479,9 +535,19 @@ module Vmpooler
       end
 
       def open_socket(host, domain = nil, timeout = 1, port = 22, &_block)
+        tracer.in_span(
+          "Vmpooler::API::Helpers.#{__method__}",
+          attributes: {
+            'net.peer.port' => port,
+            'net.transport' => 'ip_tcp'
+          },
+          kind: :client
+        ) do
           Timeout.timeout(timeout) do
             target_host = host
             target_host = "#{host}.#{domain}" if domain
+            span = OpenTelemetry::Trace.current_span
+            span.set_attribute('net.peer.name', target_host)
             sock = TCPSocket.new target_host, port
             begin
               yield sock if block_given?
@@ -490,8 +556,10 @@ module Vmpooler
             end
           end
         end
+      end
 
       def vm_ready?(vm_name, domain = nil)
+        tracer.in_span("Vmpooler::API::Helpers.#{__method__}") do
           begin
             open_socket(vm_name, domain)
           rescue StandardError => _e
@@ -502,4 +570,5 @@ module Vmpooler
         end
       end
     end
+  end
 end

lib/vmpooler/api/v1.rb

@@ -49,6 +49,7 @@ module Vmpooler
     end
 
     def get_template_aliases(template)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = []
         aliases = Vmpooler::API.settings.config[:alias]
         if aliases
@@ -57,6 +58,7 @@ module Vmpooler
         end
         result
       end
+    end
 
     def get_pool_weights(template_backends)
       pool_index = pool_index(pools)
@@ -109,6 +111,7 @@ module Vmpooler
     end
 
     def fetch_single_vm(template)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         template_backends = [template]
         aliases = Vmpooler::API.settings.config[:alias]
         if aliases
@@ -165,16 +168,21 @@ module Vmpooler
           [nil, nil, nil]
         end
       end
+    end
 
     def return_vm_to_ready_state(template, vm)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         backend.srem("vmpooler__migrating__#{template}", vm)
         backend.hdel("vmpooler__active__#{template}", vm)
         backend.hdel("vmpooler__vm__#{vm}", 'checkout', 'token:token', 'token:user')
         backend.smove("vmpooler__running__#{template}", "vmpooler__ready__#{template}", vm)
       end
+    end
 
     def account_for_starting_vm(template, vm)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do |span|
         user = backend.hget("vmpooler__token__#{request.env['HTTP_X_AUTH_TOKEN']}", 'user')
+        span.set_attribute('enduser.id', user)
         has_token_result = has_token?
         backend.sadd("vmpooler__migrating__#{template}", vm)
         backend.hset("vmpooler__active__#{template}", vm, Time.now)
@@ -189,8 +197,10 @@ module Vmpooler
           end
         end
       end
+    end
 
     def update_result_hosts(result, template, vm)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result[template] ||= {}
         if result[template]['hostname']
           result[template]['hostname'] = Array(result[template]['hostname'])
@@ -199,8 +209,10 @@ module Vmpooler
           result[template]['hostname'] = vm
         end
       end
+    end
 
     def atomically_allocate_vms(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do |span|
         result = { 'ok' => false }
         failed = false
         vms = []
@@ -227,20 +239,30 @@ module Vmpooler
           vms.each do |(vmpool, vmname, _vmtemplate)|
             return_vm_to_ready_state(vmpool, vmname)
           end
+          span.add_event('error', attributes: {
+            'error.type' => 'Vmpooler::API::V1.atomically_allocate_vms',
+            'error.message' => '503 due to failing to allocate one or more vms'
+          })
           status 503
         else
+          vm_names = []
           vms.each do |(_vmpool, vmname, vmtemplate)|
             update_result_hosts(result, vmtemplate, vmname)
+            vm_names.append(vmname)
           end
 
+          span.set_attribute('vmpooler.vm_names', vm_names.join(',')) unless vm_names.empty?
+
           result['ok'] = true
           result['domain'] = config['domain'] if config['domain']
         end
 
         result
       end
+    end
 
     def component_to_test(match, labels_string)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         return if labels_string.nil?
 
         labels_string_parts = labels_string.split(',')
@@ -251,8 +273,11 @@ module Vmpooler
         end
         'none'
       end
+    end
 
     def update_user_metrics(operation, vmname)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do |span|
+        begin
           backend.multi
           backend.hget("vmpooler__vm__#{vmname}", 'tag:jenkins_build_url')
           backend.hget("vmpooler__vm__#{vmname}", 'token:user')
@@ -271,9 +296,7 @@ module Vmpooler
             if jenkins_build_url.include? 'litmus'
               # Very simple filter for Litmus jobs - just count them coming through for the moment.
               metrics.increment("usage_litmus.#{user}.#{operation}.#{poolname}")
-          return
+            else
-        end
-
               url_parts = jenkins_build_url.split('/')[2..-1]
               jenkins_instance = url_parts[0].gsub('.', '_')
               value_stream_parts = url_parts[2].split('_')
@@ -289,11 +312,21 @@ module Vmpooler
               metrics.increment("usage_branch_project.#{branch}.#{project}.#{operation}.#{poolname}")
               metrics.increment("usage_job_component.#{job_name}.#{component_to_test}.#{operation}.#{poolname}")
             end
+          end
         rescue StandardError => e
           puts 'd', "[!] [#{poolname}] failed while evaluating usage labels on '#{vmname}' with an error: #{e}"
+          span.record_exception(e)
+          span.status = OpenTelemetry::Trace::Status.error(e.to_s)
+          span.add_event('log', attributes: {
+            'log.severity' => 'debug',
+            'log.message' => "[#{poolname}] failed while evaluating usage labels on '#{vmname}' with an error: #{e}"
+          })
+        end
+      end
     end
 
     def reset_pool_size(poolname)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = { 'ok' => false }
 
         pool_index = pool_index(pools)
@@ -318,8 +351,10 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     def update_pool_size(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = { 'ok' => false }
 
         pool_index = pool_index(pools)
@@ -338,8 +373,10 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     def reset_pool_template(poolname)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = { 'ok' => false }
 
         pool_index_live = pool_index(pools)
@@ -365,8 +402,10 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     def update_pool_template(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = { 'ok' => false }
 
         pool_index = pool_index(pools)
@@ -385,8 +424,10 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     def reset_pool(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = { 'ok' => false }
 
         payload.each do |poolname, _count|
@@ -396,8 +437,10 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     def update_clone_target(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         result = { 'ok' => false }
 
         pool_index = pool_index(pools)
@@ -416,8 +459,10 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     def sync_pool_templates
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         pool_index = pool_index(pools)
         template_configs = backend.hgetall('vmpooler__config__template')
         template_configs&.each do |poolname, template|
@@ -426,8 +471,10 @@ module Vmpooler
           pools[pool_index[poolname]]['template'] = template
         end
       end
+    end
 
     def sync_pool_sizes
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         pool_index = pool_index(pools)
         poolsize_configs = backend.hgetall('vmpooler__config__poolsize')
         poolsize_configs&.each do |poolname, size|
@@ -436,8 +483,10 @@ module Vmpooler
           pools[pool_index[poolname]]['size'] = size.to_i
         end
       end
+    end
 
     def sync_clone_targets
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         pool_index = pool_index(pools)
         clone_target_configs = backend.hgetall('vmpooler__config__clone_target')
         clone_target_configs&.each do |poolname, clone_target|
@@ -446,8 +495,10 @@ module Vmpooler
           pools[pool_index[poolname]]['clone_target'] = clone_target
         end
       end
+    end
 
     def too_many_requested?(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         payload&.each do |poolname, count|
           next unless count.to_i > config['max_ondemand_instances_per_request']
 
@@ -456,14 +507,21 @@ module Vmpooler
         end
         false
       end
+    end
 
     def generate_ondemand_request(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do |span|
         result = { 'ok': false }
 
         requested_instances = payload.reject { |k, _v| k == 'request_id' }
         if too_many_requested?(requested_instances)
-        result['message'] = "requested amount of instances exceeds the maximum #{config['max_ondemand_instances_per_request']}"
+          e_message = "requested amount of instances exceeds the maximum #{config['max_ondemand_instances_per_request']}"
+          result['message'] = e_message
           status 403
+          span.add_event('error', attributes: {
+            'error.type' => 'Vmpooler::API::V1.generate_ondemand_request',
+            'error.message' => "403 due to #{e_message}"
+          })
           return result
         end
 
@@ -471,10 +529,16 @@ module Vmpooler
         request_id = payload['request_id']
         request_id ||= generate_request_id
         result['request_id'] = request_id
+        span.set_attribute('vmpooler.request_id', request_id)
 
         if backend.exists?("vmpooler__odrequest__#{request_id}")
-        result['message'] = "request_id '#{request_id}' has already been created"
+          e_message = "request_id '#{request_id}' has already been created"
+          result['message'] = e_message
           status 409
+          span.add_event('error', attributes: {
+            'error.type' => 'Vmpooler::API::V1.generate_ondemand_request',
+            'error.message' => "409 due to #{e_message}"
+          })
           metrics.increment('ondemandrequest_generate.duplicaterequests')
           return result
         end
@@ -492,9 +556,11 @@ module Vmpooler
 
         backend.hset("vmpooler__odrequest__#{request_id}", 'requested', platforms_string)
         if Vmpooler::API.settings.config[:auth] and has_token?
-        backend.hset("vmpooler__odrequest__#{request_id}", 'token:token', request.env['HTTP_X_AUTH_TOKEN'])
+          token_token = request.env['HTTP_X_AUTH_TOKEN']
-        backend.hset("vmpooler__odrequest__#{request_id}", 'token:user',
+          token_user = backend.hget("vmpooler__token__#{token_token}", 'user')
-                     backend.hget("vmpooler__token__#{request.env['HTTP_X_AUTH_TOKEN']}", 'user'))
+          backend.hset("vmpooler__odrequest__#{request_id}", 'token:token', token_token)
+          backend.hset("vmpooler__odrequest__#{request_id}", 'token:user', token_user)
+          span.set_attribute('enduser.id', token_user)
         end
 
         result['domain'] = config['domain'] if config['domain']
@@ -502,6 +568,7 @@ module Vmpooler
         metrics.increment('ondemandrequest_generate.success')
         result
       end
+    end
 
     def generate_request_id
       SecureRandom.uuid
@@ -813,6 +880,8 @@ module Vmpooler
           data = backend.hgetall(key)
 
           if data['user'] == Rack::Auth::Basic::Request.new(request.env).username
+            span = OpenTelemetry::Trace.current_span
+            span.set_attribute('enduser.id', data['user'])
             token = key.split('__').last
 
             result[token] ||= {}
@@ -899,6 +968,8 @@ module Vmpooler
 
         backend.hset("vmpooler__token__#{result['token']}", 'user', @auth.username)
         backend.hset("vmpooler__token__#{result['token']}", 'created', Time.now)
+        span = OpenTelemetry::Trace.current_span
+        span.set_attribute('enduser.id', @auth.username)
 
         status 200
         result['ok'] = true
@@ -946,6 +1017,8 @@ module Vmpooler
           status 404
         end
       rescue JSON::ParserError
+        span = OpenTelemetry::Trace.current_span
+        span.status = OpenTelemetry::Trace::Status.error('JSON payload could not be parsed')
         status 400
         result = {
           'ok' => false,
@@ -1031,6 +1104,7 @@ module Vmpooler
     end
 
     def extract_templates_from_query_params(params)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         payload = {}
 
         params.split('+').each do |template|
@@ -1040,16 +1114,20 @@ module Vmpooler
 
         payload
       end
+    end
 
     def invalid_templates(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         invalid = []
         payload.keys.each do |template|
           invalid << template unless pool_exists?(template)
         end
         invalid
       end
+    end
 
     def invalid_template_or_size(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         invalid = []
         payload.each do |pool, size|
           invalid << pool unless pool_exists?(pool)
@@ -1061,8 +1139,10 @@ module Vmpooler
         end
         invalid
       end
+    end
 
     def invalid_template_or_path(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         invalid = []
         payload.each do |pool, template|
           invalid << pool unless pool_exists?(pool)
@@ -1072,20 +1152,30 @@ module Vmpooler
         end
         invalid
       end
+    end
 
     def invalid_pool(payload)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do
         invalid = []
         payload.each do |pool, _clone_target|
           invalid << pool unless pool_exists?(pool)
         end
         invalid
       end
+    end
 
     def check_ondemand_request(request_id)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do |span|
+        span.set_attribute('vmpooler.request_id', request_id)
         result = { 'ok' => false }
         request_hash = backend.hgetall("vmpooler__odrequest__#{request_id}")
         if request_hash.empty?
-        result['message'] = "no request found for request_id '#{request_id}'"
+          e_message = "no request found for request_id '#{request_id}'"
+          result['message'] = e_message
+          span.add_event('error', attributes: {
+            'error.type' => 'Vmpooler::API::V1.check_ondemand_request',
+            'error.message' => e_message
+          })
           return result
         end
 
@@ -1133,13 +1223,21 @@ module Vmpooler
 
         result
       end
+    end
 
     def delete_ondemand_request(request_id)
+      tracer.in_span("Vmpooler::API::V1.#{__method__}") do |span|
+        span.set_attribute('vmpooler.request_id', request_id)
         result = { 'ok' => false }
 
         platforms = backend.hget("vmpooler__odrequest__#{request_id}", 'requested')
         unless platforms
-        result['message'] = "no request found for request_id '#{request_id}'"
+          e_message = "no request found for request_id '#{request_id}'"
+          result['message'] = e_message
+          span.add_event('error', attributes: {
+            'error.type' => 'Vmpooler::API::V1.delete_ondemand_request',
+            'error.message' => e_message
+          })
           return result
         end
 
@@ -1160,6 +1258,7 @@ module Vmpooler
         result['ok'] = true
         result
       end
+    end
 
     post "#{api_prefix}/vm/:template/?" do
       content_type :json
@@ -1303,7 +1402,10 @@ module Vmpooler
       if backend.exists?("vmpooler__vm__#{params[:hostname]}")
         begin
           jdata = JSON.parse(request.body.read)
-        rescue StandardError
+        rescue StandardError => e
+          span = OpenTelemetry::Trace.current_span
+          span.record_exception(e)
+          span.status = OpenTelemetry::Trace::Status.error(e.to_s)
           halt 400, JSON.pretty_generate(result)
         end
 
@@ -1559,6 +1661,9 @@ module Vmpooler
             status 404
           end
         rescue JSON::ParserError
+          span = OpenTelemetry::Trace.current_span
+          span.record_exception(e)
+          span.status = OpenTelemetry::Trace::Status.error('JSON payload could not be parsed')
           status 400
           result = {
             'ok' => false,