search

saltstack / salt

Software to automate the management and configuration of any infrastructure or application at scale. Get access to the Salt software package repository here:
https://repo.saltproject.io/
Apache License 2.0
14.16k stars 5.48k forks source link

Proxy minion startup problem #51699

Closed mikewiebe closed 5 months ago

mikewiebe commented 5 years ago

Description of Issue/Question

It appears that a bug was fixed in salt/grains/core.py but introduced a new issue that can significantly delay the proxy minion startup process and impact the functionality of the proxy minion after startup.

The difference in startup time can up to 2 mins with the fix. If I add in a change to make the addresses list empty the minion reaches the ready state in 5-6 seconds.

The fix to salt/grains/core.py can be found here: https://github.com/saltstack/salt/commit/2910d46052adb2d722fbe59c95a7a24097501bcd#diff-6e894b39b67c4bab67796752744ea9d5

Uncertain what the correct fix should be in this case but the impact is high.

Setup

Steps to Reproduce Issue

Prior to this change the list of addresses found here (https://github.com/saltstack/salt/commit/2910d46052adb2d722fbe59c95a7a24097501bcd#diff-6e894b39b67c4bab67796752744ea9d5R2193) was typically empty and so this code was not executed.

Now with the fix, from what I can tell a reverse dns lookup is performed on every interface that has an ipv4 or ipv6 address. If the reverse dns lookup fails for even a small list of addresses (4-6) it will take a very long time for the proxy minion to reach the [INFO ] Minion is ready to receive requests! state and issuing commands to the proxy minion may fail intermittently.

The following message continues to generate for all ip's that fail the reverse dns lookup:

[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Running scheduled job: __mine_interval
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host

Versions Report

Salt Version:
           Salt: 2019.2.0-615-g7a44cd3

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: Not Installed
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.6.1
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.13 (default, Apr  4 2017, 08:47:57)
   python-gnupg: Not Installed
         PyYAML: 3.13
          PyZMQ: 17.1.2
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 5.1.1
            ZMQ: 4.2.5

System Versions:
           dist:   
         locale: UTF-8
        machine: x86_64
        release: 16.7.0
         system: Darwin
        version: 10.12.6 x86_64
dwoz commented 5 years ago

@mikewiebe Can you provide me with the output of some timed dig commands?

First the reverse lookup that's happening to your default DNS server

time dig @<your-dns-server-ip> -x <your-interface-ip>

Second, a reverse lookup using Google's DNS

time dig @8.8.8.8 -x <your-interface-ip>
dwoz commented 5 years ago

@saltstack/team-core

This is working as intended and from what I can tell in most cases it is not an issue. From what I can tell even if the ip does not have a reverse lookup defined the nameserver will still respond in a timely manner. So for the majority of people this will not be an issue. There is something @mikewiebe's setup that is causing his revers lookups to not return and timeout. The only option I can think of is to add a new option too minion's config that will prevent the minion from doing any reverse lookups. Does anyone else have thoughts on this?

mikewiebe commented 5 years ago

@mikewiebe Can you provide me with the output of some timed dig commands?

First the reverse lookup that's happening to your default DNS server

time dig @<your-dns-server-ip> -x <your-interface-ip>

Second, a reverse lookup using Google's DNS

time dig @8.8.8.8 -x <your-interface-ip>

Sorry for the very delayed reply here. I missed this.

; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 45238
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;231.160.150.10.in-addr.arpa.   IN  PTR

;; Query time: 42 msec
;; SERVER: 8.8.8.8#53(8.8.8.8)
;; WHEN: Fri Apr 12 12:47:00 2019
;; MSG SIZE  rcvd: 45

real    0m0.066s
user    0m0.006s
sys 0m0.005s

Here is my default DNS server. Don't think it shows much.

;; Query time: 32 msec
;; SERVER: xx.xxx.x.xxx#53(xx.xxx.x.xxx)
;; WHEN: Fri Apr 12 12:50:20 2019
;; MSG SIZE  rcvd: 105

real    0m0.054s
user    0m0.006s
sys 0m0.005s
waynew commented 5 years ago

This might be the issue that I was thinking of, but I seem to recall seeing a similar issue :suspect:

At first I thought this was very bizarre because trying the lookup was very fast. But then I tried a series of them and there were times that it hangs - took about 10s to do ~100 or so. Interestingly enough it does seem to cache the results at a system (?) level, because repeating the test returns almost immediately.

waynew commented 5 years ago

Can you try to run this code, but replace the addrs with whatever Salt returns for you?

import socket
import time

from collections import Counter

addrs = [
    '192.11.22.12',
    '192.11.22.13',
    '192.11.22.14',
]
times = Counter()
start = time.time()
for addr in addrs:
    try:
        sub_start = time.time()
        socket.gethostbyaddr(addr)
    except socket.herror:
        print(f'Failed getting host info for {addr}')
    finally:
        sub_end = time.time()
    times[addr] = sub_end - sub_start
end = time.time()
print('='*40)
print('Took', round(end-start, 3), 'seconds to lookup', len(addrs), 'records')
print('Longest times:', end='\n\t')
print('\n\t'.join(str(t[1]) for t in times.most_common()))

As I noted, it's possible that the results here get cached by your OS so it might return misleading values if you run it after Salt hits the gethostbyaddr line. Mostly I just care about the results after the ======= line. The earlier print could be removed to speed things up a bit, but since we're writing to a log I don't think it should be a huge change.

On my machine it might take several seconds, but the fact that you're seeing almost 2 minutes vs 5-6s startup times is puzzling. I wouldn't expect it to introduce more than a couple of tens of seconds, based on my results, and the number of IPs you have it looking up. So I'm curious about the output of this test.

mikewiebe commented 5 years ago

@waynew Sorry for the delayed response. I was traveling and had some other project demands. Here is a cut and past of me starting up the proxy minion with -l info turned on. Most of the addresses where the lookup is happening are ipv6 addresses.

NOTE: I have replaced the addresses with fake ipv6 addresses.

diff --git a/salt/grains/core.py b/salt/grains/core.py
index 04dd0fa025..69aaeecfbd 100644
--- a/salt/grains/core.py
+++ b/salt/grains/core.py
@@ -2177,6 +2177,7 @@ def fqdns():
     err_message = 'Exception during resolving address: %s'
     for ip in addresses:
         try:
+            log.info("Trying ip: %s" % ip)
             name, aliaslist, addresslist = socket.gethostbyaddr(ip)
             fqdns.update([socket.getfqdn(name)] + [als for als in aliaslist if salt.utils.network.is_fqdn(als)])
         except socket.herror as err:
(py2-salt) salt@salt-M-D2TB:~/Projects/salt$salt-proxy --proxyid n9k -l info
[INFO    ] Setting up "n9k" the Salt ProxyMinion
[INFO    ] The Proxy Minion is starting up the Salt ProxyMinion
[INFO    ] Starting pull socket on /Users/salt/Virtualenvs/py2-salt/var/run/salt/proxy/minion_event_9f6c102cae_pull.ipc
[INFO    ] Creating minion process manager
[INFO    ] Trying ip: 192.168.0.1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Loading fresh modules for state activity
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/clouds'
[INFO    ] Syncing clouds for environment 'base'
[INFO    ] Loading cache from salt://_clouds, for base
[INFO    ] Caching directory '_clouds/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/beacons'
[INFO    ] Syncing beacons for environment 'base'
[INFO    ] Loading cache from salt://_beacons, for base
[INFO    ] Caching directory '_beacons/' for environment 'base'
[INFO    ] Syncing modules for environment 'base'
[INFO    ] Loading cache from salt://_modules, for base
[INFO    ] Caching directory '_modules/' for environment 'base'
[INFO    ] Copying '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/n9k/files/base/_modules/nxos_upgrade.py' to '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/modules/nxos_upgrade.py'
[INFO    ] Syncing states for environment 'base'
[INFO    ] Loading cache from salt://_states, for base
[INFO    ] Caching directory '_states/' for environment 'base'
[INFO    ] Copying '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/n9k/files/base/_states/nxos.py' to '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/states/nxos.py'
[INFO    ] Copying '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/n9k/files/base/_states/nxos_upgrade.py' to '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/states/nxos_upgrade.py'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/sdb'
[INFO    ] Syncing sdb for environment 'base'
[INFO    ] Loading cache from salt://_sdb, for base
[INFO    ] Caching directory '_sdb/' for environment 'base'
[INFO    ] Syncing grains for environment 'base'
[INFO    ] Loading cache from salt://_grains, for base
[INFO    ] Caching directory '_grains/' for environment 'base'
[INFO    ] Copying '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/n9k/files/base/_grains/nxos.py' to '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/grains/nxos.py'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/renderers'
[INFO    ] Syncing renderers for environment 'base'
[INFO    ] Loading cache from salt://_renderers, for base
[INFO    ] Caching directory '_renderers/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/returners'
[INFO    ] Syncing returners for environment 'base'
[INFO    ] Loading cache from salt://_returners, for base
[INFO    ] Caching directory '_returners/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/output'
[INFO    ] Syncing output for environment 'base'
[INFO    ] Loading cache from salt://_output, for base
[INFO    ] Caching directory '_output/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/utils'
[INFO    ] Syncing utils for environment 'base'
[INFO    ] Loading cache from salt://_utils, for base
[INFO    ] Caching directory '_utils/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/log_handlers'
[INFO    ] Syncing log_handlers for environment 'base'
[INFO    ] Loading cache from salt://_log_handlers, for base
[INFO    ] Caching directory '_log_handlers/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/proxy'
[INFO    ] Syncing proxy for environment 'base'
[INFO    ] Loading cache from salt://_proxy, for base
[INFO    ] Caching directory '_proxy/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/engines'
[INFO    ] Syncing engines for environment 'base'
[INFO    ] Loading cache from salt://_engines, for base
[INFO    ] Caching directory '_engines/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/thorium'
[INFO    ] Syncing thorium for environment 'base'
[INFO    ] Loading cache from salt://_thorium, for base
[INFO    ] Caching directory '_thorium/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/serializers'
[INFO    ] Syncing serializers for environment 'base'
[INFO    ] Loading cache from salt://_serializers, for base
[INFO    ] Caching directory '_serializers/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/matchers'
[INFO    ] Syncing matchers for environment 'base'
[INFO    ] Loading cache from salt://_matchers, for base
[INFO    ] Caching directory '_matchers/' for environment 'base'
[INFO    ] Creating module dir '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/executors'
[INFO    ] Syncing executors for environment 'base'
[INFO    ] Loading cache from salt://_executors, for base
[INFO    ] Caching directory '_executors/' for environment 'base'
[INFO    ] Trying ip: 192.168.0.1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] nxos proxy __virtual__() called...
[INFO    ] nxos proxy __virtual__() called...
[INFO    ] onyx proxy __virtual__() called...
[INFO    ] ssh_sample proxy __virtual__() called...
[INFO    ] NXOS PROXY: Initialize nxapi proxy connection
[INFO    ] Nxapi connection arguments: {'username': 'admin', u'connect_over_uds': False, 'key_accept': True, 'password': 'idgeR09!', u'verify_ssl': False, 'verify': False, 'connection': 'nxapi', 'ssh_args': '-o PubkeyAuthentication=no', 'host': 'n9k-109.cisco.com', u'cookie': u'admin', 'no_save_config': True, u'timeout': 60, 'prompt_name': 'n9k-109', 'port': 443, 'transport': 'https'}
[INFO    ] Connecting over https
[INFO    ] request: {u'url': u'https://n9k-109.cisco.com:443/ins', u'headers': {u'content-type': u'application/json'}, u'payload': '{"ins_api": {"version": "1.0", "type": "cli_show", "chunk": "0", "sid": "1", "input": "show clock", "output_format": "json"}}', u'opts': {u'http_request_timeout': 60}}
[INFO    ] command show clock:
[INFO    ] PARSE_RESPONSE: 200 Success
[INFO    ] nxapi DEVICE_DETAILS info: {u'conn_args': {'username': 'admin', 'key_accept': True, 'password': 'idgeR09!', 'verify': False, 'connection': 'nxapi', 'ssh_args': '-o PubkeyAuthentication=no', 'host': 'n9k-109.cisco.com', 'no_save_config': True, 'prompt_name': 'n9k-109', 'port': 443, 'transport': 'https'}, u'grains_cache': {}, u'up': True, u'no_save_config': True, u'initialized': True}
[INFO    ] Trying ip: 192.168.0.1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Loading fresh modules for state activity
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Nxapi connection arguments: {'username': 'admin', u'connect_over_uds': False, 'key_accept': True, 'prompt_name': 'n9k-109', u'verify_ssl': False, 'verify': False, 'transport': 'https', 'host': 'n9k-109.cisco.com', 'connection': 'nxapi', u'cookie': u'admin', 'no_save_config': True, u'timeout': 60, 'password': 'idgeR09!', 'port': 443, 'ssh_args': '-o PubkeyAuthentication=no'}
[INFO    ] Connecting over https
[INFO    ] request: {u'url': u'https://n9k-109.cisco.com:443/ins', u'headers': {u'content-type': u'application/json'}, u'payload': '{"ins_api": {"version": "1.0", "type": "cli_show_ascii", "chunk": "0", "sid": "1", "input": "show version", "output_format": "json"}}', u'opts': {u'http_request_timeout': 60}}
[INFO    ] command show version:
[INFO    ] PARSE_RESPONSE: 200 Success
[INFO    ] Trying ip: 192.168.0.1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Added new job __mine_interval to scheduler
[INFO    ] Added mine.update to scheduler
[INFO    ] Syncing grains for environment 'base'
[INFO    ] Loading cache from salt://_grains, for base
[INFO    ] Caching directory '_grains/' for environment 'base'
[INFO    ] Copying '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/n9k/files/base/_grains/nxos.py' to '/Users/salt/Virtualenvs/py2-salt/var/cache/salt/proxy/extmods/n9k/grains/nxos.py'
[ERROR   ] Minion unable to successfully connect to a Salt Master.
[INFO    ] ProxyMinion is starting as user 'salt'
[INFO    ] Minion is ready to receive requests!
[WARNING ] /Users/salt/Projects/salt/salt/utils/msgpack.py:87: DeprecationWarning: encoding is deprecated, Use raw=False instead.
  return msgpack_module.unpackb(packed, **kwargs)

[INFO    ] Trying ip: 192.168.0.1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: 192.168.0.1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b6:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fe80::1
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b7:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92b8:xxxx:xxxx:xxxx:xxxx
[INFO    ] Trying ip: fdfb:6e63:7442:92b9:xxxx:xxxx:xxxx:xxxx
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Trying ip: fdfb:6e63:7442:92c1:xxxx:xxxx:xxxx:xxxx
mikewiebe commented 5 years ago

Here is the output form the script

Failed getting host info for 10.x.x.x
Failed getting host info for 2001:x:x:x:x:x:x:x
Failed getting host info for fe80::1
Failed getting host info for fe80::x:x:x:x
Failed getting host info for fe80::x:x:x:x
========================================
Took 15.332 seconds to lookup 6 records
Longest times:
    5.0049920082092285
    5.001755952835083
    5.001718759536743
    0.3166782855987549
    0.00614619255065918
    0.0006263256072998047
waynew commented 5 years ago

Interesting! It looks like the IPv6 failures are the slowest - by an order of magnitude or so...

catfishcrawler commented 5 months ago

Description of Issue/Question

It appears that a bug was fixed in salt/grains/core.py but introduced a new issue that can significantly delay the proxy minion startup process and impact the functionality of the proxy minion after startup.

The difference in startup time can up to 2 mins with the fix. If I add in a change to make the addresses list empty the minion reaches the ready state in 5-6 seconds.

The fix to salt/grains/core.py can be found here: 2910d46#diff-6e894b39b67c4bab67796752744ea9d5

Uncertain what the correct fix should be in this case but the impact is high.

Setup

Steps to Reproduce Issue

Prior to this change the list of addresses found here (2910d46#diff-6e894b39b67c4bab67796752744ea9d5R2193) was typically empty and so this code was not executed.

Now with the fix, from what I can tell a reverse dns lookup is performed on every interface that has an ipv4 or ipv6 address. If the reverse dns lookup fails for even a small list of addresses (4-6) it will take a very long time for the proxy minion to reach the [INFO ] Minion is ready to receive requests! state and issuing commands to the proxy minion may fail intermittently.

The following message continues to generate for all ip's that fail the reverse dns lookup:

[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[INFO    ] Running scheduled job: __mine_interval
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host
[ERROR   ] Exception during resolving address: [Errno 1] Unknown host

Versions Report

Salt Version:
           Salt: 2019.2.0-615-g7a44cd3

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: Not Installed
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.6.1
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.13 (default, Apr  4 2017, 08:47:57)
   python-gnupg: Not Installed
         PyYAML: 3.13
          PyZMQ: 17.1.2
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 5.1.1
            ZMQ: 4.2.5

System Versions:
           dist:   
         locale: UTF-8
        machine: x86_64
        release: 16.7.0
         system: Darwin
        version: 10.12.6 x86_64
dmurphy18 commented 5 months ago

Closing this issue since it relates to Salt 2019.2 and Python 2 which are both long EOL. If the issue is of concern, please retest with a currently supported version of Salt (which supports Python 3) and open a new issue ( since there are new metrics used with GitHub to track issues), that is, with the current issue template.