Grains refreshes every time you run salt cmd

[angeloudy]

Grains data get refreshed every time you run salt or salt-run cmd.
I think it was introduced by this #18351
After I added the following lines the minion config, it stops refreshing the minion grains.

grains_cache: True
grains_cache_expiration: 86400

This can stop the minion refreshing grains data, which helped improving the performance.

The question now is how do I prevent salt-run from refreshing the grains.
I have a lot of runners that run as schedulers. Refreshing all grains introduces some unnecessary overhead.

[dwoz]

@saltstack/team-core Does anyone have input to provide on this?

[waynew]

I'll look into this tomorrow.

[waynew]

Hi @angeloudym, thanks for the report!

When you say that the grains are being refreshed, what do you mean?

I'm only seeing the grains refresh when reload_grains: True is in a state, e.g.

this will reload grains:
  test.nop:
    - reload_grains: True

If that's present, it'll reload the grains, but otherwise I'm not seeing that happen.

Can you produce a mcve that demonstrates the issue that you're seeing?

[angeloudy]

My first observation was that every time I run the salt-run cmd, no matter it's a runner or orchestration runner, I will see the following in the log(My default log level is set to INFO).

10:03:55,971 [INFO    ] Executing command '/sbin/zpool list -H -o name,size' in directory '/root'
10:03:56,831 [INFO    ] Executing command '/sbin/zpool list -H -o name,size' in directory '/root'

From my understanding, these /sbin/zpool list are only called when refreshing grains.

To verify,

1. create a orchestration runner

test.sls

test_deploy_server:
  salt.function:
    - name: test.ping
    - tgt: 'colo2.ns3'

2. salt-run state.orch orchestration.test -l info
   Output is

10:03:55,971 [INFO    ] Executing command '/sbin/zpool list -H -o name,size' in directory '/root'
10:03:56,831 [INFO    ] Executing command '/sbin/zpool list -H -o name,size' in directory '/root'
10:03:57,689 [INFO    ] Loading fresh modules for state activity
10:03:57,841 [INFO    ] Running state [test.ping] at time 10:03:57.840555
10:03:57,841 [INFO    ] Executing state salt.function for [test.ping]
10:03:58,239 [INFO    ] {'out': 'highstate', 'ret': {'colo2.ns3': True}}
10:03:58,239 [INFO    ] Completed state [test.ping] at time 10:03:58.239030 (duration_in_ms=398.477)
ish.delish_master:
----------
          ID: test_deploy_server
    Function: salt.function
        Name: test.ping
      Result: True
     Comment: Function ran successfully. Function test.ping ran on colo2.ns3.
     Started: 10:03:57.840553
    Duration: 398.477 ms
     Changes:
              colo2.ns3:
                  True
Summary for salt_master
------------
Succeeded: 1 (changed=1)
Failed:    0
------------

3. Add logging in /usr/local/lib/python3.6/site-packages/salt/grains/zfs.py

--- /usr/local/lib/python3.6/site-packages/salt/grains/zfs.py.old
+++ /usr/local/lib/python3.6/site-packages/salt/grains/zfs.py
@@ -55,6 +55,7 @@ def _zfs_pool_data():
     grains = {}

     # collect zpool data
+    log.info("collecting zpool data")
     zpool_list_cmd = __utils__['zfs.zpool_command'](
         'list',
         flags=['-H'],

Then run salt-run state.orch orchestration.test -l info

Output is

10:15:36,194 [INFO    ] collecting zpool data
10:15:36,195 [INFO    ] Executing command '/sbin/zpool list -H -o name,size' in directory '/root'
10:15:39,221 [INFO    ] collecting zpool data
10:15:39,222 [INFO    ] Executing command '/sbin/zpool list -H -o name,size' in directory '/root'
10:15:40,455 [INFO    ] Loading fresh modules for state activity
10:15:40,623 [INFO    ] Running state [test.ping] at time 10:15:40.622735
10:15:40,623 [INFO    ] Executing state salt.function for [test.ping]
10:15:41,018 [INFO    ] {'out': 'highstate', 'ret': {'colo2.ns3': True}}
10:15:41,018 [INFO    ] Completed state [test.ping] at time 10:15:41.018350 (duration_in_ms=395.616)
ish.delish_master:
----------
          ID: test_deploy_server
    Function: salt.function
        Name: test.ping
      Result: True
     Comment: Function ran successfully. Function test.ping ran on colo2.ns3.
     Started: 10:15:40.622734
    Duration: 395.616 ms
     Changes:
              colo2.ns3:
                  True

Summary for salt_master
------------
Succeeded: 1 (changed=1)
Failed:    0
------------
Total states run:     1
Total run time: 395.616 ms

salt --versions-report
Salt Version:
           Salt: 2018.3.3

Dependency Versions:
           cffi: 1.11.5
       cherrypy: unknown
       dateutil: 2.7.3
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: 1.3.13
      pycparser: 2.18
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 3.6.8 (default, Feb 11 2019, 00:06:41)
   python-gnupg: Not Installed
         PyYAML: 3.13
          PyZMQ: 17.0.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.3

System Versions:
           dist:
         locale: UTF-8
        machine: amd64
        release: 11.2-RELEASE-p7
         system: FreeBSD
        version: Not Installed

[angeloudy]

In fact, if you run salt-run cmd in debug level, you can see

10:16:53,006 [DEBUG   ] Grains refresh requested. Refreshing grains.

[Trouble123]

Hi,

I am seeing this on 2019.2.0 as well. Just doing a test.ping takes about 6 seconds - and looking at the debug on the (windows) minion - i could see the "Grains refresh requested. Refreshing grains.".
I set the minion grains_refresh setting as per the first post, and the test.ping now takes 2 seconds.

Is there a way to change this without having to update each minion config file?

[waynew]

That's interesting - I wonder if this is due to orchestration. I've seen a couple of things come across recently about salt-run vs salt.

[Trouble123]

In my testing i did it on the master both via salt 'minion' test.ping, and also sending it to the CherryPy API.

[waynew]

I guess the main question is what is setting 'reload_grains' (or does that default to True in the config?)

There's not much documentation for reload_grains, which is kind of disappointing.

[stale]

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.

[mschiff]

I am having the same issue in 2019.2.3 without any orchestration.

Running one state via salt 'minion' state.sls somestate will refresh the grains 4 times in my case. The sls has 4 states in it: 3 times file.managed and one pkg/service thingy

I never have set reload_grains anywhere

[gcamblin]

I'm seeing this issue in 3000.3. The grains are being refreshed on every salt command run from the master. Even test.ping.

We have a custom grain which can't reach an external api and the python requests module goes into retry mode. The result is the minion does not return.

[tobiasvdk]

This also happens with 3003.3.

It looks like the grains are refreshed every time on module invocation and when __salt__ is used. E.g.

$ sudo salt-run salt.cmd file.grep /tmp/foo foo -l debug 2>&1 | grep 'Grains refresh'
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Grains refresh requested. Refreshing grains.

$ sudo salt -V
Salt Version:
          Salt: 3003.3
 
Dependency Versions:
          cffi: Not Installed
      cherrypy: unknown
      dateutil: 2.8.1
     docker-py: Not Installed
         gitdb: 4.0.5
     gitpython: 3.1.14
        Jinja2: 2.11.3
       libgit2: 1.1.0
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.0
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: 2.20
      pycrypto: Not Installed
  pycryptodome: 3.9.7
        pygit2: 1.4.0
        Python: 3.9.2 (default, Feb 28 2021, 17:03:44)
  python-gnupg: Not Installed
        PyYAML: 5.3.1
         PyZMQ: 20.0.0
         smmap: 4.0.0
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.3.4
 
System Versions:
          dist: debian 11 bullseye
        locale: utf-8
       machine: x86_64
       release: 5.10.0-8-amd64
        system: Linux
       version: Debian GNU/Linux 11 bullseye
 

[tobiasvdk]

@waynew : can you re-open the ticket or should I create a new one?

[ninoY25]

The reason why salt grains refreshes every time you run the salt runner command is that when salt runner execute some commands, it will initialize a MasterMinion first

salt/salt/client/mixins.py

Line 299 in b30ccda

self.mminion # pylint: disable=W0104

And the masterminion class will reload the grains during initialization

salt/salt/minion.py

Line 977 in b30ccda

self.opts["grains"] = salt.loader.grains(opts)

To avoid this, I added these lines to master config. It will cache grains for masterminion. Therefore, it will not refresh grains everytime you run the salt runner commands.

grains_cache: True
grains_cache_expiration: 600