Automation code throwing "RangeError: 0x000... is recycled object" exceptions.

Solution Verified - Updated -

Environment

Red Hat CloudForms 3.2 and 4.0

Issue

  • Automation code throwing "RangeError: 0x000... is recycled object" exceptions.
  • I have an automation and periodically it will error with:
[----] E, [2016-02-12T15:16:45.274687 #23145:13e89f0] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod retag_all> The following error occurred during method evaluation:
[----] E, [2016-02-12T15:16:45.275844 #23145:13e89f0] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod retag_all>   RangeError: 0x0000000102f688 is recycled object
[----] E, [2016-02-12T15:16:45.278051 #23145:13e89f0] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod retag_all>   (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:372:in `_id2ref'
[----] E, [2016-02-12T15:16:45.281966 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR: (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:372:in `_id2ref': 0x0000000102f688 is recycled object (RangeError)

Resolution

  • This issue is fixed in CFME 3.2 and 4.0 latest minor updates via RHBA-2016:0171-1 and RHBA-2016:0616 erratas respectively.
  • Update the CFME appliance to above version as per your environment.

Root Cause

  • Previously we have been using our own caching mechanism to cache objects sent as references to the Automate Methods. We have gotten DRb recycled object errors, since some of the objects which were sent as references were not being cached. DRb has a builtin caching mechanism based on TimerIdConv, which we are starting to use in this PR.
  • This issue is tracked in Bug 1297499 and Bug 1286864.

Diagnostic Steps

In automation.log:

[----] E, [2016-02-12T15:16:45.274687 #23145:13e89f0] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod retag_all> The following error occurred during method evaluation:
[----] E, [2016-02-12T15:16:45.275844 #23145:13e89f0] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod retag_all>   RangeError: 0x0000000102f688 is recycled object
[----] E, [2016-02-12T15:16:45.278051 #23145:13e89f0] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod retag_all>   (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:372:in `_id2ref'
[----] E, [2016-02-12T15:16:45.281966 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR: (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:372:in `_id2ref': 0x0000000102f688 is recycled object (RangeError)
[----] E, [2016-02-12T15:16:45.282167 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:372:in `to_obj'
[----] E, [2016-02-12T15:16:45.282291 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1483:in `to_obj'
[----] E, [2016-02-12T15:16:45.282409 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1779:in `to_obj'
[----] E, [2016-02-12T15:16:45.282524 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:621:in `recv_request'
[----] E, [2016-02-12T15:16:45.282657 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:930:in `recv_request'
[----] E, [2016-02-12T15:16:45.282798 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1599:in `init_with_client'
[----] E, [2016-02-12T15:16:45.282957 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1611:in `setup_message'
[----] E, [2016-02-12T15:16:45.283154 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1563:in `perform'
[----] E, [2016-02-12T15:16:45.283285 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1657:in `block (2 levels) in main_loop'
[----] E, [2016-02-12T15:16:45.283411 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `loop'
[----] E, [2016-02-12T15:16:45.283538 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `block in main_loop'
[----] E, [2016-02-12T15:16:45.283678 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) -:160:in `block (2 levels) in <main>'
[----] E, [2016-02-12T15:16:45.283819 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) -:159:in `each'
[----] E, [2016-02-12T15:16:45.284025 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) -:159:in `block in <main>'
[----] E, [2016-02-12T15:16:45.284196 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1624:in `call'
[----] E, [2016-02-12T15:16:45.284364 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1624:in `perform_without_block'
[----] E, [2016-02-12T15:16:45.284505 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1584:in `perform'
[----] E, [2016-02-12T15:16:45.284620 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1657:in `block (2 levels) in main_loop'
[----] E, [2016-02-12T15:16:45.285486 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `loop'
[----] E, [2016-02-12T15:16:45.285602 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:33613) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `block in main_loop'
[----] E, [2016-02-12T15:16:45.285739 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/invokemethod.rb:10:in `block_yield'
[----] E, [2016-02-12T15:16:45.285851 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/invokemethod.rb:17:in `block in perform_with_block'
[----] E, [2016-02-12T15:16:45.286085 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/invokemethod.rb:14:in `each'
[----] E, [2016-02-12T15:16:45.288842 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/invokemethod.rb:14:in `perform_with_block'
[----] E, [2016-02-12T15:16:45.289125 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1582:in `perform'
[----] E, [2016-02-12T15:16:45.289346 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1657:in `block (2 levels) in main_loop'
[----] E, [2016-02-12T15:16:45.289569 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `loop'
[----] E, [2016-02-12T15:16:45.289796 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from (druby://127.0.0.1:53228) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `block in main_loop'
[----] E, [2016-02-12T15:16:45.290138 #23145:d4a940] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Method STDERR:   from <code: groups.each do |group|>:89:in `<main>'
[----] I, [2016-02-12T15:16:45.368799 #23145:5df2dd4]  INFO -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod [/dev/Methods/Methods/Retag_all]> Ending
[----] E, [2016-02-12T15:16:45.369328 #23145:5df2dd4] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] E, [2016-02-12T15:16:45.451902 #23145:5df2dd4] ERROR -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod provision_simple_computer> jb23jb23jb23 Could not find floating ip address <x.x.x.x> fatal error
[----] I, [2016-02-12T15:16:45.514689 #23145:965988]  INFO -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> <AEMethod [/dev/Service/Provisioning/StateMachines/Methods/provision_simple_computer]> Ending
[----] I, [2016-02-12T15:16:45.515275 #23145:965988]  INFO -- : Q-task_id([service_template_provision_task_99000000000654]) <AutomationEngine> Aborting instantiation because [Method exited with rc=MIQ_ABORT]

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Close

Welcome! Check out the Getting Started with Red Hat page for quick tours and guides for common tasks.