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.

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

Expiration notifications are possibly broken in 3.0.0 #9

Closed
wheeskers opened this issue Aug 10, 2017 · 20 comments
Closed

Expiration notifications are possibly broken in 3.0.0 #9

wheeskers opened this issue Aug 10, 2017 · 20 comments
Assignees

Comments

@wheeskers
Copy link

Hi TFM team,

We have an issue with foreman_expire_hosts plugin: hosts' owners no longer receive notifications about host expiration and entering grace period.

I'll try to provide as many details as I can but I must say that I am not very familiar with Rails framework so please excuse me if my understanding of the situation isn't complete. I was not involved in this TFM configuration but I will try to contact any person who may have any useful information if needed.

Versions:

  • Foreman main application – 1.15.2;
  • foreman_expire_hosts plugin – 3.0.0.

Running rake command:

# /usr/sbin/foreman-rake --backtrace --rules -v expired_hosts:deliver_notifications

Produces the same error as in system logs (see below).

Please share any ideas if there's a way to fix this without major downtime or TFM instance reinstalling.
If this is not a bug but configuration/installation flaw -- comments on what is wrong would be great.

Thanks!


Log lines from /var/log/foreman/expired_hosts.log file:

rake aborted!
NoMethodError: undefined method `provided_attributes' for nil:NilClass
/usr/share/foreman/app/models/concerns/orchestration/compute.rb:29:in `compute_provides?'
/usr/share/foreman/app/models/nic/base.rb:169:in `compute_provides_ip?'
/usr/share/foreman/app/models/nic/managed.rb:78:in `ip6_available?'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:23:in `dns6?'
/usr/share/foreman/app/models/concerns/dns_interface.rb:29:in `dns_feasible?'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:84:in `block in queue_dns_destroy'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:82:in `each'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:82:in `queue_dns_destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `block in halting'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `block in call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_destroy_callbacks'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/callbacks.rb:292:in `destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `block in destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:351:in `block in with_transaction_returning_status'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:211:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/persistence.rb:185:in `destroy!'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:171:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:171:in `delete_records'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:525:in `remove_records'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:518:in `block in delete_or_destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:183:in `block in transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:211:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:182:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:518:in `delete_or_destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:279:in `destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:223:in `destroy_all'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:27:in `handle_dependency'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/builder/association.rb:146:in `block in add_destroy_callbacks'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:448:in `instance_exec'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:448:in `block in make_lambda'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `block in halting'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `block in call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_destroy_callbacks'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/callbacks.rb:292:in `destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `block in destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:351:in `block in with_transaction_returning_status'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `block in transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:184:in `within_new_transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `destroy'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:27:in `block in delete_expired_hosts'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:24:in `delete_expired_hosts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake:5:in `block (2 levels) in <top (required)>'
Tasks: TOP => expired_hosts:deliver_notifications
(See full trace by running task with --trace)
@timogoebel
Copy link
Member

timogoebel commented Aug 10, 2017

@wheeskers : Thanks for the report. I'll have to look into that in more detail, but as a hotfix you can change
/usr/share/foreman/app/models/concerns/orchestration/compute.rb:29
to

  def compute_provides?(attr)
    compute? && compute_resource && compute_resource.provided_attributes.keys.include?(attr)
  end

@wheeskers
Copy link
Author

@timogoebel, thank you for the fast reply!

I've applied this hotfix and it partially worked because initial exception changed.
Now the task stops at mail method (log contents below).

It seems that notifiable_hosts array collects all expiring/expired hosts (Host::Managed subclass instances if I understand this correctly) and is OK but then hosts_by_user block fails on iteration.

Log:

rake aborted!
NoMethodError: undefined method `mail' for nil:NilClass
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:100:in `block in hosts_by_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:94:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:94:in `hosts_by_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:34:in `delete_expired_hosts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake:5:in `block (2 levels) in <top (required)>'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `block in execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:172:in `invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:165:in `invoke'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:150:in `invoke_task'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block (2 levels) in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:115:in `run_with_threads'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:100:in `top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:78:in `block in run'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:176:in `standard_exception_handling'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:75:in `run'
/opt/rh/rh-ruby22/root/usr/bin/rake:33:in `<main>'
Tasks: TOP => expired_hosts:deliver_notifications
Host object: #<Host::Managed id: 353, name: "host05.domain.com", last_compile: nil, last_report: "2017-08-07 08:07:02", updated_at: "2017-08-07 08:07:20", created_at: "2017-01-17 15:00:49", root_pass: "<...>...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-01-17 15:18:20", model_id: 1, hostgroup_id: 1, owner_id: 68, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: nil, compute_resource_id: nil, puppet_proxy_id: 7, certname: "host05@domain.com", image_id: nil, organization_id: nil, location_id: 9, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "<...>...", global_status: 2, lookup_value_matcher: "fqdn=host05.domain.c...", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-03">
Owner object:nil
Emails object:["adm@domain.com"]

Note: I substituted some sensitive data in log above (hostnames, emails etc) but everything else is intact.

@timogoebel timogoebel added the bug label Aug 14, 2017
@timogoebel timogoebel self-assigned this Aug 14, 2017
@timogoebel
Copy link
Member

@wheeskers: I'm sorry, this wasn't a quick fix. But it revealed the actually error happening here. I have looked at the error and have a pretty good understanding, what's causing this. I will get back to you with a fix asap.

@wheeskers
Copy link
Author

@timogoebel, thanks!

@timogoebel
Copy link
Member

This is really weird and although I have an idea what is happening, I have no clue as to why this happens.
The code builds an array of host objects that should be deleted. It then iterates over these hosts and calls .destroy on them. Somehow this host object doesn't seem to have any associations.
The first stack trace shows, that although compute_resource_id is set, compute_resource is nil. It should be the compute resource object that has the id compute_resource_id. The second stack shows, that owner_type and owner_id is set, but owner is nil.
My initial thought was, that this was a permissions related. But I wasn't able to actually reproduce this behavior. Trust me, I've tried.

I have a couple of questions. Maybe this helps us find the issue.

  • Do you have Taxonomies (Locations, Organizations) enabled?
  • Can you add some debugging code to lib/expire_hosts_notifications.rb? Can you provide the output of another run? Together with SQL logger enabled on debug level this should help us find the issue.
diff --git a/lib/expire_hosts_notifications.rb b/lib/expire_hosts_notifications.rb
index defd467..ea033b5 100644
--- a/lib/expire_hosts_notifications.rb
+++ b/lib/expire_hosts_notifications.rb
@@ -24,11 +24,25 @@ module ExpireHostsNotifications
       deletable_hosts.each do |deletable_host|
         Rails.logger.info "Deleting expired host #{deletable_host}"
         deletable_host.audit_comment = _('Destroyed since it got expired on %s') % deletable_host.expired_on
+        puts "Before destroy"
+        puts "Current User: #{User.current}"
+        puts "User Tax: Loc: #{User.current.try(:locations)} - Orgs: #{User.current.try(:organizations)}"
+        puts "Host: #{deletable_host.inspect}"
+        puts "Tax: Location: #{deletable_host.location} Organization: #{deletable_host.organization}"
+        puts "Compute Resource: ID: #{deletable_host.compute_resource_id} Record: #{deletable_host.compute_resource}"
+        puts "Owner: ID: #{deletable_host.owner_id} Type: #{deletable_host.owner_type} Record: #{deletable_host.owner}"
         if deletable_host.destroy
           deleted_hosts << deletable_host
         else
           failed_delete_hosts << deletable_host
         end
+        puts "After destroy"
+        puts "Current User: #{User.current}"
+        puts "User Tax: Loc: #{User.current.try(:locations)} - Orgs: #{User.current.try(:organizations)}"
+        puts "Host: #{deletable_host.inspect}"
+        puts "Tax: Location: #{deletable_host.location} Organization: #{deletable_host.organization}"
+        puts "Compute Resource: ID: #{deletable_host.compute_resource_id} Record: #{deletable_host.compute_resource}"
+        puts "Owner: ID: #{deletable_host.owner_id} Type: #{deletable_host.owner_type} Record: #{deletable_host.owner}"
       end
       unless deleted_hosts.empty?
         ExpireHostsNotifications.hosts_by_user(deleted_hosts).each do |user_id, hosts_hash|
  • Another thing we could try would be the following:
diff --git a/lib/tasks/expired_hosts.rake b/lib/tasks/expired_hosts.rake
index 7af8092..f822f24 100644
--- a/lib/tasks/expired_hosts.rake
+++ b/lib/tasks/expired_hosts.rake
@@ -2,10 +2,12 @@
 namespace :expired_hosts do
   desc 'Delete all expired hosts, send notification email about expiring hosts'
   task :deliver_notifications => :environment do
-    ExpireHostsNotifications.delete_expired_hosts
-    ExpireHostsNotifications.stop_expired_hosts
-    ExpireHostsNotifications.deliver_expiry_warning_notification(1)
-    ExpireHostsNotifications.deliver_expiry_warning_notification(2)
+    User.as_anonymous_admin do
+      ExpireHostsNotifications.delete_expired_hosts
+      ExpireHostsNotifications.stop_expired_hosts
+      ExpireHostsNotifications.deliver_expiry_warning_notification(1)
+      ExpireHostsNotifications.deliver_expiry_warning_notification(2)
+    end
   end
 end

@wheeskers
Copy link
Author

@timogoebel,

Do you have Taxonomies (Locations, Organizations) enabled?

Currently there are multiple Foreman Locations in use with "relations" (i.e. Names are PLACE, PLACE/SUB1, PLACE/SUB2 and so on). Hosts are bound to "sub-locations" (SUB1 etc).

I couldn't find any mentions about "Organizations" in admin interface or searching in our task history so I guess this feature is not used at all.

Can you add some debugging code to lib/expire_hosts_notifications.rb? Can you provide the output of another run?

Yes, sure. Can't do this right now because we are crating a large group of VMs today so I'll have to wait some time until most of the operations complete.

Thanks again for the help, I'll try this as soon as possible and post new log output.

@wheeskers
Copy link
Author

@timogoebel, it seems that the problem is more complex. I have added debug code to expire_hosts_notifications.rb but somehow running notifications task yields a different error now.

As far as I know this is already happened before I were tasked to review this problem in our environment. I suppose this may be related to some specific hosts (i.e. "bare metal" provisioned) that are periodically deleted manually by VM users and then this exception goes away on its own. This is just an assumption though because there were no code modifications on TFM host (except the debug code from this issue).

Launch command is still the same:
# /usr/sbin/foreman-rake --backtrace --rules -v expired_hosts:deliver_notifications > logfile 2>&1

Log lines are below. I've substituted some sensitive data (person names, locations, host names, etc) by simple placeholder values but they are still consistent (same hostname = same substitute through log file). Null or empty values are not modified and left 'as is'.

Before destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 662, name: "4a4cf823.com", last_compile: nil, last_report: "2017-08-12 03:29:15", updated_at: "2017-08-12 03:29:36", created_at: "2017-05-29 11:45:13", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-05-29 11:59:39", model_id: 1, hostgroup_id: 1, owner_id: 68, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "6d58d0dd", compute_resource_id: 1, puppet_proxy_id: 7, certname: "4a4cf823.com", image_id: nil, organization_id: nil, location_id: 4, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=4a4cf823.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-03">
Tax: Location: 437910f1 Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 68 Type: User Record: 
After destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 662, name: "4a4cf823.com", last_compile: nil, last_report: "2017-08-12 03:29:15", updated_at: "2017-08-12 03:29:36", created_at: "2017-05-29 11:45:13", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-05-29 11:59:39", model_id: 1, hostgroup_id: 1, owner_id: 68, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "6d58d0dd", compute_resource_id: 1, puppet_proxy_id: 7, certname: "4a4cf823.com", image_id: nil, organization_id: nil, location_id: 4, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=4a4cf823.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-03">
Tax: Location: 437910f1 Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 68 Type: User Record: 

# -----------------------------------------------------------------------------------------------------
# Removed large amount of log lines with similar content for readability, first and last hosts are left
# -----------------------------------------------------------------------------------------------------

Before destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 506, name: "74824212.com", last_compile: nil, last_report: "2017-06-22 17:40:44", updated_at: "2017-06-29 16:53:28", created_at: "2017-03-14 14:34:29", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-03-14 16:43:14", model_id: 1, hostgroup_id: 1, owner_id: 46, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "af156cbe", compute_resource_id: 1, puppet_proxy_id: 7, certname: "74824212.com", image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=74824212.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-20">
Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 46 Type: User Record: 
After destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 506, name: "74824212.com", last_compile: nil, last_report: "2017-06-22 17:40:44", updated_at: "2017-06-29 16:53:28", created_at: "2017-03-14 14:34:29", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-03-14 16:43:14", model_id: 1, hostgroup_id: 1, owner_id: 46, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "af156cbe", compute_resource_id: 1, puppet_proxy_id: 7, certname: "74824212.com", image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=74824212.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-20">rake aborted!
Foreman::Exception: ERF42-1251 [Foreman::Exception]: Error has occurred while communicating with : undefined method `find_vm_by_uuid' for nil:NilClass
/usr/share/foreman/app/services/power_manager/virt.rb:15:in `rescue in initialize'
/usr/share/foreman/app/services/power_manager/virt.rb:7:in `initialize'
/usr/share/foreman/app/models/concerns/hostext/power_interface.rb:8:in `new'
/usr/share/foreman/app/models/concerns/hostext/power_interface.rb:8:in `power'
/usr/share/foreman/app/models/concerns/hostext/power_interface.rb:22:in `supports_power_and_running?'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:66:in `block in stop_expired_hosts'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:65:in `stop_expired_hosts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake:6:in `block (2 levels) in <top (required)>'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `block in execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:172:in `invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:165:in `invoke'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:150:in `invoke_task'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block (2 levels) in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:115:in `run_with_threads'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:100:in `top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:78:in `block in run'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:176:in `standard_exception_handling'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:75:in `run'
/opt/rh/rh-ruby22/root/usr/bin/rake:33:in `<main>'
NoMethodError: undefined method `find_vm_by_uuid' for nil:NilClass
/usr/share/foreman/app/services/power_manager/virt.rb:9:in `block in initialize'
/opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout'
/opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch'
/opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch'
/opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch'
/opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout'
/usr/share/foreman/app/services/power_manager/virt.rb:8:in `initialize'
/usr/share/foreman/app/models/concerns/hostext/power_interface.rb:8:in `new'
/usr/share/foreman/app/models/concerns/hostext/power_interface.rb:8:in `power'
/usr/share/foreman/app/models/concerns/hostext/power_interface.rb:22:in `supports_power_and_running?'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:66:in `block in stop_expired_hosts'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:65:in `stop_expired_hosts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake:6:in `block (2 levels) in <top (required)>'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `block in execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:172:in `invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:165:in `invoke'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:150:in `invoke_task'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block (2 levels) in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:115:in `run_with_threads'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:100:in `top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:78:in `block in run'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:176:in `standard_exception_handling'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:75:in `run'
/opt/rh/rh-ruby22/root/usr/bin/rake:33:in `<main>'
Tasks: TOP => expired_hosts:deliver_notifications

Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 46 Type: User Record: 
Before destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 475, name: "ccff701d.c...", last_compile: nil, last_report: "2017-06-22 17:51:27", updated_at: "2017-06-29 16:53:29", created_at: "2017-02-27 12:20:04", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-02-27 12:32:49", model_id: 1, hostgroup_id: 1, owner_id: 7, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "07b1a770", compute_resource_id: 1, puppet_proxy_id: 7, certname: "ccff701d.c...", image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=534221d7", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-20">
Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 7 Type: User Record: 
After destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 475, name: "ccff701d.c...", last_compile: nil, last_report: "2017-06-22 17:51:27", updated_at: "2017-06-29 16:53:29", created_at: "2017-02-27 12:20:04", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: "2017-02-27 12:32:49", model_id: 1, hostgroup_id: 1, owner_id: 7, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "07b1a770", compute_resource_id: 1, puppet_proxy_id: 7, certname: "ccff701d.c...", image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=534221d7", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-20">
Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 7 Type: User Record: 
Before destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 142, name: "dd4f9963.com", last_compile: nil, last_report: "2017-08-22 11:24:36", updated_at: "2017-08-22 11:24:55", created_at: "2016-12-03 13:03:02", root_pass: "...", architecture_id: 1, operatingsystem_id: 3, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: nil, model_id: 1, hostgroup_id: 1, owner_id: 130, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "406e169a", compute_resource_id: 1, puppet_proxy_id: 7, certname: "dd4f9963.com", image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: nil, grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=dd4f9963.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-15">
Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 130 Type: User Record: 
After destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 142, name: "dd4f9963.com", last_compile: nil, last_report: "2017-08-22 11:24:36", updated_at: "2017-08-22 11:24:55", created_at: "2016-12-03 13:03:02", root_pass: "...", architecture_id: 1, operatingsystem_id: 3, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: nil, model_id: 1, hostgroup_id: 1, owner_id: 130, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "406e169a", compute_resource_id: 1, puppet_proxy_id: 7, certname: "dd4f9963.com", image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: nil, grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=dd4f9963.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-15">
Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 130 Type: User Record: 
Before destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 109, name: "b088d54f.com", last_compile: nil, last_report: "2017-06-22 17:45:38", updated_at: "2017-06-29 17:10:36", created_at: "2016-12-03 12:55:31", root_pass: "...", architecture_id: 1, operatingsystem_id: 3, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: nil, model_id: 1, hostgroup_id: 1, owner_id: 3, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "57529ca1", compute_resource_id: 1, puppet_proxy_id: 7, certname: "b088d54f.com", image_id: nil, organization_id: nil, location_id: 6, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: nil, grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=b088d54f.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-20">
Tax: Location: b15b5c62 Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 3 Type: User Record: 
After destroy
Current User: 
User Tax: Loc:  - Orgs: 
Host: #<Host::Managed id: 109, name: "b088d54f.com", last_compile: nil, last_report: "2017-06-22 17:45:38", updated_at: "2017-06-29 17:10:36", created_at: "2016-12-03 12:55:31", root_pass: "...", architecture_id: 1, operatingsystem_id: 3, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: nil, model_id: 1, hostgroup_id: 1, owner_id: 3, owner_type: "User", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "57529ca1", compute_resource_id: 1, puppet_proxy_id: 7, certname: "b088d54f.com", image_id: nil, organization_id: nil, location_id: 6, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: nil, grub_pass: "...", global_status: 2, lookup_value_matcher: "fqdn=b088d54f.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-20">
Tax: Location: b15b5c62 Organization: 
Compute Resource: ID: 1 Record: 
Owner: ID: 3 Type: User Record: 

@timogoebel
Copy link
Member

timogoebel commented Aug 22, 2017

@wheeskers : Thanks for providing the data. This helps a lot. In the data you can see, that even before deletion the associations cannot be resolved properly.

I seriously suspect, that this is related to a permissions problem.

Could you try next with this patch applied?
This sets the current user to an anonymous admin and should at least rule out any permissions problem.

diff --git a/lib/tasks/expired_hosts.rake b/lib/tasks/expired_hosts.rake
index 7af8092..f822f24 100644
--- a/lib/tasks/expired_hosts.rake
+++ b/lib/tasks/expired_hosts.rake
@@ -2,10 +2,12 @@
 namespace :expired_hosts do
   desc 'Delete all expired hosts, send notification email about expiring hosts'
   task :deliver_notifications => :environment do
-    ExpireHostsNotifications.delete_expired_hosts
-    ExpireHostsNotifications.stop_expired_hosts
-    ExpireHostsNotifications.deliver_expiry_warning_notification(1)
-    ExpireHostsNotifications.deliver_expiry_warning_notification(2)
+    User.as_anonymous_admin do
+      ExpireHostsNotifications.delete_expired_hosts
+      ExpireHostsNotifications.stop_expired_hosts
+      ExpireHostsNotifications.deliver_expiry_warning_notification(1)
+      ExpireHostsNotifications.deliver_expiry_warning_notification(2)
+    end
   end
 end

@wheeskers
Copy link
Author

@timogoebel, I've applied this patch to .../foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake, user is now set to Anonymous Admin.

Log output:

rake aborted!
ActiveRecord::RecordNotDestroyed: Failed to destroy the record
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/persistence.rb:185:in `destroy!'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:171:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:171:in `delete_records'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:525:in `remove_records'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:518:in `block in delete_or_destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:183:in `block in transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:211:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:182:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:518:in `delete_or_destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:279:in `destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:223:in `destroy_all'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:27:in `handle_dependency'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/builder/association.rb:146:in `block in add_destroy_callbacks'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:448:in `instance_exec'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:448:in `block in make_lambda'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `block in halting'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `block in call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_destroy_callbacks'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/callbacks.rb:292:in `destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `block in destroy'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:351:in `block in with_transaction_returning_status'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `block in transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:184:in `within_new_transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `destroy'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:35:in `block in delete_expired_hosts'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/relation/delegation.rb:46:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/expire_hosts_notifications.rb:24:in `delete_expired_hosts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake:6:in `block (3 levels) in <top (required)>'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:75:in `as'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:81:in `as_anonymous_admin'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_expire_hosts-3.0.0/lib/tasks/expired_hosts.rake:5:in `block (2 levels) in <top (required)>'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:240:in `block in execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:235:in `execute'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:172:in `invoke_with_call_chain'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/task.rb:165:in `invoke'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:150:in `invoke_task'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block (2 levels) in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `each'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:106:in `block in top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:115:in `run_with_threads'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:100:in `top_level'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:78:in `block in run'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:176:in `standard_exception_handling'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/rake-10.4.2/lib/rake/application.rb:75:in `run'
/opt/rh/rh-ruby22/root/usr/bin/rake:33:in `<main>'
Tasks: TOP => expired_hosts:deliver_notifications
Before destroy
Current User: Anonymous Admin
User Tax: Loc: #<Taxonomy::ActiveRecord_Associations_CollectionProxy:0x0000000d5fb4c0> - Orgs: #<Taxonomy::ActiveRecord_Associations_CollectionProxy:0x0000000d7caf58>
Host: #<Host::Managed id: 594, name: "ce27ee5c.com", last_compile: nil, last_report: nil, updated_at: "2017-06-27 10:08:14", created_at: "2017-04-11 09:04:05", root_pass: "...", architecture_id: 1, operatingsystem_id: 4, environment_id: 2, ptable_id: 92, medium_id: 9, build: false, comment: "", disk: "", installed_at: nil, model_id: nil, hostgroup_id: 1, owner_id: 8, owner_type: "Usergroup", enabled: true, puppet_ca_proxy_id: 8, managed: true, use_image: nil, image_file: nil, uuid: "92c2bcac", compute_resource_id: 1, puppet_proxy_id: 7, certname: nil, image_id: nil, organization_id: nil, location_id: 5, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 4, provision_method: "build", grub_pass: "...", global_status: 0, lookup_value_matcher: "fqdn=ce27ee5c.com", pxe_loader: "PXELinux BIOS", discovery_rule_id: nil, expired_on: "2017-07-10">
Tax: Location: d5f06d5f Organization: 
Compute Resource: ID: 1 Record: vSphere (VMware)
Owner: ID: 8 Type: Usergroup Record: a92ca1b0

@timogoebel
Copy link
Member

@wheeskers: We're getting somewhere. The associations are now resolved properly. I'll open a PR with a fix for the permissions soon.
I'll look into the other error soon and let you know what we can do about that. I might ask you to add more debug code for this. Have you already checked if Foreman's production log reveals anything out of the ordinary? Thanks.

@wheeskers
Copy link
Author

@timogoebel,

I might ask you to add more debug code for this.

No problem, I'll try to add it ASAP when I'm at the office.

Have you already checked if Foreman's production log reveals anything out of the ordinary?

I did some basic review of existing logs. Do you have any ideas what to look for? May be there is something specific that I am missing out.

@timogoebel
Copy link
Member

@wheeskers: Can you delete the host manually via the UI? This error should only occur when the host cannot be deleted properly. One reason for this could be that for example a DNS record could not be deleted on the smart-proxy. You should check the logs for that.

However, this plugin should still continue to delete other hosts and not stop at the first failure. This should prevent this from happening:

diff --git a/lib/expire_hosts_notifications.rb b/lib/expire_hosts_notifications.rb
index 233294e..91d8745 100644
--- a/lib/expire_hosts_notifications.rb
+++ b/lib/expire_hosts_notifications.rb
@@ -23,7 +23,7 @@ module ExpireHostsNotifications
       deletable_hosts.each do |deletable_host|
         Rails.logger.info "Deleting expired host #{deletable_host}"
         deletable_host.audit_comment = _('Destroyed since it got expired on %s') % deletable_host.expired_on
-        if deletable_host.destroy
+        if safe_destroy(deletable_host)
           deleted_hosts << deletable_host
         else
           failed_delete_hosts << deletable_host
@@ -115,5 +115,17 @@ module ExpireHostsNotifications
       end
       hosts_hash
     end
+
+    def safe_destroy(host)
+      host.destroy!
+    rescue ActiveRecord::RecordNotDestroyed => invalid
+      message = _("Failed to delete Host %{host}: %{message} - Errors: %{errors}") % {
+        :host => host,
+        :message => invalid.message,
+        :errors => invalid.record.errors.full_messages.to_sentence
+      }
+      Foreman::Logging.exception(message, invalid)
+      false
+    end
   end
 end

@wheeskers
Copy link
Author

@timogoebel,

Can you delete the host manually via the UI? This error should only occur when the host cannot be deleted properly. One reason for this could be that for example a DNS record could not be deleted on the smart-proxy.

Errors regarding one of our smart-proxies are not very common because majority of hosts are located in "normal" environment. This specific proxy is located in "nonstandard" environment and may be problematic. We are planning to remove it or migrate it to different platform/environment.

However, this plugin should still continue to delete other hosts and not stop at the first failure. This should prevent this from happening:
<...>

Thank you! I'll add this code soon and report back results.

@wheeskers
Copy link
Author

@timogoebel, sorry for the delayed reply.

I've tested this on small group of expired hosts today and it worked. Thanks!
I'll run this on bigger group of hosts this week and reply back results.

Will this hotfix skip all/any other hosts with "bad" permissions (i.e. insufficient vSphere account permissions)?

@timogoebel
Copy link
Member

Will this hotfix skip all/any other hosts with "bad" permissions (i.e. insufficient vSphere account permissions)?

Yes. That's the aim. I'll close this for now. Thanks for your reply. The next plugin release will contain all the fixes and UI notifications.

@vladimirsafronov1251
Copy link

vladimirsafronov1251 commented Aug 30, 2017

The next plugin release will contain all the fixes and UI notifications.

Thanks @timogoebel, I can confirm that at least notifications are working with your fix. We are waiting for grace period ending for test hosts to ensure that hosts will be really deleted. This plugin was the real relief and allowed us to start managing lifecycle of VMs in our environment. Hovewer, I'm going to open one more bug and one feature request regarding notifications. I'll mention this ticket there.

@timogoebel
Copy link
Member

@vladimirsafronov1251: Sure, go ahead and let me know if you need anything. Happy to help.

@wheeskers
Copy link
Author

Hi @timogoebel,
It seems that problem is fixed for common hosts (no vSphere permission problems, etc).

Can you please clarify:

  1. Will this (current manual hotfix) work with main TFM instance updates or it is better to postpone update until new version of expire hosts plugin is released?
  2. What version of expire hosts plugin is expected to include this fix out of the box?

Thanks!

@timogoebel
Copy link
Member

timogoebel commented Oct 4, 2017

@wheeskers: Updates to Foreman core in the 1.15 branch should have no impact to the hotfix. We are currently preparing Foreman 1.16 for release. I will release a new version of this plugin (probably 4.0.0) that will require 1.16 with all the fixes and features we discussed. Sorry for not backporting this to 1.15, I didn't have the time.

@wheeskers
Copy link
Author

@timogoebel, thanks again for the detailed reply and your help.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants