[BUG] Deltaproxy: Long/Non-linear setup time.

[n-holmstedt]

Description
I'm trying to host 32 proxy-minions in a delta-proxy process. The setup time is more than 10minutes. It seems like the master is re-rendering pillar for all the minions currently connected to to the master from the deltaproxy.

deltaproxy-1 connects to the master, its pillar is rendered.
rectifier-1 connects to the master, its pillar is rendered plus the pillar of deltaproxy-1
rectifier-2 connects to the master, its pillar is rendered plus the pillar of deltaproxy-1, rectifier 1
rectifier-3 connects to the master, its pillar is rendered plus the pillar of deltaproxy-1, rectifier 1, rectifier 2
The time it takes between two renderings is about 1s. This would be: Σ i*1s = 561s with 32 minions plus deltaproxy. which is about the setuptime that i'm looking at.

Setup
(Please provide relevant configs and/or SLS files (be sure to remove sensitive info. There is no general set-up of Salt.)

Please be as specific as possible and give set-up details.

• on-prem machine
• VM (Virtualbox, KVM, etc. please specify)
• VM running on a cloud service, please be explicit and add details
• container (Kubernetes, Docker, containerd, etc. please specify)
• or a combination, please be explicit
• jails if it is FreeBSD

Using the official docker image, running on a Redhat 8.2 VM.
1x Master container
1x Deltaproxy container running 32x proxy-minions with connections to http-interfaces.

top.sls

base:
  'delta*':
    - deltaproxy
  'e*':
    - eltek

deltaproxy.sls

proxy:
  proxytype: deltaproxy

  ids:
    - eltek-10.128.103.139
    - eltek-10.128.103.166
    - eltek-10.128.98.140
    - eltek-10.128.99.34
    #... 32 minions

eltek.sls

proxy:
  {% set ip = opts.id|replace("eltek-", "") %}
  proxytype: eltek_rectifier
  username: <username>
  password: <password>
  url: http://{{ ip }}/
  proxy_keep_alive_interval: 4

Steps to Reproduce the behavior

Trimmed debug logs:

rect-master  | 2022-03-17T08:12:40.425825791Z [INFO    ] Setting up the Salt Master

rect-master  | 2022-03-17T08:12:43.301623895Z [DEBUG   ] compound_match delta_proxy ? "delta*" => "True"
rect-master  | 2022-03-17T08:12:43.308040417Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/deltaproxy.sls:

rect-master  | 2022-03-17T08:12:44.102964475Z [INFO    ] Authentication request from eltek-10.128.103.139
rect-master  | 2022-03-17T08:12:44.103180831Z [INFO    ] Authentication accepted from eltek-10.128.103.139
rect-master  | 2022-03-17T08:12:44.209308520Z [DEBUG   ] compound_match eltek-10.128.103.139 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:44.213216500Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:44.740150444Z [DEBUG   ] compound_match delta_proxy ? "delta*" => "True"
rect-master  | 2022-03-17T08:12:44.753181668Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/deltaproxy.sls:

rect-master  | 2022-03-17T08:12:45.488217634Z [DEBUG   ] compound_match eltek-10.128.103.139 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:45.491816260Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:46.558525115Z [INFO    ] Authentication request from eltek-10.128.103.166
rect-master  | 2022-03-17T08:12:46.558541720Z [INFO    ] Authentication accepted from eltek-10.128.103.166
rect-master  | 2022-03-17T08:12:46.656550969Z [DEBUG   ] compound_match eltek-10.128.103.166 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:46.660096019Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:47.162810981Z [DEBUG   ] compound_match delta_proxy ? "delta*" => "True"
rect-master  | 2022-03-17T08:12:47.171154101Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/deltaproxy.sls:

rect-master  | 2022-03-17T08:12:47.897208523Z [DEBUG   ] compound_match eltek-10.128.103.139 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:47.900922659Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:48.920556018Z [DEBUG   ] compound_match eltek-10.128.103.166 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:48.923023979Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:50.028183243Z [INFO    ] Authentication request from eltek-10.128.98.140
rect-master  | 2022-03-17T08:12:50.028296027Z [INFO    ] Authentication accepted from eltek-10.128.98.140
rect-master  | 2022-03-17T08:12:50.119928249Z [DEBUG   ] compound_match eltek-10.128.98.140 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:50.122357794Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:50.595144036Z [DEBUG   ] compound_match delta_proxy ? "delta*" => "True"
rect-master  | 2022-03-17T08:12:50.600170244Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/deltaproxy.sls:

rect-master  | 2022-03-17T08:12:51.618493585Z [DEBUG   ] compound_match eltek-10.128.103.139 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:51.620990062Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:52.611120420Z [DEBUG   ] compound_match eltek-10.128.103.166 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:52.615123247Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:53.613226513Z [DEBUG   ] compound_match eltek-10.128.98.140 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:53.613492877Z [DEBUG   ] compile template: /etc/salt/pillar/eltek.sls

rect-master  | 2022-03-17T08:12:54.540989442Z [INFO    ] Authentication request from eltek-10.128.99.34
rect-master  | 2022-03-17T08:12:54.541006331Z [INFO    ] Authentication accepted from eltek-10.128.99.34
rect-master  | 2022-03-17T08:12:54.633158502Z [DEBUG   ] compound_match eltek-10.128.99.34 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:54.633161843Z [DEBUG   ] compile template: /etc/salt/pillar/eltek.sls

rect-master  | 2022-03-17T08:12:55.197925160Z [DEBUG   ] compound_match delta_proxy ? "delta*" => "True"
rect-master  | 2022-03-17T08:12:55.204295120Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/deltaproxy.sls:

rect-master  | 2022-03-17T08:12:55.954047346Z [DEBUG   ] compound_match eltek-10.128.103.139 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:55.956866932Z [DEBUG   ] Rendered data from file: /etc/salt/pillar/eltek.sls:

rect-master  | 2022-03-17T08:12:56.943289968Z [DEBUG   ] compound_match eltek-10.128.103.166 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:56.943535022Z [DEBUG   ] compile template: /etc/salt/pillar/eltek.sls

rect-master  | 2022-03-17T08:12:57.972278766Z [DEBUG   ] compound_match eltek-10.128.98.140 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:57.972547250Z [DEBUG   ] compile template: /etc/salt/pillar/eltek.sls

rect-master  | 2022-03-17T08:12:58.971021713Z [DEBUG   ] compound_match eltek-10.128.99.34 ? "e*" => "True"
rect-master  | 2022-03-17T08:12:58.971024533Z [DEBUG   ] compile template: /etc/salt/pillar/eltek.sls

rect-master  | 2022-03-17T08:13:00.158145470Z [INFO    ] Authentication request from eltek-10.128.102.125
rect-master  | 2022-03-17T08:13:00.158335418Z [INFO    ] Authentication accepted from eltek-10.128.102.125
rect-master  | 2022-03-17T08:13:00.252251989Z [DEBUG   ] compound_match eltek-10.128.102.125 ? "e*" => "True"
rect-master  | 2022-03-17T08:13:00.252517879Z [DEBUG   ] compile template: /etc/salt/pillar/eltek.sls

Expected behavior
The master should render each device pillar once.

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: 3004

Dependency Versions:
          cffi: 1.14.6
      cherrypy: unknown
      dateutil: 2.8.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 2.11.3
       libgit2: 1.1.0
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: 2.17
      pycrypto: Not Installed
  pycryptodome: 3.9.8
        pygit2: 1.6.1
        Python: 3.7.12 (default, Sep  8 2021, 01:55:52)
  python-gnupg: 0.4.4
        PyYAML: 5.4.1
         PyZMQ: 18.0.1
         smmap: Not Installed
       timelib: 0.2.4
       Tornado: 4.5.3
           ZMQ: 4.3.1

System Versions:
          dist: alpine 3.14.2
        locale: UTF-8
       machine: x86_64
       release: 4.18.0-348.12.2.el8_5.x86_64
        system: Linux
       version: Alpine Linux 3.14.2

Additional context
This might also affect #61153

[garethgreenaway]

@n-holmstedt Thanks for the report. Based on the logs above I'm not seeing the issue you're reporting, I do see Salt rendering the same file for each proxy device, which could be a source of some improvement. Can you point me at some logs where you're seeing the multiple pillar data for minions being rendered for each minion?

[n-holmstedt]

delta_load_logs.txt

@garethgreenaway No problem. I'm not entirely sure how to explain it, or if i'm using the right terms at all. I uploaded some logs from the rectifiers we're using. It's just the first 10 minutes since setting up about 30 of them can take upwards to 40ish minutes and it looks like each "new" minion causes the salt-master to redo all the inits from the first minion.

[garethgreenaway]

@n-holmstedt Thanks I'll look through the logs. The startup being slow is a known issue and will be fixed in 3006, the other issue about the init happening from the first minion sounds like there might be some global variables involved. And this is a custom proxy minion? Would it be possible to see the source for it? Thanks!

[Zpell82]

rect-minion_delta  | 2022-10-04T06:05:17.935337068Z   File "/usr/local/lib/python3.7/site-packages/salt/minion.py", line 1134, in _connect_minion
rect-minion_delta  | 2022-10-04T06:05:17.935339785Z     yield minion.connect_master(failed=failed)
rect-minion_delta  | 2022-10-04T06:05:17.935342143Z   File "/usr/local/lib/python3.7/site-packages/salt/ext/tornado/gen.py", line 1056, in run
rect-minion_delta  | 2022-10-04T06:05:17.935344735Z     value = future.result()
rect-minion_delta  | 2022-10-04T06:05:17.935347002Z   File "/usr/local/lib/python3.7/site-packages/salt/ext/tornado/concurrent.py", line 249, in result
rect-minion_delta  | 2022-10-04T06:05:17.935349404Z     raise_exc_info(self._exc_info)
rect-minion_delta  | 2022-10-04T06:05:17.935351611Z   File "<string>", line 4, in raise_exc_info
rect-minion_delta  | 2022-10-04T06:05:17.935354391Z   File "/usr/local/lib/python3.7/site-packages/salt/ext/tornado/gen.py", line 1064, in run
rect-minion_delta  | 2022-10-04T06:05:17.935356794Z     yielded = self.gen.throw(*exc_info)
rect-minion_delta  | 2022-10-04T06:05:17.935359048Z   File "/usr/local/lib/python3.7/site-packages/salt/minion.py", line 1375, in connect_master
rect-minion_delta  | 2022-10-04T06:05:17.935361420Z     yield self._post_master_init(master)
rect-minion_delta  | 2022-10-04T06:05:17.935363936Z   File "/usr/local/lib/python3.7/site-packages/salt/ext/tornado/gen.py", line 1056, in run
rect-minion_delta  | 2022-10-04T06:05:17.935366320Z     value = future.result()
rect-minion_delta  | 2022-10-04T06:05:17.935371630Z   File "/usr/local/lib/python3.7/site-packages/salt/ext/tornado/concurrent.py", line 249, in result
rect-minion_delta  | 2022-10-04T06:05:17.935374521Z     raise_exc_info(self._exc_info)
rect-minion_delta  | 2022-10-04T06:05:17.935377195Z   File "<string>", line 4, in raise_exc_info
rect-minion_delta  | 2022-10-04T06:05:17.935379609Z   File "/usr/local/lib/python3.7/site-packages/salt/ext/tornado/gen.py", line 1070, in run
rect-minion_delta  | 2022-10-04T06:05:17.935388515Z     yielded = self.gen.send(value)
rect-minion_delta  | 2022-10-04T06:05:17.935390995Z   File "/usr/local/lib/python3.7/types.py", line 208, in send
rect-minion_delta  | 2022-10-04T06:05:17.935393536Z     return self.__wrapped.send(val)
rect-minion_delta  | 2022-10-04T06:05:17.935395768Z   File "/usr/local/lib/python3.7/site-packages/salt/metaproxy/deltaproxy.py", line 420, in post_master_init
rect-minion_delta  | 2022-10-04T06:05:17.935398217Z     proxy_init_fn = _proxy_minion.proxy[_fq_proxyname + ".init"]
rect-minion_delta  | 2022-10-04T06:05:17.935400611Z   File "/usr/local/lib/python3.7/site-packages/salt/loader/lazy.py", line 336, in __getitem__
rect-minion_delta  | 2022-10-04T06:05:17.935403093Z     super().__getitem__(item)  # try to get the item from the dictionary
rect-minion_delta  | 2022-10-04T06:05:17.935405406Z   File "/usr/local/lib/python3.7/site-packages/salt/utils/lazy.py", line 107, in __getitem__
rect-minion_delta  | 2022-10-04T06:05:17.935407764Z     return self._dict[key]
rect-minion_delta  | 2022-10-04T06:05:17.935409952Z KeyError: 'eltek_rectifier.init' 

---

And This happens if I run the code via _proxy mounted with the docker-compose same issue if I copy Dummy.py and test to run it via _proxy and I renamed it too, proxyenabled = ["patrik_dummy"].
"""

rect-minion  | 2022-10-04T06:25:58.258680204Z   File "/usr/local/lib/python3.7/site-packages/salt/metaproxy/deltaproxy.py", line 420, in post_master_init
rect-minion  | 2022-10-04T06:25:58.258682654Z     proxy_init_fn = _proxy_minion.proxy[_fq_proxyname + ".init"]
rect-minion  | 2022-10-04T06:25:58.258685058Z   File "/usr/local/lib/python3.7/site-packages/salt/loader/lazy.py", line 336, in __getitem__
rect-minion  | 2022-10-04T06:25:58.258687427Z     super().__getitem__(item)  # try to get the item from the dictionary
rect-minion  | 2022-10-04T06:25:58.258689855Z   File "/usr/local/lib/python3.7/site-packages/salt/utils/lazy.py", line 107, in __getitem__
rect-minion  | 2022-10-04T06:25:58.258692288Z     return self._dict[key] 

"""

volumes:
  - ./files/master:/etc/salt/master
  - ./files/pillar:/etc/salt/pillar
  - ./files/_proxy:/etc/salt/_proxy 
  - ./files/_modules:/etc/salt/_modules
  - ./files/_utils:/etc/salt/_utils
  - ./files/proxy:/etc/salt/proxy

If i build an image with my custom module and put it in /usr/local/lib/python3.8/dist-packages/salt/proxy/ and exclude - ./files/_proxy:/etc/salt/_proxy ## this is in ubuntu:20.04
The code works just fine and created 208 deltaproxys in less than 6 min

I have the same issue with whatever image I use via the custom proxy module via _proxy.

Tested :
saltstack/salt: [3004.1, 3004.2, 3005, 3005.1]
Ubuntu:20.04, salt versions: [3004.1, 3004.2, 3005, 3005.1]

edit: i'm one of the code writers for this custom module
@garethgreenaway

[garethgreenaway]

Circling back to this one with some good news. I was able to reproduce it, the bug exists when using a custom proxy module. I suspect the available modules needs to be synced for the control proxy before attempting to load any sub proxies.