Salt: [BUG] salt-proxy unable to render states with jinja tags such as "from" and "import_yaml"

[lomeroe]

Description
salt-proxy minions are unable to render state files that load other files through jinja statements such as from and import_yaml. The minion seems to never receive the message response from the future returned from the channel.send (if it ever even makes it to the master).

Setup
salt-master (no special config)
salt-proxy minion (dummy minion)

state/default files:

works.sls:

{% set v = 'asdf' %}
/not/real:
  file.managed:
    - name: works
    - defaults:
        something: {{ v }}

defaults.yml

adefault: 'value'

noworky.sls:

{% import_yaml 'defaults.yml' as d -%}
/not/real:
  file.managed:
    - source: salt://some/path
    - defaults: {{ d|tojson }}

Steps to Reproduce the behavior

working state:

salt 'dummytest' state.show_sls works
dummytest:
    ----------
    /not/real:
        ----------
        __env__:
            base
        __sls__:
            works
        file:
            |_
              ----------
              name:
                  works
            |_
              ----------
              defaults:
                  ----------
                  something:
                      asdf
            - managed
            |_
              ----------
              order:
                  10000

not working state:

#salt 'dummytest' state.show_sls noworky
Minion did not return

you can see the show_sls is still running (and will forever) with saltutil.running:

#salt 'dummytest' saltutil.running
jid: 20200415224756813557
dummytest:
    |_
      ----------
      arg:
          - noworky
      fun:
          state.show_sls
      jid:
          20200415223939878042
      master_id:
          my_awesome_master
      pid:
          6564
      ret:
      tgt:
          dummy*
      tgt_type:
          glob
      user:
          root

Expected behavior
A proxy minion can render a state with jinja "from" or "import_*" statements.

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

Versions Report

Salt Version:
           Salt: 3000.1

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 1.5
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
         Jinja2: 2.7.2
        libgit2: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.6.2
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.5 (default, Aug  7 2019, 00:51:29)
   python-gnupg: 0.4.3
         PyYAML: 3.11
          PyZMQ: 15.3.0
          smmap: Not Installed
        timelib: 0.2.4
        Tornado: 4.5.3
            ZMQ: 4.1.4

System Versions:
           dist: centos 7.7.1908 Core
         locale: UTF-8
        machine: x86_64
        release: 3.10.0-1062.18.1.el7.x86_64
         system: Linux
        version: CentOS Linux 7.7.1908 Core

Same issues in 2019.2

Additional context
Adding debug statements the hang seems to appear in fileclient.py in __hash_and_stat_file the future is returned from the "self.channel.send(load)" statement, but from what I can tell the response never comes in. It doesn't seem like the master ever gets the request either (again from adding extra debug statements in the fileserver/roots.py file)

For example, adding debugging in fileclient.py:

    def __hash_and_stat_file(self, path, saltenv='base'):
        '''
        Common code for hashing and stating files
        '''
        log.debug('ELM - __hash_and_stat_file path = {}'.format(path))
        try:
            path = self._check_proto(path)
        except MinionError as err:
            if not os.path.isfile(path):
                log.warning(
                    'specified file %s is not present to generate hash: %s',
                    path, err
                )
                return {}, None
            else:
                ret = {}
                hash_type = self.opts.get('hash_type', 'md5')
                ret['hsum'] = salt.utils.hashutils.get_hash(path, form=hash_type)
                ret['hash_type'] = hash_type
                return ret
        load = {'path': path,
                'saltenv': saltenv,
                'cmd': '_file_hash'}
        log.debug('ELM - sending load {} to cahnnel'.format(load))
        return self.channel.send(load)

and in fileserver/roots.py:

def find_file(path, saltenv='base', **kwargs):
    '''
    Search the environment for the relative path.
    '''
    if 'env' in kwargs:
        # "env" is not supported; Use "saltenv".
        kwargs.pop('env')

    log.debug('ELM - searching for path {}'.format(path))

salt-proxy output from works.sls

[DEBUG   ] ELM - __hash_and_stat_file path = salt://works.sls
[DEBUG   ] ELM - sending load {u'path': u'works.sls', u'saltenv': u'base', u'cmd': u'_file_hash'} to cahnnel
[DEBUG   ] In saltenv 'base', looking at rel_path 'works.sls' to resolve 'salt://works.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummytest/files/base/works.sls' to resolve 'salt://works.sls'
[DEBUG   ] ELM - __hash_and_stat_file path = /var/cache/salt/proxy/dummytest/files/base/works.sls
[DEBUG   ] compile template: /var/cache/salt/proxy/dummytest/files/base/works.sls
[DEBUG   ] Jinja search path: [u'/var/cache/salt/proxy/dummytest/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/proxy/dummytest/files/base/works.sls' using 'jinja' renderer: 0.00307297706604
[DEBUG   ] Rendered data from file: /var/cache/salt/proxy/dummytest/files/base/works.sls:

/not/real:
  file.managed:
    - name: works
    - defaults:
        something: asdf

[DEBUG   ] Results of YAML rendering:

proxy output from noworky.sls

DEBUG   ] ELM - __hash_and_stat_file path = salt://noworky.sls
[DEBUG   ] ELM - sending load {u'path': u'noworky.sls', u'saltenv': u'base', u'cmd': u'_file_hash'} to cahnnel
[DEBUG   ] In saltenv 'base', looking at rel_path 'noworky.sls' to resolve 'salt://noworky.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummytest/files/base/noworky.sls' to resolve 'salt://noworky.sls'
[DEBUG   ] ELM - __hash_and_stat_file path = /var/cache/salt/proxy/dummytest/files/base/noworky.sls
[DEBUG   ] compile template: /var/cache/salt/proxy/dummytest/files/base/noworky.sls
[DEBUG   ] Jinja search path: [u'/var/cache/salt/proxy/dummytest/files/base']
[DEBUG   ] ELM - __hash_and_stat_file path = salt://defaults.yml
[DEBUG   ] ELM - sending load {u'path': u'defaults.yml', u'saltenv': u'base', u'cmd': u'_file_hash'} to cahnnel

master output from noworky.sls:

[DEBUG   ] Gathering reactors for tag minion/refresh/dummytest
[DEBUG   ] ELM - searching for path noworky.sls
[DEBUG   ] ELM - searching for path noworky.sls
[DEBUG   ] Sending event: tag = 20200415225320495367; data = {u'_stamp': '2020-04-15T22:53:20.495820', u'minions': ['dummytest']}
[DEBUG   ] Sending event: tag = salt/job/20200415225320495367/new; data = {u'tgt_type': 'list', u'jid': u'20200415225320495367', u'user': 'root', u'tgt': ['dummytest'], u'arg': ['20200415225315450363'], u'fun': 'saltutil.find_job', u'missing': [], u'_stamp': '2020-04-15T22:53:20.496409', u'minions': ['dummytest']}

Looks like the minion thinks it sent the load, but the master doesn't seem to pick it up

I'm out of my element here, so I may be looking in the wrong spots...I'll take any direction to help troubleshoot.

Other information that may/may not be helpful:

Regular "include" statements work (as long as the included file doesn't have any jinja loads/etc). For example:

include:
  - some.other.state

...

[Akm0d]

@lomeroe Thank you for submitting the issue! I want to label this as a feature given that there are no errors in the logs you shared; Unless we can verify that what you are seeing isn't documented behavior.

[lomeroe]

I'll respectfully disagree that this is a feature add. In my opinion, this is standard functionality of the state templating system and it is not documented anywhere (that I can find) that the salt-proxy minion is exempt from using any subset of any jinja tags. However, you can obviously label it how you want.

That said, I was able to work around the problem, though it feels like a big hammer.

It turns out the fileclient channel is not actually open when it tries to send (why, I cannot say at this point). This makes sense why the future never gets a return, b/c no one is on the other end of the channel.

In the __hash_and_stat_file function of the RemoteClient, adding a call to the _refresh_channel function prior to the send makes the other files load properly...

The real question is probably "why isn't the channel open, even though it is instantiated as part of the RemoteClient class init?" It is not obvious to me as it seems to be initialized with the same options/etc that the _refresh_channel uses.

Work around code.

    def __hash_and_stat_file(self, path, saltenv='base'):
        '''
        Common code for hashing and stating files
        '''
        try:
            path = self._check_proto(path)
        except MinionError as err:
            if not os.path.isfile(path):
                log.warning(
                    'specified file %s is not present to generate hash: %s',
                    path, err
                )
                return {}, None
            else:
                ret = {}
                hash_type = self.opts.get('hash_type', 'md5')
                ret['hsum'] = salt.utils.hashutils.get_hash(path, form=hash_type)
                ret['hash_type'] = hash_type
                return ret
        load = {'path': path,
                'saltenv': saltenv,
                'cmd': '_file_hash'}
        self._refresh_channel() # if this is not run, the send will never return
        return self.channel.send(load)

I'm not seeing a way to check if the channel is open/connected so it could conditionally be refreshed (the other usage of the refresh_channel function is an an exception -- no exception is ever thrown here, so it can't be used that way).

Hopefully someone that better understands the FileClient will be able to say how this could be resolved for efficiently...

[hupebln]

Hey,
we faced the same problem you face. We see a difference in the behavior of dummy-proxies and napalm-proxies.
With napalm it renders fine, without any issues, but not with dummy-proxies.
I tried to follow the workflow of slsutil.renderer and at the point of this line I compared the decoded_context and found a difference in multiprocessing.
Multiprocessing is enabled in the dummy-proxy, but not in the napalm-proxy.
When we set multiprocessing to false in dummy-proxies it is working as expected.

[hemebond]

To help searchers, this also affects import_json. Putting multiprocessing: False into the proxy minion config or updating fileclient.RemoteClient.get_file() with:

        if not salt.utils.platform.is_windows():
            self._refresh_channel()
            hash_server, stat_server = self.hash_and_stat_file(path, saltenv)

also works even in the latest master branch commit where the issue is still present.