Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log the original trace for the actor #326

Merged
merged 2 commits into from
Jul 9, 2019
Merged

Log the original trace for the actor #326

merged 2 commits into from
Jul 9, 2019

Conversation

iNecas
Copy link
Member

@iNecas iNecas commented May 25, 2019 •
edited
Loading

This helps a lot figuring out where the particular errors are coming
from.

Before - long backtrace that doesn't lead to the original caller:

E, [2019-05-25T22:12:00.588309 #13630] ERROR -- /client-dispatcher: No executor available (Dynflow::Error)
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/connectors/direct.rb:44:in `find_receiver'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/connectors/direct.rb:29:in `handle_envelope'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/actor.rb:6: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'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/actor.rb:26: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'
/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/awaits.rb:15: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'
/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/sets_results.rb:14: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'
/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/buffer.rb:38:in `process_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/buffer.rb:31:in `process_envelopes?'
/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/buffer.rb:20: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'
/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/termination.rb:55: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'
/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/removes_child.rb:10: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'
/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/sets_results.rb:14: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/core.rb:162:in `process_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/core.rb:96:in `block 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/core.rb:119:in `block (2 levels) in schedule_execution'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/promises.rb:1257:in `raise'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/promises.rb:1257:in `wait_until_resolved!'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/promises.rb:987:in `value!'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/dispatcher/client_dispatcher.rb:148:in `dispatch_request'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/actor.rb:6: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'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/actor.rb:26: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'
/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/awaits.rb:15: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'
/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/sets_results.rb:14: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'
/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/buffer.rb:38:in `process_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/buffer.rb:31:in `process_envelopes?'
/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/buffer.rb:20: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'
/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/termination.rb:55: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'
/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/removes_child.rb:10: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'
/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/sets_results.rb:14: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/core.rb:162:in `process_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/core.rb:96:in `block 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/core.rb:119:in `block (2 levels) in schedule_execution'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/home/inecas/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'

After - the concurrent-ruby part is filtered out, and the original backtrace back to the initiator
is included, including jumps though multiple actors:

E, [2019-05-25T22:06:56.311751 #11038] ERROR -- /connector-direct-core: No executor available (Dynflow::Error)
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/connectors/direct.rb:44:in `find_receiver'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/connectors/direct.rb:29:in `handle_envelope'
[ concurrent-ruby ]
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/connectors/direct.rb:68:in `send'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/dispatcher/client_dispatcher.rb:148:in `dispatch_request'
[ concurrent-ruby ]
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/world/invalidation.rb:54:in `block in invalidate_execution_lock'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/world/invalidation.rb:94:in `with_valid_execution_plan_for_lock'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/world/invalidation.rb:35:in `invalidate_execution_lock'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/dispatcher/executor_dispatcher.rb:38:in `when_done'
/home/inecas/active/projects/foreman-main/dynflow/lib/dynflow/dispatcher/executor_dispatcher.rb:23:in `block (2 levels) in perform_execution'
[ concurrent-ruby ]

FYI there is a track to propagate the backtraces within concurrent-ruby executor here ruby-concurrency/concurrent-ruby#810

@iNecas iNecas mentioned this pull request May 25, 2019
Open
@iNecas
Log the original trace for the actor
403a2ba 
This helps a lot figuring out where the particular errors are coming
from.
@iNecas
Copy link
Member Author

iNecas commented May 25, 2019

The ruby 2.2 is failing due to missing chunk_while method: I feel like dropping that release at this point.

adamruzicka
adamruzicka reviewed Jul 3, 2019
View reviewed changes
Copy link
Contributor

@adamruzicka adamruzicka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Left one comment inline, I'm ok with dropping support for 2.2

lib/dynflow/actor.rb Show resolved Hide resolved
@iNecas
Copy link
Member Author

iNecas commented Jul 9, 2019

Can we get this in?

@adamruzicka
Copy link
Contributor

I thought we're dropping support for 2.2 before this gets in

@iNecas
Copy link
Member Author

iNecas commented Jul 9, 2019

You're right. Dropped. Feels good to remove all the conditions checking for older ruby version :)

adamruzicka
adamruzicka approved these changes Jul 9, 2019
View reviewed changes
Copy link
Contributor

@adamruzicka adamruzicka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

APT

@adamruzicka adamruzicka merged commit 60830dd into Dynflow:master Jul 9, 2019
@adamruzicka
Copy link
Contributor

Thanks @iNecas !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@adamruzicka adamruzicka adamruzicka approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@iNecas @adamruzicka