[BUG] module.run new style defintion is identified as legacy

[redbaron4]

Description
New style module.run is considered legacy Salt version - 3005 leading to failures

Setup

Consider a state file that has the following state to invoke a custom module something.do

some foo:
  module.wait:
    - something.do:
      - config: /etc/foo
      - foo: bar

And this state is referenced in another stae file

my_pkg:
  pkg.installed:
    - name: mypkg
    - require:
      - pkgrepo: custom_repo_stable
      - pkgrepo: custom_repo_testing
    - watch_in:
      - module: some foo

Trying to run the state causes an error Module function some foo is not available

Steps to Reproduce the behavior

The debug logs are

[INFO    ] Executing state module.mod_watch for [some foo]
[DEBUG   ] Detected legacy module.run syntax: some foo
[ERROR   ] Module function some foo is not available

Expected behavior

The state should be detected as using new style module.run and should run as expected

Screenshots
If applicable, add screenshots to help explain your problem.

Versions Report

salt --versions-report

(Provided by running salt --versions-report. Please also mention any differences in master/minion versions.)

Salt Version:
          Salt: 3005
 
Dependency Versions:
          cffi: 1.14.6
      cherrypy: 18.6.1
      dateutil: 2.8.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.1.0
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: 2.21
      pycrypto: Not Installed
  pycryptodome: 3.9.8
        pygit2: Not Installed
        Python: 3.9.13 (main, Aug 23 2022, 18:33:26)
  python-gnupg: 0.4.8
        PyYAML: 5.4.1
         PyZMQ: 23.2.0
         smmap: Not Installed
       timelib: 0.2.4
       Tornado: 4.5.3
           ZMQ: 4.3.4
 
System Versions:
          dist: rocky 8.6 Green Obsidian
        locale: utf-8
       machine: x86_64
       release: 4.18.0-372.16.1.el8_6.0.1.x86_64
        system: Linux
       version: Rocky Linux 8.6 Green Obsidian

Additional context

Tinkering with the source in states/modules.py to add logging for offending keys that are triggering detection as legacy style gives following logs

[INFO    ] Executing state module.mod_watch for [some foo]
[DEBUG   ] ['name', 'something.do', 'sfun', '__reqs__']
[DEBUG   ] Detected legacy module.run syntax: some foo
[ERROR   ] Module function some foo is not available

which shows that additional kwargs sfun and __reqs__ which are not handled in code maybe triggering the legacy flag. The code ignores the name kwarg but does not handle the other two addtional kwargs.

[OrangeDog]

What happens if you use

• watch on the module.wait state?
• module.run and onchanges_in?

[redbaron4]

Thanks for looking at this @OrangeDog .

The states are a part of cmplex setup which I cannot tinker too much. I will try to setup a simpler environment on a test machine to reproduce this and add more information

[redbaron4]

@OrangeDog I have reproduced this in a simpler setup

There is a custom module testme.py which has a function run that returns sum of passed two arguments

# cat _modules/testme.py 
"""
Execution module that runs dummy things
"""
def __virtual__():
    return True


def run(arg1=1, arg2=2):
    """
    Runs the dummy thing to add the result
    Returns a dictionary with following keys:
        result: Int
    """
    try:
        arg1 = int(arg1)
    except ValueError:
        arg1 = 1
    try:
        arg2 = int(arg2)
    except ValueError:
        arg2 = 2
    return dict(result=arg1 + arg2)

I have added a logging line after this line on minion to log the keys

log.debug(keys)

Case 1 - require and module.run - Pass

/home/admin/test.txt:
  file.managed:
    - source: salt://teststate/test.txt

run mod:
  module.run:
    - testme.run:
      - arg1: 2
      - arg2: 3
    - require:
      - file: /home/admin/test.txt


[INFO    ] File /home/admin/test.txt is in the correct state
[INFO    ] Completed state [/home/admin/test.txt] at time 12:19:23.933458 (duration_in_ms=94.802)
[DEBUG   ] The functions from module 'module' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded module.run
[INFO    ] Running state [run mod] at time 12:19:23.938162
[INFO    ] Executing state module.run for [run mod]
[DEBUG   ] ['name', 'testme.run']
[DEBUG   ] Using new style module.run syntax: run mod
[DEBUG   ] The functions from module 'testme' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded testme.run
[INFO    ] {'testme.run': {'result': 5}}
[INFO    ] Completed state [run mod] at time 12:19:23.941001 (duration_in_ms=2.84)
[DEBUG   ] File /var/cache/salt/minion/accumulator/139927910436384 does not exist, no need to cleanup
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'testme', 'tcp://10.44.0.254:4506')
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'highstate' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
local:
----------
          ID: /home/admin/test.txt
    Function: file.managed
      Result: True
     Comment: File /home/admin/test.txt is in the correct state
     Started: 12:19:23.838656
    Duration: 94.802 ms
     Changes:   
----------
          ID: run mod
    Function: module.run
      Result: True
     Comment: testme.run: Success
     Started: 12:19:23.938161
    Duration: 2.84 ms
     Changes:   
              ----------
              testme.run:
                  ----------
                  result:
                      5

Summary for local
------------
Succeeded: 2 (changed=1)
Failed:    0

Case 2 - module.wait and watch - FAIL

/home/admin/test.txt:
  file.managed:
    - source: salt://teststate/test.txt

run mod:
  module.wait:
    - testme.run:
      - arg1: 2
      - arg2: 3
    - watch:
      - file: /home/admin/test.txt




[INFO    ] File changed:
--- 
+++ 
@@ -1 +1 @@
-This is a atest
+This is a test

[INFO    ] Completed state [/home/admin/test.txt] at time 12:21:24.797364 (duration_in_ms=108.149)
[DEBUG   ] The functions from module 'module' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded module.wait
[INFO    ] Running state [run mod] at time 12:21:24.801828
[INFO    ] Executing state module.wait for [run mod]
[INFO    ] No changes made for run mod
[INFO    ] Completed state [run mod] at time 12:21:24.803381 (duration_in_ms=1.553)
[INFO    ] Running state [run mod] at time 12:21:24.803566
[INFO    ] Executing state module.mod_watch for [run mod]
[DEBUG   ] ['name', 'testme.run', 'sfun', '__reqs__']
[DEBUG   ] Detected legacy module.run syntax: run mod
[ERROR   ] Module function run mod is not available
[INFO    ] Completed state [run mod] at time 12:21:24.805762 (duration_in_ms=2.197)
[DEBUG   ] File /var/cache/salt/minion/accumulator/140029543093968 does not exist, no need to cleanup
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'testme', 'tcp://10.44.0.254:4506')
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'highstate' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
local:
----------
          ID: /home/admin/test.txt
    Function: file.managed
      Result: True
     Comment: File /home/admin/test.txt updated
     Started: 12:21:24.689215
    Duration: 108.149 ms
     Changes:   
              ----------
              diff:
                  --- 
                  +++ 
                  @@ -1 +1 @@
                  -This is a atest
                  +This is a test
----------
          ID: run mod
    Function: module.wait
      Result: False
     Comment: Module function run mod is not available
     Started: 12:21:24.803565
    Duration: 2.197 ms
     Changes:   

Summary for local
------------
Succeeded: 1 (changed=1)
Failed:    1
------------

Case 3 - watch_in and module.wait - FAIL

/home/admin/test.txt:
  file.managed:
    - source: salt://teststate/test.txt
    - watch_in:
      - module: run mod

run mod:
  module.wait:
    - testme.run:
      - arg1: 2
      - arg2: 3



[INFO    ] File changed:
--- 
+++ 
@@ -1 +1 @@
-This is a test
+This is a 1test

[INFO    ] Completed state [/home/admin/test.txt] at time 12:23:19.576680 (duration_in_ms=112.551)
[DEBUG   ] The functions from module 'module' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded module.wait
[INFO    ] Running state [run mod] at time 12:23:19.580872
[INFO    ] Executing state module.wait for [run mod]
[INFO    ] No changes made for run mod
[INFO    ] Completed state [run mod] at time 12:23:19.582311 (duration_in_ms=1.44)
[INFO    ] Running state [run mod] at time 12:23:19.582510
[INFO    ] Executing state module.mod_watch for [run mod]
[DEBUG   ] ['name', 'testme.run', 'sfun', '__reqs__']
[DEBUG   ] Detected legacy module.run syntax: run mod
[ERROR   ] Module function run mod is not available
[INFO    ] Completed state [run mod] at time 12:23:19.584487 (duration_in_ms=1.977)
[DEBUG   ] File /var/cache/salt/minion/accumulator/140288176837872 does not exist, no need to cleanup
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'testme', 'tcp://10.44.0.254:4506')
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'highstate' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
local:
----------
          ID: /home/admin/test.txt
    Function: file.managed
      Result: True
     Comment: File /home/admin/test.txt updated
     Started: 12:23:19.464129
    Duration: 112.551 ms
     Changes:   
              ----------
              diff:
                  --- 
                  +++ 
                  @@ -1 +1 @@
                  -This is a test
                  +This is a 1test
----------
          ID: run mod
    Function: module.wait
      Result: False
     Comment: Module function run mod is not available
     Started: 12:23:19.582510
    Duration: 1.977 ms
     Changes:   

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

Case 4 - onchanges_in and module.run

/home/admin/test.txt:
  file.managed:
    - source: salt://teststate/test.txt
    - onchanges_in:
      - module: run mod

run mod:
  module.run:
    - testme.run:
      - arg1: 2
      - arg2: 3

[INFO    ] File changed:
--- 
+++ 
@@ -1 +1 @@
-This is a 1test
+This is a 2test

[INFO    ] Completed state [/home/admin/test.txt] at time 12:24:42.585717 (duration_in_ms=510.178)
[DEBUG   ] The functions from module 'module' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded module.run
[INFO    ] Running state [run mod] at time 12:24:42.590048
[INFO    ] Executing state module.run for [run mod]
[DEBUG   ] ['name', 'testme.run']
[DEBUG   ] Using new style module.run syntax: run mod
[DEBUG   ] The functions from module 'testme' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded testme.run
[INFO    ] {'testme.run': {'result': 5}}
[INFO    ] Completed state [run mod] at time 12:24:42.592917 (duration_in_ms=2.869)
[DEBUG   ] File /var/cache/salt/minion/accumulator/140063312561392 does not exist, no need to cleanup
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'testme', 'tcp://10.44.0.254:4506')
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'highstate' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded highstate.output
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
[DEBUG   ] The functions from module 'nested' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded nested.output
local:
----------
          ID: /home/admin/test.txt
    Function: file.managed
      Result: True
     Comment: File /home/admin/test.txt updated
     Started: 12:24:42.075539
    Duration: 510.178 ms
     Changes:   
              ----------
              diff:
                  --- 
                  +++ 
                  @@ -1 +1 @@
                  -This is a 1test
                  +This is a 2test
----------
          ID: run mod
    Function: module.run
      Result: True
     Comment: testme.run: Success
     Started: 12:24:42.590048
    Duration: 2.869 ms
     Changes:   
              ----------
              testme.run:
                  ----------
                  result:
                      5

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

It looks like module.wait adds the sfun and __reqs__ keys which break the code.

In our setup, we cannot easily switch to the onchanges_in and module.run because of complex state dependencies which are better handled by module.wait

[OrangeDog]

I think module.run with onchanges_in should behave exactly the same as module.wait with watch_in.

I don't know how long it's going to take for someone to get around to fixing this.

[redbaron4]

I can take a stab at generating a PR for this if the change is to simply ignore sfun and __reqs__. Looking at the code, it doesn't look like any other keys are expected.