Created attachment 1155853 [details] Script to reproduce the error Description of problem: When running an automate script that iterates through a result set returned from a $evm.vmdb search we often get corruption of the $evm object resulting in a "could not obtain a database connection within 5.000 seconds (waited 5.000 seconds)" error. Version-Release number of selected component (if applicable): CFME 5.5.3 How reproducible: Every time Steps to Reproduce: 1. Create a 'visibility' tag category, containing a single tag 2. Run the attached script via the RESTful API to duplicate the tags in the category 3. Observe the error Actual results: [----] I, [2016-05-10T17:50:52.898664 #3369:fc7998] INFO -- : Updated namespace [miqaedb:/System/Policy/AutomationRequest_created#create sIT/System] [----] I, [2016-05-10T17:50:52.973546 #3369:fc7998] INFO -- : Evaluating substituted assertion ["approved" == "pending_approval"] [----] I, [2016-05-10T17:50:52.973764 #3369:fc7998] INFO -- : Assertion Failed: <"approved" == "pending_approval"> [----] I, [2016-05-10T17:50:52.973966 #3369:fc7998] INFO -- : Followed Relationship [miqaedb:/System/Policy/AutomationRequest_created#create] [----] I, [2016-05-10T17:50:52.974288 #3369:fc7998] INFO -- : Followed Relationship [miqaedb:/System/Policy/request_created#create] [----] I, [2016-05-10T17:50:52.974600 #3369:fc7998] INFO -- : Followed Relationship [miqaedb:/System/Event/RequestEvent/Request/request_created#create] [----] I, [2016-05-10T17:50:52.985602 #3360:2856860] INFO -- : Q-task_id([automation_task_1000000000121]) <AEMethod reproduce_connection_timeout_error> Duplicating tag: "visibility/at01906342" as "visibility/at019063422" [----] E, [2016-05-10T17:50:58.014452 #3360:2cbca1c] ERROR -- : Q-task_id([automation_task_1000000000121]) MiqAeServiceModelBase.ar_method raised: <ActiveRecord::ConnectionTimeoutError>: <could not obtain a database connection within 5.000 seconds (waited 5.000 seconds)> [----] E, [2016-05-10T17:50:58.014674 #3360:2cbca1c] ERROR -- : Q-task_id([automation_task_1000000000121]) /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:189:in `block in wait_poll' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:180:in `loop' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:180:in `wait_poll' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:135:in `block in poll' /opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `synchronize' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:133:in `poll' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:425:in `acquire_connection' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:349:in `block in checkout' /opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:348:in `checkout' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:263:in `block in connection' /opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:262:in `connection' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:571:in `retrieve_connection' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_handling.rb:113:in `retrieve_connection' /opt/rh/cfme-gemset/gems/activerecord-4.2.6/lib/active_record/connection_handling.rb:87:in `connection' /var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_service_model_base.rb:260:in `ar_method' /var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_service_model_base.rb:271:in `ar_method' /var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_service_model_base.rb:240:in `object_send' /var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_service_model_base.rb:93:in `block (2 levels) in expose' /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1624:in `perform_without_block' /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1584:in `perform' /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1657:in `block (2 levels) in main_loop' /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `loop' /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `block in main_loop' [----] E, [2016-05-10T17:50:58.016471 #3360:2856860] ERROR -- : Q-task_id([automation_task_1000000000121]) <AEMethod reproduce_connection_timeout_error> Generic Error : ActiveRecord ["/opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1149:in `method_missing'", "<code: automation_request = $evm.root['automation_task'].automation_request>:19:in `<main>'"] [----] I, [2016-05-10T17:50:58.049263 #3360:5b7994] INFO -- : Q-task_id([automation_task_1000000000121]) <AEMethod [/sIT/Utility/TagManagement/Methods/reproduce_connection_timeout_error]> Ending [----] I, [2016-05-10T17:50:58.049374 #3360:5b7994] INFO -- : Q-task_id([automation_task_1000000000121]) Method exited with rc=MIQ_OK Expected results: No error Additional info:
Created attachment 1156008 [details] Simpler script to reproduce the error
This happens because the Generic Workers have a :connection_pool_size of 1 and some of the $evm.execute methods are not releasing the Database connection after the method has ended. The following methods called from $evm.execute could have a problem. category_exists? category_create tag_exists? tag_create The workaround could have been to increase the :connection_pool_size in our Advanced settings. Created a fix to release the connection once we have accessed the objects from the database.
https://github.com/ManageIQ/manageiq/pull/8669
New commit detected on ManageIQ/manageiq/master: https://github.com/ManageIQ/manageiq/commit/c4e8d8f90b27bf591410f5948fd1479f2aa88c39 commit c4e8d8f90b27bf591410f5948fd1479f2aa88c39 Author: Madhu Kanoor <mkanoor> AuthorDate: Thu May 12 17:52:14 2016 -0400 Commit: Madhu Kanoor <mkanoor> CommitDate: Thu May 12 17:52:14 2016 -0400 Wrap ar_method around Database calls https://bugzilla.redhat.com/show_bug.cgi?id=1334909 ar_method is responsible for releasing the connection to the database. It wasn't being called when creating tags and categories and also when checking for their existence. .../service_models/miq_ae_service_methods.rb | 40 +++++++++++++--------- .../service_methods/miq_ae_service_methods_spec.rb | 32 +++++++++++++++++ 2 files changed, 56 insertions(+), 16 deletions(-)
New commit detected on cfme/5.5.z: https://code.engineering.redhat.com/gerrit/gitweb?p=cfme.git;a=commitdiff;h=fa40cde2a1fed16e75a2d97a492ffc98114866fc commit fa40cde2a1fed16e75a2d97a492ffc98114866fc Author: Madhu Kanoor <mkanoor> AuthorDate: Thu May 12 17:52:14 2016 -0400 Commit: Madhu Kanoor <mkanoor> CommitDate: Fri May 13 18:22:34 2016 -0400 Wrap ar_method around Database calls https://bugzilla.redhat.com/show_bug.cgi?id=1334909 ar_method is responsible for releasing the connection to the database. It wasn't being called when creating tags and categories and also when checking for their existence. .../service_models/miq_ae_service_methods.rb | 40 +++++++++++++--------- .../service_methods/miq_ae_service_methods_spec.rb | 32 +++++++++++++++++ 2 files changed, 56 insertions(+), 16 deletions(-)
New commit detected on cfme/5.5.z: https://code.engineering.redhat.com/gerrit/gitweb?p=cfme.git;a=commitdiff;h=27d5d0b1c7e845772000acbf9343c91e0997b67b commit 27d5d0b1c7e845772000acbf9343c91e0997b67b Merge: eaef822 f5c9ac2 Author: Greg McCullough <gmccullo> AuthorDate: Tue May 31 12:10:02 2016 -0400 Commit: Greg McCullough <gmccullo> CommitDate: Tue May 31 12:10:02 2016 -0400 Merge branch 'bugzilla_1334909_5_5_z' into '5.5.z' DB Connections not closed, after tag & category functions called in Automate methods https://bugzilla.redhat.com/show_bug.cgi?id=1334909 Cherry pick from https://github.com/ManageIQ/manageiq/pull/8669 Clean Cherry pick Specs failed because of rspec 3 changes (changed from truthy to true) See merge request !940 .../service_models/miq_ae_service_methods.rb | 40 +++++++++++++--------- .../service_methods/miq_ae_service_methods_spec.rb | 32 +++++++++++++++++ 2 files changed, 56 insertions(+), 16 deletions(-)
So, checked in 5.6.0.9, I got this in the log when running this through a button: [----] I, [2016-06-02T08:05:23.387304 #2949:333998] INFO -- : <AEMethod [/test/System/Request/test]> Starting [----] I, [2016-06-02T08:05:23.949466 #2949:694fec] INFO -- : <AEMethod test> Duplicating tag: "visibility/a_tag" as "visibility/a_tag2" [----] I, [2016-06-02T08:05:24.060147 #2949:333998] INFO -- : <AEMethod [/test/System/Request/test]> Ending [----] I, [2016-06-02T08:05:59.447956 #2955:333998] INFO -- : <AEMethod [/test/System/Request/test]> Starting [----] I, [2016-06-02T08:06:00.184244 #2955:5c1e4b8] INFO -- : <AEMethod test> Duplicating tag: "visibility/a_tag" as "visibility/a_tag2" [----] I, [2016-06-02T08:06:00.232422 #2955:5c1e4b8] INFO -- : <AEMethod test> Duplicating tag: "visibility/a_tag2" as "visibility/a_tag22" [----] I, [2016-06-02T08:06:00.392143 #2955:333998] INFO -- : <AEMethod [/test/System/Request/test]> Ending [----] I, [2016-06-02T08:06:20.868076 #2944:333998] INFO -- : <AEMethod [/test/System/Request/test]> Starting [----] I, [2016-06-02T08:06:21.675131 #2944:7ae194] INFO -- : <AEMethod test> Duplicating tag: "visibility/a_tag" as "visibility/a_tag2" [----] I, [2016-06-02T08:06:21.714203 #2944:7ae194] INFO -- : <AEMethod test> Duplicating tag: "visibility/a_tag2" as "visibility/a_tag22" [----] I, [2016-06-02T08:06:21.747040 #2944:7ae194] INFO -- : <AEMethod test> Duplicating tag: "visibility/a_tag22" as "visibility/a_tag222" [----] I, [2016-06-02T08:06:21.861777 #2944:333998] INFO -- : <AEMethod [/test/System/Request/test]> Ending No errors. I had to change .find_all_by_parent_id(tag_classification.id) to .where(:parent_id => tag_classification.id) in the script in order for it to work.
New commit detected on cfme/5.5.z: https://code.engineering.redhat.com/gerrit/gitweb?p=cfme.git;a=commitdiff;h=908d022e8b8c449f3007dea9949b92901f9b7c6e commit 908d022e8b8c449f3007dea9949b92901f9b7c6e Author: Madhu Kanoor <mkanoor> AuthorDate: Thu May 12 17:52:14 2016 -0400 Commit: Madhu Kanoor <mkanoor> CommitDate: Tue Jun 14 10:46:24 2016 -0400 Wrap ar_method around Database calls https://bugzilla.redhat.com/show_bug.cgi?id=1334909 ar_method is responsible for releasing the connection to the database. It wasn't being called when creating tags and categories and also when checking for their existence. .../service_models/miq_ae_service_methods.rb | 40 +++++++++++++--------- .../service_methods/miq_ae_service_methods_spec.rb | 32 +++++++++++++++++ 2 files changed, 56 insertions(+), 16 deletions(-)
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2016:1348
Created attachment 1232559 [details] Fixed script, replaced find_all_by_parent_id with where Original script no longer works but the fix was simple.