2014.7.0 multimaster / multiprocessing issues

[Rucknar]

Slightly odd one this... We are upgrading from 2014.1.13 to 2014.7.0 in a multi-master environment. We've upgraded 3 of 600 minions to test (1RHEL5/2RHEL6) and all have exhibited the issue below:

With multiprocessing: True as is set by default, the minions successfully connect to both master servers, receive commands from both masters successfully but the return's only ever seem to work with one of the two masters.

For example, running a test.ping from master01 will show a return, running from master02 times out. The minion's log shows both masters as being connected and shows the results of the command as being sent off to the salt master.

We've spent a while looking at this and started grabbing as straws, one of these was to disable multiprocessing. Once that's done then the minion successfully reports to both masters.

I suspect this is just highlighting the root cause in a different light but were quite stuck with this and it's quite urgent for us. Disabling multiprocessing doesn't really work with our work flows.

[Rucknar]

Master versions:

           Salt: 2014.7.0
         Python: 2.6.6 (r266:84292, Nov 21 2013, 10:50:32)
         Jinja2: unknown
       M2Crypto: 0.20.2
 msgpack-python: 0.1.13
   msgpack-pure: Not Installed
       pycrypto: 2.0.1
        libnacl: Not Installed
         PyYAML: 3.10
          ioflo: Not Installed
          PyZMQ: 14.3.1
           RAET: Not Installed
            ZMQ: 4.0.4
           Mako: Not Installed

Minion Versions:

           Salt: 2014.7.0
         Python: 2.6.8 (unknown, Nov  7 2012, 14:47:34)
         Jinja2: 2.5.5
       M2Crypto: 0.21.1
 msgpack-python: 0.1.12
   msgpack-pure: Not Installed
       pycrypto: 2.3
        libnacl: Not Installed
         PyYAML: 3.08
          ioflo: Not Installed
          PyZMQ: 14.3.1
           RAET: Not Installed
            ZMQ: 4.0.4
           Mako: Not Installed

[rallytime]

That is very strange behavior. I tested multi-master before we tagged the release, and I have set up a simple environment again to see if I can reproduce your issue. So far I don't see any problems. I installed 2014.7.0 on an Ubuntu 14.04 master (nt-m1) as well as a CentOS 6.5 master (nt-m2) and a salt-minion on another CentOS 6.5 VM. I did not edit anything in the minion config file except for the location of the masters. (so muliprocessing: True is still the default).

Master 1:

root@nt-m1:~# salt nt-minion test.ping
nt-minion:
    True

Master 2:

[root@nt-m2 pki]# salt '*' test.ping
nt-minion:
    True

Minion running in debug mode:

[DEBUG   ] Attempting to authenticate with the Salt Master at 23.253.248.200
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[INFO    ] Authentication with master at 23.253.248.200 successful!
...
[DEBUG   ] Attempting to authenticate with the Salt Master at 23.253.106.233
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[INFO    ] Authentication with master at 23.253.106.233 successful!
...
[INFO    ] User root Executing command test.ping with jid 20141120214856713180
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20141120214856713180', 'tgt': 'nt-minion', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
[INFO    ] Starting a new job with PID 3683
[INFO    ] Returning information for job: 20141120214856713180
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[INFO    ] User root Executing command test.ping with jid 20141120214949369028
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20141120214949369028', 'tgt': '*', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
[INFO    ] Starting a new job with PID 3754
[INFO    ] Returning information for job: 20141120214949369028

@Rucknar When you say "only seem to work with one of the masters" do you mean you are only seeing feedback on the CLI for one master? And when you say only one master shows a return, is it the same master each time that doesn't show the return? What OS's are your master's running on?

[Rucknar]

Thanks for taking a look @rallytime. To further expand, it doesn't appear to be the same master each time. The problems also exhibited its-self with the minions installed on the respective master.

• The minion for master1 appears in the salt-run manage.down output on master.
• On master2 the master2 minion shows itself as down that master.

The minion is however up on the masters counter-part.

With the remote minion we upgraded (standard vm, no master) commands work on master1 and not master2, appearing in the salt-run manage.down output for the master we have issues with. When running that command, i see the minion respond to it and it seems to think it's returned and all is okay.

I did wonder if the return was somehow ending up at the wrong master but not sure how i could possibly tell. We've tried restarts (full OS) of the master that's not working and we've tried restarting the salt-minion process on our remote node but the behaviour persists.

[Rucknar]

Were in a different timezone to yourself it's quite late, if there is any debug/error capture we can do then it's our top priority tomorrow so we will get right to it. Fortunately we've only partially upgraded our DR site so far, interestingly however the salt 2014.1.13 minions are connecting to both masters just fine and commands work as per normal on these servers.

[rallytime]

Thanks for the update @Rucknar. Are you exclusively using/seeing this on manage.down? There is another issue open where manage.down is giving false positives, but test.ping is working properly. I want to make sure that isn't the same issue.

[gavala]

Hello @rallytime, yes we're seeing test.ping fail as well as manage.down saying the minion is down. I'm half wondering if the multi-master connection randomisation has something to do with it when multiprocessing is enabled but we can do more tests on this in the morning and get some debug logs for everyone to look at

[Rucknar]

So that makes sense... we work on the same team :)

[rallytime]

@gavala That is useful information as well.

Also, is it possible for you guys to try a clean install of 2014.7.0 (instead of an upgrade) on your masters and only one of the minions? Maybe something funny is happening with the upgrade. You know, in the morning when you get a chance. :)

We fixed a ton of multi-master bugs with this release, and timeouts got a pretty big overhaul also.

[rallytime]

Are you guys using master_type or master_shuffle at all?

[Rucknar]

@rallytime Yep we can do that tomorrow! We're not using master_type or master_shuffle but like gavala said, we have used random_master.

[rallytime]

Alright, one more update. I installed 2014.7.0 minions on each of my masters, so I now have 2 masters and 3 minions. Each master is on a separate VM (with one minion) and then I have one VM with only a minion on it. All three minions are pointing to both masters and still have the default of multiprocessing: True.

Next, I set each minion to random_master: True and restarted the minions. Everything returned on the CLI as expected. I also tried master_shuffle: True (I tired that one first and then realized I had the wrong config option for your setup) and everything worked as expected there as well.

Here's the output from the random_master: True setup: Master 1:

root@nt-m1:~# salt '*' test.ping
nt-m1:
    True
nt-m2:
    True
nt-minion:
    True

Master 2:

[root@nt-m2 ~]# salt '*' test.ping
nt-m1:
    True
nt-m2:
    True
nt-minion:
    True

And the debug information for the stand-alone minion:

[INFO    ] User root Executing command test.ping with jid 20141120235420790219
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20141120235420790219', 'tgt': '*', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
[INFO    ] Starting a new job with PID 11444
[INFO    ] Returning information for job: 20141120235420790219
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[INFO    ] User root Executing command test.ping with jid 20141120235424222196
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20141120235424222196', 'tgt': '*', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
[INFO    ] Starting a new job with PID 11451
[INFO    ] Returning information for job: 20141120235424222196

[Rucknar]

Some more information before we try the fresh install, server-names and ip's have been replaced.

Minion configuration explicitly set.

master:
    - master1.fqdn
    - master2.fqdn
random_master: True
id: minion1.fqdn
random_reauth_delay: 60
auth_timeout: 60
recon_randomize: False
startup_states: 'highstate'

Master configuration explicitly set.

worker_threads: 10
autoreject_file: /etc/salt/autoreject.conf
keep_jobs: 24
ping_on_rotate: True
auto_accept: True
file_roots:
  base:
    - /srv/salt

Minion Logs from start and with a command then issued from the salt master that's not getting the return.

2014-11-21 07:28:39,576 [salt.fileclient                             ][INFO    ] Caching directory '_modules/' for environment 'base'
2014-11-21 07:26:57,053 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:26:57,275 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:26:57,493 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:25,919 [salt             ][INFO    ] Setting up the Salt Minion "minion1.fqdn"
2014-11-21 07:28:25,924 [salt.utils.process][DEBUG   ] Created pidfile: /var/run/salt-minion.pid
2014-11-21 07:28:25,935 [salt.minion      ][DEBUG   ] MultiMinion PUB socket URI: ipc:///var/run/salt/minion/minion_event_104df00a9f_pub.ipc
2014-11-21 07:28:25,936 [salt.minion      ][DEBUG   ] MultiMinion PULL socket URI: ipc:///var/run/salt/minion/minion_event_104df00a9f_pull.ipc
2014-11-21 07:28:25,936 [salt.minion      ][INFO    ] Starting pub socket on ipc:///var/run/salt/minion/minion_event_104df00a9f_pub.ipc
2014-11-21 07:28:25,938 [salt.minion      ][INFO    ] Starting pull socket on ipc:///var/run/salt/minion/minion_event_104df00a9f_pull.ipc
2014-11-21 07:28:25,941 [salt.config      ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:26,423 [salt.minion                              ][DEBUG   ] Attempting to authenticate with the Salt Master at master1-ip
2014-11-21 07:28:26,424 [salt.crypt                               ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:26,815 [salt.crypt                               ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:26,816 [salt.crypt                               ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:27,412 [salt.minion                              ][INFO    ] Authentication with master at master1-ip successful!
2014-11-21 07:28:27,555 [salt.crypt                               ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:27,556 [salt.crypt                               ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:28,116 [salt.crypt                               ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:28,403 [salt.config                              ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:28,879 [salt.cloud                                 ][DEBUG   ] Mako not available
2014-11-21 07:28:29,338 [salt.utils.schedule                         ][DEBUG   ] schedule.clean_proc_dir: checking job {'tgt_type': 'pcre', 'jid': '20141121072621712789', 'tgt': 'minion1', 'pid': 31059, 'ret': '', 'user': 'marshalle', 'arg': [], 'fun': 'test.ping'} for process existence
2014-11-21 07:28:29,339 [salt.utils.schedule                         ][DEBUG   ] schedule.clean_proc_dir: checking job {'tgt_type': 'grain', 'jid': '20141121051923853253', 'tgt': 'environment:LIVE_B', 'pid': 31059, 'ret': '', 'user': 'vco', 'arg': ['20141121051513468556'], 'fun': 'saltutil.find_job'} for process existence
2014-11-21 07:28:29,339 [salt.utils.schedule                         ][DEBUG   ] schedule.clean_proc_dir: checking job {'tgt_type': 'pcre', 'jid': '20141121072613679187', 'tgt': 'minion1', 'pid': 31059, 'ret': '', 'user': 'marshalle', 'arg': [], 'fun': 'test.ping'} for process existence
2014-11-21 07:28:29,340 [salt.minion                                 ][INFO    ] Added mine.update to schedular
2014-11-21 07:28:29,340 [salt.utils.schedule                         ][INFO    ] Added new job __mine_interval to scheduler
2014-11-21 07:28:29,340 [salt.minion                                 ][DEBUG   ] I am minion1.fqdn and I am not supposed to start any proxies. (Likely not a problem)
2014-11-21 07:28:29,341 [salt.config                                 ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:29,966 [salt.minion                                 ][DEBUG   ] Attempting to authenticate with the Salt Master at master2-ip
2014-11-21 07:28:29,968 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:30,429 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:30,430 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:31,064 [salt.minion                                 ][INFO    ] Authentication with master at master2-ip successful!
2014-11-21 07:28:31,215 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:31,216 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:31,971 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:32,243 [salt.config                                 ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:33,100 [salt.minion                                 ][INFO    ] Added mine.update to schedular
2014-11-21 07:28:33,101 [salt.utils.schedule                         ][INFO    ] Updating job settings for scheduled job: __mine_interval
2014-11-21 07:28:33,101 [salt.minion                                 ][DEBUG   ] I am minion1.fqdn and I am not supposed to start any proxies. (Likely not a problem)
2014-11-21 07:28:33,101 [salt.utils.schedule                         ][INFO    ] Running scheduled job: __mine_interval
2014-11-21 07:28:33,102 [salt.utils.schedule                         ][DEBUG   ] schedule: This job was scheduled with jid_include, adding to cache (jid_include defaults to True)
2014-11-21 07:28:33,102 [salt.utils.schedule                         ][DEBUG   ] schedule: This job was scheduled with a max number of 2
2014-11-21 07:28:33,109 [salt.utils.schedule                         ][DEBUG   ] schedule.handle_func: adding this job to the jobcache with data {'fun': 'mine.update', 'jid': '20141121072833105826', 'pid': 15032, 'id': 'minion1.fqdn', 'schedule': '__mine_interval'}
2014-11-21 07:28:33,112 [salt.utils.schedule                         ][INFO    ] Running scheduled job: __mine_interval
2014-11-21 07:28:33,112 [salt.utils.schedule                         ][DEBUG   ] schedule: This job was scheduled with jid_include, adding to cache (jid_include defaults to True)
2014-11-21 07:28:33,113 [salt.utils.schedule                         ][DEBUG   ] schedule: This job was scheduled with a max number of 2
2014-11-21 07:28:33,116 [salt.utils.schedule                         ][DEBUG   ] schedule.handle_func: Checking job against fun mine.update: {'fun': 'mine.update', 'jid': '20141121072833105826', 'pid': 15032, 'id': 'minion1.fqdn', 'schedule': '__mine_interval'}
2014-11-21 07:28:33,117 [salt.utils.schedule                         ][DEBUG   ] schedule.handle_func: Incrementing jobcount, now 1, maxrunning is 2
2014-11-21 07:28:33,120 [salt.minion                                 ][INFO    ] Minion is starting as user 'root'
2014-11-21 07:28:33,121 [salt.minion                                 ][DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
2014-11-21 07:28:33,121 [salt.utils.schedule                         ][DEBUG   ] schedule.handle_func: adding this job to the jobcache with data {'fun': 'mine.update', 'jid': '20141121072833114763', 'pid': 15037, 'id': 'minion1.fqdn', 'schedule': '__mine_interval'}
2014-11-21 07:28:33,255 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:33,256 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:33,267 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:33,269 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:33,270 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:33,271 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:33,783 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:33,819 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:33,989 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:33,990 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:34,146 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:34,146 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:34,220 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:34,220 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:34,458 [salt.minion                                 ][INFO    ] Starting a new job with PID 15052
2014-11-21 07:28:34,633 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:34,634 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:35,236 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:35,237 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:35,464 [salt.minion                                 ][INFO    ] Minion is starting as user 'root'
2014-11-21 07:28:35,465 [salt.minion                                 ][DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
2014-11-21 07:28:35,607 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:35,608 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:35,811 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:36,039 [salt.state                                  ][INFO    ] Loading fresh modules for state activity
2014-11-21 07:28:36,217 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:36,218 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:36,470 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://top.sls'
2014-11-21 07:28:36,473 [salt.utils.jinja                            ][DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
2014-11-21 07:28:36,481 [salt.template                               ][DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/top.sls:
base:
  '*':
    - common

2014-11-21 07:28:36,483 [salt.loaded.int.render.yaml                 ][DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['common'])]))])
2014-11-21 07:28:36,484 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:36,706 [salt.minion                                 ][INFO    ] Starting a new job with PID 15071
2014-11-21 07:28:36,723 [salt.loaded.int.module.saltutil             ][DEBUG   ] Syncing all
2014-11-21 07:28:36,723 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing modules for environment 'base'
2014-11-21 07:28:36,724 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_modules, for base)
2014-11-21 07:28:36,871 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:36,871 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:36,881 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:36,881 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:37,369 [salt.fileclient                             ][INFO    ] Caching directory '_modules/' for environment 'base'
2014-11-21 07:28:37,378 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/aide.py'
2014-11-21 07:28:37,382 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/bomextract.py'
2014-11-21 07:28:37,387 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/chefclient.py'
2014-11-21 07:28:37,391 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/compliance.py'
2014-11-21 07:28:37,395 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/groundhog.py'
2014-11-21 07:28:37,398 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/lamp.py'
2014-11-21 07:28:37,401 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/lockdown.py'
2014-11-21 07:28:37,405 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/netcat.py'
2014-11-21 07:28:37,409 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/obcontrol.py'
2014-11-21 07:28:37,412 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/obmisc.py'
2014-11-21 07:28:37,416 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/platform.py'
2014-11-21 07:28:37,419 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/sysstat.py'
2014-11-21 07:28:37,422 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/telnet.py'
2014-11-21 07:28:37,425 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/tramp.py'
2014-11-21 07:28:37,428 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/yumprep.py'
2014-11-21 07:28:37,428 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_modules'
2014-11-21 07:28:37,429 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/aide.py' to '/var/cache/salt/minion/extmods/modules/aide.py'
2014-11-21 07:28:37,429 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/bomextract.py' to '/var/cache/salt/minion/extmods/modules/bomextract.py'
2014-11-21 07:28:37,430 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/chefclient.py' to '/var/cache/salt/minion/extmods/modules/chefclient.py'
2014-11-21 07:28:37,430 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/compliance.py' to '/var/cache/salt/minion/extmods/modules/compliance.py'
2014-11-21 07:28:37,431 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/groundhog.py' to '/var/cache/salt/minion/extmods/modules/groundhog.py'
2014-11-21 07:28:37,431 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/lamp.py' to '/var/cache/salt/minion/extmods/modules/lamp.py'
2014-11-21 07:28:37,432 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/lockdown.py' to '/var/cache/salt/minion/extmods/modules/lockdown.py'
2014-11-21 07:28:37,432 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/netcat.py' to '/var/cache/salt/minion/extmods/modules/netcat.py'
2014-11-21 07:28:37,433 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/obcontrol.py' to '/var/cache/salt/minion/extmods/modules/obcontrol.py'
2014-11-21 07:28:37,433 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/obmisc.py' to '/var/cache/salt/minion/extmods/modules/obmisc.py'
2014-11-21 07:28:37,434 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/platform.py' to '/var/cache/salt/minion/extmods/modules/platform.py'
2014-11-21 07:28:37,434 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/sysstat.py' to '/var/cache/salt/minion/extmods/modules/sysstat.py'
2014-11-21 07:28:37,435 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/telnet.py' to '/var/cache/salt/minion/extmods/modules/telnet.py'
2014-11-21 07:28:37,435 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/tramp.py' to '/var/cache/salt/minion/extmods/modules/tramp.py'
2014-11-21 07:28:37,436 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/yumprep.py' to '/var/cache/salt/minion/extmods/modules/yumprep.py'
2014-11-21 07:28:37,438 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/states'
2014-11-21 07:28:37,439 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing states for environment 'base'
2014-11-21 07:28:37,439 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_states, for base)
2014-11-21 07:28:37,439 [salt.fileclient                             ][INFO    ] Caching directory '_states/' for environment 'base'
2014-11-21 07:28:37,442 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_states'
2014-11-21 07:28:37,443 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/grains'
2014-11-21 07:28:37,443 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing grains for environment 'base'
2014-11-21 07:28:37,443 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_grains, for base)
2014-11-21 07:28:37,443 [salt.fileclient                             ][INFO    ] Caching directory '_grains/' for environment 'base'
2014-11-21 07:28:37,446 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_grains'
2014-11-21 07:28:37,447 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/renderers'
2014-11-21 07:28:37,447 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing renderers for environment 'base'
2014-11-21 07:28:37,447 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_renderers, for base)
2014-11-21 07:28:37,448 [salt.fileclient                             ][INFO    ] Caching directory '_renderers/' for environment 'base'
2014-11-21 07:28:37,450 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_renderers'
2014-11-21 07:28:37,451 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/returners'
2014-11-21 07:28:37,451 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing returners for environment 'base'
2014-11-21 07:28:37,452 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_returners, for base)
2014-11-21 07:28:37,452 [salt.fileclient                             ][INFO    ] Caching directory '_returners/' for environment 'base'
2014-11-21 07:28:37,454 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_returners'
2014-11-21 07:28:37,455 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/outputters'
2014-11-21 07:28:37,455 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing outputters for environment 'base'
2014-11-21 07:28:37,455 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_outputters, for base)
2014-11-21 07:28:37,456 [salt.fileclient                             ][INFO    ] Caching directory '_outputters/' for environment 'base'
2014-11-21 07:28:37,458 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_outputters'
2014-11-21 07:28:37,459 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/utils'
2014-11-21 07:28:37,459 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing utils for environment 'base'
2014-11-21 07:28:37,459 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_utils, for base)
2014-11-21 07:28:37,460 [salt.fileclient                             ][INFO    ] Caching directory '_utils/' for environment 'base'
2014-11-21 07:28:37,462 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_utils'
2014-11-21 07:28:37,463 [salt.state                                  ][DEBUG   ] Refreshing modules...
2014-11-21 07:28:37,490 [salt.state                                  ][INFO    ] Loading fresh modules for state activity
2014-11-21 07:28:37,530 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:37,530 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:37,862 [salt.utils.event                            ][DEBUG   ] SaltEvent PUB socket URI: ipc:///var/run/salt/minion/minion_event_104df00a9f_pub.ipc
2014-11-21 07:28:37,863 [salt.utils.event                            ][DEBUG   ] SaltEvent PULL socket URI: ipc:///var/run/salt/minion/minion_event_104df00a9f_pull.ipc
2014-11-21 07:28:37,863 [salt.utils.event                            ][DEBUG   ] Sending event - data = {'_stamp': '2014-11-21T07:28:37.863097'}
2014-11-21 07:28:37,894 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://common.sls'
2014-11-21 07:28:37,897 [salt.utils.jinja                            ][DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
2014-11-21 07:28:37,899 [salt.template                               ][DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/common.sls:
salt-minion:
  pkg:
    - installed

2014-11-21 07:28:37,901 [salt.loaded.int.render.yaml                 ][DEBUG   ] Results of YAML rendering:
OrderedDict([('salt-minion', OrderedDict([('pkg', ['installed'])]))])
2014-11-21 07:28:37,902 [salt.state                                  ][INFO    ] Running state [salt-minion] at time 07:28:37.901592
2014-11-21 07:28:37,902 [salt.state                                  ][INFO    ] Executing state pkg.installed for salt-minion
2014-11-21 07:28:37,903 [salt.loaded.int.module.cmdmod               ][INFO    ] Executing command 'repoquery --plugins --queryformat="%{NAME}_|-%{VERSION}_|-%{RELEASE}_|-%{ARCH}_|-%{REPOID}" --all --pkgnarrow=installed' in directory '/root'
2014-11-21 07:28:38,032 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:38,282 [salt.state                                  ][INFO    ] Loading fresh modules for state activity
2014-11-21 07:28:38,704 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://top.sls'
2014-11-21 07:28:38,707 [salt.utils.jinja                            ][DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
2014-11-21 07:28:38,715 [salt.template                               ][DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/top.sls:
base:
  '*':
    - common

2014-11-21 07:28:38,717 [salt.loaded.int.render.yaml                 ][DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['common'])]))])
2014-11-21 07:28:38,718 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:38,952 [salt.loaded.int.module.saltutil             ][DEBUG   ] Syncing all
2014-11-21 07:28:38,953 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing modules for environment 'base'
2014-11-21 07:28:38,953 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_modules, for base)
2014-11-21 07:28:39,094 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:39,094 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:39,233 [salt.state                                  ][INFO    ] Package salt-minion is already installed.
2014-11-21 07:28:39,234 [salt.state                                  ][INFO    ] Completed state [salt-minion] at time 07:28:39.233685
2014-11-21 07:28:39,234 [salt.minion                                 ][INFO    ] Returning information for job: req
2014-11-21 07:28:39,377 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:39,378 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:39,576 [salt.fileclient                             ][INFO    ] Caching directory '_modules/' for environment 'base'
2014-11-21 07:28:39,584 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/aide.py'
2014-11-21 07:28:39,588 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/bomextract.py'
2014-11-21 07:28:39,591 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/chefclient.py'
2014-11-21 07:28:39,595 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/compliance.py'
2014-11-21 07:28:39,598 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/groundhog.py'
2014-11-21 07:28:39,601 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/lamp.py'
2014-11-21 07:28:39,605 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/lockdown.py'
2014-11-21 07:28:39,608 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/netcat.py'
2014-11-21 07:28:39,612 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/obcontrol.py'
2014-11-21 07:28:39,615 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/obmisc.py'
2014-11-21 07:28:39,618 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/platform.py'
2014-11-21 07:28:39,621 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/sysstat.py'
2014-11-21 07:28:39,624 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/telnet.py'
2014-11-21 07:28:39,627 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/tramp.py'
2014-11-21 07:28:39,630 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/yumprep.py'
2014-11-21 07:28:39,630 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_modules'
2014-11-21 07:28:39,630 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/aide.py' to '/var/cache/salt/minion/extmods/modules/aide.py'
2014-11-21 07:28:39,631 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/bomextract.py' to '/var/cache/salt/minion/extmods/modules/bomextract.py'
2014-11-21 07:28:39,632 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/chefclient.py' to '/var/cache/salt/minion/extmods/modules/chefclient.py'
2014-11-21 07:28:39,632 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/compliance.py' to '/var/cache/salt/minion/extmods/modules/compliance.py'
2014-11-21 07:28:39,633 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/groundhog.py' to '/var/cache/salt/minion/extmods/modules/groundhog.py'
2014-11-21 07:28:39,633 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/lamp.py' to '/var/cache/salt/minion/extmods/modules/lamp.py'
2014-11-21 07:28:39,634 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/lockdown.py' to '/var/cache/salt/minion/extmods/modules/lockdown.py'
2014-11-21 07:28:39,635 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/netcat.py' to '/var/cache/salt/minion/extmods/modules/netcat.py'
2014-11-21 07:28:39,635 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/obcontrol.py' to '/var/cache/salt/minion/extmods/modules/obcontrol.py'
2014-11-21 07:28:39,636 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/obmisc.py' to '/var/cache/salt/minion/extmods/modules/obmisc.py'
2014-11-21 07:28:39,636 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/platform.py' to '/var/cache/salt/minion/extmods/modules/platform.py'
2014-11-21 07:28:39,637 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/sysstat.py' to '/var/cache/salt/minion/extmods/modules/sysstat.py'
2014-11-21 07:28:39,637 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/telnet.py' to '/var/cache/salt/minion/extmods/modules/telnet.py'
2014-11-21 07:28:39,638 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/tramp.py' to '/var/cache/salt/minion/extmods/modules/tramp.py'
2014-11-21 07:28:39,639 [salt.loaded.int.module.saltutil             ][INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/yumprep.py' to '/var/cache/salt/minion/extmods/modules/yumprep.py'
2014-11-21 07:28:39,642 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/states'
2014-11-21 07:28:39,642 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing states for environment 'base'
2014-11-21 07:28:39,643 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_states, for base)
2014-11-21 07:28:39,643 [salt.fileclient                             ][INFO    ] Caching directory '_states/' for environment 'base'
2014-11-21 07:28:39,646 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_states'
2014-11-21 07:28:39,646 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/grains'
2014-11-21 07:28:39,647 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing grains for environment 'base'
2014-11-21 07:28:39,647 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_grains, for base)
2014-11-21 07:28:39,647 [salt.fileclient                             ][INFO    ] Caching directory '_grains/' for environment 'base'
2014-11-21 07:28:39,651 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_grains'
2014-11-21 07:28:39,651 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/renderers'
2014-11-21 07:28:39,652 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing renderers for environment 'base'
2014-11-21 07:28:39,652 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_renderers, for base)
2014-11-21 07:28:39,652 [salt.fileclient                             ][INFO    ] Caching directory '_renderers/' for environment 'base'
2014-11-21 07:28:39,655 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_renderers'
2014-11-21 07:28:39,655 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/returners'
2014-11-21 07:28:39,656 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing returners for environment 'base'
2014-11-21 07:28:39,656 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_returners, for base)
2014-11-21 07:28:39,656 [salt.fileclient                             ][INFO    ] Caching directory '_returners/' for environment 'base'
2014-11-21 07:28:39,659 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_returners'
2014-11-21 07:28:39,660 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/outputters'
2014-11-21 07:28:39,660 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing outputters for environment 'base'
2014-11-21 07:28:39,660 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_outputters, for base)
2014-11-21 07:28:39,661 [salt.fileclient                             ][INFO    ] Caching directory '_outputters/' for environment 'base'
2014-11-21 07:28:39,663 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_outputters'
2014-11-21 07:28:39,664 [salt.loaded.int.module.saltutil             ][INFO    ] Creating module dir '/var/cache/salt/minion/extmods/utils'
2014-11-21 07:28:39,664 [salt.loaded.int.module.saltutil             ][INFO    ] Syncing utils for environment 'base'
2014-11-21 07:28:39,664 [salt.loaded.int.module.saltutil             ][INFO    ] Loading cache from salt://_utils, for base)
2014-11-21 07:28:39,665 [salt.fileclient                             ][INFO    ] Caching directory '_utils/' for environment 'base'
2014-11-21 07:28:39,667 [salt.loaded.int.module.saltutil             ][DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_utils'
2014-11-21 07:28:39,668 [salt.state                                  ][DEBUG   ] Refreshing modules...
2014-11-21 07:28:39,699 [salt.state                                  ][INFO    ] Loading fresh modules for state activity
2014-11-21 07:28:39,712 [salt.config                                 ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:40,062 [salt.utils.event                            ][DEBUG   ] SaltEvent PUB socket URI: ipc:///var/run/salt/minion/minion_event_104df00a9f_pub.ipc
2014-11-21 07:28:40,062 [salt.utils.event                            ][DEBUG   ] SaltEvent PULL socket URI: ipc:///var/run/salt/minion/minion_event_104df00a9f_pull.ipc
2014-11-21 07:28:40,063 [salt.utils.event                            ][DEBUG   ] Sending event - data = {'_stamp': '2014-11-21T07:28:40.062806'}
2014-11-21 07:28:40,095 [salt.fileclient                             ][INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://common.sls'
2014-11-21 07:28:40,098 [salt.utils.jinja                            ][DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
2014-11-21 07:28:40,100 [salt.template                               ][DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/common.sls:
salt-minion:
  pkg:
    - installed

2014-11-21 07:28:40,102 [salt.loaded.int.render.yaml                 ][DEBUG   ] Results of YAML rendering:
OrderedDict([('salt-minion', OrderedDict([('pkg', ['installed'])]))])
2014-11-21 07:28:40,103 [salt.state                                  ][INFO    ] Running state [salt-minion] at time 07:28:40.102999
2014-11-21 07:28:40,103 [salt.state                                  ][INFO    ] Executing state pkg.installed for salt-minion
2014-11-21 07:28:40,104 [salt.loaded.int.module.cmdmod               ][INFO    ] Executing command 'repoquery --plugins --queryformat="%{NAME}_|-%{VERSION}_|-%{RELEASE}_|-%{ARCH}_|-%{REPOID}" --all --pkgnarrow=installed' in directory '/root'
2014-11-21 07:28:41,243 [salt.state                                  ][INFO    ] Package salt-minion is already installed.
2014-11-21 07:28:41,243 [salt.state                                  ][INFO    ] Completed state [salt-minion] at time 07:28:41.242989
2014-11-21 07:28:41,244 [salt.minion                                 ][INFO    ] Returning information for job: req
2014-11-21 07:28:41,386 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:41,387 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
2014-11-21 07:28:41,415 [salt.config                                 ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:43,236 [salt.config                                 ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:45,164 [salt.config                                 ][DEBUG   ] Reading configuration from /etc/salt/minion
2014-11-21 07:28:54,200 [salt.minion                                 ][INFO    ] User marshalle Executing command test.ping with jid 20141121072853602503
2014-11-21 07:28:54,200 [salt.minion                                 ][DEBUG   ] Command details {'tgt_type': 'pcre', 'jid': '20141121072853602503', 'tgt': 'minion1', 'ret': '', 'user': 'marshalle', 'arg': [], 'fun': 'test.ping'}
2014-11-21 07:28:54,215 [salt.minion                                 ][INFO    ] Starting a new job with PID 15150
2014-11-21 07:28:54,219 [salt.minion                                 ][INFO    ] Returning information for job: 20141121072853602503
2014-11-21 07:28:54,367 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key
2014-11-21 07:28:54,368 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

[Rucknar]

Hello,

I've removed all of the salt packages from one of our masters and i've re-installed them (with same config as above). Once the minions had all connected back in, the upgraded minions still show'd as offline. Essentially the issue was still the same as before the yum remove and re-install.

I've then removed and re-installed the minion packages on a remote minion, deleted the keys in salt on both masters and started salt-minion... it works!

Now, this process isn't something easily repeatable, i'm going to try a bit of testing on upgrading some other minions, all ears if anyone has any bright ideas!

Edit: No it doesn't, accidentally deployed 2014.1.13. Still in the same state sadly. :(

[jacksontj]

@Rucknar It sounds like you guys are trying to set up a Mulit-Master setup (meaning minions connected to multiple masters). If thats the case you'll want to set "random_master" to false. What "random_master" does is have the minion connect to a random master-- but just one of them. If you disable that feature the minion will connect to all masters simultaneously-- and I believe that is what you are looking for (judging from your bug).

[Rucknar]

@jacksontj That is the case, we see the same scenario however with random_master set to false, i should of mentioned it's one of the first things we tried. From what i can tell random_master is more to do with the order in which it connects. Are you perhaps thinking of master_shuffle: True?

Edit: The minion does successfully connect to both masters in the minion logs on startup, it's simply the act of returning data of any kind that seems to cause it issues.

[rallytime]

@Rucknar I am now wondering if this has something to do with the keys? If you remove the key of only one minion that was upgraded from 2014.1.13 to 2014.7.0 (without uninstalling and reinstalling salt), can you get it to work?

[jacksontj]

Could you paste the logs from minion startup? If it is a key problem it should have some logging about that :)

[rallytime]

@Rucknar Have you also tried deleting the master and minion caches? That could also be causing some trouble here.

[Rucknar]

@jacksontj should be one further up the ticket.

I'm away from a computer right now, I'll try these once I'm home and on VPN.

[Rucknar]

Hello,

Apologies for the delay, just been through some more testing. Sadly no fix found yet. We tried removing the salt/salt-minon packages from the minion, clearing the cache folder on the minion, then deleting the keys from the master and removing the /var/cache/salt/master/minions/servename folder. Once registered the minion starts and connects successfully but still exhibits the issue above where only one server can contact it.

[Rucknar]

Also, just tried setting random_master to False and restarting the minion, no change.

[Rucknar]

Finally getting somewhere...

Ran strace -f salt-minion on a 2014.7.0 minion and a 2014.1.13 minion at the same time, issued a salt-run manage.down from master2 and compared the output, what sticks out is this line

[pid 8512] connect(75, {sa_family=AF_INET, sin_port=htons(4506), sin_addr=inet_addr("master1-ip")}, 16) = -1 EINPROGRESS (Operation now in progress)

Here it's sending the return to the first master and not the second, this is confirmed when i look at the strace of the 2014.1.13 client which correctly sends it to the master2-ip.

I have a full strace here showing this happening, it's perhaps a bit verbose to post here though but this does seem to suggest there is a bug in the 2014.7.0 release.

[thedrow]

@Rucknar If you're already this low level I suggest using https://github.com/draios/sysdig instead of strace. It might reveal more information.

[Rucknar]

Further to this, master-1 logs the unexpected return:

2014-11-24 10:29:11,757 [salt.loaded.int.returner.local_cache ][ERROR ] An extra return was detected from minion server1, please verify the minion, this could be a replay attack 2014-11-24 10:29:16,776 [salt.loaded.int.returner.local_cache ][ERROR ] An extra return was detected from minion server1, please verify the minion, this could be a replay attack 2014-11-24 10:30:51,345 [salt.loaded.int.returner.local_cache ][ERROR ] An extra return was detected from minion server1, please verify the minion, this could be a replay attack 2014-11-24 10:30:56,373 [salt.loaded.int.returner.local_cache ][ERROR ] An extra return was detected from minion server1, please verify the minion, this could be a replay attack

[Rucknar]

Thought this might be some strange DNS issue causing it, verified forward/reverse lookup and i've tried with using IP's instead of DNS, same symptoms. I've browsed the code to see if there were any suspect changes but i'm afraid python is still something i'm learning so haven't found anything.

[Rucknar]

Also noted this error on master-1 (the server not sending the command)

2014-11-24 10:30:57,142 [salt.loaded.int.returner.local_cache ][ERROR ] An inconsistency occurred, a job was received with a job id that is not present in the local cache: 20141124103055885615

[basepi]

So I'm not sure on the current state of job caches in multi-master -- if we're having minions return jobs to all masters, we're going to have to handle that error better. But the error itself is not unexpected.

[Rucknar]

@basepi should minions send back to both masters then by design? If so then yes we can ignore the last error i guess. Issue's still outstanding though and i've run flat out of ideas!

[thedrow]

Can you reproduce this in a vagrant project? Something we can vagrant up and see what happens?

[basepi]

@Rucknar I do not know, I haven't been involved with recent multi-master conversations. I just wanted to point out that that's probably the culprit there.

[Rucknar]

I've had to roll-back the 2014.7.0 upgrade from our DC, did as much debugging with it as we could afford to in that environment. If i get chance i'll try get something in vagrant to test, it's a fairly major bug so suspect others will also report it once 2014.7.0 is more widespread, hopefully they can link the tickets to this one.

[basepi]

I guess we'll see. We've had a bear of a time reproducing it, which makes it really hard to track down the source.

[basepi]

Sorry for the inconvenience and the roll-back. Hopefully if others run into this we can find the source.

[smithjm]

I am seeing this issue as well, with 2014.7.0 deployed on various OSes (Centos 7, Scientific Linux 6.x, Fedora 17, Fedora19, and Fedora20 to name a few)

[thedrow]

@smithjm It would be really helpful if you can set up some vagrant project we can reproduce.

[gavala]

Coming back to have a look at this again I seem to now be able to reproduce this quite easily. The offending piece of config is on the minion, and this seems to happen when startup_states is set to 'highstate'.

The setup I am using to investigate is two masters, master01 and master02 along with one salt minion, client01. Running "salt '*' test.ping" on master01 with startup_states set to 'highstate' on the minion results in no return and an error in the master log on master02:

2015-01-14 11:25:58,025 [salt.utils.event                           ][DEBUG   ] Sending event - data = {'fun_args': [], 'jid': '20150114111424565561', 'return': True, 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2015-01-14T11:25:58.024948', 'fun': 'test.ping', 'id': 'client01.skybet.net'}
2015-01-14 11:25:58,026 [salt.utils.event                           ][DEBUG   ] Sending event - data = {'fun_args': [], 'jid': '20150114111424565561', 'return': True, 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2015-01-14T11:25:58.025602', 'fun': 'test.ping', 'id': 'client01.skybet.net'}
2015-01-14 11:25:58,027 [salt.loaded.int.returner.local_cache       ][ERROR   ] An inconsistency occurred, a job was received with a job id that is not present in the local cache: 20150114111424565561

Running the same command from master02 works as expected. This is reproducible every time, and only happens when startup_states is set to 'high state'. Our top.sls looks like this:

base:
  '*':
    - common

common.sls looks like this:

salt-minion:
  pkg:
    - installed

Hope this helps

[thedrow]

@gavala Thanks for the information. @smithjm @Rucknar Is that the case for you guys as well? If it isn't then @gavala should file a new issue about his problem.

[gavala]

Apologies @thedrow, both myself and @Rucknar a reporting this issue from the same site

[thedrow]

Oh cool. Good to know :)

[smithjm]

Omar, no, in our case we do NOT have a startup state defined at all. We also don't have ANY multimaster configuration options defined in our minion or master config files, just a list of masters configured for our minions implicitly creating a multi-master setup, exactly as was done in Hydrogen.

On Wed, Jan 14, 2015 at 6:10 AM, Omer Katz notifications@github.com wrote:

Oh cool. Good to know :)

— Reply to this email directly or view it on GitHub https://github.com/saltstack/salt/issues/18322#issuecomment-69907562.

[thedrow]

@smithjm First of all it's Omer. Common mistake. Second, it means that either @gavala found one bug but not all of them or that he did not find the root cause of this bug yet. Can you paste your (sanitized) configuration files? What exactly are the steps to reproduce the same environment?

[Rucknar]

Might be worth creating a seperate ticket if the issue appears to be different. @gavala indeed hasn't found the smoking gun but he's found a way to replicate the issue, this means the dev's can now troubleshoot locally and hopefully find the root cause.

[gavala]

Hi, here is the minion configuration that causes this issue for me:

master:
    - master01
    - master02
id: client01
random_reauth_delay: 60
auth_timeout: 60
recon_randomize: True
startup_states: 'highstate'
log_level: info
log_level_logfile: info
tcp_keepalive: True
tcp_keepalive_idle: 300
tcp_keepalive_cnt: 5
tcp_keepalive_intvl: 60

This minion configuration does not cause the issue:

master:
    - master01
    - master02
id: client01
random_reauth_delay: 60
auth_timeout: 60
recon_randomize: True
log_level: info
log_level_logfile: info
tcp_keepalive: True
tcp_keepalive_idle: 300
tcp_keepalive_cnt: 5
tcp_keepalive_intvl: 60

This is using a master configuration as follows:

id: master01
worker_threads: 10
autoreject_file: /etc/salt/autoreject.conf
keep_jobs: 24
ping_on_rotate: True
auto_accept: True
file_roots:
  base:
    - /srv/salt

[jhenry82]

I believe we are seeing this and/or issue #19932 after updating about 1000 minions from 2014.1.7 to 2014.7.1. Switching our minion config to "multiprocessing: False" helped, but did not eliminate the issue. We run four masters (all listed in every minion's config). At any given time, about 10% of our minions are failing to respond to a simple "test.ping" from one or more master.

Would love any guidance on a workaround or where to start working to develop a patch. Otherwise we are going to have to roll back to the 2014.1 series. Salt is unusable in our environment as it stands. Let me know if there's anything I can do to help with debugging.

[gavala]

@jhenry82 Do you have "startup_states: 'high state'" set in your minion config?

[jhenry82]

@gavala Nope. Here's a lightly sanitized gist with our non-default master and minion configs.

https://gist.github.com/jhenry82/57d3ae69b1b3994e4b1a

[bigg01]

Hi I have the same issue with reactor. Any idea to fix that?

Works:

# /etc/salt/minion
master: master1

doesn't work:

# /etc/salt/minion
master:
 - master1
 - master2

salt --versions-report
           Salt: 2014.7.2
         Python: 2.6.9 (unknown, Mar 31 2014, 22:15:20)
         Jinja2: 2.7.3
       M2Crypto: 0.22
 msgpack-python: 0.4.6
   msgpack-pure: Not Installed
       pycrypto: 2.6.1
        libnacl: Not Installed
         PyYAML: 3.11
          ioflo: Not Installed
          PyZMQ: 14.5.0
           RAET: Not Installed
            ZMQ: 4.0.4
           Mako: Not Installed

[rallytime]

@bigg01 Without more information, I think perhaps what you're seeing might be #17033 or maybe even with #13879.

@Rucknar or @gavala After skimming the more recent responses, are you saying that you've narrowed this problem down to when you run a highstate? (I have been spending a lot of time in MM testing it and trying to track down bugs, and I have definitely seen problems with running highstates.)

[c4milo]

I'm seeing this same problem with 2015.5:

salt --versions-report
                  Salt: 2015.5.0
                Python: 2.7.6 (default, Mar 22 2014, 22:59:56)
                Jinja2: 2.7.2
              M2Crypto: 0.21.1
        msgpack-python: 0.3.0
          msgpack-pure: Not Installed
              pycrypto: 2.6.1
               libnacl: Not Installed
                PyYAML: 3.10
                 ioflo: Not Installed
                 PyZMQ: 14.0.1
                  RAET: Not Installed
                   ZMQ: 4.0.4
                  Mako: 0.9.1
 Debian source package: 2015.5.0+ds-1trusty1

I'm not using reactor by the way. Just a simple multi-master setup with two masters. Also, I can replicate the problem just by trying to send pings to the minions. From my perspective, it seems minions are only connecting to one of the masters.

This is my minions configuration:

# Generated by consul-template - Sat, 16 May 2015 05:56:04 +0000

master:
  - saltmaster.service.us-east-1a.stg.managedbyq.com
  - saltmaster.service.us-east-1b.stg.managedbyq.com

master_type: failover
master_shuffle: True
master_alive_interval: 30

grains:
  roles:
    - app

[c4milo]

ah, I was misled by:

master_type: failover
master_shuffle: True

Removing them fixed my "issue".