Presence events constantly indicating every minion as a "new" connection

[morganwillcock]

This has only been an issue since upgrading to 2016.3.0, but with presence events enabled I'm getting every minion listed as a new connection, every time the events are fired:

salt-run state.event pretty=True

salt/presence/change   {
    "_stamp": "2016-05-27T15:01:19.427580", 
    "lost": [], 
    "new": [
        "minion01", 
        "minion02", 
        "minion03"
    ]
}

Versions Report

Salt Version:
Salt: 2016.3.0

Dependency Versions:
cffi: 0.8.6
cherrypy: Not Installed
dateutil: 2.2
gitdb: 0.5.4
gitpython: 0.3.2 RC1
ioflo: Not Installed
Jinja2: 2.7.3
libgit2: Not Installed
libnacl: Not Installed
M2Crypto: Not Installed
Mako: Not Installed
msgpack-pure: Not Installed
msgpack-python: 0.4.2
mysql-python: 1.2.3
pycparser: 2.10
pycrypto: 2.6.1
pygit2: Not Installed
Python: 2.7.9 (default, Mar 1 2015, 12:57:24)
python-gnupg: Not Installed
PyYAML: 3.11
PyZMQ: 14.4.0
RAET: Not Installed
smmap: 0.8.2
timelib: Not Installed
Tornado: 4.2.1
ZMQ: 4.0.5

System Versions:
dist: debian 8.4
machine: x86_64
release: 3.16.0-4-amd64
system: Linux
version: debian 8.4

[Ch3LL]

@morganwillcock i'm not able to replicate this on 2016.3.0:

salt/presence/present   {
    "_stamp": "2016-05-27T21:37:12.084759", 
    "present": [
        "ch3ll-master"
    ]

It shows as present and not new. Are there any other factors that would help me replicate this?

[morganwillcock]

@Ch3LL thanks for testing. salt/presence/change, rather than salt/presence/present, is where I'm seeing the problem. Do you see any of those events being fired?

[morganwillcock]

@Ch3LL I tried to test this a little more today. Disabling a scheduled grain sync that was configured (via pillar data, so just a pillar refresh) seemed to stop the change events being fired, but a couple of hours later they started again (all minions indicating as new and the change event firing every couple of minutes). I'm hoping to test this further tomorrow, but it seems it isn't straightforward to easily recreate the problem.

[morganwillcock]

@Ch3LL I think I've narrowed it down, the event appearing coincides with a maintenance process being restarted:

grep "Gathering reactors for tag salt/presence/change" /var/log/salt/master | tail

2016-06-02 08:55:53,994 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 09:07:26,339 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 09:29:26,447 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 09:50:23,925 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 09:58:48,046 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 10:29:07,969 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 11:23:34,170 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 11:45:34,814 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 11:47:42,318 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change
2016-06-02 12:04:27,979 [salt.utils.reactor][DEBUG   ][18561] Gathering reactors for tag salt/presence/change

grep "died with exit status" /var/log/salt/master | tail

2016-06-02 08:55:51,990 [salt.utils.process][INFO    ][18478] Process  (16700) died with exit status None, restarting...
2016-06-02 09:07:24,354 [salt.utils.process][INFO    ][18478] Process  (16861) died with exit status None, restarting...
2016-06-02 09:29:24,464 [salt.utils.process][INFO    ][18478] Process  (17772) died with exit status None, restarting...
2016-06-02 09:50:21,916 [salt.utils.process][INFO    ][18478] Process  (19436) died with exit status None, restarting...
2016-06-02 09:58:46,050 [salt.utils.process][INFO    ][18478] Process  (21001) died with exit status None, restarting...
2016-06-02 10:29:06,037 [salt.utils.process][INFO    ][18478] Process  (21662) died with exit status None, restarting...
2016-06-02 11:23:32,212 [salt.utils.process][INFO    ][18478] Process  (23849) died with exit status None, restarting...
2016-06-02 11:45:32,794 [salt.utils.process][INFO    ][18478] Process  (27808) died with exit status None, restarting...
2016-06-02 11:47:40,288 [salt.utils.process][INFO    ][18478] Process  (29470) died with exit status None, restarting...
2016-06-02 12:04:25,957 [salt.utils.process][INFO    ][18478] Process  (29709) died with exit status None, restarting...

Traceback for maintenance process:

Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/salt/utils/process.py", line 613, in _run
    return self._original_run()
  File "/usr/lib/python2.7/dist-packages/salt/master.py", line 236, in run
    salt.daemons.masterapi.clean_old_jobs(self.opts)
  File "/usr/lib/python2.7/dist-packages/salt/daemons/masterapi.py", line 187, in clean_old_jobs
    mminion.returners[fstr]()
  File "/usr/lib/python2.7/dist-packages/salt/returners/local_cache.py", line 413, in clean_old_jobs
    shutil.rmtree(t_path)
  File "/usr/lib/python2.7/shutil.py", line 239, in rmtree
    onerror(os.listdir, path, sys.exc_info())
  File "/usr/lib/python2.7/shutil.py", line 237, in rmtree
    names = os.listdir(path)
OSError: [Errno 2] No such file or directory: '/var/cache/salt/master/jobs/39'

I'm guessing this is fixed with #33555 ?

[morganwillcock]

Fixed on upgrade to 2016.3.1