Consistency and expected behavior of resource notifications

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Unknown Unknown
  • Resolution: Fixed
  • Affects Version/s: None
  • Fix Version/s: 10.14.0
  • Component/s: None
  • Labels:

Description

There seem to be a few issues around the behavior or resource notifications. Below are some examples to help demonstrate the issue. First a test recipe to display the behavior:

Unable to find source-code formatter for language: ruby. Available languages are: javascript, sql, xhtml, actionscript, none, html, xml, java
ruby_block 'default_runs' do
  block do
    true
  end
end

ruby_block 'subscribe_runs' do
  block do
    raise 'fail'
  end
  action :nothing
  retries 1
  subscribes :create, resources(:ruby_block => 'default_runs')
end

Currently this results in:

[Thu, 07 Jun 2012 01:07:26 +0000] INFO: Processing ruby_block[default_runs] action create (testbook::default line 1)
[Thu, 07 Jun 2012 01:07:26 +0000] INFO: ruby_block[default_runs] called
[Thu, 07 Jun 2012 01:07:26 +0000] INFO: Processing ruby_block[subscribe_runs] action nothing (testbook::default line 7)
[Thu, 07 Jun 2012 01:07:26 +0000] INFO: ruby_block[default_runs] sending create action to ruby_block[subscribe_runs] (delayed)
[Thu, 07 Jun 2012 01:07:26 +0000] INFO: Processing ruby_block[subscribe_runs] action create (testbook::default line 7)
[Thu, 07 Jun 2012 01:07:26 +0000] ERROR: ruby_block[subscribe_runs] (testbook::default line 7) has had an error
[Thu, 07 Jun 2012 01:07:26 +0000] ERROR: Running exception handlers
[Thu, 07 Jun 2012 01:07:26 +0000] FATAL: Saving node information to /var/cache/chef/failed-run-data.json
[Thu, 07 Jun 2012 01:07:26 +0000] ERROR: Exception handlers complete
[Thu, 07 Jun 2012 01:07:26 +0000] FATAL: Stacktrace dumped to /var/cache/chef/chef-stacktrace.out
[Thu, 07 Jun 2012 01:07:26 +0000] FATAL: RuntimeError: ruby_block[subscribe_runs] (testbook::default line 7) had an error: RuntimeError: fail

Which I would think the expected behavior would be for the 'subscribes_run' resource to be retried. Now if we add retries to the 'default_runs' resource and make the subscription immediate so our recipe looks like this:

Unable to find source-code formatter for language: ruby. Available languages are: javascript, sql, xhtml, actionscript, none, html, xml, java
ruby_block 'default_runs' do
  block do
    true
  end
  retries 1
end

ruby_block 'subscribe_runs' do
  block do
    raise 'fail'
  end
  action :nothing
  subscribes :create, resources(:ruby_block => 'default_runs'), :immediate
end

This currently results in:

[Thu, 07 Jun 2012 01:14:58 +0000] INFO: Processing ruby_block[default_runs] action create (testbook::default line 1)
[Thu, 07 Jun 2012 01:14:58 +0000] INFO: ruby_block[default_runs] called
[Thu, 07 Jun 2012 01:14:58 +0000] INFO: ruby_block[default_runs] sending create action to ruby_block[subscribe_runs] (immediate)
[Thu, 07 Jun 2012 01:14:58 +0000] INFO: Processing ruby_block[subscribe_runs] action create (testbook::default line 8)
[Thu, 07 Jun 2012 01:14:58 +0000] ERROR: ruby_block[subscribe_runs] (testbook::default line 8) has had an error
[Thu, 07 Jun 2012 01:14:58 +0000] ERROR: ruby_block[default_runs] (/var/cache/chef/cookbooks/testbook/recipes/default.rb:1:in `from_file') had an error:
ruby_block[subscribe_runs] (testbook::default line 8) had an error: RuntimeError: fail
...
[Thu, 07 Jun 2012 01:14:58 +0000] INFO: Retrying execution of ruby_block[default_runs], 0 attempt(s) left
[Thu, 07 Jun 2012 01:15:00 +0000] INFO: Processing ruby_block[default_runs] action create (testbook::default line 1)
[Thu, 07 Jun 2012 01:15:00 +0000] INFO: ruby_block[default_runs] called
[Thu, 07 Jun 2012 01:15:00 +0000] INFO: ruby_block[default_runs] sending create action to ruby_block[subscribe_runs] (immediate)
[Thu, 07 Jun 2012 01:15:00 +0000] INFO: Processing ruby_block[subscribe_runs] action create (testbook::default line 8)
[Thu, 07 Jun 2012 01:15:00 +0000] ERROR: ruby_block[subscribe_runs] (testbook::default line 8) has had an error
[Thu, 07 Jun 2012 01:15:00 +0000] ERROR: ruby_block[default_runs] (/var/cache/chef/cookbooks/testbook/recipes/default.rb:1:in `from_file') had an error:
ruby_block[subscribe_runs] (testbook::default line 8) had an error: RuntimeError: fail
...
[Thu, 07 Jun 2012 01:15:00 +0000] ERROR: Running exception handlers
[Thu, 07 Jun 2012 01:15:00 +0000] FATAL: Saving node information to /var/cache/chef/failed-run-data.json
[Thu, 07 Jun 2012 01:15:00 +0000] ERROR: Exception handlers complete
[Thu, 07 Jun 2012 01:15:00 +0000] FATAL: Stacktrace dumped to /var/cache/chef/chef-stacktrace.out
[Thu, 07 Jun 2012 01:15:00 +0000] FATAL: RuntimeError: ruby_block[subscribe_runs] (testbook::default line 8) had an error: RuntimeError: fail

Here we see the failing 'subscribe_runs' being retried due to the retries on 'default_run'. This isn't consistent though as this behavior is only seen when the notification is :immediate. For :delayed notifications, the same behavior as the first example is observed.

After patching with the supplied pull request, the behavior of the retries works as expected. Output of the first example with patched chef:

[Thu, 07 Jun 2012 14:31:11 +0000] INFO: Processing ruby_block[default_runs] action create (testbook::default line 1)
[Thu, 07 Jun 2012 14:31:11 +0000] INFO: ruby_block[default_runs] called
[Thu, 07 Jun 2012 14:31:11 +0000] INFO: ruby_block[default_runs] sending create action to ruby_block[subscribe_runs] (immediate)
[Thu, 07 Jun 2012 14:31:11 +0000] INFO: Processing ruby_block[subscribe_runs] action create (testbook::default line 7)
[Thu, 07 Jun 2012 14:31:11 +0000] ERROR: ruby_block[subscribe_runs] (testbook::default line 7) has had an error
[Thu, 07 Jun 2012 14:31:11 +0000] ERROR: ruby_block[subscribe_runs] (/var/cache/chef/cookbooks/testbook/recipes/default.rb:7:in `from_file') had an error:
ruby_block[subscribe_runs] (testbook::default line 7) had an error: RuntimeError: fail
...
[Thu, 07 Jun 2012 14:31:11 +0000] INFO: Retrying execution of ruby_block[subscribe_runs], 0 attempt(s) left
[Thu, 07 Jun 2012 14:31:13 +0000] INFO: Processing ruby_block[subscribe_runs] action create (testbook::default line 7)
[Thu, 07 Jun 2012 14:31:13 +0000] ERROR: ruby_block[subscribe_runs] (testbook::default line 7) has had an error
[Thu, 07 Jun 2012 14:31:13 +0000] ERROR: ruby_block[subscribe_runs] (/var/cache/chef/cookbooks/testbook/recipes/default.rb:7:in `from_file') had an error:
ruby_block[subscribe_runs] (testbook::default line 7) had an error: RuntimeError: fail
...
[Thu, 07 Jun 2012 14:31:13 +0000] ERROR: Running exception handlers
[Thu, 07 Jun 2012 14:31:13 +0000] FATAL: Saving node information to /var/cache/chef/failed-run-data.json
[Thu, 07 Jun 2012 14:31:13 +0000] ERROR: Exception handlers complete
[Thu, 07 Jun 2012 14:31:13 +0000] FATAL: Stacktrace dumped to /var/cache/chef/chef-stacktrace.out
[Thu, 07 Jun 2012 14:31:13 +0000] FATAL: RuntimeError: ruby_block[subscribe_runs] (testbook::default line 7) had an error: RuntimeError: fail

properly retries the 'subscribe_runs' resource and the output of the second example:

[Thu, 07 Jun 2012 14:39:15 +0000] INFO: Processing ruby_block[default_runs] action create (testbook::default line 1)
[Thu, 07 Jun 2012 14:39:15 +0000] INFO: ruby_block[default_runs] called
[Thu, 07 Jun 2012 14:39:15 +0000] INFO: ruby_block[default_runs] sending create action to ruby_block[subscribe_runs] (immediate)
[Thu, 07 Jun 2012 14:39:15 +0000] INFO: Processing ruby_block[subscribe_runs] action create (testbook::default line 8)
[Thu, 07 Jun 2012 14:39:15 +0000] ERROR: ruby_block[subscribe_runs] (testbook::default line 8) has had an error
[Thu, 07 Jun 2012 14:39:15 +0000] ERROR: ruby_block[subscribe_runs] (/var/cache/chef/cookbooks/testbook/recipes/default.rb:8:in `from_file') had an error:
ruby_block[subscribe_runs] (testbook::default line 8) had an error: RuntimeError: fail
...
[Thu, 07 Jun 2012 14:39:15 +0000] ERROR: Running exception handlers
[Thu, 07 Jun 2012 14:39:15 +0000] FATAL: Saving node information to /var/cache/chef/failed-run-data.json
[Thu, 07 Jun 2012 14:39:15 +0000] ERROR: Exception handlers complete
[Thu, 07 Jun 2012 14:39:15 +0000] FATAL: Stacktrace dumped to /var/cache/chef/chef-stacktrace.out
[Thu, 07 Jun 2012 14:39:15 +0000] FATAL: RuntimeError: ruby_block[subscribe_runs] (testbook::default line 8) had an error: RuntimeError: fail

shows that even though 'default_runs' allows retries, it does not retry on a failed notification.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Chris Roberts added a comment -

Pull Request: https://github.com/opscode/chef/pull/313

Show
Chris Roberts added a comment - Pull Request: https://github.com/opscode/chef/pull/313
Hide
Permalink
Steven Danna added a comment -

Hi Chris,

We looked at this at code review on Monday. While we didn't have specific issues with your patch, there are other problems related to retries on notifications and retries when #run_action is called directly on a resource that could also be fixed when fixing this issue. Namely, the right approach is most likely to make the retry part of the Resource rather than the runner. I believe that Dan DeLeo has made some progress with this approach. I've pinged him asking him to send a quick update to this ticket with further details.

Cheers,

Steven

Show
Steven Danna added a comment - Hi Chris, We looked at this at code review on Monday. While we didn't have specific issues with your patch, there are other problems related to retries on notifications and retries when #run_action is called directly on a resource that could also be fixed when fixing this issue. Namely, the right approach is most likely to make the retry part of the Resource rather than the runner. I believe that Dan DeLeo has made some progress with this approach. I've pinged him asking him to send a quick update to this ticket with further details. Cheers, Steven
Hide
Permalink
Daniel DeLeo added a comment -

I had to move a bunch of logic out of Runner and into Resource to fix some bugs related to making new features work with compile-time (e.g., run_action() resources, so I moved the retry logic into Resouce#run_action as well. This should result in retries working as expected with compile-time resources and with resources triggered by notifications.

Commit: https://github.com/opscode/chef/commit/0e94e411e7e2732e71a715d34845b9f1d622546c

Since we have already entered the RC phase of the Chef 10.12 release and this bug is not a blocker for that, and the whyrun branch where I made this commit will be merged to mainline for the next release, I'm going to consider this bug closed.

Chris, thanks for your patch.

Show
Daniel DeLeo added a comment - I had to move a bunch of logic out of Runner and into Resource to fix some bugs related to making new features work with compile-time (e.g., run_action() resources, so I moved the retry logic into Resouce#run_action as well. This should result in retries working as expected with compile-time resources and with resources triggered by notifications. Commit: https://github.com/opscode/chef/commit/0e94e411e7e2732e71a715d34845b9f1d622546c Since we have already entered the RC phase of the Chef 10.12 release and this bug is not a blocker for that, and the whyrun branch where I made this commit will be merged to mainline for the next release, I'm going to consider this bug closed. Chris, thanks for your patch.

People

  • Assignee:
    Daniel DeLeo
    Reporter:
    Chris Roberts
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: