Bug 1304745

Summary: During a provision "recycled object" errors occur.
Product: Red Hat CloudForms Management Engine Reporter: Josh Carter <jocarter>
Component: AutomateAssignee: mkanoor
Status: CLOSED DUPLICATE QA Contact: Dave Johnson <dajohnso>
Severity: high Docs Contact:
Priority: high    
Version: 5.4.0CC: cpelland, fdewaley, gmccullo, jhardy, jocarter, jprause, mkanoor, obarenbo, simaishi, tfitzger
Target Milestone: GAKeywords: ZStream
Target Release: 5.6.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1304859 (view as bug list) Environment:
Last Closed: 2016-02-10 20:22:31 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1304859    

Description Josh Carter 2016-02-04 14:15:46 UTC 
Description of problem:

During a provision "recycled object" errors occur. 

[----] I, [2016-02-03T14:15:07.446612 #18454:7e5e8c]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod [/sIT/Infrastructure/VM/Provisioning/Placement/vmware_best_fit_by_visibility_sit]> Starting 
[----] I, [2016-02-03T14:15:07.670810 #18454:70308e8]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit> VM=<rhel7_64-template>, Space Required=<11811160064>, group=<1906288>
[----] I, [2016-02-03T14:15:07.672281 #18454:70308e8]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit> storage_max_vms:<0> storage_max_pct_used:<100>
[----] I, [2016-02-03T14:15:07.889138 #18454:70308e8]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit> Sorted host Order:<[:active_provioning_memory, :current_memory_headroom, :random]> Res
ults:<[[[0, -901620, 540], "esx-vhana1.vi"], [[0, -353253, 459], "vsepc4-00-01.vi.eb-grp.net"], [[0, -352122, 231], "vsepc3-00-02.vi.eb-grp.net"], [[0, -345536, 114], "vsepc4-00-02.vi.eb-grp.net"], [[0, -344844, 940], "vsepc3-00-01.vi.eb
-grp.net"]]>
[----] I, [2016-02-03T14:15:08.115388 #18454:70308e8]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit> Evaluating storages:<900_LLP3_StorageLocal_VSEPC4-00-01-SAS1>
[----] I, [2016-02-03T14:15:08.356044 #18454:70308e8]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit> Sorted storage Order:<[:active_provisioning_vms, :random]>  Results:<[[[0, 944], "900_
LLP3_StorageLocal_VSEPC4-00-01-SAS1", 0]]>
[----] E, [2016-02-03T14:15:08.359898 #18454:72ac11c] ERROR -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit> The following error occurred during method evaluation:
[----] E, [2016-02-03T14:15:08.360387 #18454:72ac11c] ERROR -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit>   RangeError: 0x0000000742b5c4 is recycled object
[----] E, [2016-02-03T14:15:08.361243 #18454:72ac11c] ERROR -- : Q-task_id([miq_provision_1000000001622]) <AEMethod vmware_best_fit_by_visibility_sit>   (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:369:in `_id
2ref'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:369:in `to_obj'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1446:in `to_obj'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1748:in `to_obj'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:618:in `recv_request'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:926:in `recv_request'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1563:in `init_with_client'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1575:in `setup_message'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1527:in `perform'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1626:in `block (2 levels) in main_loop'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1622:in `loop'
(druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1622:in `block in main_loop'
(druby://127.0.0.1:54663) /var/www/miq/vmdb/lib/extensions/ar_thread.rb:22:in `block in start_with_release'
<code: storage = storages[selected_idx]>:221:in `block in <main>'
<code: hosts.each do |h|>:107:in `each'
[----] E, [2016-02-03T14:15:08.363808 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR: (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:369:in `_id2ref': 0x0000000742b5c4 is recyc
led object (RangeError)
[----] E, [2016-02-03T14:15:08.363881 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:369:in `to_obj'
[----] E, [2016-02-03T14:15:08.363952 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1446:in `to_obj'
[----] E, [2016-02-03T14:15:08.364003 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1748:in `to_obj'
[----] E, [2016-02-03T14:15:08.364053 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:618:in `recv_request'
[----] E, [2016-02-03T14:15:08.364102 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:926:in `recv_request'
[----] E, [2016-02-03T14:15:08.364165 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1563:in `init_with_client'
[----] E, [2016-02-03T14:15:08.364214 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1575:in `setup_message'
[----] E, [2016-02-03T14:15:08.364260 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1527:in `perform'
[----] E, [2016-02-03T14:15:08.364307 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1626:in `block (2 levels) in ma
in_loop'
[----] E, [2016-02-03T14:15:08.364355 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1622:in `loop'
[----] E, [2016-02-03T14:15:08.364401 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /opt/rh/ruby200/root/usr/share/ruby/drb/drb.rb:1622:in `block in main_loop'
[----] E, [2016-02-03T14:15:08.364447 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from (druby://127.0.0.1:54663) /var/www/miq/vmdb/lib/extensions/ar_thread.rb:22:in `block in start_with_relea
se'
[----] E, [2016-02-03T14:15:08.364501 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from <code: storage = storages[selected_idx]>:221:in `block in <main>'
[----] E, [2016-02-03T14:15:08.364549 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from <code: hosts.each do |h|>:107:in `each'
[----] E, [2016-02-03T14:15:08.364596 #18454:7030adc] ERROR -- : Q-task_id([miq_provision_1000000001622]) Method STDERR:        from <code: hosts.each do |h|>:107:in `<main>'
[----] I, [2016-02-03T14:15:08.369860 #18454:7e5e8c]  INFO -- : Q-task_id([miq_provision_1000000001622]) <AEMethod [/sIT/Infrastructure/VM/Provisioning/Placement/vmware_best_fit_by_visibility_sit]> Ending
[----] E, [2016-02-03T14:15:08.370173 #18454:7e5e8c] ERROR -- : Q-task_id([miq_provision_1000000001622]) Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] E, [2016-02-03T14:15:08.370273 #18454:7e5e8c] ERROR -- : Q-task_id([miq_provision_1000000001622]) State=<Placement> running  raised exception: <Method exited with rc=Unknown RC: [1]>
--------------
Is this related to this problem: https://bugzilla.redhat.com/show_bug.cgi?id=1297097


Version-Release number of selected component (if applicable): 5.4.3


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:
Comment 2 mkanoor 2016-02-04 14:59:30 UTC 
This relates to https://bugzilla.redhat.com/show_bug.cgi?id=1297952
Waiting for the Merge Request to be merged.
Comment 3 Greg McCullough 2016-02-04 15:20:52 UTC 
Madhu - Please provide a hotfix to this BZ based on the pending MR http://gitlab.cloudforms.lab.eng.rdu2.redhat.com/cloudforms/cfme/merge_requests/731
Comment 4 mkanoor 2016-02-04 20:06:59 UTC 
Josh,
Can you provide the fix that is available in https://bugzilla.redhat.com/show_bug.cgi?id=1297952

Thanks,
Madhu
Comment 5 Greg McCullough 2016-02-10 20:22:31 UTC 
Followed up with Josh today and we have not heard from the customer since providing the hotfix.  Closing as a duplicate.

*** This bug has been marked as a duplicate of bug 1297097 ***