Bug 1279601 - dozens of "[RuntimeError]: Expected scheduled time 'at' to be 'numeric', received 'Time' Method:[rescue in deliver]" associated with specific default reports
Summary: dozens of "[RuntimeError]: Expected scheduled time 'at' to be 'numeric', rece...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Reporting
Version: 5.5.0
Hardware: x86_64
OS: Linux
high
medium
Target Milestone: GA
: 5.5.0
Assignee: Tim Wade
QA Contact: Milan Falešník
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-11-09 20:21 UTC by Thomas Hennessy
Modified: 2015-12-08 13:45 UTC (History)
6 users (show)

Fixed In Version: 5.5.0.11
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-12-08 13:45:48 UTC
Category: ---
Cloudforms Team: ---
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2015:2551 0 normal SHIPPED_LIVE Moderate: CFME 5.5.0 bug fixes and enhancement update 2015-12-08 17:58:09 UTC

Description Thomas Hennessy 2015-11-09 20:21:15 UTC
Description of problem:error apparently generated after some scheduled reports are being rescheduled for future execution


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

How reproducible: Create hourly schedule for "VM disk Usage" report


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:
Full error sequence from message initiating report to end of message processing:
=====
[----] I, [2015-11-06T11:00:23.084261 #2886:f6d998]  INFO -- : MIQ(MiqReportingWorker::Runner#get_message_via_drb) Message id: [441000000007735], MiqWorker id: [441000000000021], Zone: [], Role: [reporting], Server: [], Ident: [reporting], Target id: [], Instance id: [441000000000004], Task id: [], Command: [MiqReport.build_report_result], Timeout: [3600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [441000000000014, {:send_email=>false, :userid=>"admin"}, {:at=>2015-11-06 15:00:00 -0500, :source=>"Scheduled"}], Dequeued in: [5.895468075] seconds
[----] I, [2015-11-06T11:00:23.445481 #2886:f6d998]  INFO -- : MIQ(MiqReport#build_report_result) Generating report table with taskid [441000000000014] and options [{:send_email=>false, :userid=>"admin"}]
[----] I, [2015-11-06T11:00:23.449824 #2886:f6d998]  INFO -- : MIQ(MiqTask#update_status) Task: [441000000000014] [Active] [Ok] [Generating report]
[----] I, [2015-11-06T11:00:23.903058 #2886:f6d998]  INFO -- : MIQ(MiqReport#build_create_results) Creating report results with hash: [{:name=>"VM Disk Usage", :userid=>"admin", :report_source=>"Scheduled", :db=>"VmPerformance", :last_run_on=>2015-11-06 16:00:23 UTC, :last_accessed_on=>2015-11-06 16:00:23 UTC, :miq_report_id=>441000000000004}]
[----] I, [2015-11-06T11:00:24.282505 #2886:f6d998]  INFO -- : MIQ(MiqReport#build_create_results) Finished creating report result with id [441000000000001] for report id: [441000000000004], name: [VM Disk Usage]
[----] I, [2015-11-06T11:00:24.369273 #2886:f6d998]  INFO -- : MIQ(MiqTask#update_status) Task: [441000000000014] [Finished] [Ok] [Generating report complete]
[----] I, [2015-11-06T11:00:24.399094 #2886:f6d998]  INFO -- : MIQ(MiqReport#build_report_result) Generating report table with taskid [441000000000014]... Complete
[----] E, [2015-11-06T11:00:24.399768 #2886:f6d998] ERROR -- : MIQ(MiqQueue#deliver) Message id: [441000000007735], Error: [Expected scheduled time 'at' to be 'numeric', received 'Time']
[----] E, [2015-11-06T11:00:24.400072 #2886:f6d998] ERROR -- : [RuntimeError]: Expected scheduled time 'at' to be 'numeric', received 'Time'  Method:[rescue in deliver]
[----] E, [2015-11-06T11:00:24.400244 #2886:f6d998] ERROR -- : /var/www/miq/vmdb/app/models/miq_report/generator.rb:771:in `build_report_result'
/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:151:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:145:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:145:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:323:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:320:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:320:in `do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:142:in `run'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:123:in `start'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:24:in `start_worker'
/var/www/miq/vmdb/lib/workers/bin/worker.rb:2:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands/runner.rb:60:in `load'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands/runner.rb:60:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands/commands_tasks.rb:123:in `require'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands/commands_tasks.rb:123:in `require_command!'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands/commands_tasks.rb:90:in `runner'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
/opt/rh/cfme-gemset/bundler/gems/rails-a37d0e57571f/railties/lib/rails/commands.rb:17:in `<top (required)>'
/var/www/miq/vmdb/bin/rails:4:in `require'
/var/www/miq/vmdb/bin/rails:4:in `<main>'
[----] I, [2015-11-06T11:00:24.400603 #2886:f6d998]  INFO -- : MIQ(MiqQueue#delivered) Message id: [441000000007735], State: [error], Delivered in [1.315867487] seconds

=====

Comment 2 Tim Wade 2015-11-10 23:14:12 UTC
PR: https://github.com/ManageIQ/manageiq/pull/5379

Comment 4 Milan Falešník 2015-11-19 12:49:28 UTC
Verified in 5.5.0.11 against 5.5.0.9, both identically set, 5.5.0.9 spat the error message, 5.5.0.11 did not. \o/

Comment 6 errata-xmlrpc 2015-12-08 13:45:48 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-2015:2551


Note You need to log in before you can comment on or make changes to this bug.