Improve logging by adding details

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

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

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

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
 

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

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

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)

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)

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
 

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

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: #<StandardError: StandardError>')
+          .with('Unable to poll for an activity task', error: '#<StandardError: StandardError>')
       end
     end
   end

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

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: #<TestSagaConcernError: execution failed>')
+        .with('Saga execution aborted', error: '#<TestSagaConcernError: execution failed>')
       expect(logger).to have_received(:debug).with("line 1\nline 2")
     end
 

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: #<StandardError: StandardError>')
+          .with('Unable to poll for a decision task', error: '#<StandardError: StandardError>')
       end
     end
   end