From 0903d47c5f2f0ed0c589305b3c4829f3c45485dc Mon Sep 17 00:00:00 2001 From: Anthony Dmitriyev Date: Tue, 29 Jun 2021 18:57:16 +0100 Subject: [PATCH 1/2] Detailed logger to replace the default one --- lib/cadence/configuration.rb | 4 +-- lib/cadence/logger.rb | 26 ++++++++++++++ spec/unit/lib/cadence/logger_spec.rb | 51 ++++++++++++++++++++++++++++ 3 files changed, 79 insertions(+), 2 deletions(-) create mode 100644 lib/cadence/logger.rb create mode 100644 spec/unit/lib/cadence/logger_spec.rb diff --git a/lib/cadence/configuration.rb b/lib/cadence/configuration.rb index 55cd31bf..6d39fec2 100644 --- a/lib/cadence/configuration.rb +++ b/lib/cadence/configuration.rb @@ -1,4 +1,4 @@ -require 'logger' +require 'cadence/logger' require 'cadence/metrics_adapters/null' module Cadence @@ -24,7 +24,7 @@ class Configuration def initialize @connection_type = :thrift - @logger = Logger.new(STDOUT, progname: 'cadence_client') + @logger = Cadence::Logger.new(STDOUT, progname: 'cadence_client') @metrics_adapter = MetricsAdapters::Null.new @timeouts = DEFAULT_TIMEOUTS @domain = DEFAULT_DOMAIN diff --git a/lib/cadence/logger.rb b/lib/cadence/logger.rb new file mode 100644 index 00000000..a3d2b4ec --- /dev/null +++ b/lib/cadence/logger.rb @@ -0,0 +1,26 @@ +require 'logger' +require 'oj' + +module Cadence + class Logger < ::Logger + SEVERITIES = %i[debug info warn error fatal unknown].freeze + + SEVERITIES.each do |severity| + define_method(severity) do |message, details = {}| + super("#{message} #{format_details(details)}") + end + end + + def log(severity, message, details = {}) + add(severity, "#{message} #{format_details(details)}") + end + + private + + def format_details(details) + return '' if details.empty? + + Oj.dump(details, mode: :strict) + end + end +end diff --git a/spec/unit/lib/cadence/logger_spec.rb b/spec/unit/lib/cadence/logger_spec.rb new file mode 100644 index 00000000..5a8dceac --- /dev/null +++ b/spec/unit/lib/cadence/logger_spec.rb @@ -0,0 +1,51 @@ +require 'cadence/logger' + +describe Cadence::Logger do + subject { described_class.new(STDERR) } + + describe 'logging' do + before { allow(subject).to receive(:add) } + + it 'accepts data argument to log method' do + subject.log(Logger::DEBUG, 'test', a: 1) + + expect(subject).to have_received(:add).with(Logger::DEBUG, 'test {"a":1}') + end + + it 'accepts data argument to debug method' do + subject.debug('test', a: 1) + + expect(subject).to have_received(:add).with(Logger::DEBUG, nil, 'test {"a":1}') + end + + it 'accepts data argument to info method' do + subject.info('test', a: 1) + + expect(subject).to have_received(:add).with(Logger::INFO, nil, 'test {"a":1}') + end + + it 'accepts data argument to warn method' do + subject.warn('test', a: 1) + + expect(subject).to have_received(:add).with(Logger::WARN, nil, 'test {"a":1}') + end + + it 'accepts data argument to error method' do + subject.error('test', a: 1) + + expect(subject).to have_received(:add).with(Logger::ERROR, nil, 'test {"a":1}') + end + + it 'accepts data argument to fatal method' do + subject.fatal('test', a: 1) + + expect(subject).to have_received(:add).with(Logger::FATAL, nil, 'test {"a":1}') + end + + it 'accepts data argument to unknown method' do + subject.unknown('test', a: 1) + + expect(subject).to have_received(:add).with(Logger::UNKNOWN, nil, 'test {"a":1}') + end + end +end From ba2a795df766b5735bdee60d46921233efde8afb Mon Sep 17 00:00:00 2001 From: Anthony Dmitriyev Date: Tue, 29 Jun 2021 18:58:00 +0100 Subject: [PATCH 2/2] Use detailed logger in internal logging --- examples/bin/reset | 2 +- examples/bin/trigger | 2 +- examples/middleware/logging_middleware.rb | 15 ++++++++++++--- lib/cadence/activity/poller.rb | 6 +++--- lib/cadence/saga/concern.rb | 2 +- lib/cadence/workflow.rb | 2 +- lib/cadence/workflow/poller.rb | 6 +++--- lib/cadence/workflow/replay_aware_logger.rb | 8 ++++---- spec/unit/lib/cadence/activity/poller_spec.rb | 2 +- spec/unit/lib/cadence/saga/concern_spec.rb | 4 ++-- spec/unit/lib/cadence/workflow/poller_spec.rb | 2 +- 11 files changed, 30 insertions(+), 21 deletions(-) diff --git a/examples/bin/reset b/examples/bin/reset index 24fa2e94..c3879ea9 100755 --- a/examples/bin/reset +++ b/examples/bin/reset @@ -4,4 +4,4 @@ require_relative '../init' domain, workflow_id, run_id = ARGV run_id = Cadence.reset_workflow(domain, workflow_id, run_id) -Cadence.logger.info "Reset workflow: #{run_id}" +Cadence.logger.info 'Workflow workflow', workflow_id: workflow_id, new_run_id: run_id diff --git a/examples/bin/trigger b/examples/bin/trigger index 70431012..826a81f4 100755 --- a/examples/bin/trigger +++ b/examples/bin/trigger @@ -11,4 +11,4 @@ workflow_id = SecureRandom.uuid input = args.map { |arg| Integer(arg) rescue arg } run_id = Cadence.start_workflow(workflow_class, *input, options: { workflow_id: workflow_id }) -Cadence.logger.info "Started workflow: #{run_id} / #{workflow_id}" +Cadence.logger.info 'Workflow started', workflow_id: workflow_id, run_id: run_id diff --git a/examples/middleware/logging_middleware.rb b/examples/middleware/logging_middleware.rb index 8661693d..050b05e1 100644 --- a/examples/middleware/logging_middleware.rb +++ b/examples/middleware/logging_middleware.rb @@ -4,14 +4,15 @@ def initialize(app_name) end def call(metadata) + type = type_from(metadata) entity_name = name_from(metadata) - Cadence.logger.info("[#{app_name}]: Started #{entity_name}") + Cadence.logger.debug("[#{app_name}]: #{type} for #{entity_name} started") yield - Cadence.logger.info("[#{app_name}]: Finished #{entity_name}") + Cadence.logger.debug("[#{app_name}]: #{type} for #{entity_name} finished") rescue StandardError => e - Cadence.logger.error("[#{app_name}]: Error #{entity_name}") + Cadence.logger.error("[#{app_name}]: #{type} for #{entity_name} error") raise end @@ -20,6 +21,14 @@ def call(metadata) attr_reader :app_name + def type_from(metadata) + if metadata.activity? + 'Activity task' + elsif metadata.decision? + 'Decision task' + end + end + def name_from(metadata) if metadata.activity? metadata.name diff --git a/lib/cadence/activity/poller.rb b/lib/cadence/activity/poller.rb index a51966d3..7988be29 100644 --- a/lib/cadence/activity/poller.rb +++ b/lib/cadence/activity/poller.rb @@ -27,7 +27,7 @@ def start def stop @shutting_down = true - Cadence.logger.info('Shutting down activity poller') + Cadence.logger.info('Shutting down activity poller', domain: domain, task_list: task_list) end def wait @@ -58,7 +58,7 @@ def poll_loop time_diff_ms = ((Time.now - last_poll_time) * 1000).round Cadence.metrics.timing('activity_poller.time_since_last_poll', time_diff_ms, metrics_tags) - Cadence.logger.debug("Polling for activity tasks (#{domain} / #{task_list})") + Cadence.logger.debug('Polling for activity tasks', domain: domain, task_list: task_list) task = poll_for_task last_poll_time = Time.now @@ -71,7 +71,7 @@ def poll_loop def poll_for_task connection.poll_for_activity_task(domain: domain, task_list: task_list) rescue StandardError => error - Cadence.logger.error("Unable to poll for an activity task: #{error.inspect}") + Cadence.logger.error('Unable to poll for an activity task', error: error.inspect) nil end diff --git a/lib/cadence/saga/concern.rb b/lib/cadence/saga/concern.rb index 43c0e361..f6761f0b 100644 --- a/lib/cadence/saga/concern.rb +++ b/lib/cadence/saga/concern.rb @@ -11,7 +11,7 @@ def run_saga(configuration = {}, &block) Result.new(true) rescue StandardError => error # TODO: is there a need for a specialized error here? - logger.error("Saga execution aborted: #{error.inspect}") + logger.error('Saga execution aborted', error: error.inspect) logger.debug(error.backtrace.join("\n")) if compensate?(error, **configuration) diff --git a/lib/cadence/workflow.rb b/lib/cadence/workflow.rb index 051c9256..c6e6b058 100644 --- a/lib/cadence/workflow.rb +++ b/lib/cadence/workflow.rb @@ -15,7 +15,7 @@ def self.execute_in_context(context, input) context.complete(result) rescue StandardError, ScriptError => error - Cadence.logger.error("Workflow execution failed with: #{error.inspect}") + Cadence.logger.error('Workflow execution failed', error: error.inspect) Cadence.logger.debug(error.backtrace.join("\n")) context.fail(error.class.name, error.message) diff --git a/lib/cadence/workflow/poller.rb b/lib/cadence/workflow/poller.rb index 0fcb8317..68d45ce9 100644 --- a/lib/cadence/workflow/poller.rb +++ b/lib/cadence/workflow/poller.rb @@ -27,7 +27,7 @@ def start def stop @shutting_down = true - Cadence.logger.info('Shutting down a workflow poller') + Cadence.logger.info('Shutting down a workflow poller', domain: domain, task_list: task_list) end def wait @@ -58,7 +58,7 @@ def poll_loop time_diff_ms = ((Time.now - last_poll_time) * 1000).round Cadence.metrics.timing('workflow_poller.time_since_last_poll', time_diff_ms, metrics_tags) - Cadence.logger.debug("Polling for decision tasks (#{domain} / #{task_list})") + Cadence.logger.debug('Polling for decision tasks', domain: domain, task_list: task_list) task = poll_for_task last_poll_time = Time.now @@ -71,7 +71,7 @@ def poll_loop def poll_for_task connection.poll_for_decision_task(domain: domain, task_list: task_list) rescue StandardError => error - Cadence.logger.error("Unable to poll for a decision task: #{error.inspect}") + Cadence.logger.error('Unable to poll for a decision task', error: error.inspect) nil end diff --git a/lib/cadence/workflow/replay_aware_logger.rb b/lib/cadence/workflow/replay_aware_logger.rb index 05067dd3..b9ef5f93 100644 --- a/lib/cadence/workflow/replay_aware_logger.rb +++ b/lib/cadence/workflow/replay_aware_logger.rb @@ -11,17 +11,17 @@ def initialize(main_logger, replay = true) end SEVERITIES.each do |severity| - define_method severity do |message| + define_method severity do |message, details = {}| return if replay? - main_logger.public_send(severity, message) + main_logger.public_send(severity, message, details) end end - def log(severity, message) + def log(severity, message, details = {}) return if replay? - main_logger.log(severity, message) + main_logger.log(severity, message, details) end private diff --git a/spec/unit/lib/cadence/activity/poller_spec.rb b/spec/unit/lib/cadence/activity/poller_spec.rb index d33cf69e..b673a242 100644 --- a/spec/unit/lib/cadence/activity/poller_spec.rb +++ b/spec/unit/lib/cadence/activity/poller_spec.rb @@ -159,7 +159,7 @@ def call(_); end expect(Cadence.logger) .to have_received(:error) - .with('Unable to poll for an activity task: #') + .with('Unable to poll for an activity task', error: '#') end end end diff --git a/spec/unit/lib/cadence/saga/concern_spec.rb b/spec/unit/lib/cadence/saga/concern_spec.rb index a5ee99ef..75a77234 100644 --- a/spec/unit/lib/cadence/saga/concern_spec.rb +++ b/spec/unit/lib/cadence/saga/concern_spec.rb @@ -67,7 +67,7 @@ def expect_saga_not_to_be_compensated end context 'when execution does not complete' do - let(:logger) { instance_double('Logger') } + let(:logger) { instance_double('Cadence::Logger') } let(:error) { TestSagaConcernError.new('execution failed') } before do @@ -82,7 +82,7 @@ def expect_saga_not_to_be_compensated expect(logger) .to have_received(:error) - .with('Saga execution aborted: #') + .with('Saga execution aborted', error: '#') expect(logger).to have_received(:debug).with("line 1\nline 2") end diff --git a/spec/unit/lib/cadence/workflow/poller_spec.rb b/spec/unit/lib/cadence/workflow/poller_spec.rb index 1acadaa9..3516e39e 100644 --- a/spec/unit/lib/cadence/workflow/poller_spec.rb +++ b/spec/unit/lib/cadence/workflow/poller_spec.rb @@ -161,7 +161,7 @@ def call(_); end expect(Cadence.logger) .to have_received(:error) - .with('Unable to poll for a decision task: #') + .with('Unable to poll for a decision task', error: '#') end end end