Bug 1763890 - [NoMethodError]: undefined method `path' for nil:NilClass Method:[block (2 levels) in <class:LogProxy>] during scheduled NFS backup
Summary: [NoMethodError]: undefined method `path' for nil:NilClass Method:[block (2 l...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Appliance
Version: 5.10.7
Hardware: Unspecified
OS: Unspecified
medium
low
Target Milestone: GA
: 5.12.0
Assignee: Nick LaMuro
QA Contact: Jaroslav Henner
Red Hat CloudForms Documentation
URL:
Whiteboard:
Depends On:
Blocks: 1767895
TreeView+ depends on / blocked
 
Reported: 2019-10-21 20:23 UTC by Jared Deubel
Modified: 2020-06-10 12:56 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1767895 (view as bug list)
Environment:
Last Closed: 2020-06-10 12:56:01 UTC
Category: Bug
Cloudforms Team: CFME Core
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1703278 0 high CLOSED Scheduled NFS backup is not directly stored on NFS location rather stored on /tmp and then moved to NFS storage. 2021-02-22 00:41:40 UTC
Red Hat Bugzilla 1717025 0 high CLOSED Scheduled NFS backup is not directly stored on NFS location rather stored on /tmp and then moved to NFS storage. 2021-02-22 00:41:40 UTC
Red Hat Bugzilla 1749933 0 medium CLOSED [RFE] Scheduled backup overestimates the needed space quite a lot. Backup may not happen because of that. 2021-02-22 00:41:40 UTC

Description Jared Deubel 2019-10-21 20:23:19 UTC 
Description of problem:
When doing a NFS scheduled backup in the UI we are presented with the below error: 

[----] I, [2019-10-21T15:25:22.461605 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-mount_share) Connecting to host: [10.10.181.14], share: [/backup] using mount point: [/tmp/miq_20191021-29272-1tszd8o]...
[----] I, [2019-10-21T15:25:22.520940 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-mount_share) Connecting to host: [10.10.181.14], share: [/backup]...Complete
[----] I, [2019-10-21T15:25:22.521238 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-relative_to_mount) mount point [/backup], uri: [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup]...
[----] I, [2019-10-21T15:25:22.521778 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-relative_to_mount) mount point [/backup], uri: [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup]...relative: [db_backup/region_1/jared_backup]
[----] I, [2019-10-21T15:25:22.521909 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-mkdir) Building relative path: [/tmp/miq_20191021-29272-1tszd8o/db_backup/region_1/jared_backup]...
[----] I, [2019-10-21T15:25:22.524095 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-mkdir) Building relative path: [/tmp/miq_20191021-29272-1tszd8o/db_backup/region_1/jared_backup]...complete
[----] I, [2019-10-21T15:25:22.524773 #29272:78a8fac]  INFO -- : MIQ(MiqNfsSession-relative_to_mount) mount point [/backup], uri: [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup/region_1_20191021_192522.backup]...
[----] I, [2019-10-21T15:25:22.524866 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-relative_to_mount) mount point [/backup], uri: [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup/region_1_20191021_192522.backup]...
[----] I, [2019-10-21T15:25:22.525058 #29272:78a8fac]  INFO -- : MIQ(MiqNfsSession-relative_to_mount) mount point [/backup], uri: [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup/region_1_20191021_192522.backup]...relative: [db_backup/region_1/jared_backup/region_1_20191021_192522.backup]
[----] I, [2019-10-21T15:25:22.525268 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-relative_to_mount) mount point [/backup], uri: [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup/region_1_20191021_192522.backup]...relative: [db_backup/region_1/jared_backup/region_1_20191021_192522.backup]
[----] I, [2019-10-21T15:25:22.540669 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-upload_single) Copying file [<STREAMED_FROM_CMD>] to [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup/region_1_20191021_192522.backup]...
[----] I, [2019-10-21T15:25:22.544689 #29272:78a8fac]  INFO -- : MIQ(PostgresAdmin.runcmd_with_logging) Running command... psql --no-password --dbname vmdb_production --username root --host localhost --command SELECT\ pg_database_size\(\'vmdb_production\'\)\;
[----] W, [2019-10-21T15:25:22.588652 #29272:78a8fac]  WARN -- : MIQ(EvmDatabaseOps.validate_free_space) Destination location: [/tmp/miq_20191021-29272-1tszd8o/db_backup/region_1/jared_backup/region_1_20191021_192522.backup], does not have enough free disk space: [1941962752 bytes] for database of size: [3512615084 bytes]
[----] I, [2019-10-21T15:25:22.626061 #29272:78a8fac]  INFO -- : MIQ(MiqQueue.put) Message id: [1000019144540],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 1000000000009], "evm_server_db_backup_low_space", {:event_details=>"Destination location: [/tmp/miq_20191021-29272-1tszd8o/db_backup/region_1/jared_backup/region_1_20191021_192522.backup], does not have enough free disk space: [1941962752 bytes] for database of size: [3512615084 bytes]"}]
[----] I, [2019-10-21T15:25:22.626466 #29272:11b6f60]  INFO -- : MIQ(MiqNfsSession-upload_single) Copying file [<STREAMED_FROM_CMD>] to [nfs://10.10.181.14/backup/db_backup/region_1/jared_backup/region_1_20191021_192522.backup] complete
[----] I, [2019-10-21T15:25:22.626952 #29272:11b6f60]  INFO -- : MIQ(Class-disconnect) Disconnecting mount point: /tmp/miq_20191021-29272-1tszd8o
[----] I, [2019-10-21T15:25:22.666766 #29272:11b6f60]  INFO -- : MIQ(Class-disconnect) Disconnecting mount point: /tmp/miq_20191021-29272-1tszd8o...Complete
[----] E, [2019-10-21T15:25:22.669145 #29272:11b6f60] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000019144531], Error: [undefined method `path' for nil:NilClass]
[----] E, [2019-10-21T15:25:22.669511 #29272:11b6f60] ERROR -- : [NoMethodError]: undefined method `path' for nil:NilClass  Method:[block (2 levels) in <class:LogProxy>]
[----] E, [2019-10-21T15:25:22.669891 #29272:11b6f60] ERROR -- : /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-4ccebc6545f4/lib/gems/pending/util/mount/miq_generic_mount_session.rb:493:in `source_for_log'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-4ccebc6545f4/lib/gems/pending/util/mount/miq_generic_mount_session.rb:265:in `rescue in add'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-4ccebc6545f4/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-4ccebc6545f4/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>'




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

How reproducible:
100%

Steps to Reproduce:
1. Schedule an NFS backup on a volume that doesn't have enough free space
Comment 2 Jaroslav Henner 2019-10-22 18:08:11 UTC 
Adding similar BZ that I verified recently. I wonder what did I wrong so we still have a problem.
Comment 3 Jaroslav Henner 2019-10-22 18:15:44 UTC 
I cannot see the exception MiqDatabaseBackupInsufficientSpace that I was hitting when verifying https://bugzilla.redhat.com/show_bug.cgi?id=1703278#c19 with too low space on the target NFS. I do not understand how is this possible.
Also note I created a RFE 1749933 about the errors are not presented to the user.
Comment 4 Nick LaMuro 2019-10-23 14:47:50 UTC 
Fixed a while ago here:  https://github.com/ManageIQ/manageiq-gems-pending/pull/447

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