Backtrace propagation into the executor

[iNecas]

When an error occurs within some code running inside concurrent-ruby executor, it ends up with something like this, while loosing the info about the true origin of the code:

concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:162:in `process_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:96:in `block in on_envelope'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:18:in `call'
concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:96:in `work'
concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'

Example:

require 'concurrent'
require 'concurrent-edge'

class Counter < Concurrent::Actor::Context
  def initialize(initial_value)
    @count = initial_value
  end

  def on_message(message)
    if Integer === message
      @count += message
    else
      raise "error"
    end
  end
end

def run
  counter = Counter.spawn(:first, 5)
  counter.tell("1")
end
run
sleep 3

Result:

2019-05-25 06:27:07.466] ERROR -- /first: error (RuntimeError)
/home/inecas/tmp/actor.rb:13:in `on_message'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/context.rb:46:in `on_envelope'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
# the backtrace goes on with concurrent-ruby internal details

Desired would be something like

2019-05-25 06:27:07.466] ERROR -- /first: error (RuntimeError)
/home/inecas/tmp/actor.rb:13:in `on_message'
[ concurrent-ruby ]
/home/inecas/tmp/actor.rb:20:in `run'

This is very bad developer experience and makes it very hard to deal with the code that is using actors or other concurrent-ruby abstractions.

[ianks]

Depending on you environment, you can configure backtrace filtering. It's not reasonable to rewrite this code to optimize for short backtraces.

This is a good article about backtrace filtering in RSpec to help get you started.

[iNecas]

Please note that this is not that much about filtering, as it is about propagating the backtrace when running some code via concurrent-ruby executor. The filtering can be handled separately (although if the backtrace propagation would be handled, I think it would improve the out-of-box usability)

[iNecas]

In other words, the key thing in this desired outcome:

2019-05-25 06:27:07.466] ERROR -- /first: error (RuntimeError)
/home/inecas/tmp/actor.rb:13:in `on_message'
[ concurrent-ruby ]
/home/inecas/tmp/actor.rb:20:in `run'

is not [ concurrent-ruby ], but the /home/inecas/tmp/actor.rb:20:in run'`, that you don't get at the moment.

See https://github.com/Dynflow/dynflow/pull/326 for real-world example of such a situation. Without that patch, it's next to impossible to find that dynflow/dispatcher/client_dispatcher.rb:148 has been initiated from /dynflow/world/invalidation.rb:54. With the backtrace propagation, you just get it screaming into your face:

dynflow/dispatcher/client_dispatcher.rb:148:in `dispatch_request'
[ concurrent-ruby ]
/dynflow/world/invalidation.rb:54:in `block in invalidate_execution_lock'

[laasem]

Any update here?

[pitr-ch]

Nobody is working on it at the moment.

[laasem]

We did this as a workaround for the moment - still testing it out though:

class ConcurrencyKlass
  def self.execute(&block)
    Concurrent::Promises.future {
      begin
        yield block
      rescue => e
        new_backtrace = [caller, e.backtrace].flatten
        e.set_backtrace(new_backtrace)
        CustomErrorHandler.send_error_to_error_alerting_system(e)
      end 
    }
  end
end

and then used as such

ConcurrencyKlass.execute { # Concurrent code here }