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

2014.7.0 multimaster / multiprocessing issues #18322

Closed
Rucknar opened this Issue Nov 20, 2014 · 56 comments

Comments

Projects
None yet
@Rucknar

Rucknar commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 20, 2014

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

Rucknar commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 20, 2014

Contributor

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?

Contributor

rallytime commented Nov 20, 2014

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?

@rallytime rallytime added this to the Blocked milestone Nov 20, 2014

@rallytime rallytime added the Bug label Nov 20, 2014

@Rucknar

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 20, 2014

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 commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 20, 2014

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.

Rucknar commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 20, 2014

Contributor

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.

Contributor

rallytime commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@gavala

gavala Nov 20, 2014

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

gavala commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 20, 2014

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

Rucknar commented Nov 20, 2014

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

@rallytime

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 20, 2014

Contributor

@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.

Contributor

rallytime commented Nov 20, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 20, 2014

Contributor

Are you guys using master_type or master_shuffle at all?

Contributor

rallytime commented Nov 20, 2014

Are you guys using master_type or master_shuffle at all?

@Rucknar

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 20, 2014

@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.

Rucknar commented Nov 20, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 20, 2014

Contributor

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
Contributor

rallytime commented Nov 20, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 21, 2014

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 commented Nov 21, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 21, 2014

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.
:(

Rucknar commented Nov 21, 2014

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

This comment has been minimized.

Show comment
Hide comment
@jacksontj

jacksontj Nov 21, 2014

Contributor

@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).

Contributor

jacksontj commented Nov 21, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 21, 2014

@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.

Rucknar commented Nov 21, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 21, 2014

Contributor

@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?

Contributor

rallytime commented Nov 21, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@jacksontj

jacksontj Nov 21, 2014

Contributor

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

Contributor

jacksontj commented Nov 21, 2014

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

@rallytime

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Nov 21, 2014

Contributor

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

Contributor

rallytime commented Nov 21, 2014

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

@Rucknar

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 21, 2014

@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 commented Nov 21, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 24, 2014

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 commented Nov 24, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 24, 2014

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

Rucknar commented Nov 24, 2014

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

@Rucknar

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 24, 2014

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.

Rucknar commented Nov 24, 2014

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

This comment has been minimized.

Show comment
Hide comment
@thedrow

thedrow Nov 24, 2014

Contributor

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

Contributor

thedrow commented Nov 24, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 24, 2014

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 commented Nov 24, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 24, 2014

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 commented Nov 24, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 24, 2014

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

Rucknar commented Nov 24, 2014

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

This comment has been minimized.

Show comment
Hide comment
@basepi

basepi Nov 24, 2014

Collaborator

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.

Collaborator

basepi commented Nov 24, 2014

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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 25, 2014

@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!

Rucknar commented Nov 25, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@thedrow

thedrow Nov 25, 2014

Contributor

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

Contributor

thedrow commented Nov 25, 2014

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

@basepi

This comment has been minimized.

Show comment
Hide comment
@basepi

basepi Nov 25, 2014

Collaborator

@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.

Collaborator

basepi commented Nov 25, 2014

@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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Nov 25, 2014

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.

Rucknar commented Nov 25, 2014

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

This comment has been minimized.

Show comment
Hide comment
@basepi

basepi Nov 25, 2014

Collaborator

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.

Collaborator

basepi commented Nov 25, 2014

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

This comment has been minimized.

Show comment
Hide comment
@basepi

basepi Nov 25, 2014

Collaborator

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

Collaborator

basepi commented Nov 25, 2014

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

@smithjm

This comment has been minimized.

Show comment
Hide comment
@smithjm

smithjm Jan 5, 2015

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)

smithjm commented Jan 5, 2015

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

This comment has been minimized.

Show comment
Hide comment
@thedrow

thedrow Jan 6, 2015

Contributor

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

Contributor

thedrow commented Jan 6, 2015

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

@gavala

This comment has been minimized.

Show comment
Hide comment
@gavala

gavala Jan 14, 2015

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

gavala commented Jan 14, 2015

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

This comment has been minimized.

Show comment
Hide comment
@thedrow

thedrow Jan 14, 2015

Contributor

@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.

Contributor

thedrow commented Jan 14, 2015

@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

This comment has been minimized.

Show comment
Hide comment
@gavala

gavala Jan 14, 2015

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

gavala commented Jan 14, 2015

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

@thedrow

This comment has been minimized.

Show comment
Hide comment
@thedrow

thedrow Jan 14, 2015

Contributor

Oh cool. Good to know :)

Contributor

thedrow commented Jan 14, 2015

Oh cool. Good to know :)

@smithjm

This comment has been minimized.

Show comment
Hide comment
@smithjm

smithjm Jan 14, 2015

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
#18322 (comment).

smithjm commented Jan 14, 2015

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
#18322 (comment).

@thedrow

This comment has been minimized.

Show comment
Hide comment
@thedrow

thedrow Jan 15, 2015

Contributor

@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?

Contributor

thedrow commented Jan 15, 2015

@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

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar Jan 15, 2015

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.

Rucknar commented Jan 15, 2015

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

This comment has been minimized.

Show comment
Hide comment
@gavala

gavala Jan 15, 2015

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

gavala commented Jan 15, 2015

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

This comment has been minimized.

Show comment
Hide comment
@jhenry82

jhenry82 Jan 29, 2015

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.

jhenry82 commented Jan 29, 2015

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

This comment has been minimized.

Show comment
Hide comment
@gavala

gavala Jan 29, 2015

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

gavala commented Jan 29, 2015

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

@jhenry82

This comment has been minimized.

Show comment
Hide comment
@jhenry82

jhenry82 Jan 29, 2015

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

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

jhenry82 commented Jan 29, 2015

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

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

@bigg01

This comment has been minimized.

Show comment
Hide comment
@bigg01

bigg01 Mar 24, 2015

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

bigg01 commented Mar 24, 2015

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

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime Mar 24, 2015

Contributor

@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.)

Contributor

rallytime commented Mar 24, 2015

@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

This comment has been minimized.

Show comment
Hide comment
@c4milo

c4milo May 16, 2015

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 commented May 16, 2015

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

This comment has been minimized.

Show comment
Hide comment
@c4milo

c4milo May 16, 2015

ah, I was misled by:

master_type: failover
master_shuffle: True

Removing them fixed my "issue".

c4milo commented May 16, 2015

ah, I was misled by:

master_type: failover
master_shuffle: True

Removing them fixed my "issue".

@jfindlay jfindlay added Core and removed Core labels May 26, 2015

@jhenry82

This comment has been minimized.

Show comment
Hide comment
@jhenry82

jhenry82 May 30, 2015

Just wanted to check in and say that multimaster seems MUCH improved in 2015.5.1. I upgraded our 2014.1.7 masters and minions this week and have encountered none of the many issues we saw with the 2014.7 series.

@Rucknar have you tried the new version yet? This may be fixed.

jhenry82 commented May 30, 2015

Just wanted to check in and say that multimaster seems MUCH improved in 2015.5.1. I upgraded our 2014.1.7 masters and minions this week and have encountered none of the many issues we saw with the 2014.7 series.

@Rucknar have you tried the new version yet? This may be fixed.

@Rucknar

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar May 30, 2015

I'm not currently working with a client that uses salt so can't say I'm afraid. Sounds promising though!

Sent from my iPhone

On 30 May 2015, at 04:44, Jon Henry notifications@github.com wrote:

Just wanted to check in and say that multimaster seems MUCH improved in 2015.5.1. I upgraded our 2014.1.7 masters and minions this week and have encountered none of the many issues we saw with the 2014.7 series.

@Rucknar have you tried the new version yet? This may be fixed.


Reply to this email directly or view it on GitHub.

Rucknar commented May 30, 2015

I'm not currently working with a client that uses salt so can't say I'm afraid. Sounds promising though!

Sent from my iPhone

On 30 May 2015, at 04:44, Jon Henry notifications@github.com wrote:

Just wanted to check in and say that multimaster seems MUCH improved in 2015.5.1. I upgraded our 2014.1.7 masters and minions this week and have encountered none of the many issues we saw with the 2014.7 series.

@Rucknar have you tried the new version yet? This may be fixed.


Reply to this email directly or view it on GitHub.

@rallytime

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime May 31, 2015

Contributor

@jhenry82 This is such good news! I am glad the new release branch is working better for you. @Rucknar Since you're not able to test the new releases currently, and we have confirmation from @jhenry82 that this is fixed (we made multiple improvements and fixes to Multi Master in the 2015.5.x releases), do you think it is okay to close this issue? We can always open it again if this pops back up for you.

Contributor

rallytime commented May 31, 2015

@jhenry82 This is such good news! I am glad the new release branch is working better for you. @Rucknar Since you're not able to test the new releases currently, and we have confirmation from @jhenry82 that this is fixed (we made multiple improvements and fixes to Multi Master in the 2015.5.x releases), do you think it is okay to close this issue? We can always open it again if this pops back up for you.

@Rucknar

This comment has been minimized.

Show comment
Hide comment
@Rucknar

Rucknar May 31, 2015

Sounds fair enough to me!

Sent from my iPhone

On 31 May 2015, at 05:08, Nicole Thomas notifications@github.com wrote:

@jhenry82 This is such good news! I am glad the new release branch is working better for you. @Rucknar Since you're not able to test the new releases currently, and we have confirmation from @jhenry82 that this is fixed (we made multiple improvements and fixes to Multi Master in the 2015.5.x releases), do you think it is okay to close this issue? We can always open it again if this pops back up for you.


Reply to this email directly or view it on GitHub.

Rucknar commented May 31, 2015

Sounds fair enough to me!

Sent from my iPhone

On 31 May 2015, at 05:08, Nicole Thomas notifications@github.com wrote:

@jhenry82 This is such good news! I am glad the new release branch is working better for you. @Rucknar Since you're not able to test the new releases currently, and we have confirmation from @jhenry82 that this is fixed (we made multiple improvements and fixes to Multi Master in the 2015.5.x releases), do you think it is okay to close this issue? We can always open it again if this pops back up for you.


Reply to this email directly or view it on GitHub.

@gavala

This comment has been minimized.

Show comment
Hide comment
@gavala

gavala May 31, 2015

Hello,

We've also recently updated to 2015.5.1, this problem seems to have gone away and it's much more stable on the whole now as well

gavala commented May 31, 2015

Hello,

We've also recently updated to 2015.5.1, this problem seems to have gone away and it's much more stable on the whole now as well

@rallytime

This comment has been minimized.

Show comment
Hide comment
@rallytime

rallytime May 31, 2015

Contributor

Excellent! That is great to hear. :)

Thanks all!

Contributor

rallytime commented May 31, 2015

Excellent! That is great to hear. :)

Thanks all!

@rallytime rallytime closed this May 31, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment