2017.7: module.wait used as in documentation provides deprecation warning

[Talkless]

Description of Issue/Question

running module.wait with 2017.7.5 produces warning The function "module.run" is using its deprecated version and will expire in version "Sodium".:

2018-04-12 16:48:20,109 [salt.state       :1794][INFO    ][9992] Executing state module.mod_watch for [cmd.shell]
2018-04-12 16:48:20,110 [salt.utils.decorators:613 ][WARNING ][9992] The function "module.run" is using its deprecated version and will expire in version "Sodium".
2018-04-12 16:48:20,110 [salt.loaded.int.module.cmdmod:394 ][INFO    ][9992] Executing command 'echo salt-call --local service.restart salt-minion | at now + 1 minute' in directory '/root'

I know that module.run has new way of specifying modules to be executed, but there is no instructions on how module.wait should use new declaration style. Using it as before produces mentioned deprecation warning.

Setup

My minion-restarting state (changing minion conf invokes this)

salt_minion_restart:
    module.wait:
        - name: cmd.shell
        - cmd: echo salt-call --local service.restart salt-minion | at now + 1 minute
        - order: last

Steps to Reproduce Issue

Make module.wait to run, logs are above.

Versions Report

Salt Version:
           Salt: 2017.7.5
 
Dependency Versions:
           cffi: 0.8.6
       cherrypy: Not Installed
       dateutil: 2.2
      docker-py: Not Installed
          gitdb: 0.5.4
      gitpython: 0.3.2 RC1
          ioflo: Not Installed
         Jinja2: 2.9.4
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 1.0.0
   msgpack-pure: Not Installed
 msgpack-python: 0.4.2
   mysql-python: 1.2.3
      pycparser: 2.10
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.9 (default, Jun 29 2016, 13:08:31)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 14.4.0
           RAET: Not Installed
          smmap: 0.8.2
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5
 
System Versions:
           dist: debian 8.10 
         locale: UTF-8
        machine: x86_64
        release: 3.16.0-5-amd64
         system: Linux
        version: debian 8.10 

[Ch3LL]

i'm not seeing that warning when i run this state:

salt_minion_restart:
    module.wait:
        - name: cmd.shell
        - cmd: echo test
        - order: last

[root@9671200eda30 /]# salt-call --local state.sls test -ldebug > /tmp/test 2>&1 ; grep -i warning /tmp/test
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.

But when i change the state to module.run i then see the warning:

[root@9671200eda30 /]# salt-call --local state.sls test -ldebug > /tmp/test 2>&1 ; grep -i warning /tmp/test
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[WARNING ] The function "module.run" is using its deprecated version and will expire in version "Sodium".

[root@9671200eda30 /]# salt --version
salt 2017.7.5 (Nitrogen)

Are you only running that state? Is there possibly another module.run state in there? Any other ideas on how to replicate this issue?

[Talkless]

I failed to grep module.run in my file root, there's only module.wait in my case.

I managed to reproduce with this:

mod_wait:
    module.wait:
        - name: cmd.shell
        - cmd: date

test_file:
    file.managed:
        - name: /tmp/mod_watch_test
        - contents: {{ salt['cmd.run']('date') }}
        - watch_in:
            - module: mod_wait

# salt-call state.sls test_mod_wait
[DEBUG   ] Configuration file path: /etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/gpt-salt-minion.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/gpt-salt-minion.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/zzz.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/zzz.conf
[DEBUG   ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG   ] Connecting to master. Attempt 1 (infinite attempts)
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506')
[DEBUG   ] Generated random reconnect delay between '1000ms' and '11000ms' (7766)
[DEBUG   ] Setting zmq_reconnect_ivl to '7766ms'
[DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506', 'clear')
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506')
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded state.sls
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506')
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] In saltenv 'base', looking at rel_path 'test_mod_wait.sls' to resolve 'salt://test_mod_wait.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test_mod_wait.sls' to resolve 'salt://test_mod_wait.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/test_mod_wait.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506')
[DEBUG   ] LazyLoaded cmd.run
[INFO    ] Executing command 'date' in directory '/root'
[DEBUG   ] stdout: Fri Apr 13 09:08:36 EEST 2018
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test_mod_wait.sls' using 'jinja' renderer: 0.045224905014
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/test_mod_wait.sls:
mod_wait:
    module.wait:
        - name: cmd.shell
        - cmd: date

test_file:
    file.managed:
        - name: /tmp/mod_watch_test
        - contents: Fri Apr 13 09:08:36 EEST 2018
        - watch_in:
            - module: mod_wait

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering: 
OrderedDict([('mod_wait', OrderedDict([('module.wait', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('cmd', 'date')])])])), ('test_file', OrderedDict([('file.managed', [OrderedDict([('name', '/tmp/mod_watch_test')]), OrderedDict([('contents', 'Fri Apr 13 09:08:36 EEST 2018')]), OrderedDict([('watch_in', [OrderedDict([('module', 'mod_wait')])])])])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test_mod_wait.sls' using 'yaml' renderer: 0.00681400299072
[DEBUG   ] LazyLoaded module.wait
[DEBUG   ] LazyLoaded file.managed
[INFO    ] Running state [/tmp/mod_watch_test] at time 09:08:36.215383
[INFO    ] Executing state file.managed for [/tmp/mod_watch_test]
[DEBUG   ] LazyLoaded file.source_list
[INFO    ] File changed:
--- 
+++ 
@@ -1 +1 @@
-Fri Apr 13 09:06:26 EEST 2018
+Fri Apr 13 09:08:36 EEST 2018

[INFO    ] Completed state [/tmp/mod_watch_test] at time 09:08:36.223094 duration_in_ms=7.711
[INFO    ] Running state [cmd.shell] at time 09:08:36.223439
[INFO    ] Executing state module.wait for [cmd.shell]
[INFO    ] No changes made for cmd.shell
[INFO    ] Completed state [cmd.shell] at time 09:08:36.224172 duration_in_ms=0.734
[INFO    ] Running state [cmd.shell] at time 09:08:36.224367
[INFO    ] Executing state module.mod_watch for [cmd.shell]
[WARNING ] The function "module.run" is using its deprecated version and will expire in version "Sodium".
[INFO    ] Executing command 'date' in directory '/root'
[DEBUG   ] stdout: Fri Apr 13 09:08:36 EEST 2018
[INFO    ] {'ret': 'Fri Apr 13 09:08:36 EEST 2018'}
[INFO    ] Completed state [cmd.shell] at time 09:08:36.265346 duration_in_ms=40.98
[DEBUG   ] File /var/cache/salt/minion/accumulator/140318448153552 does not exist, no need to cleanup.
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://?.?.?.?:4506')
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] LazyLoaded nested.output
[DEBUG   ] LazyLoaded nested.output
local:
----------
          ID: test_file
    Function: file.managed
        Name: /tmp/mod_watch_test
      Result: True
     Comment: File /tmp/mod_watch_test updated
     Started: 09:08:36.215383
    Duration: 7.711 ms
     Changes:   
              ----------
              diff:
                  --- 
                  +++ 
                  @@ -1 +1 @@
                  -Fri Apr 13 09:06:26 EEST 2018
                  +Fri Apr 13 09:08:36 EEST 2018
----------
          ID: mod_wait
    Function: module.wait
        Name: cmd.shell
      Result: True
     Comment: Module function cmd.shell executed
     Started: 09:08:36.224366
    Duration: 40.98 ms
     Changes:   
              ----------
              ret:
                  Fri Apr 13 09:08:36 EEST 2018

Summary for local
------------
Succeeded: 2 (changed=2)
Failed:    0
------------
Total states run:     2
Total run time:  48.691 ms

[WARNING ] The function "module.run" is using its de... is in the output.

[Talkless]

Ping @Ch3LL

[Ch3LL]

thanks for the test case I am able to replicate this now. It seems to be caused by the combination of contents and the watch_in. ping @saltstack/team-core any ideas here?

[gtmanfred]

Probably because module.wait only runs on a watch_in, and module.mod_watch is aliased to whatever module.run you are using, and if you don't move to the new module.run format (use_superseded), then the old module.run is used on a watch/listen.

https://github.com/saltstack/salt/blob/2017.7/salt/states/module.py#L554

Which is what that deprecation message is about.