Salt: Extraneous debug output "LazyLoaded nested.output"?

[lorengordon]

Description of Issue/Question

It seems that each state that does something, or perhaps just cmd.run, will output extraneous debug messages [DEBUG ] LazyLoaded nested.output.

Setup

Run 1 test.sls:

test1:
  cmd.run:
    - name: echo test1

Run 2 test.sls

test1:
  cmd.run:
    - name: echo test1

test2:
  cmd.run:
    - name: echo test2

Duplicating that setup for run 3 would produce a third line, [DEBUG ] LazyLoaded nested.output, etc...

Steps to Reproduce Issue

Run 1:

salt-call --local -l debug state.sls test
# <...snip...>
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] LazyLoaded nested.output            # <---- note a single line

Run 2:

salt-call --local -l debug state.sls test
# <...snip...>
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] LazyLoaded nested.output            # <---- 
[DEBUG   ] LazyLoaded nested.output            # <---- note the line duplicates

Versions Report

Salt Version:
           Salt: 2016.11.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.8.1
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.6.6 (r266:84292, Aug 18 2016, 15:13:37)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 14.5.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist: centos 6.8 Final
        machine: x86_64
        release: 2.6.32-642.13.1.el6.x86_64
         system: Linux
        version: CentOS 6.8 Final

[ninja-]

As someone with good knowledge about how current far-from-perfect loader.py works, I'd probably say that it's expected behaviour or at least not a bug. It's probably because the module is getting loaded after process is forked to execute the command.

[lorengordon]

I can't imagine that anyone truly expects this kind of noise. In a highstate with hundreds of states, it's quite annoying.

[ninja-]

You seem to forget that this is DEBUG level logging and normally what you should see is INFO, ERROR and WARNING. Debug is all about noise with inside info for developers and debugging problems. It's not turned on by default.

[lorengordon]

No, I don't think I am forgetting anything. This is the end of the run, provides no valuable information, and I'm fairly certain that in past versions this line only displayed once. It also doesn't display at all if the state reports no changes.

[lorengordon]

And it also appears specific to the highstate outputter. If using the yaml or json (or presumably other) outputters, the line is not printed.

[ninja-]

Ehh.
It might be related to
https://github.com/saltstack/salt/blob/3b81c37a531c48ff54a2332c4ea9c0d108ce0e74/salt/output/__init__.py#L171
https://github.com/saltstack/salt/blob/3b81c37a531c48ff54a2332c4ea9c0d108ce0e74/salt/loader.py#L383

You can see the same behaviour for roots.envs for example.
It's a small area to improve, but I wouldn't call it a bug.
I'll have a closer look.

But if you don't like the spam, then please stop using the DEBUG logging level in production.

[lorengordon]

It's certainly not critical. Only reporting because it seems odd. I'd usually investigate more and fix it myself, but I'm focused on something else for the next few weeks, so the issue was more a placeholder for me to get back to later. But if you want to tackle it, by all means! :D

We have a tool that wraps salt that others then use. If we didn't have the debug logs, we'd never be able to tell what half their issues were. So, gonna keep saving off the debug logs.

[ninja-]

Ok here is a POC patch that fixes the problem

diff --git a/salt/output/__init__.py b/salt/output/__init__.py
index c6657f971e..10deb979df 100644
--- a/salt/output/__init__.py
+++ b/salt/output/__init__.py
@@ -28,6 +28,8 @@ from salt.utils import print_cli

 log = logging.getLogger(__name__)

+global outputters
+outputters = {} # Cached list of outputters

 def try_printout(data, out, opts, **kwargs):
     '''
@@ -168,7 +170,10 @@ def get_printout(out, opts=None, **kwargs):
         else:
             opts['color'] = True

-    outputters = salt.loader.outputters(opts)
+    global outputters
+    if not outputters:
+        outputters = salt.loader.outputters(opts)
+
     if out not in outputters:
         # Since the grains outputter was removed we don't need to fire this
         # error when old minions are asking for it

I'd rather cache it at loader.py level tbh, because it's guaranteed that there would be no new outputters at runtime added. I guess. Maybe not.

[lorengordon]

Ahh, yeah, euw, I see what you mean about the lazy loader inefficiencies...

[ninja-]

😄 yeah I've kind of given up on refactoring the loader for now, but I might get back to that PR within a month with some fresh ideas on how to not break it...

[lorengordon]

And yes, that patch fixes the extraneous output.

[gtmanfred]

I am going to mark this as a very low bug.

Thanks for reporting,
Daniel

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.