saltstack / saltstack/salt

[BUG] Race condition in master fileserver file_list cache rebuild

Open
#61,407 5 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug Core Performance severity-low
Dominant language
Python
Stars
15.7k
Forks
5.6k
Avg merge
2d 44m
Merged PRs (30d)
80

Description

Description

Executing a state on minion(s) will cause the file list cache on the master to
be rebuilt an indeterminate number of times. There is high CPU utilization on
the master because of the repeated rebuilds. The amount of time for a state
run to complete is a function of the number of minions running the state, how
many files are in the fileserver, and the number of times the master
regenerates the filename cache.

Setup

Environment is in AWS EC2, t3.large for master, t3.small for 6 minions.
There are no pillars to minimize pillar rendering from being a consideration
in the performance.

I have tested two different configurations, one with gitfs+roots backends and
one with just the roots backend.

In order to make the file_list rebuild process take a somewhat "long" time (seconds),
I have a test git repo filled with about 55K files, which are just multiple copies of the
salt source tree. The same 55K files are also copied into /srv/bigjunk on the
master.

master config w/ gitfs:

gitfs_provider: gitpython

gitfs_remotes:
  - git@gitfs:duckfez/gitfs.git:
      - name: gitfs
      - base: main
      - mountpoint: salt://gitfs

fileserver_backend:
  - roots
  - gitfs

file_roots:
  base:
    - /srv/salt

log_level: warning
log_fmt_console: '%(asctime)s,%(msecs)03d [%(name)-17s][%(colorlevel)s] %(message)s'
log_level_logfile: all
log_fmt_logfile: '%(asctime)s,%(msecs)03d [%(process)d][%(name)-17s][%(levelname)-8s] %(message)s'

master config w/ roots only:

fileserver_backend:
  - roots
file_roots:
  base:
    - /srv/salt
    - /srv/bigjunk
log_level: warning
log_fmt_console: '%(asctime)s,%(msecs)03d [%(name)-17s][%(colorlevel)s] %(message)s'
log_level_logfile: all
log_fmt_logfile: '%(asctime)s,%(msecs)03d [%(process)d][%(name)-17s][%(levelname)-8s] %(message)s'

My dummy minimal test state, teststate.sls is:

teststate:
  test.succeed_without_changes:
    - name: "I am a test"

Steps to Reproduce the behavior

I'm tailing the master logs with this grep to capture specific messages relevant to this:

tail -f /var/log/salt/master  | egrep "(Returning file list from cache)|Updating roots fileserver cache|AES payload received with command _file_list|Master function call _file_list|Start rebuilding roots file_list cache"
  1. Start with a list of minions:
# salt '*' test.ping --out=txt
master: True
ip-172-31-0-64.ec2.internal: True
i-052bc1517d7f5a0f7.ec2.internal: True
i-0034e65490b9bce51.ec2.internal: True
i-00206eddd83fe120a.ec2.internal: True
i-0632a5fe83779f6b5.ec2.internal: True
i-06d3dd31d057dcb92.ec2.internal: True
  1. Run a state against just one, and measure wall time of it:
# time salt 'ip*' state.sls teststate --state-verbose=False --state-output=terse
ip-172-31-0-64.ec2.internal:

Summary for ip-172-31-0-64.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.327 ms

real    0m18.120s
user    0m1.188s
sys     0m0.169s

Logs from this:

2021-12-30 19:23:33,075 [332892][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)
2021-12-30 19:23:46,485 [328902][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:23:46,485 [328902][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:24:02,325 [328902][salt.master                              ][TRACE   ] Master function call _file_list took 15.839807271957397 seconds
2021-12-30 19:24:34,525 [332892][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)
2021-12-30 19:25:35,824 [332892][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)
  1. Run same state against all 6 minions, but do it a few times to catch the race
# time salt 'i*' state.sls teststate --state-verbose=False --state-output=terse
[ERROR   ] Message timed out
Salt request timed out. The master is not responding. You may need to run your command with `--async` in order to bypass the congested event bus. With `--async`, the CLI tool will print the job id (jid) and exit immediately without listening for responses. You can then use `salt-run jobs.lookup_jid` to look up the results of the job in the job cache later.

real    0m47.044s
user    0m1.011s
sys     0m0.132s

logs:

2021-12-30 19:26:50,361 [328910][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:26:50,362 [328910][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:26:50,442 [328912][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:26:50,454 [328914][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:26:50,571 [328902][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:26:50,646 [328913][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:26:53,445 [328912][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:26:53,466 [328914][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:26:53,574 [328902][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:26:53,656 [328913][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:27:34,991 [328910][salt.master                              ][TRACE   ] Master function call _file_list took 44.618460178375244 seconds
2021-12-30 19:27:35,442 [328910][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:27:35,443 [328910][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=1 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:27:37,595 [328910][salt.master                              ][TRACE   ] Master function call _file_list took 2.1520118713378906 seconds
2021-12-30 19:27:38,613 [332892][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)
2021-12-30 19:27:43,871 [328913][salt.master                              ][TRACE   ] Master function call _file_list took 53.22390127182007 seconds
2021-12-30 19:27:44,370 [328902][salt.master                              ][TRACE   ] Master function call _file_list took 53.798537492752075 seconds
2021-12-30 19:27:44,635 [328912][salt.master                              ][TRACE   ] Master function call _file_list took 54.19292092323303 seconds
2021-12-30 19:27:44,902 [328914][salt.master                              ][TRACE   ] Master function call _file_list took 54.44801068305969 seconds

Notice how we rebuilt the file_list cache 5 times (out of 6), 4 of the 5 kicked
off basically concurrently. Where running the state on 1 minion finished in 18
seconds, doing it on 6 took 47.

Now if I run 2 back-to-back in quick succession I get a slightly different result. The
cache from the prior run is still valid, and none of the worker threads attempt to rebuild
it, so the state runs on all 6 minions in about 6 seconds.

(v) [root@i-0292831be31ca19e2 srv]# time salt 'i*' state.sls teststate --state-verbose=False --state-output=terse
[ERROR   ] Message timed out
Salt request timed out. The master is not responding. You may need to run your command with `--async` in order to bypass the congested event bus. With `--async`, the CLI tool will print the job id (jid) and exit immediately without listening for responses. You can then use `salt-run jobs.lookup_jid` to look up the results of the job in the job cache later.

real    0m47.156s
user    0m1.068s
sys     0m0.129s
(v) [root@i-0292831be31ca19e2 srv]# time salt 'i*' state.sls teststate --state-verbose=False --state-output=terse
i-052bc1517d7f5a0f7.ec2.internal:

Summary for i-052bc1517d7f5a0f7.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.731 ms
ip-172-31-0-64.ec2.internal:

Summary for ip-172-31-0-64.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.493 ms
i-0034e65490b9bce51.ec2.internal:

Summary for i-0034e65490b9bce51.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.561 ms
i-06d3dd31d057dcb92.ec2.internal:

Summary for i-06d3dd31d057dcb92.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   2.647 ms
i-00206eddd83fe120a.ec2.internal:

Summary for i-00206eddd83fe120a.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.812 ms
i-0632a5fe83779f6b5.ec2.internal:

Summary for i-0632a5fe83779f6b5.ec2.internal
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.501 ms

real    0m5.736s
user    0m0.993s
sys     0m0.142s

The logs:

2021-12-30 19:29:32,075 [328912][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:29:32,076 [328912][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:29:32,197 [328913][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:29:32,304 [328914][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:29:32,313 [328910][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:29:32,375 [328902][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:29:35,200 [328913][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:29:35,311 [328914][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:29:35,322 [328910][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:29:35,391 [328902][salt.loaded.int.fileserver.roots         ][TRACE   ] Start rebuilding roots file_list cache
2021-12-30 19:29:44,614 [333562][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)
2021-12-30 19:30:19,010 [328912][salt.master                              ][TRACE   ] Master function call _file_list took 46.93488335609436 seconds
2021-12-30 19:30:19,447 [328912][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:19,448 [328912][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=1 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:21,693 [328912][salt.master                              ][TRACE   ] Master function call _file_list took 2.2455427646636963 seconds
2021-12-30 19:30:26,412 [328910][salt.master                              ][TRACE   ] Master function call _file_list took 54.09862756729126 seconds
2021-12-30 19:30:26,911 [328914][salt.master                              ][TRACE   ] Master function call _file_list took 54.60709810256958 seconds
2021-12-30 19:30:27,207 [328902][salt.master                              ][TRACE   ] Master function call _file_list took 54.83136487007141 seconds
2021-12-30 19:30:27,221 [328913][salt.master                              ][TRACE   ] Master function call _file_list took 55.02363920211792 seconds
2021-12-30 19:30:35,928 [328912][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:35,929 [328912][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=8 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:35,976 [328914][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:35,976 [328914][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=8 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:36,057 [328913][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:36,057 [328913][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=9 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:36,343 [328910][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:36,343 [328910][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=9 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:37,603 [328912][salt.master                              ][TRACE   ] Master function call _file_list took 1.6741526126861572 seconds
2021-12-30 19:30:37,980 [328914][salt.master                              ][TRACE   ] Master function call _file_list took 2.0038652420043945 seconds
2021-12-30 19:30:37,984 [328912][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:37,985 [328912][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=10 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:38,011 [328913][salt.master                              ][TRACE   ] Master function call _file_list took 1.9535884857177734 seconds
2021-12-30 19:30:38,332 [328914][salt.master                              ][TRACE   ] AES payload received with command _file_list
2021-12-30 19:30:38,333 [328914][salt.fileserver                          ][DEBUG   ] Returning file list from cache: age=11 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2021-12-30 19:30:38,408 [328910][salt.master                              ][TRACE   ] Master function call _file_list took 2.065243721008301 seconds
2021-12-30 19:30:39,246 [328912][salt.master                              ][TRACE   ] Master function call _file_list took 1.2613167762756348 seconds
2021-12-30 19:30:39,486 [328914][salt.master                              ][TRACE   ] Master function call _file_list took 1.1531543731689453 seconds
2021-12-30 19:30:49,726 [333562][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)
2021-12-30 19:31:51,151 [333562][salt.master                              ][DEBUG   ] Updating roots fileserver cache (master)

Expected behavior

The master should regenerate the file_list cache for a given backend only once
per fileserver_cache_list_time.

Screenshots

N/A

Versions Report

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

Master is running the master branch from git as of commit 306aa6dd29 with some local
changes to add in additional debug logging for my help. Minions are running 3004 from the RPM repo.

Salt Version:
          Salt: 3003rc1+1373.g306aa6dd29

Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: Not Installed
     docker-py: Not Installed
         gitdb: 4.0.9
     gitpython: 3.1.20
        Jinja2: 3.0.3
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.3
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: Not Installed
      pycrypto: 2.6.1
  pycryptodome: 3.12.0
        pygit2: Not Installed
        Python: 3.6.8 (default, Sep  9 2021, 07:49:02)
  python-gnupg: Not Installed
        PyYAML: 6.0
         PyZMQ: 22.3.0
         smmap: 5.0.0
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.3.4

System Versions:
          dist: rhel 8.5 Ootpa
        locale: UTF-8
       machine: x86_64
       release: 4.18.0-305.el8.x86_64
        system: Linux
       version: Red Hat Enterprise Linux 8.5 Ootpa

Additional context
Add any other context about the problem here.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by tracing the master _file_list request through the roots fileserver cache rebuild, using the logged commands and messages to reproduce concurrent requests from multiple minions. Done should prevent redundant concurrent file_list cache rebuilds while preserving successful state runs and avoiding the reported master timeouts.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
backend, infrastructure
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.