Bug 1397247

Summary: Getting Couldn't find MiqTask Errors in evm.log
Product: Red Hat CloudForms Management Engine Reporter: Jerome Marc <jmarc>
Component: C&U Capacity and UtilizationAssignee: Yuri Rudman <yrudman>
Status: CLOSED ERRATA QA Contact: Nandini Chandra <nachandr>
Severity: medium Docs Contact:
Priority: medium    
Version: 5.6.0CC: dajohnso, gekis, jhardy, jmarc, nachandr, obarenbo, saali, simaishi, yrudman
Target Milestone: GAKeywords: ZStream
Target Release: 5.9.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: c&u
Fixed In Version: 5.9.0.1 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1550276 (view as bug list) Environment:
Last Closed: 2018-03-01 13:08:18 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:
Embargoed:
Bug Depends On:    
Bug Blocks: 1550276    
Attachments:
Description Flags
evm.log with raise_record_not_found_exception errors none

Description Jerome Marc 2016-11-22 02:20:50 UTC
Description of problem:
I have been monitoring my environment and am getting many occurrences of this error daily on evm.log:

[----] I, [2016-11-21T09:17:12.099144 #32362:53f994]  INFO -- : MIQ(MiqQueue#deliver) Message id: [10000070272161], Delivering...
[----] E, [2016-11-21T09:17:12.102554 #32362:53f994] ERROR -- : MIQ(MiqQueue#deliver) Message id: [10000070272161], Error: [Couldn't find MiqTask with 'id'=10000000137883]
[----] E, [2016-11-21T09:17:12.102822 #32362:53f994] ERROR -- : [ActiveRecord::RecordNotFound]: Couldn't find MiqTask with 'id'=10000000137883  Method:[rescue in deliver]
[----] E, [2016-11-21T09:17:12.103038 #32362:53f994] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation/finder_methods.rb:357:in `raise_record_not_found_exception!'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation/finder_methods.rb:477:in `find_one'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation/finder_methods.rb:456:in `find_with_ids'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation/finder_methods.rb:66:in `find'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation.rb:491:in `destroy'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation.rb:489:in `block in destroy'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation.rb:489:in `map'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/relation.rb:489:in `destroy'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/querying.rb:8:in `destroy'
/var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver'
/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'
/var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:347:in `block in start'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/var/www/miq/vmdb/app/models/miq_worker.rb:345:in `start'
/var/www/miq/vmdb/app/models/miq_worker.rb:274:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:154:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_worker.rb:154:in `times'
/var/www/miq/vmdb/app/models/miq_worker.rb:154:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server.rb:173:in `start'
/var/www/miq/vmdb/app/models/miq_server.rb:265:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>'
[----] I, [2016-11-21T09:17:12.103350 #32362:53f994]  INFO -- : MIQ(MiqQueue#delivered) Message id: [10000070272161], State: [error], Delivered in [0.004209486] seconds

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

How reproducible:
Not sure.

Actual results:
See Exception

Expected results:
No error.

Additional info:
Environment credentials can be shared on request.

Comment 2 Jerome Marc 2016-11-22 02:22:06 UTC
Created attachment 1222562 [details]
evm.log with raise_record_not_found_exception errors

Comment 3 Dave Johnson 2016-11-23 17:34:47 UTC
Nandini, can you try and reproduce this?  Jerome was thinking maybe it as something to do with managing providers that do not support c&u when c&u is enabled.

Comment 7 Nandini Chandra 2017-01-19 21:46:48 UTC
I haven't been able to reproduce this issue.

I tested an appliance managing SCVMM(SCVMM doesn't support C&U)with C&U enabled.

Comment 11 CFME Bot 2017-06-21 21:06:59 UTC
New commit detected on ManageIQ/manageiq/master:
https://github.com/ManageIQ/manageiq/commit/ad3525f246832d90824b415c5b11e56187493f34

commit ad3525f246832d90824b415c5b11e56187493f34
Author:     Yuri Rudman <yrudman>
AuthorDate: Tue Jun 20 14:47:18 2017 -0400
Commit:     Yuri Rudman <yrudman>
CommitDate: Wed Jun 21 09:55:16 2017 -0400

    no need to delete task records in 2 steps (get list of ID first and queue destroy for those id). If queue is busy then there are could be several request to delete task with the same id. Instead queue actual condition to filter record and execute destroy_all.
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1397247

 app/models/miq_task.rb       | 15 ++++++++++++---
 spec/models/miq_task_spec.rb | 21 +++++++++++++--------
 2 files changed, 25 insertions(+), 11 deletions(-)

Comment 12 Yuri Rudman 2017-07-10 13:33:32 UTC
*** Bug 1422601 has been marked as a duplicate of this bug. ***

Comment 13 Nandini Chandra 2017-11-08 21:57:39 UTC
Yuri,

I'm working on reproducing this issue.Could you provide steps to reproduce this issue?

Thanks,
Nandini

Comment 14 Yuri Rudman 2017-11-09 17:35:46 UTC
To duplicate this error: there should be 2 request in the queue to delete tasks and 
some tasks(to delete) should be present in both requests.

Steps:
1. Generate several reports
2. Stop EVM Server Processes
3. from rails console execute 2 commands:
 > MiqTask.delete_older(Time.now, "name LIKE 'Generate Report:%'")
 > MiqTask.delete_older(Time.now, "name LIKE 'Generate Report:%'")
4. Start EVM Server Processes

Comment 15 Nandini Chandra 2018-02-14 22:14:09 UTC
Verified in 5.9.0.20

Comment 16 Nandini Chandra 2018-02-14 22:19:31 UTC
Steps:
1. Disable Reporting role.
2. Queue several reports.Reporting role is disabled so that these reports remain queued and don't get run.
2. Stop EVM Server Processes
3. from rails console execute 2 commands:
 > MiqTask.delete_older(Time.now, "name LIKE 'Generate Report:%'")
 > MiqTask.delete_older(Time.now, "name LIKE 'Generate Report:%'")

   'evmserver' is stopped so that these two 'delete' tasks remain queued and   don't get run
4. Start EVM Server Processes

Before fix:
Error message in evm.log

After fix:
No error message in evm.log

Comment 17 Nandini Chandra 2018-02-14 22:20:31 UTC
This issue impact 58 as well.

Can the fix be backported to 58?

Comment 22 errata-xmlrpc 2018-03-01 13:08:18 UTC
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/RHSA-2018:0380