From 967105b97fee1918a32ce45c9568786c44be0618 Mon Sep 17 00:00:00 2001 From: Thorsten Eckel Date: Fri, 22 Jun 2018 16:36:20 +0200 Subject: [PATCH 1/3] - Reduced Sequencer logging to debug. - Added Setting to change sequencer log level for various actions. --- ...80622140531_sequencer_log_level_setting.rb | 42 +++++++++++++++++++ db/seeds/settings.rb | 35 ++++++++++++++++ lib/sequencer.rb | 21 ++++++++-- lib/sequencer/state.rb | 26 +++++++----- 4 files changed, 110 insertions(+), 14 deletions(-) create mode 100644 db/migrate/20180622140531_sequencer_log_level_setting.rb diff --git a/db/migrate/20180622140531_sequencer_log_level_setting.rb b/db/migrate/20180622140531_sequencer_log_level_setting.rb new file mode 100644 index 000000000..083011a06 --- /dev/null +++ b/db/migrate/20180622140531_sequencer_log_level_setting.rb @@ -0,0 +1,42 @@ +class SequencerLogLevelSetting < ActiveRecord::Migration[5.1] + def change + + # return if it's a new setup + return if !Setting.find_by(name: 'system_init_done') + + Setting.create_if_not_exists( + title: 'Sequencer log level', + name: 'sequencer_log_level', + area: 'Core', + description: 'Defines the log levels for various logging actions of the Sequencer.', + options: {}, + state: { + sequence: { + start_finish: :debug, + unit: :debug, + result: :debug, + }, + state: { + optional: :debug, + set: :debug, + get: :debug, + attribute_initialization: { + start_finish: :debug, + attributes: :debug, + }, + parameter_initialization: { + parameters: :debug, + start_finish: :debug, + unused: :debug, + }, + expectations_initialization: :debug, + cleanup: { + start_finish: :debug, + remove: :debug, + } + } + }, + frontend: false, + ) + end +end diff --git a/db/seeds/settings.rb b/db/seeds/settings.rb index 93e98bf1e..7166fa0d2 100644 --- a/db/seeds/settings.rb +++ b/db/seeds/settings.rb @@ -2938,6 +2938,41 @@ Setting.create_if_not_exists( frontend: false ) +Setting.create_if_not_exists( + title: 'Sequencer log level', + name: 'sequencer_log_level', + area: 'Core', + description: 'Defines the log levels for various logging actions of the Sequencer.', + options: {}, + state: { + sequence: { + start_finish: :debug, + unit: :debug, + result: :debug, + }, + state: { + optional: :debug, + set: :debug, + get: :debug, + attribute_initialization: { + start_finish: :debug, + attributes: :debug, + }, + parameter_initialization: { + parameters: :debug, + start_finish: :debug, + unused: :debug, + }, + expectations_initialization: :debug, + cleanup: { + start_finish: :debug, + remove: :debug, + } + } + }, + frontend: false, +) + Setting.create_if_not_exists( title: 'Time Accounting', name: 'time_accounting', diff --git a/lib/sequencer.rb b/lib/sequencer.rb index a0a662877..05059257e 100644 --- a/lib/sequencer.rb +++ b/lib/sequencer.rb @@ -25,6 +25,17 @@ class Sequencer new(sequence, *args).process end + # Provides the log level definition for the requested Sequencer component. + # + # @example + # Sequencer.log_level_for(:state) + # #=> { get: :debug, set: :debug, ... } + # + # @return [ActiveSupport::HashWithIndifferentAcces] the log level definition + def self.log_level_for(component) + Setting.get('sequencer_log_level').with_indifferent_access[component] + end + # Initializes a new Sequencer instance for the given Sequence with parameters and expecting result. # # @example @@ -55,13 +66,13 @@ class Sequencer # # @return [Hash{Symbol => Object}] the final result state attributes and values def process - log_start_finish(:info, "Sequence '#{sequence.name}'") do + log_start_finish(log_level[:start_finish], "Sequence '#{sequence.name}'") do sequence.units.each_with_index do |unit, index| state.process do - log_start_finish(:info, "Sequence '#{sequence.name}' Unit '#{unit.name}' (index: #{index})") do + log_start_finish(log_level[:unit], "Sequence '#{sequence.name}' Unit '#{unit.name}' (index: #{index})") do unit.process(state) end end @@ -69,7 +80,7 @@ class Sequencer end state.to_h.tap do |result| - logger.debug { "Returning Sequence '#{sequence.name}' result: #{result.inspect}" } + logger.public_send(log_level[:result]) { "Returning Sequence '#{sequence.name}' result: #{result.inspect}" } end end @@ -80,4 +91,8 @@ class Sequencer parameters: @parameters, expecting: @expecting) end + + def log_level + @log_level ||= self.class.log_level_for(:sequence) + end end diff --git a/lib/sequencer/state.rb b/lib/sequencer/state.rb index 62736dfc9..5f8915dcc 100644 --- a/lib/sequencer/state.rb +++ b/lib/sequencer/state.rb @@ -88,7 +88,7 @@ class Sequencer # @return [Object, nil] def optional(attribute) return get(attribute) if @attributes.known?(attribute) - logger.debug { "Access to unknown optional attribute '#{attribute}'." } + logger.public_send(log_level[:optional]) { "Access to unknown optional attribute '#{attribute}'." } nil end @@ -184,13 +184,13 @@ class Sequencer end def set(attribute, value) - logger.debug { "Setting '#{attribute}' value (#{value.class.name}): #{value.inspect}" } + logger.public_send(log_level[:set]) { "Setting '#{attribute}' value (#{value.class.name}): #{value.inspect}" } @values[attribute] = value end def get(attribute) value = @values[attribute] - logger.debug { "Getting '#{attribute}' value (#{value.class.name}): #{value.inspect}" } + logger.public_send(log_level[:get]) { "Getting '#{attribute}' value (#{value.class.name}): #{value.inspect}" } value end @@ -207,21 +207,21 @@ class Sequencer end def initialize_attributes(units) - log_start_finish(:debug, 'Attributes lifespan initialization') do + log_start_finish(log_level[:attribute_initialization][:start_finish], 'Attributes lifespan initialization') do @attributes = Sequencer::Units::Attributes.new(units.declarations) - logger.debug { "Attributes lifespan: #{@attributes.inspect}" } + logger.public_send(log_level[:attribute_initialization][:attributes]) { "Attributes lifespan: #{@attributes.inspect}" } end end def initialize_parameters(parameters) - logger.debug { "Initializing Sequencer::State with initial parameters: #{parameters.inspect}" } + logger.public_send(log_level[:parameter_initialization][:parameters]) { "Initializing Sequencer::State with initial parameters: #{parameters.inspect}" } - log_start_finish(:debug, 'Attribute value provisioning check and initialization') do + log_start_finish(log_level[:parameter_initialization][:start_finish], 'Attribute value provisioning check and initialization') do @attributes.each do |identifier, attribute| if !attribute.will_be_used? - logger.debug { "Attribute '#{identifier}' is provided by Unit(s) but never used." } + logger.public_send(log_level[:parameter_initialization][:unused]) { "Attribute '#{identifier}' is provided by Unit(s) but never used." } next end @@ -250,23 +250,27 @@ class Sequencer def initialize_expectations(expected_attributes) expected_attributes.each do |identifier| - logger.debug { "Adding attribute '#{identifier}' to the list of expected result attributes." } + logger.public_send(log_level[:expectations_initialization]) { "Adding attribute '#{identifier}' to the list of expected result attributes." } @attributes[identifier].to = @result_index end end def cleanup - log_start_finish(:info, "State cleanup of Unit #{unit.name} (index: #{@index})") do + log_start_finish(log_level[:cleanup][:start_finish], "State cleanup of Unit #{unit.name} (index: #{@index})") do @attributes.delete_if do |identifier, attribute| remove = !attribute.will_be_used? remove ||= attribute.to <= @index if remove && attribute.will_be_used? - logger.debug { "Removing unneeded attribute '#{identifier}': #{@values[identifier].inspect}" } + logger.public_send(log_level[:cleanup][:remove]) { "Removing unneeded attribute '#{identifier}': #{@values[identifier].inspect}" } end remove end end end + + def log_level + @log_level ||= Sequencer.log_level_for(:state) + end end end From 295844c72e32ae9f460e24e3f9da7def91be5db8 Mon Sep 17 00:00:00 2001 From: Thorsten Eckel Date: Tue, 26 Jun 2018 09:26:19 +0200 Subject: [PATCH 2/3] Fixed race condition: AJAX data fetch requests re-set sessions that should get deleted by logout request. --- app/controllers/sessions_controller.rb | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/app/controllers/sessions_controller.rb b/app/controllers/sessions_controller.rb index d65a9711c..fef102c5f 100644 --- a/app/controllers/sessions_controller.rb +++ b/app/controllers/sessions_controller.rb @@ -114,12 +114,13 @@ class SessionsController < ApplicationController # "Delete" a login, aka "log the user out" def destroy + reset_session + # Remove the user id from the session @_current_user = nil # reset session request.env['rack.session.options'][:expire_after] = nil - session.clear render json: {} end From f1296f65004610dd4f3e2ed93259ce489eb26c22 Mon Sep 17 00:00:00 2001 From: Thorsten Eckel Date: Wed, 27 Jun 2018 16:46:45 +0200 Subject: [PATCH 3/3] Stablized tests: Organization select in user create modal is stale. --- test/browser_test_helper.rb | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/test/browser_test_helper.rb b/test/browser_test_helper.rb index e34d43f31..2095ce1f5 100644 --- a/test/browser_test_helper.rb +++ b/test/browser_test_helper.rb @@ -2748,12 +2748,20 @@ wait untill text in selector disabppears element = instance.find_elements(css: '.modal input.searchableSelect-main')[0] element.clear element.send_keys(data[:organization]) - target = nil - until target - sleep 0.5 - target = instance.find_elements(css: ".modal li[title='#{data[:organization]}']")[0] + + begin + retries ||= 0 + target = nil + until target + sleep 0.5 + target = instance.find_elements(css: ".modal li[title='#{data[:organization]}']")[0] + end + target.click() + rescue Selenium::WebDriver::Error::StaleElementReferenceError + sleep retries + retries += 1 + retry if retries < 3 end - target.click() end check( browser: instance,