Hide Forgot
Description of problem: 'Permission to perform this operation was denied.' error appearing in log several times in every second , causing log filesystem full . Seems like this error production is running in a closed loop. Please take a look. There is a problem about permissions in a Vmware provider which indicate this error. 17786 [----] E, [2016-10-30T22:05:45.958970 #27602:c5998c] ERROR -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::MetricsCapture.realtime_interval) EMS: [V0023VCSCD01.AD.XXXXXXXX.COM] The following error occurred: [Handsoap::Fault { :code => 'ServerFaultCode', :reason => 'Permission to perform this operation was denied.' }] 17787 [----] E, [2016-10-30T22:05:45.959144 #27602:c5998c] ERROR -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::MetricsCapture#perf_collect_metrics) [realtime] for: [ManageIQ::Providers::Vmware::InfraManager::Vm], [1000000000835], [V 0023SCD234] Unhandled exception during metrics data collection: [Handsoap::Fault { :code => 'ServerFaultCode', :reason => 'Permission to perform this operation was denied.' }], class: [Handsoap::Fault] 17788 [----] E, [2016-10-30T22:05:45.959217 #27602:c5998c] ERROR -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::MetricsCapture#perf_collect_metrics) [realtime] for: [ManageIQ::Providers::Vmware::InfraManager::Vm], [1000000000835], [V 0023SCD234] Timings at time of error: {:capture_state=>0.0013720989227294922, :vim_connect=>0.02701592445373535, :capture_intervals=>0.00437617301940918} 17789 [----] E, [2016-10-30T22:05:45.959308 #27602:c5998c] ERROR -- : [Handsoap::Fault]: Handsoap::Fault { :code => 'ServerFaultCode', :reason => 'Permission to perform this operation was denied.' } Method:[rescue in perf_collect_metrics ] 17790 [----] E, [2016-10-30T22:05:45.959362 #27602:c5998c] ERROR -- : (druby://127.0.0.1:56159) /opt/rh/cfme-gemset/bundler/gems/handsoap-4b342ee6124d/lib/handsoap/service.rb:195:in `on_fault' 17791 (druby://127.0.0.1:56159) /opt/rh/cfme-gemset/bundler/gems/handsoap-4b342ee6124d/lib/handsoap/service.rb:283:in `dispatch' 17792 (druby://127.0.0.1:56159) /opt/rh/cfme-gemset/bundler/gems/handsoap-4b342ee6124d/lib/handsoap/service.rb:189:in `invoke' 17793 (druby://127.0.0.1:56159) /var/www/miq/vmdb/gems/pending/VMwareWebService/VimService.rb:672:in `queryPerfProviderSummary' 17794 (druby://127.0.0.1:56159) /var/www/miq/vmdb/gems/pending/VMwareWebService/MiqVimPerfHistory.rb:99:in `queryProviderSummary' 17795 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1624:in `perform_without_block' 17796 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1584:in `perform' 17797 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1657:in `block (2 levels) in main_loop' 17798 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `loop' 17799 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `block in main_loop' 17800 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:38:in `realtime_interval' 17801 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:345:in `block in perf_capture_intervals' 17802 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:343:in `each' 17803 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:343:in `perf_capture_intervals' 17804 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:303:in `block in perf_collect_metrics' 17805 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' 17806 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' 17807 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:303:in `perf_collect_metrics' 17808 /var/www/miq/vmdb/app/models/metric/ci_mixin/capture.rb:6:in `perf_collect_metrics' 17809 /var/www/miq/vmdb/app/models/metric/ci_mixin/capture.rb:151:in `block in perf_capture' 17810 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' 17811 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' 17812 /var/www/miq/vmdb/app/models/metric/ci_mixin/capture.rb:148:in `perf_capture' 17813 /var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver' 17814 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout' 17815 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch' 17816 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' 17817 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' 17818 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout' 17819 /var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver' 17820 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message' 17821 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message' 17822 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:151:in `block in do_work' 17823 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:145:in `loop' 17824 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:145:in `do_work' 17825 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop' 17826 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop' 17827 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop' 17828 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run' 17829 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start' 17830 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:29:in `start_worker' 17831 /var/www/miq/vmdb/lib/workers/bin/worker.rb:2:in `<top (required)>' 17832 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `load' 17833 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `<top (required)>' 17834 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require' 17835 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require_command!' 17836 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner' 17837 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!' 17838 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>' 17839 /var/www/miq/vmdb/bin/rails:4:in `require' 17840 /var/www/miq/vmdb/bin/rails:4:in `<main>' 17841 [----] E, [2016-10-30T22:05:45.961656 #27602:c5998c] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000010165411], Error: [Handsoap::Fault { :code => 'ServerFaultCode', :reason => 'Permission to perform this operation was denied.' } ] 17842 [----] E, [2016-10-30T22:05:45.961753 #27602:c5998c] ERROR -- : [Handsoap::Fault]: Handsoap::Fault { :code => 'ServerFaultCode', :reason => 'Permission to perform this operation was denied.' } Method:[rescue in deliver] 17843 [----] E, [2016-10-30T22:05:45.961800 #27602:c5998c] ERROR -- : (druby://127.0.0.1:56159) /opt/rh/cfme-gemset/bundler/gems/handsoap-4b342ee6124d/lib/handsoap/service.rb:195:in `on_fault' 17844 (druby://127.0.0.1:56159) /opt/rh/cfme-gemset/bundler/gems/handsoap-4b342ee6124d/lib/handsoap/service.rb:283:in `dispatch' 17845 (druby://127.0.0.1:56159) /opt/rh/cfme-gemset/bundler/gems/handsoap-4b342ee6124d/lib/handsoap/service.rb:189:in `invoke' 17846 (druby://127.0.0.1:56159) /var/www/miq/vmdb/gems/pending/VMwareWebService/VimService.rb:672:in `queryPerfProviderSummary' 17847 (druby://127.0.0.1:56159) /var/www/miq/vmdb/gems/pending/VMwareWebService/MiqVimPerfHistory.rb:99:in `queryProviderSummary' 17848 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1624:in `perform_without_block' 17849 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1584:in `perform' 17850 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1657:in `block (2 levels) in main_loop' 17851 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `loop' 17852 (druby://127.0.0.1:56159) /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1653:in `block in main_loop' 17853 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:38:in `realtime_interval' 17854 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:345:in `block in perf_capture_intervals' 17855 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:343:in `each' 17856 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:343:in `perf_capture_intervals' 17857 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:303:in `block in perf_collect_metrics' 17858 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' 17859 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' 17860 /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/metrics_capture.rb:303:in `perf_collect_metrics' 17861 /var/www/miq/vmdb/app/models/metric/ci_mixin/capture.rb:6:in `perf_collect_metrics' 17862 /var/www/miq/vmdb/app/models/metric/ci_mixin/capture.rb:151:in `block in perf_capture' 17863 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' 17864 /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' 17865 /var/www/miq/vmdb/app/models/metric/ci_mixin/capture.rb:148:in `perf_capture' 17866 /var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver' 17867 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout' 17868 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch' 17869 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' 17870 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' 17871 /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout' 17872 /var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver' 17873 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message' 17874 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message' 17875 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:151:in `block in do_work' 17876 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:145:in `loop' 17877 /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:145:in `do_work' 17878 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop' 17879 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop' 17880 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop' 17881 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run' 17882 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start' 17883 /var/www/miq/vmdb/app/models/miq_worker/runner.rb:29:in `start_worker' 17884 /var/www/miq/vmdb/lib/workers/bin/worker.rb:2:in `<top (required)>' 17885 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `load' 17886 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `<top (required)>' 17887 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require' 17888 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require_command!' 17889 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner' 17890 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!' 17891 /opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>' 17892 /var/www/miq/vmdb/bin/rails:4:in `require' 17893 /var/www/miq/vmdb/bin/rails:4:in `<main>' Version-Release number of selected component (if applicable): How reproducible: Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info:
James, can you see if its feasible to add some increasing delay if we get an error like this? Gellert if the permission problem is a known issue on the VC side can they just disable metrics collection until that is resolved?
@adam : Already recommended to disable metrics collection , but it seems they don't want to go disable .
Curt looks to have tracked down the issue. The Red Hat CloudForms user/group must have at least the read-only role at the vCenter level. We are still doing some testing, but this seems to have resolved the issue from our initial testing. Important to note is that with the vCenter 5.1.0 in the internal Red Hat lab this vCenter level permission is not required but the customer has vCenter 6.0.0 so the difference in permission requirements seems to be a difference between vCenter 5.1.0 and vCenter 6.0.0 Currently the documentation only says the following: ---------------- Additionally, you must assign the new role to the following objects: Datacenter: At the Datacenter the Red Hat CloudForms user/group must have at least the read-only role at the Datacenter level (Not Propagated) to be able to see the datacenter. Without this access, relationships cannot be made. Specifically, the datastores will not show up. Cluster: Each Cluster that the Red Hat CloudForms needs access to must have the new role assigned and propagated. Folders: Each Folder that Red Hat CloudForms needs access to must have the new role assigned and propagated. Datastores: Each Datastore that Red Hat CloudForms needs access to must have the new role assigned and propagated. Networking: Each vLAN or Port Group that Red Hat CloudForms needs access to must have the new role assigned and propagated. ---------------- The documentation should be updated to add a line about the vCenter read-only requirment for vCenter 6.x (and maybe others, probably best just to do it across the board)
This is highly likely to be the same issue and can be corrected by doc update as specified here https://bugzilla.redhat.com/show_bug.cgi?id=1430826#c6