Pillar data is refreshed for EVERY salt command in 2019.2.1 and 2019.2.2

[UtahDave]

Description of Issue

In Salt 2019.2.1 and 2019.2.2 the pillar top file and all pillar data are re-rendered for every single salt command that is run. Including things like salt \* test.ping

Setup

Install Salt 2019.2.1 or 2019.2.2. Set the master log to debug and tail /var/log/salt/master
Create a /srv/pillar/top.sls and add a pillar sls file so that your minion will be assigned pillar data.

Steps to Reproduce Issue

Run salt \* saltutil.refresh_pillar
Run salt \* pillar.items
Run salt \* test.ping

You'll see that the pillar top file and pillar data are rendered for every command, when pillar data should only be rendered with refresh_pillar, highstate and the other proscribed times.

2019-10-09 22:52:14,844 [salt.config      :2185][DEBUG   ][2682] Reading configuration from /etc/salt/master
2019-10-09 22:52:14,846 [salt.config      :3666][DEBUG   ][2682] Using cached minion ID from /etc/salt/minion_id: xxPing
2019-10-09 22:52:14,848 [salt.config      :2289][DEBUG   ][2682] Missing configuration file: /root/.saltrc
2019-10-09 22:52:14,851 [salt.utils.event :323 ][DEBUG   ][2682] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
2019-10-09 22:52:14,851 [salt.utils.event :324 ][DEBUG   ][2682] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
2019-10-09 22:52:14,902 [salt.transport.zeromq:138 ][DEBUG   ][2682] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/master', u'xxPing_master', u'tcp://127.0.0.1:4506', u'clear')
2019-10-09 22:52:14,902 [salt.transport.zeromq:209 ][DEBUG   ][2682] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-10-09 22:52:14,903 [salt.transport.zeromq:1189][DEBUG   ][2682] Trying to connect to: tcp://127.0.0.1:4506
2019-10-09 22:52:14,908 [salt.utils.event :738 ][DEBUG   ][1367] Sending event: tag = 20191009225214907427; data = {u'_stamp': '2019-10-09T22:52:14.908008', u'minions': [u'xxPing']}
2019-10-09 22:52:14,908 [salt.utils.event :738 ][DEBUG   ][1367] Sending event: tag = salt/job/20191009225214907427/new; data = {u'tgt_type': 'glob', u'jid': u'20191009225214907427', u'user': 'root', u'tgt': '*', u'arg': [], u'fun': 'test.ping', u'missing': [], u'_stamp': '2019-10-09T22:52:14.908485', u'minions': [u'xxPing']}
2019-10-09 22:52:14,909 [salt.loaded.int.returner.local_cache:252 ][DEBUG   ][1367] Adding minions for job 20191009225214907427: [u'xxPing']
2019-10-09 22:52:14,909 [salt.master      :2346][INFO    ][1367] User root Published command test.ping with jid 20191009225214907427
2019-10-09 22:52:14,909 [salt.master      :2354][DEBUG   ][1367] Published command details {u'tgt_type': 'glob', u'jid': u'20191009225214907427', u'tgt': '*', u'ret': '', u'user': 'root', u'arg': [], u'fun': 'test.ping'}
2019-10-09 22:52:14,910 [salt.transport.zeromq:1023][DEBUG   ][1367] Signing data packet
2019-10-09 22:52:14,910 [salt.crypt       :200 ][DEBUG   ][1367] salt.crypt.get_rsa_key: Loading private key
2019-10-09 22:52:14,910 [salt.crypt       :225 ][DEBUG   ][1367] salt.crypt.sign_message: Signing message.
2019-10-09 22:52:14,912 [salt.transport.zeromq:1045][DEBUG   ][1367] Sending payload to publish daemon. jid=20191009225214907427 size=436
2019-10-09 22:52:14,913 [salt.transport.zeromq:1050][DEBUG   ][1367] Sent payload to publish daemon.
2019-10-09 22:52:14,913 [salt.transport.zeromq:906 ][DEBUG   ][1351] Publish daemon received payload. size=436
2019-10-09 22:52:14,913 [salt.transport.zeromq:904 ][DEBUG   ][1351] Publish daemon getting data from puller ipc:///var/run/salt/master/publish_pull.ipc
2019-10-09 22:52:14,915 [salt.transport.zeromq:233 ][DEBUG   ][2682] Closing AsyncZeroMQReqChannel instance
2019-10-09 22:52:14,918 [salt.utils.lazy  :104 ][DEBUG   ][2682] LazyLoaded local_cache.get_load
2019-10-09 22:52:14,919 [salt.loaded.int.returner.local_cache:323 ][DEBUG   ][2682] Reading minion list from /var/cache/salt/master/jobs/b4/e944dfcf53c1e383d37c3ee6d8ec3527e964ddb669dbdc03e22e3026504c0b/.minions.p
2019-10-09 22:52:14,920 [salt.client      :1100][DEBUG   ][2682] get_iter_returns for jid 20191009225214907427 sent to set(['xxPing']) will timeout at 22:52:19.919999
2019-10-09 22:52:14,927 [salt.pillar      :57  ][DEBUG   ][1366] Determining pillar cache
2019-10-09 22:52:14,968 [salt.utils.lazy  :104 ][DEBUG   ][1366] LazyLoaded jinja.render
2019-10-09 22:52:14,969 [salt.utils.lazy  :104 ][DEBUG   ][1366] LazyLoaded yaml.render
2019-10-09 22:52:14,981 [salt.template    :59  ][DEBUG   ][1366] compile template: /srv/pillar/top.sls
2019-10-09 22:52:14,981 [salt.utils.jinja :83  ][DEBUG   ][1366] Jinja search path: [u'/srv/pillar', u'/srv/spm/pillar']
2019-10-09 22:52:14,982 [salt.template    :26  ][PROFILE ][1366] Time (in seconds) to render '/srv/pillar/top.sls' using 'jinja' renderer: 0.00102114677429
2019-10-09 22:52:14,983 [salt.template    :120 ][DEBUG   ][1366] Rendered data from file: /srv/pillar/top.sls:
base:
  '*':
    - test

2019-10-09 22:52:14,983 [salt.loaded.int.render.yaml:80  ][DEBUG   ][1366] Results of YAML rendering:
OrderedDict([(u'base', OrderedDict([(u'*', [u'test'])]))])
2019-10-09 22:52:14,984 [salt.template    :26  ][PROFILE ][1366] Time (in seconds) to render '/srv/pillar/top.sls' using 'yaml' renderer: 0.000813007354736
2019-10-09 22:52:14,985 [salt.utils.lazy  :104 ][DEBUG   ][1366] LazyLoaded confirm_top.confirm_top
2019-10-09 22:52:14,987 [salt.utils.lazy  :104 ][DEBUG   ][1366] LazyLoaded compound_match.match
2019-10-09 22:52:14,989 [salt.loaded.int.matchers.compound_match:35  ][DEBUG   ][1366] compound_match: xxPing ? *
2019-10-09 22:52:14,989 [salt.utils.lazy  :104 ][DEBUG   ][1366] LazyLoaded glob_match.match
2019-10-09 22:52:14,990 [salt.loaded.int.matchers.compound_match:108 ][DEBUG   ][1366] compound_match xxPing ? "*" => "True"
2019-10-09 22:52:14,990 [salt.template    :59  ][DEBUG   ][1366] compile template: /srv/pillar/test.sls
2019-10-09 22:52:14,991 [salt.utils.jinja :83  ][DEBUG   ][1366] Jinja search path: [u'/srv/pillar', u'/srv/spm/pillar']
2019-10-09 22:52:14,991 [salt.template    :26  ][PROFILE ][1366] Time (in seconds) to render '/srv/pillar/test.sls' using 'jinja' renderer: 0.000850915908813
2019-10-09 22:52:14,992 [salt.template    :120 ][DEBUG   ][1366] Rendered data from file: /srv/pillar/test.sls:
boucha: True

2019-10-09 22:52:14,992 [salt.loaded.int.render.yaml:80  ][DEBUG   ][1366] Results of YAML rendering:
OrderedDict([(u'boucha', True)])
2019-10-09 22:52:14,992 [salt.template    :26  ][PROFILE ][1366] Time (in seconds) to render '/srv/pillar/test.sls' using 'yaml' renderer: 0.000324964523315
2019-10-09 22:52:14,993 [salt.utils.event :738 ][DEBUG   ][1366] Sending event: tag = minion/refresh/xxPing; data = {u'Minion data cache refresh': 'xxPing', u'_stamp': '2019-10-09T22:52:14.993499'}
2019-10-09 22:52:14,994 [salt.crypt       :208 ][DEBUG   ][1366] salt.crypt.get_rsa_pub_key: Loading public key
2019-10-09 22:52:15,072 [salt.utils.job   :68  ][INFO    ][1358] Got return from xxPing for job 20191009225214907427
2019-10-09 22:52:15,072 [salt.utils.event :738 ][DEBUG   ][1358] Sending event: tag = salt/job/20191009225214907427/ret/xxPing; data = {'fun_args': [], 'jid': '20191009225214907427', 'return': True, 'retcode': 0, 'success': True, 'cmd': '_return', u'_stamp': '2019-10-09T22:52:15.072368', 'fun': 'test.ping', 'id': 'xxPing'}
2019-10-09 22:52:15,073 [salt.client      :1129][DEBUG   ][2682] jid 20191009225214907427 return from xxPing
2019-10-09 22:52:15,074 [salt.client      :1529][DEBUG   ][2682] return event: {u'xxPing': {u'jid': u'20191009225214907427', u'retcode': 0, u'ret': True}}
2019-10-09 22:52:15,076 [salt.utils.lazy  :104 ][DEBUG   ][2682] LazyLoaded nested.output
2019-10-09 22:52:15,178 [salt.client      :1135][DEBUG   ][2682] jid 20191009225214907427 found all minions set([u'xxPing'])
2019-10-09 22:52:15,179 [salt.transport.ipc:364 ][DEBUG   ][2682] Closing IPCMessageSubscriber instance

Versions Report

[root@xxPing ~]# salt \* test.versions_report
xxPing:
    Salt Version:
               Salt: 2019.2.1

    Dependency Versions:
               cffi: Not Installed
           cherrypy: Not Installed
           dateutil: Not Installed
          docker-py: Not Installed
              gitdb: Not Installed
          gitpython: Not Installed
              ioflo: Not Installed
             Jinja2: 2.7.2
            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
       pycryptodome: Not Installed
             pygit2: Not Installed
             Python: 2.7.5 (default, Aug  7 2019, 00:51:29)
       python-gnupg: Not Installed
             PyYAML: 3.11
              PyZMQ: 15.3.0
               RAET: Not Installed
              smmap: Not Installed
            timelib: Not Installed
            Tornado: 4.2.1
                ZMQ: 4.1.4

    System Versions:
               dist: centos 7.7.1908 Core
             locale: ascii
            machine: x86_64
            release: 4.15.0-65-generic
             system: Linux
            version: CentOS Linux 7.7.1908 Core

[UtahDave]

I tested on 2019.2.0 and this issue did NOT occur

[KChandrashekhar]

Closing as the issue is fixed via #54942