Bug 1609905

Summary: Debug logging spams evm.log with deprecation warnings
Product: Red Hat CloudForms Management Engine Reporter: Tasos Papaioannou <tpapaioa>
Component: ApplianceAssignee: Brandon Dunne <bdunne>
Status: CLOSED ERRATA QA Contact: Tasos Papaioannou <tpapaioa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 5.9.4CC: abellott, bdunne, dmetzger, obarenbo, simaishi, smallamp
Target Milestone: GAKeywords: Reopened
Target Release: 5.10.0   
Hardware: All   
OS: All   
Whiteboard:
Fixed In Version: 5.10.0.15 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-02-07 23:03:31 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:

Description Tasos Papaioannou 2018-07-30 19:02:47 UTC
Description of problem:

After setting :level to debug, there are many deprecation warnings logged to evm.log:

[----] D, [2018-07-30T13:47:43.568060 #1929:f96f78] DEBUG -- : MIQ(VMDB::Config#initialize) VMDB::Config.new is deprecated.  Prefer using Settings directly.
[----] D, [2018-07-30T13:47:43.568121 #1929:f96f78] DEBUG -- : MIQ(VMDB::Config#config) VMDB::Config#config is deprecated.  Prefer using Settings directly.

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

Verified on 5.9.4.1 and 5.10.0.6.

How reproducible:

100%

Steps to Reproduce:
1.) In a server's Advanced tab, set :level to debug and restart the server.
2.) Monitor evm.log.

Actual results:

Thousands of repeated deprecation warnings.

Expected results:

No deprecation warnings.

Additional info:

Most if not all of the deprecation warnings seem to come from MiqWorker.fetch_worker_settings_from_server:

./app/models/miq_worker.rb:

  def self.fetch_worker_settings_from_server(miq_server, options = {})
    settings = {}

    unless miq_server.nil?
      server_config = options[:config] || miq_server.get_config("vmdb")
      server_config = server_config.config if server_config.respond_to?(:config)

Comment 2 dmetzger 2018-07-31 14:27:36 UTC
Working as designed

Comment 3 Tasos Papaioannou 2018-07-31 15:42:42 UTC
I don't see how it's working as designed. It's just spamming the logs with the same two statements over and over. A full 85-90% of the debug logging consists of these repeated deprecation warnings.

Comment 5 CFME Bot 2018-08-09 21:47:06 UTC
New commit detected on ManageIQ/manageiq/master:

https://github.com/ManageIQ/manageiq/commit/df146c89b6e9077f31610540195748c0fa74f0ad
commit df146c89b6e9077f31610540195748c0fa74f0ad
Author:     Brandon Dunne <brandondunne@hotmail.com>
AuthorDate: Thu Aug  9 15:01:50 2018 -0400
Commit:     Brandon Dunne <brandondunne@hotmail.com>
CommitDate: Thu Aug  9 15:01:50 2018 -0400

    Don't log the deprecation debug messages in production

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

 lib/vmdb/deprecation.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Comment 6 Tasos Papaioannou 2018-08-29 18:31:09 UTC
The commit doesn't fix the issue. The deprecation messages are coming from a different location:

/var/www/miq/vmdb/lib/vmdb/config.rb:

    def initialize(name)
      _log.debug("VMDB::Config.new is deprecated.  Prefer using Settings directly.")
      @name = name
      @errors = nil
    end

    def config
      _log.debug("VMDB::Config#config is deprecated.  Prefer using Settings directly.")
      @config ||= self.class.filter_settings_by_name(::Settings.to_hash, name).to_hash
    end

Comment 8 CFME Bot 2018-08-30 20:01:22 UTC
New commit detected on ManageIQ/manageiq/master:

https://github.com/ManageIQ/manageiq/commit/e406368909cfd7d32d86fee47e48d5a39c9a1ca7
commit e406368909cfd7d32d86fee47e48d5a39c9a1ca7
Author:     Brandon Dunne <brandondunne@hotmail.com>
AuthorDate: Thu Aug 30 14:31:38 2018 -0400
Commit:     Brandon Dunne <brandondunne@hotmail.com>
CommitDate: Thu Aug 30 14:31:38 2018 -0400

    Use Vmdb::Deprecation rather than custom warnings

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

 lib/vmdb/config.rb | 4 +-
 1 file changed, 2 insertions(+), 2 deletions(-)

Comment 9 Tasos Papaioannou 2018-09-07 15:04:40 UTC
Now the deprecation messages are getting logged at WARN level, so they are spamming evm.log without even changing the level to debug.

****
[----] W, [2018-09-07T09:52:30.414991 #64183:3f4f80]  WARN -- : DEPRECATION WARNING: initialize is deprecated and will be removed from ManageIQ H-release (Prefer using Settings directly) (called from new at /var/www/miq/vmdb/app/models/miq_server/configuration_management.rb:7)
[----] W, [2018-09-07T09:52:30.415118 #64183:3f4f80]  WARN -- : DEPRECATION WARNING: config is deprecated and will be removed from ManageIQ H-release (Prefer using Settings directly) (called from fetch_worker_settings_from_server at /var/www/miq/vmdb/app/models/miq_worker.rb:193)
****

Comment 11 CFME Bot 2018-09-11 20:16:21 UTC
New commit detected on ManageIQ/manageiq/master:

https://github.com/ManageIQ/manageiq/commit/656378447366f7cf06eb83d7e1cf0eca48a12a94
commit 656378447366f7cf06eb83d7e1cf0eca48a12a94
Author:     Brandon Dunne <brandondunne@hotmail.com>
AuthorDate: Fri Sep  7 15:52:21 2018 -0400
Commit:     Brandon Dunne <brandondunne@hotmail.com>
CommitDate: Fri Sep  7 15:52:21 2018 -0400

    Consolidate production env checks

    Don't log any deprecations anywhere in production mode.

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

 lib/vmdb/deprecation.rb | 4 +-
 1 file changed, 2 insertions(+), 2 deletions(-)

Comment 12 Tasos Papaioannou 2018-09-17 14:39:51 UTC
Verified on 5.10.0.15.

Comment 13 errata-xmlrpc 2019-02-07 23:03:31 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-2019:0212