Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] Salt exit with bound method Client.__del__ of <etcd.client.Client object at ignored #57196

Open
pankajghadge opened this issue May 11, 2020 · 24 comments
Labels
Bug broken, incorrect, or confusing behavior Confirmed Salt engineer has confirmed bug/feature - often including a MCVE Core relates to code central or existential to Salt severity-medium 3rd level, incorrect or bad functionality, confusing and lacks a work around
Milestone

Comments

@pankajghadge
Copy link

pankajghadge commented May 11, 2020

Description
After upgrading salt master and minion to 2019.2.4, we started getting an error
We have upgraded due to CVE issue

ERROR: Minions returned with non-zero exit code
Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method Client.__del__ of <etcd.client.Client object at 0x7f4f62781810>> ignored

This error occurs after several execution of salt run.
When we restart the salt-master then it goes for a while, but after few hours it starts appearing again

Setup
(Please provide relevant configs and/or SLS files (be sure to remove sensitive info).

Steps to Reproduce the behavior
(Include debug logs if possible and relevant)

salt 'target' cmd.run 'ls -l /var' -l debug

[DEBUG   ] .Passing on saltutil error. Key 'u'retcode' missing from client return. This may be an error in the client
[DEBUG   ] return event: {'example1.com': {u'failed': True}}
[DEBUG   ] Could not LazyLoad etcd.init_kwargs: 'etcd.init_kwargs' is not available.
[INFO    ] etcd: Setting up client with params: {u'username': u'saltmaster', u'protocol': u'http', u'ca_cert': u'None', u'allow_redirect': False, u'srv_domain': None, u'host': u'192.168.1.98', u'read_timeout': 60, u'password': u'test_pass', u'port': 2379, u'allow_reconnect': True, u'cert': u'None'}
[DEBUG   ] Starting new HTTP connection (1): 192.168.1.98:2379
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/machines HTTP/1.1" 200 23
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/keys/salt_cache HTTP/1.1" 200 178
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/keys/salt_cache/minions HTTP/1.1" 200 None
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/keys/salt_cache/minions?recursive=true HTTP/1.1" 200 None
[DEBUG   ] Could not LazyLoad etcd.init_kwargs: 'etcd.init_kwargs' is not available.
[INFO    ] etcd: Setting up client with params: {u'username': u'saltmaster', u'protocol': u'http', u'ca_cert': u'None', u'allow_redirect': False, u'srv_domain': None, u'host': u'192.168.1.98', u'read_timeout': 60, u'password': u'test_pass', u'port': 2379, u'allow_reconnect': True, u'cert': u'None'}
[DEBUG   ] Starting new HTTP connection (1): 192.168.1.98:2379
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/machines HTTP/1.1" 200 23
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/keys/salt_cache HTTP/1.1" 200 178
[DEBUG   ] http://192.168.1.98:2379 "GET /v2/keys/salt_cache/minions?recursive=true HTTP/1.1" 200 None

[DEBUG   ] Closing IPCMessageSubscriber instance
ERROR: Minions returned with non-zero exit code
Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method Client.__del__ of <etcd.client.Client object at 0x7f4f62781810>> ignored

Warning on minion log:

2020-05-05 17:00:15,248 [salt.utils.parsers:1071][WARNING ][1844] Minion received a SIGTERM. Exiting.
2020-05-05 17:02:00,540 [salt.utils.parsers:1071][WARNING ][25113] Minion received a SIGTERM. Exiting.
2020-05-06 01:07:57,521 [salt.utils.parsers:1071][WARNING ][25358] Minion received a SIGTERM. Exiting.

For simple salt.run it occurs after 10-15 continuous salt call from master

Expected behavior
Error must go, instead it should print expected output

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 --versions-report
Salt Version:
           Salt: 2019.2.4

Dependency Versions:
           cffi: 1.6.0
       cherrypy: Not Installed
       dateutil: 1.5
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: 0.26.4
        libnacl: Not Installed
       M2Crypto: 0.21.1
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: 2.14
       pycrypto: 2.6.1
   pycryptodome: 3.9.7
         pygit2: 0.26.4
         Python: 2.7.5 (default, Jun 11 2019, 14:33:56)
   python-gnupg: 0.4.4
         PyYAML: 3.10
          PyZMQ: 15.3.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.1.4

System Versions:
           dist: redhat 7.6 Maipo
         locale: UTF-8
        machine: x86_64
        release: 3.10.0-1127.el7.x86_64
         system: Linux
        version: Red Hat Enterprise Linux Server 7.6

Additional context
Add any other context about the problem here.

@pankajghadge pankajghadge added the Bug broken, incorrect, or confusing behavior label May 11, 2020
@DmitryKuzmenko
Copy link
Contributor

@pankajghadge thank you for report. Any details about your configuration related to etcd?

@DmitryKuzmenko DmitryKuzmenko added the info-needed waiting for more info label May 13, 2020
@DmitryKuzmenko DmitryKuzmenko added this to the Blocked milestone May 13, 2020
@pankajghadge
Copy link
Author

pankajghadge commented May 14, 2020

@DmitryKuzmenko I think this issue is not related to etcd service.
When I run this command it give above error randomly it will not always fail but after 2-3 run it will surly fail.

salt 'target' test.ping --return etcd -l trace

When I run the same command directly from minion, it always work

salt-call test.ping --return etcd -l trace

By the way what etcd Configuration do you need? Specify command if possible

One strange thing I have observed when I restart salt-master error doesn't come for 1-2 days later on it starts coming.
Note: salt-syndic also gets auto restart when I restart salt-master

One more update:

  1. Following commands also show error
salt-run manage.not_reaped
salt-run manage.alived
salt-run manage.allowed

Error:
Exception AttributeError: AttributeError("'NoneType' object has no attribute 'Empty'",) in <bound method Client.__del__ of <etcd.client.Client object at 0x7f6903730fd0>> ignored

This command doesn't show error but minions are changing for every run

[salt]# salt-run manage.down
- minion01
- minion02
- minion03
- minion05
- minion07
[salt]# salt-run manage.down
- minion10
- minion03
- minion06
- minion05
- minion09

@DmitryKuzmenko
Copy link
Contributor

@pankajghadge thank you for additional details.
About etcd: I wan't to understand what do you have in your configuration related to etcd. Do you use the only etcd returner? Do you use etcd pillars or cache? If you could provide related sanitized configuration it would be helpful.

@pankajghadge
Copy link
Author

@DmitryKuzmenko
We only have following configuration in master /etc/salt/master.d/etcd-cache.conf
we don't use etcd pillars, also there is nothing like etcd returner

`cache: etcd

etcd.host: remote_host
etcd.port: 2379
etcd.protocol: http
etcd.allow_reconnect: True
etcd.allow_redirect: False
etcd.read_timeout: 60
etcd.username: etcd_name
etcd.password: etcd_password
etcd.cert: None
etcd.ca_cert: None
`

Remote etcd server version:

[user@~]# etcd --version
etcd Version: 3.3.11
Git SHA: 2cf9e51
Go Version: go1.10.3
Go OS/Arch: linux/amd64

etcd systemctl.service

[Service]
Type=notify
WorkingDirectory=/var/lib/etcd/
EnvironmentFile=-/etc/etcd/etcd.conf
User=etcd
# set GOMAXPROCS to number of processors
ExecStart=/bin/bash -c "GOMAXPROCS=$(nproc) /usr/bin/etcd --name=\"${ETCD_NAME}\" --data-dir=\"${ETCD_DATA_DIR}\" --listen-client-urls=\"${ETCD_LISTEN_CLIENT_URLS}\""
Restart=on-failure
LimitNOFILE=65536

@malletp
Copy link

malletp commented May 15, 2020

Hello @DmitryKuzmenko,

I work with Pankaj. We used etcd as backend for minion data cache to synchronize mine data between all master and syndics.
We got the message each time the salt command use the etcd client library.

@DmitryKuzmenko DmitryKuzmenko self-assigned this May 16, 2020
@pankajghadge
Copy link
Author

@DmitryKuzmenko Any finding or progress regarding this issue ?

@DmitryKuzmenko
Copy link
Contributor

Sorry, I've stopped on installing environment and switched to another task. Now I'm back on this.

@DmitryKuzmenko
Copy link
Contributor

I still can not reproduce this. But I have found an upstream bug in python-etcd project.
jplana/python-etcd#179
jplana/python-etcd#190
I have tried different versions but still can not reproduce it.
Anyway possibly upgrade to the latest versions of python-etcd and urllib3 could help.

@pankajghadge are you able to try it?

@pankajghadge
Copy link
Author

@DmitryKuzmenko
python-etcd already have latest version 0.4.5 from the beginning
urllib3 upgraded from 1.25.7 to 1.25.9 (It is just a minor version upgrade)
We are still facing this issue.
If you want more trace details let me know. I will add log.trace or log.debug in salt python code.

@DmitryKuzmenko
Copy link
Contributor

DmitryKuzmenko commented Jun 4, 2020

I've just re-read all our discussion. Could you please detail some more things?

  1. In the very beginning you've provided the log ending with
Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method Client.__del__ of <etcd.client.Client object at 0x7f4f62781810>> ignored

This log is from salt command or from minion?

  1. When it happens the targeted minion terminates? Could you provide the debug log from the targeted minion? I want to understand what's happening there before this appears:
2020-05-05 17:00:15,248 [salt.utils.parsers:1071][WARNING ][1844] Minion received a SIGTERM. Exiting.
  1. You mentioned syndic. What's your salt layout? Master - Syndic - Minion?
  2. Is etcd cache enabled on all nodes: Master, Syndic, Minion?
  3. What cache related things are enabled on what nodes? Just grep cache from configs would be enough.

I think the Exception TypeError could be not directly related. It happens on exit during shutdown but something is starting the shutdown process.

@pankajghadge
Copy link
Author

pankajghadge commented Jun 12, 2020

@DmitryKuzmenko

  1. This log is from salt command or from minion?
    => salt command (we execute salt command from salt master only )
    => we don't execute salt command from salt-master-of-master (only few are executed )

  2. When it happens the targeted minion terminates?
    => no target minion do not terminate, also no error log entry on target minion

  3. You mentioned syndic. What's your salt layout? Master - Syndic - Minion?
    => (salt master of master)+(etcd server) => (Master + syndic) => (minion)

In every salt-master configuration we have entry of salt master of master (Multi master)
syndic_master: salt-master-of-master.example.com
etcd configuration I already mentioned

We have total:
1 master of master + 1 etcd cache
20 salt master + syndic
90-120 minions under each master

  1. Is etcd cache enabled on all nodes: Master, Syndic, Minion?
    => only on salt master ans salt-master-of-master we have etcd configuration

  2. What cache related things are enabled on what nodes? Just grep cache from configs would be enough
    => nothing is enabled on minion related to cache
    => On master only we have configuration related to etcd server as posted earlier

detailed Trace log

[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Including configuration from '/etc/salt/master.d/autoacceptkey.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/autoacceptkey.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/etcd-cache.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/etcd-cache.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/gitduma.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/gitduma.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/gitfs.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/gitfs.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/id.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/id.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/logging.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/logging.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/output.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/output.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/pillar.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/pillar.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/roots.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/roots.conf
[DEBUG   ] Missing configuration file: /root/.saltrc
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[TRACE   ] Loaded logstash_mod as virtual logstash
[INFO    ] Processing `log_handlers.logstash`
[DEBUG   ] Adding the 'logstash' provided logging handler: '<salt.loaded.int.log_handlers.logstash_mod.ZMQLogstashHander object at 0x7f60842aaf10>'
[DEBUG   ] Configuration file path: /etc/salt/master
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Including configuration from '/etc/salt/master.d/autoacceptkey.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/autoacceptkey.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/etcd-cache.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/etcd-cache.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/gitduma.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/gitduma.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/gitfs.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/gitfs.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/id.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/id.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/logging.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/logging.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/output.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/output.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/pillar.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/pillar.conf
[DEBUG   ] Including configuration from '/etc/salt/master.d/roots.conf'
[DEBUG   ] Reading configuration from /etc/salt/master.d/roots.conf
[DEBUG   ] Missing configuration file: /root/.saltrc
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/master', u'salt-master1.example.com_master', u'tcp://127.0.0.1:4506', u'clear')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
[DEBUG   ] Trying to connect to: tcp://127.0.0.1:4506
[TRACE   ] Inserted key into loop_instance_map id 140052477950864 for key (u'/etc/salt/pki/master', u'salt-master1.example.com_master', u'tcp://127.0.0.1:4506', u'clear') and process 20505
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[TRACE   ] func get_cli_event_returns()
[DEBUG   ] LazyLoaded local_cache.get_load
[DEBUG   ] Reading minion list from /var/cache/salt/master/jobs/83/003c5a988f1e488df5ac21fc61c4edef90c9ed50f6dc30302dc55fd1764128/.minions.p
[DEBUG   ] get_iter_returns for jid 20200612125355282393 sent to set(['vm-minion01']) will timeout at 12:54:00.291040
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] get_event() received = {u'tag': 'salt/job/20200612125355282393/new', u'data': {u'tgt_type': u'glob', u'jid': u'20200612125355282393', u'tgt': u'vm-minion01', u'missing': [], u'_stamp': u'2020-06-12T10:53:55.283282', u'user': u'root', u'arg': [u'ls -l /var'], u'fun': u'cmd.run', u'minions': [u'vm-minion01']}}
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[DEBUG   ] Checking whether jid 20200612125355282393 is still running
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/master', u'salt-master1.example.com_master', u'tcp://127.0.0.1:4506', u'clear')
[DEBUG   ] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
[DEBUG   ] Trying to connect to: tcp://127.0.0.1:4506
[TRACE   ] Inserted key into loop_instance_map id 140052460918832 for key (u'/etc/salt/pki/master', u'salt-master1.example.com_master', u'tcp://127.0.0.1:4506', u'clear') and process 20505
[DEBUG   ] Closing AsyncZeroMQReqChannel instance
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] get_event() caching unwanted event = {u'tag': '20200612125400311074', u'data': {u'_stamp': u'2020-06-12T10:54:00.311398', u'minions': [u'vm-minion01']}}
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] get_event() caching unwanted event = {u'tag': 'salt/job/20200612125400311074/new', u'data': {u'tgt_type': u'list', u'jid': u'20200612125400311074', u'tgt': [u'vm-minion01'], u'missing': [], u'_stamp': u'2020-06-12T10:54:00.311905', u'user': u'root', u'arg': [u'20200612125355282393'], u'fun': u'saltutil.find_job', u'minions': [u'vm-minion01']}}
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] get_event() returning cached event = {u'tag': 'salt/job/20200612125400311074/new', u'data': {u'tgt_type': u'list', u'jid': u'20200612125400311074', u'tgt': [u'vm-minion01'], u'missing': [], u'_stamp': u'2020-06-12T10:54:00.311905', u'user': u'root', u'arg': [u'20200612125355282393'], u'fun': u'saltutil.find_job', u'minions': [u'vm-minion01']}}
[DEBUG   ] Passing on saltutil error. Key 'u'retcode' missing from client return. This may be an error in the client.
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: (salt/job|syndic/.*)/20200612125355282393
[TRACE   ] _get_event() waited 0 seconds and received nothing
[TRACE   ] Get event. tag: salt/job/20200612125400311074
[TRACE   ] _get_event() waited 0 seconds and received nothing
[DEBUG   ] return event: {'vm-minion01': {u'failed': True}}
[TRACE   ] Loaded etcd_cache as virtual etcd
[TRACE   ] Error loading cache.consul: Failed to invoke consul.Consul, please make sure you have python-consul >= 0.2.0 installed
[TRACE   ] Error loading cache.mysql_cache: No python mysql client installed.
[TRACE   ] Error loading cache.redis_cache: Please install the python-redis package.
[DEBUG   ] Could not LazyLoad etcd.init_kwargs: 'etcd.init_kwargs' is not available.
[INFO    ] etcd: Setting up client with params: {u'username': u'salt-master-user', u'protocol': u'http', u'ca_cert': u'None', u'allow_redirect': False, u'srv_domain': None, u'host': u'etcd-cache-server', u'read_timeout': 60, u'password': u'testpass', u'port': 2379, u'allow_reconnect': True, u'cert': u'None'}
[DEBUG   ] Starting new HTTP connection (1): etcd-cache-server:2379
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/machines HTTP/1.1" 200 23
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/keys/salt_cache HTTP/1.1" 200 178
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/keys/salt_cache/minions HTTP/1.1" 200 None
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/keys/salt_cache/minions?recursive=true HTTP/1.1" 200 None
[TRACE   ] Loaded etcd_cache as virtual etcd
[TRACE   ] Error loading cache.consul: Failed to invoke consul.Consul, please make sure you have python-consul >= 0.2.0 installed
[TRACE   ] Error loading cache.mysql_cache: No python mysql client installed.
[TRACE   ] Error loading cache.redis_cache: Please install the python-redis package.
[DEBUG   ] Could not LazyLoad etcd.init_kwargs: 'etcd.init_kwargs' is not available.
[INFO    ] etcd: Setting up client with params: {u'username': u'salt-master-user', u'protocol': u'http', u'ca_cert': u'None', u'allow_redirect': False, u'srv_domain': None, u'host': u'etcd-cache-server', u'read_timeout': 60, u'password': u'testpass', u'port': 2379, u'allow_reconnect': True, u'cert': u'None'}
[DEBUG   ] Starting new HTTP connection (1): etcd-cache-server:2379
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/machines HTTP/1.1" 200 23
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/keys/salt_cache HTTP/1.1" 200 178
[DEBUG   ] http://etcd-cache-server:2379 "GET /v2/keys/salt_cache/minions?recursive=true HTTP/1.1" 200 None
[DEBUG   ] LazyLoaded no_return.output
[TRACE   ] data = {'vm-minion01': u'Minion did not return. [No response]'}
[DEBUG   ] Closing IPCMessageSubscriber instance
ERROR: Minions returned with non-zero exit code
vm-minion01:
    Minion did not return. [No response]
Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method Client.__del__ of <etcd.client.Client object at 0x7f608232ee50>> ignored

@DmitryKuzmenko
Copy link
Contributor

@pankajghadge thank you for information. I still can not reproduce it on my side.
Are you able to patch your etcd client python package and check would it help? In this case I can work on a patch and if it would help we can contribute it to etcd client team.

@arizvisa
Copy link
Contributor

@pankajghadge, maybe a stupid question, but did you recently switch from python2 to python3?

@arizvisa
Copy link
Contributor

@DmitryKuzmenko, this is a scoping issue and is based on Python's GC. So it won't be easy to reproduce unless your interpreter's garbage collection is aggressive. You might be able to reproduce by explicitly deleting the etcd client when it has gone out of scope, and then calling gc.collect to get Python to clean it up.

You can likely consider it an upstream bug, though, as python-etcd should not be trying to access anything in the object at the time it's being deleted anyways because members of said object aren't guaranteed to exist at the time of deletion (an antipattern).

@DmitryKuzmenko
Copy link
Contributor

@arizvisa thank you for comment. I understand the possible reasons of the issue. And I've done a number of tests to try to reproduce it including small synthetic tests playing around destruction of the etcd client. The best way to fix it is to rewrite etcd client to be a context manager. But it's a big enough change in the upstream project. On the other hand there is etcd3 client that is already written in this way. We could port our code to it that looks better from my view point but it is not 2 lines patch because etcd3 API are different.

@arizvisa
Copy link
Contributor

Agreed. It should definitely be a context manager, or even persisted.

Yeah actually, I've been trying to get my rewrite of the etcd returner merged into master since saltstack was split up into the "develop" branch like 2 years ago (#51363, with another addition in PR #55186).

Right now it's stuck in the "Merge ports into master" project, but once that finaally gets merged into the "master" branch. I'd be willing to re-implement the logic for the etcd returner to use the etcd3 api.

@pankajghadge
Copy link
Author

@pankajghadge, maybe a stupid question, but did you recently switch from python2 to python3?

no we didn't switch to python 3

@pankajghadge
Copy link
Author

pankajghadge commented Jun 23, 2020

@pankajghadge thank you for information. I still can not reproduce it on my side.
Are you able to patch your etcd client python package and check would it help? In this case I can work on a patch and if it would help we can contribute it to etcd client team.

@DmitryKuzmenko I don't know how to patch etcd client python package.
in pip i don't see any updates are available
Here is the list of python packages which are available updates but i don't see python etcd package

$ pip list --outdated

Babel (0.9.6) - Latest: 2.8.0 [wheel]
backports.ssl-match-hostname (3.5.0.1) - Latest: 3.7.0.1 [sdist]
cffi (1.6.0) - Latest: 1.14.0 [wheel]
chardet (2.2.1) - Latest: 3.0.4 [wheel]
cheroot (8.2.1) - Latest: 8.3.0 [wheel]
CherryPy (17.4.2) - Latest: 18.6.0 [wheel]
configobj (4.7.2) - Latest: 5.0.6 [sdist]
configshell-fb (1.1.23) - Latest: 1.1.28 [sdist]
decorator (3.4.0) - Latest: 4.4.2 [wheel]
ethtool (0.8) - Latest: 0.14 [sdist]
futures (3.1.1) - Latest: 3.3.0 [wheel]
gevent (1.4.0) - Latest: 20.6.2 [sdist]
greenlet (0.4.15) - Latest: 0.4.16 [wheel]
iniparse (0.4) - Latest: 0.5 [wheel]
ipaddress (1.0.16) - Latest: 1.0.23 [wheel]
jaraco.functools (2.0) - Latest: 3.0.1 [sdist]
Jinja2 (2.7.2) - Latest: 2.11.2 [wheel]
kitchen (1.1.1) - Latest: 1.2.6 [sdist]
kmod (0.1) - Latest: 0.9.2 [sdist]
langtable (0.0.31) - Latest: 0.0.51 [sdist]
lxml (3.2.1) - Latest: 4.5.1 [wheel]
M2Crypto (0.21.1) - Latest: 0.35.2 [sdist]
MarkupSafe (0.11) - Latest: 1.1.1 [wheel]
more-itertools (5.0.0) - Latest: 8.4.0 [sdist]
msgpack (0.6.2) - Latest: 1.0.0 [sdist]
netaddr (0.7.5) - Latest: 0.7.20 [wheel]
pip (8.1.2) - Latest: 20.1.1 [wheel]
ply (3.4) - Latest: 3.11 [wheel]
psutil (2.2.1) - Latest: 5.7.0 [sdist]
pycparser (2.19) - Latest: 2.20 [wheel]
pycurl (7.19.0) - Latest: 7.43.0.5 [sdist]
pygit2 (0.26.4) - Latest: 1.2.1 [sdist]
pygobject (3.22.0) - Latest: 3.36.1 [sdist]
pyinotify (0.9.4) - Latest: 0.9.6 [sdist]
pyOpenSSL (0.13.1) - Latest: 19.1.0 [wheel]
pyparsing (1.5.6) - Latest: 2.4.7 [wheel]
python-augeas (0.5.0) - Latest: 1.1.0 [sdist]
python-dateutil (1.5) - Latest: 2.8.1 [wheel]
python-gnupg (0.4.4) - Latest: 0.4.6 [wheel]
python-ldap (2.4.15) - Latest: 3.3.0 [sdist]
pytz (2019.3) - Latest: 2020.1 [wheel]
pyudev (0.15) - Latest: 0.22.0 [sdist]
pywbem (0.7.0) - Latest: 0.17.2 [wheel]
pyxattr (0.5.1) - Latest: 0.7.1 [sdist]
PyYAML (3.10) - Latest: 5.3.1 [sdist]
pyzmq (15.3.0) - Latest: 19.0.1 [wheel]
requests (2.6.0) - Latest: 2.24.0 [wheel]
salt (2019.2.4) - Latest: 3001 [sdist]
setuptools (36.6.0) - Latest: 47.3.1 [sdist]
six (1.12.0) - Latest: 1.15.0 [wheel]
slip (0.4.0) - Latest: 20191113 [sdist]
tempora (1.14.1) - Latest: 3.0.0 [wheel]
tornado (4.2.1) - Latest: 6.0.4 [sdist]
urlgrabber (3.10) - Latest: 4.1.0 [sdist]
urllib3 (1.25.7) - Latest: 1.25.9 [wheel]
urwid (1.1.1) - Latest: 2.1.0 [sdist]
xmldiff (2.3) - Latest: 2.4 [wheel]

@arizvisa
Copy link
Contributor

Hey @DmitryKuzmenko, do you think it would be safe to assign the connection globally (in the module) so that it doesn't go out of scope, or is there some way to attach the etcd connection object somewhere so it doesn't get gc'd?

Or do you think that it would just be safer to explicitly call .__del__() when the connection object is done being used so that way client.http can be set to None to avoid hitting that conditional? I feel like tampering with client.http might break whenever upstream issues their fix, but it might be the better than the solution of avoiding garbage collection altogether...

@DmitryKuzmenko
Copy link
Contributor

@arizvisa the connection is already global in the cache module. Maybe that's the issue. We can probably try to move it out of the global scope but this will produce a performance regression. Probably it is worth to try to keep the client in the __context__ dunder.

@DmitryKuzmenko
Copy link
Contributor

@pankajghadge could you try to patch salt on master node where you run salt command with this patch and try to reproduce the issue again?

diff --git a/salt/cache/etcd_cache.py b/salt/cache/etcd_cache.py
index 97d43edd82..da7a33d399 100644
--- a/salt/cache/etcd_cache.py
+++ b/salt/cache/etcd_cache.py
@@ -67,7 +67,7 @@ if HAS_ETCD:
     etcd._log.setLevel(logging.INFO)  # pylint: disable=W0212
 
 log = logging.getLogger(__name__)
-client = None
+etcd_kwargs = None
 path_prefix = None
 
 # Module properties
@@ -90,9 +90,10 @@ def __virtual__():
 def _init_client():
     '''Setup client and init datastore.
     '''
-    global client, path_prefix
-    if client is not None:
-        return
+    global etcd_kwargs, path_prefix
+
+    if etcd_kwargs is not None:
+        return etcd.Client(**etcd_kwargs)
 
     etcd_kwargs = {
             'host': __opts__.get('etcd.host', '127.0.0.1'),
@@ -117,13 +118,14 @@ def _init_client():
     except etcd.EtcdKeyNotFound:
         log.info("etcd: Creating dir %r", path_prefix)
         client.write(path_prefix, None, dir=True)
+    return client
 
 
 def store(bank, key, data):
     '''
     Store a key value.
     '''
-    _init_client()
+    client = _init_client()
     etcd_key = '{0}/{1}/{2}'.format(path_prefix, bank, key)
     try:
         value = __context__['serial'].dumps(data)
@@ -138,7 +140,7 @@ def fetch(bank, key):
     '''
     Fetch a key value.
     '''
-    _init_client()
+    client = _init_client()
     etcd_key = '{0}/{1}/{2}'.format(path_prefix, bank, key)
     try:
         value = client.read(etcd_key).value
@@ -157,7 +159,7 @@ def flush(bank, key=None):
     '''
     Remove the key from the cache bank with all the key content.
     '''
-    _init_client()
+    client = _init_client()
     if key is None:
         etcd_key = '{0}/{1}'.format(path_prefix, bank)
     else:
@@ -195,7 +197,7 @@ def ls(bank):
     Return an iterable object containing all entries stored in the specified
     bank.
     '''
-    _init_client()
+    client = _init_client()
     path = '{0}/{1}'.format(path_prefix, bank)
     try:
         return _walk(client.read(path))
@@ -211,7 +213,7 @@ def contains(bank, key):
     '''
     Checks if the specified bank contains the specified key.
     '''
-    _init_client()
+    client = _init_client()
     etcd_key = '{0}/{1}/{2}'.format(path_prefix, bank, key)
     try:
         r = client.read(etcd_key)

@malletp
Copy link

malletp commented Jun 25, 2020

Hello @DmitryKuzmenko,

I just applied your patch to a master and that solves the problem.
Without the patch:

...
[DEBUG   ] LazyLoaded no_return.output
myminion:
    Minion did not return. [No response]
[DEBUG   ] Closing IPCMessageSubscriber instance
ERROR: Minions returned with non-zero exit code
Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method Client.__del__ of <etcd.client.Client object at 0x7facf457e5d0>> ignored

With the patch:

...
[DEBUG   ] LazyLoaded no_return.output
myminion:
    Minion did not return. [No response]
[DEBUG   ] Closing IPCMessageSubscriber instance
ERROR: Minions returned with non-zero exit code

@DmitryKuzmenko DmitryKuzmenko added Confirmed Salt engineer has confirmed bug/feature - often including a MCVE severity-medium 3rd level, incorrect or bad functionality, confusing and lacks a work around Core relates to code central or existential to Salt and removed info-needed waiting for more info labels Jun 25, 2020
@DmitryKuzmenko
Copy link
Contributor

@malletp thank you! Just one thing: to test the change I have to fully cover the module with tests =) I'll do it some day.

@pankajghadge
Copy link
Author

pankajghadge commented Jun 29, 2020

@DmitryKuzmenko :
for this issue : ERROR: Minions returned with non-zero exit code
We have 2 processor and 16 GB RAM . Can less CPU be the reason of it?
What is the Hardware recommendation for architecture that we showed above ?

Also swap memory is 0 on salt master and minions
So we have modified the /etc/sysctl.d/99-salt.conf

cat /etc/sysctl.d/99-salt.conf
#
# Kernel sysctl configuration
#
vm.hugetlb_shm_group = 439
vm.swappiness = 0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug broken, incorrect, or confusing behavior Confirmed Salt engineer has confirmed bug/feature - often including a MCVE Core relates to code central or existential to Salt severity-medium 3rd level, incorrect or bad functionality, confusing and lacks a work around
Projects
None yet
Development

No branches or pull requests

4 participants