Bug 1717025 - Scheduled NFS backup is not directly stored on NFS location rather stored on /tmp and then moved to NFS storage.
Summary: Scheduled NFS backup is not directly stored on NFS location rather stored on ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Appliance
Version: 5.10.3
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: GA
: 5.10.6
Assignee: Nick LaMuro
QA Contact: Jaroslav Henner
Red Hat CloudForms Documentation
URL:
Whiteboard:
Depends On: 1703278
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-06-04 14:43 UTC by Satoe Imaishi
Modified: 2019-12-04 11:24 UTC (History)
8 users (show)

Fixed In Version: 5.10.6.0
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1703278
Environment:
Last Closed: 2019-07-02 04:33:27 UTC
Category: ---
Cloudforms Team: CFME Core
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2019:1644 None None None 2019-07-02 04:33:36 UTC

Internal Links: 1763890 1767895

Comment 2 CFME Bot 2019-06-10 13:45:45 UTC
New commit detected on ManageIQ/manageiq/hammer:

https://github.com/ManageIQ/manageiq/commit/c3c65b640900e0e5381c91a43ba414cb647d770a
commit c3c65b640900e0e5381c91a43ba414cb647d770a
Author:     Nick Carboni <ncarboni@redhat.com>
AuthorDate: Fri May 17 11:39:09 2019 -0400
Commit:     Nick Carboni <ncarboni@redhat.com>
CommitDate: Fri May 17 11:39:09 2019 -0400

    Merge pull request #18745 from NickLaMuro/fix_database_backup_diskspace_check

    [EvmDatabaseOps] Fix .validate_free_space target

    (cherry picked from commit 6642bf629f9e642e3cc8665d6ca52580f3e2c01d)

    Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1717025

 lib/evm_database_ops.rb | 16 +-
 spec/lib/evm_database_ops_spec.rb | 8 +-
 2 files changed, 15 insertions(+), 9 deletions(-)

Comment 3 Jaroslav Henner 2019-06-13 12:55:59 UTC
[----] I, [2019-06-13T08:10:11.420028 #12868:1244f54]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1000000001773], Delivering...
[----] I, [2019-06-13T08:10:11.421092 #12868:1244f54]  INFO -- : MIQ(MiqTask#update_status) Task: [1000000000030] [Active] [Ok] [Task starting]
[----] I, [2019-06-13T08:10:11.437198 #12868:1244f54]  INFO -- : MIQ(MiqTask#update_status) Task: [1000000000030] [Active] [Ok] [Starting DB Backup for Region: region_1]
[----] I, [2019-06-13T08:10:11.611254 #12868:1244f54]  INFO -- : MIQ(MiqNfsSession-mount_share) Connecting to host: [10.8.196.195], share: [/srv/export/db_backup/] using mount point: [/tmp/miq_20190613-12868-x2q5u3]...
[----] I, [2019-06-13T08:10:11.764415 #12868:1244f54]  INFO -- : MIQ(Class-disconnect) Disconnecting mount point: /tmp/miq_20190613-12868-x2q5u3
[----] I, [2019-06-13T08:10:11.784265 #12868:1244f54]  INFO -- : MIQ(Class-disconnect) Disconnecting mount point: /tmp/miq_20190613-12868-x2q5u3...Complete
[----] E, [2019-06-13T08:10:11.785510 #12868:1244f54] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000000001773], Error: [undefined method `path' for nil:NilClass]
[----] E, [2019-06-13T08:10:11.785687 #12868:1244f54] ERROR -- : [NoMethodError]: undefined method `path' for nil:NilClass  Method:[block (2 levels) in <class:LogProxy>]
[----] E, [2019-06-13T08:10:11.785817 #12868:1244f54] ERROR -- : /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-98680009fe14/lib/gems/pending/util/mount/miq_generic_mount_session.rb:493:in `source_for_log'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-98680009fe14/lib/gems/pending/util/mount/miq_generic_mount_session.rb:265:in `rescue in add'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-98680009fe14/lib/gems/pending/util/mount/miq_generic_mount_session.rb:270:in `add'
/var/www/miq/vmdb/lib/evm_database_ops.rb:160:in `block in with_file_storage'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-98680009fe14/lib/gems/pending/util/miq_file_storage.rb:31:in `with_interface_class'
/var/www/miq/vmdb/lib/evm_database_ops.rb:133:in `with_file_storage'
/var/www/miq/vmdb/lib/evm_database_ops.rb:57:in `backup'
/var/www/miq/vmdb/app/models/database_backup.rb:53:in `_backup'
/var/www/miq/vmdb/app/models/database_backup.rb:37:in `backup'
/var/www/miq/vmdb/app/models/database_backup.rb:14:in `backup'
/var/www/miq/vmdb/app/models/miq_queue.rb:455:in `block in dispatch_method'
/usr/share/ruby/timeout.rb:93:in `block in timeout'
/usr/share/ruby/timeout.rb:33:in `block in catch'
/usr/share/ruby/timeout.rb:33:in `catch'
/usr/share/ruby/timeout.rb:33:in `catch'
/usr/share/ruby/timeout.rb:108:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:453:in `dispatch_method'
/var/www/miq/vmdb/app/models/miq_queue.rb:430:in `block in deliver'
/var/www/miq/vmdb/app/models/user.rb:275:in `with_user_group'
/var/www/miq/vmdb/app/models/miq_queue.rb:430:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:104:in `deliver_queue_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:137:in `deliver_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:155:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:149:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:149:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:329:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:326:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:326: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:127:in `start'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:22:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:408:in `block in start_runner_via_fork'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.4/lib/nakayoshi_fork.rb:23:in `fork'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.4/lib/nakayoshi_fork.rb:23:in `fork'
/var/www/miq/vmdb/app/models/miq_worker.rb:406:in `start_runner_via_fork'
/var/www/miq/vmdb/app/models/miq_worker.rb:396:in `start_runner'
/var/www/miq/vmdb/app/models/miq_worker.rb:447:in `start'
/var/www/miq/vmdb/app/models/miq_worker.rb:277: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:53: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:148:in `start'
/var/www/miq/vmdb/app/models/miq_server.rb:240:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:27:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:48:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>'
[----] I, [2019-06-13T08:10:11.785952 #12868:1244f54]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1000000001773], State: [error], Delivered in [0.365913405] seconds
[----] I, [2019-06-13T08:10:11.787934 #12868:1244f54]  INFO -- : MIQ(MiqQueue#m_callback) Message id: [1000000001773], Invoking Callback with args: ["Finished", "error", "undefined method `path' for nil:NilClass", "nil"]
[----] I, [2019-06-13T08:10:11.788074 #12868:1244f54]  INFO -- : MIQ(MiqTask#update_status) Task: [1000000000030] [Finished] [Error] [undefined method `path' for nil:NilClass]
[----] I, [2019-06-13T08:10:14.089231 #13233:1244f54]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc67-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator@vsphere.local] Skipping caught event [UserLoginSessionEvent] chainId [2536443]

Comment 4 Nick LaMuro 2019-06-13 18:27:21 UTC
Worked with Jaroslav to debug this, and I am pretty sure that this is a issue with an invalid nfs path being passed in, meaning this is "technically" a user error and should still be working okay given a proper NFS endpoint (I hope...) without a code change required.


* * *


That said, we probably both agree that there are some other issues at hand here that should be addressed, but in separate tickets:

1. The above error is a known issue that masks the true error, and should be resolved.  Effectively a variable is being accessed in a `rescue` clause that is assumed to be set, but is not, causing a secondary error to be thrown, masking the original.  This should be safe guarded against so errors can be better propagated.
2. Even with this, errors probably won't get passed up to the UI, which is really where that should exist for something like this, and shouldn't have to be shown in the logs.


Again, both of these are separate issues to the original complaint and not addressed as part of this fix, but should really be addressed in other tickets.

Comment 5 Jaroslav Henner 2019-06-14 13:33:25 UTC
Right now I cannot test this better than check whether the basic functionality still works.

I have found the file on nfs after the schedule should have triggered
/net/X.X.X.X/srv/export/db_backup/region_0/test/region_0_20190614_132510.backup: gzip compressed data, from Unix, original size 78149120

Comment 7 errata-xmlrpc 2019-07-02 04:33:27 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/RHBA-2019:1644


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