{"action":"created","issue":{"url":"https://api.github.com/repos/saltstack/salt/issues/35069","repository_url":"https://api.github.com/repos/saltstack/salt","labels_url":"https://api.github.com/repos/saltstack/salt/issues/35069/labels{/name}","comments_url":"https://api.github.com/repos/saltstack/salt/issues/35069/comments","events_url":"https://api.github.com/repos/saltstack/salt/issues/35069/events","html_url":"https://github.com/saltstack/salt/issues/35069","id":168422688,"number":35069,"title":"2016.3.1 (Boron) does not execute reactors on minion connect","user":{"login":"jdelic","id":1956349,"avatar_url":"https://avatars.githubusercontent.com/u/1956349?v=3","gravatar_id":"","url":"https://api.github.com/users/jdelic","html_url":"https://github.com/jdelic","followers_url":"https://api.github.com/users/jdelic/followers","following_url":"https://api.github.com/users/jdelic/following{/other_user}","gists_url":"https://api.github.com/users/jdelic/gists{/gist_id}","starred_url":"https://api.github.com/users/jdelic/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jdelic/subscriptions","organizations_url":"https://api.github.com/users/jdelic/orgs","repos_url":"https://api.github.com/users/jdelic/repos","events_url":"https://api.github.com/users/jdelic/events{/privacy}","received_events_url":"https://api.github.com/users/jdelic/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/saltstack/salt/labels/Info%20Needed","name":"Info Needed","color":"c7def8"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/saltstack/salt/milestones/37","html_url":"https://github.com/saltstack/salt/milestones/Blocked","labels_url":"https://api.github.com/repos/saltstack/salt/milestones/37/labels","id":343741,"number":37,"title":"Blocked","description":"Issues which are blocked in some way, whether they need further discussion, clarification, justification, or are blocked for some other reason.","creator":{"login":"basepi","id":702318,"avatar_url":"https://avatars.githubusercontent.com/u/702318?v=3","gravatar_id":"","url":"https://api.github.com/users/basepi","html_url":"https://github.com/basepi","followers_url":"https://api.github.com/users/basepi/followers","following_url":"https://api.github.com/users/basepi/following{/other_user}","gists_url":"https://api.github.com/users/basepi/gists{/gist_id}","starred_url":"https://api.github.com/users/basepi/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/basepi/subscriptions","organizations_url":"https://api.github.com/users/basepi/orgs","repos_url":"https://api.github.com/users/basepi/repos","events_url":"https://api.github.com/users/basepi/events{/privacy}","received_events_url":"https://api.github.com/users/basepi/received_events","type":"User","site_admin":false},"open_issues":505,"closed_issues":968,"state":"open","created_at":"2013-05-28T22:24:12Z","updated_at":"2016-08-02T22:29:05Z","due_on":null,"closed_at":null},"comments":3,"created_at":"2016-07-29T21:56:55Z","updated_at":"2016-08-03T08:15:07Z","closed_at":null,"body":"### Description of Issue/Question\r\nWIth `2016.3.1 (Boron)` suddenly my reactor synchronizing grains is not executed anymore.\r\n\r\n### Setup\r\nI have the following vagrant setup using the `salt` provisioner:\r\n```ruby\r\nmaster.vm.synced_folder 'saltshaker/srv/salt', '/srv/salt'\r\nmaster.vm.synced_folder 'saltshaker/srv/salt-modules', '/srv/salt-modules'\r\nmaster.vm.synced_folder 'saltshaker/srv/pillar', '/srv/pillar'\r\nmaster.vm.synced_folder 'saltshaker/srv/reactor', '/srv/reactor'\r\nmaster.vm.synced_folder 'saltshaker/etc/salt-minion/minion.d', '/etc/salt/minion.d'\r\nmaster.vm.synced_folder 'saltshaker/etc/salt-master/master.d', '/etc/salt/master.d'\r\n\r\nmaster.vm.provision :shell do |s|\r\n            s.inline = <<SCRIPT\r\n                mkdir -p /etc/salt/roles.d\r\n                touch /etc/salt/roles.d/master\r\n                touch /etc/salt/roles.d/vault\r\n                touch /etc/salt/roles.d/consulserver\r\nSCRIPT\r\n        end\r\n\r\nmaster.vm.provision :salt do |salt|\r\n            salt.run_highstate = true\r\n            salt.colorize = true\r\n            salt.log_level = 'warning'\r\n            salt.verbose = true\r\n            salt.no_minion = false\r\n            salt.always_install = true\r\n            salt.install_master = true\r\n            salt.install_syndic = false\r\n            salt.bootstrap_script = 'saltshaker/vagrant/bootstrap-salt.sh'\r\n            salt.bootstrap_options = '-P -c /tmp'\r\n            salt.master_pub = 'saltshaker/vagrant/preseed-keys/saltmaster.local.pub'\r\n            salt.master_key = 'saltshaker/vagrant/preseed-keys/saltmaster.local.pem'\r\n            salt.minion_pub = 'saltshaker/vagrant/preseed-keys/saltmaster.local.pub'\r\n            salt.minion_key = 'saltshaker/vagrant/preseed-keys/saltmaster.local.pem'\r\n            salt.seed_master = {\r\n                'saltmaster.local' => salt.minion_pub,\r\n            }\r\n        end\r\n```\r\n\r\nI have the following reactor setup in `/srv/reactor/sync_grains.sls`:\r\n```yaml\r\nsync_grains:\r\n    local.saltutil.sync_grains:\r\n        - tgt: {{ data['id'] }}\r\n```\r\n\r\nand the according setup in `/etc/salt/master.d/saltshaker.conf`:\r\n```yaml\r\nreactor:\r\n    - 'salt/minion/*/start':  # this was 'minion_start' before\r\n        - /srv/reactor/sync_grains.sls\r\n```\r\n\r\nI use the following custom grain in `/srv/salt/_grains/roledir.py`:\r\n```python\r\nimport os\r\nimport logging\r\n\r\n_rolespath = \"/etc/salt/roles.d\"\r\n_log = logging.getLogger(__name__)\r\n\r\ndef roles():\r\n    global _rolespath, _log\r\n    if not os.path.exists(_rolespath):\r\n        return {}\r\n\r\n    if _rolespath.endswith(os.sep):\r\n        _rolespath = os.path.split(_rolespath)[0]\r\n\r\n    dirpath, dirnames, filenames = os.walk(_rolespath).next()\r\n    roles = filenames\r\n    return { 'roles': roles }\r\n```\r\n\r\nIn previous versions when the box was provisioned the `roles` grain contained `['master', 'vault', 'consulserver']`, but now it's always empty on the initial `state.highstate` run and will only be filled on the second `highstate`.\r\n\r\nThere is no output regarding reactor events (aside from \"Creating master reactor process\") in `/var/log/salt/master`, either.\r\n\r\n### Versions Report\r\n```\r\nSalt Version:\r\n           Salt: 2016.3.1\r\n\r\nDependency Versions:\r\n           cffi: 0.8.6\r\n       cherrypy: Not Installed\r\n       dateutil: 2.2\r\n          gitdb: 0.5.4\r\n      gitpython: 0.3.2 RC1\r\n          ioflo: Not Installed\r\n         Jinja2: 2.7.3\r\n        libgit2: Not Installed\r\n        libnacl: Not Installed\r\n       M2Crypto: Not Installed\r\n           Mako: Not Installed\r\n   msgpack-pure: Not Installed\r\n msgpack-python: 0.4.2\r\n   mysql-python: 1.2.3\r\n      pycparser: 2.10\r\n       pycrypto: 2.6.1\r\n         pygit2: Not Installed\r\n         Python: 2.7.9 (default, Mar  1 2015, 12:57:24)\r\n   python-gnupg: Not Installed\r\n         PyYAML: 3.11\r\n          PyZMQ: 14.4.0\r\n           RAET: Not Installed\r\n          smmap: 0.8.2\r\n        timelib: Not Installed\r\n        Tornado: 4.2.1\r\n            ZMQ: 4.0.5\r\n\r\nSystem Versions:\r\n           dist: debian 8.5\r\n        machine: x86_64\r\n        release: 3.16.0-4-amd64\r\n         system: Linux\r\n        version: debian 8.5\r\n```"},"comment":{"url":"https://api.github.com/repos/saltstack/salt/issues/comments/237172904","html_url":"https://github.com/saltstack/salt/issues/35069#issuecomment-237172904","issue_url":"https://api.github.com/repos/saltstack/salt/issues/35069","id":237172904,"user":{"login":"jdelic","id":1956349,"avatar_url":"https://avatars.githubusercontent.com/u/1956349?v=3","gravatar_id":"","url":"https://api.github.com/users/jdelic","html_url":"https://github.com/jdelic","followers_url":"https://api.github.com/users/jdelic/followers","following_url":"https://api.github.com/users/jdelic/following{/other_user}","gists_url":"https://api.github.com/users/jdelic/gists{/gist_id}","starred_url":"https://api.github.com/users/jdelic/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jdelic/subscriptions","organizations_url":"https://api.github.com/users/jdelic/orgs","repos_url":"https://api.github.com/users/jdelic/repos","events_url":"https://api.github.com/users/jdelic/events{/privacy}","received_events_url":"https://api.github.com/users/jdelic/received_events","type":"User","site_admin":false},"created_at":"2016-08-03T08:15:06Z","updated_at":"2016-08-03T08:15:06Z","body":"@Ch3LL Thank you for your reply and suggestions, those were quite helpful. First of all, I managed to get debug logs. So with minion and master running on the same host, installed via `salt-bootstrap.sh`, their configuration mounted into `/srv/salt` etc. on the VM using `vboxsf`, this is what happens during the initial highstate in chronological order:\r\n\r\n 1. `/var/log/salt/master`: The `master` renders the grain config. Note the timestamp `06:59:22,874`.\r\n\r\n    ```\r\n2016-08-03 06:59:22,858 [salt.utils.reactor][DEBUG   ][15888] Gathering reactors for tag salt/minion/saltmaster.local/start\r\n2016-08-03 06:59:22,859 [salt.utils.reactor][DEBUG   ][15888] Compiling reactions for tag salt/minion/saltmaster.local/start\r\n2016-08-03 06:59:22,860 [salt.template    ][DEBUG   ][15888] compile template: /srv/reactor/sync_grains.sls\r\n2016-08-03 06:59:22,869 [salt.utils.jinja ][DEBUG   ][15888] Jinja search path: ['/var/cache/salt/master/files/base']\r\n2016-08-03 06:59:22,873 [salt.template    ][PROFILE ][15888] Time (in seconds) to render '/srv/reactor/sync_grains.sls' using 'jinja' renderer: 0.00390815734863\r\n2016-08-03 06:59:22,874 [salt.template    ][DEBUG   ][15888] Rendered data from file: /srv/reactor/sync_grains.sls:\r\n    sync_grains:\r\n        local.saltutil.sync_grains:\r\n            - tgt: saltmaster.local\r\n2016-08-03 06:59:22,883 [salt.utils.lazy  ][DEBUG   ][15888] LazyLoaded config.get\r\n2016-08-03 06:59:22,885 [salt.loaded.int.render.yaml][DEBUG   ][15888] Results of YAML rendering:\r\nOrderedDict([('sync_grains', OrderedDict([('local.saltutil.sync_grains', [OrderedDict([('tgt', 'saltmaster.local')])])]))])\r\n2016-08-03 06:59:22,969 [salt.utils.event ][DEBUG   ][15907] Sending event - data = {'tgt_type': 'glob', 'jid': '20160803065922967213', 'tgt': 'saltmaster.local', '_stamp': '2016-08-03T06:59:22.969093', 'user': 'root', 'arg': [], 'fun': 'saltutil.sync_grains', 'minions': ['saltmaster.local']}\r\n2016-08-03 06:59:22,970 [salt.loaded.int.returner.local_cache][DEBUG   ][15907] Adding minions for job 20160803065922967213: ['saltmaster.local']\r\n2016-08-03 06:59:22,970 [salt.master      ][INFO    ][15907] User root Published command saltutil.sync_grains with jid 20160803065922967213\r\n2016-08-03 06:59:22,970 [salt.master      ][DEBUG   ][15907] Published command details {'tgt_type': 'glob', 'jid': '20160803065922967213', 'tgt': 'saltmaster.local', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'saltutil.sync_grains'}\r\n    ```\r\n\r\n 2. `/var/log/salt/minion`: the grains are synced to the master\r\n\r\n    ```\r\n2016-08-03 06:59:22,971 [salt.minion      ][INFO    ][15773] User root Executing command saltutil.sync_grains with jid 20160803065922967213\r\n    ```\r\n\r\n 3. `/var/log/salt/master`: The `master` renders the pillar top.sls\r\n\r\n    ```\r\n2016-08-03 06:59:23,117 [salt.template    ][PROFILE ][15907] Time (in seconds) to render '/srv/pillar/top.sls' using 'jinja' renderer: 0.00374889373779\r\n2016-08-03 06:59:23,120 [salt.utils.jinja ][DEBUG   ][15905] Jinja search path: ['/srv/pillar']\r\n2016-08-03 06:59:23,118 [salt.template    ][DEBUG   ][15907] Rendered data from file: /srv/pillar/top.sls:\r\n*** Pillar data omitted ***\r\n    ````\r\n\r\n 4. `/var/log/salt/minion`: The minion renders the state top.sls and none of the grains match\r\n\r\n    ```\r\n2016-08-03 06:59:23,379 [salt.template    ][PROFILE ][16576] Time (in seconds) to render '/var/cache/salt/minion/files/base/top.sls' using 'jinja' renderer: 0.00642204284668\r\n2016-08-03 06:59:23,380 [salt.template    ][DEBUG   ][16576] Rendered data from file: /var/cache/salt/minion/files/base/top.sls:\r\n...\r\n2016-08-03 06:59:23,409 [salt.minion      ][DEBUG   ][16576] grains target: roles:master\r\n2016-08-03 06:59:23,409 [salt.utils       ][DEBUG   ][16576] Attempting to match 'master' in 'roles' using delimiter ':'\r\n...\r\n2016-08-03 06:59:23,413 [salt.minion      ][DEBUG   ][16585] grains target: roles:consulserver\r\n2016-08-03 06:59:23,413 [salt.utils       ][DEBUG   ][16585] Attempting to match 'consulserver' in 'roles' using delimiter ':'\r\n...\r\n    ```\r\n\r\n 5. `/var/log/salt/minion`: The minion executes the custom grain\r\n\r\n    ```\r\n2016-08-03 06:59:23,613 [salt.fileclient  ][DEBUG   ][16576] In saltenv 'base', looking at rel_path '_grains/roledir.py' to resolve 'salt://_grains/roledir.py'\r\n2016-08-03 06:59:23,617 [salt.fileclient  ][DEBUG   ][16576] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/_grains/roledir.py' to resolve 'salt://_grains/roledir.py'\r\n2016-08-03 06:59:23,617 [salt.fileclient  ][INFO    ][16576] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_grains/roledir.py'\r\n2016-08-03 06:59:23,617 [salt.utils.extmods][DEBUG   ][16576] Local cache dir: '/var/cache/salt/minion/files/base/_grains'\r\n2016-08-03 06:59:23,618 [salt.utils.extmods][INFO    ][16576] Copying '/var/cache/salt/minion/files/base/_grains/roledir.py' to '/var/cache/salt/minion/extmods/grains/roledir.py'\r\n    ```\r\n\r\n 6. `/var/log/salt/master`: The sync_grains job returns:\r\n\r\n    ```\r\n2016-08-03 06:59:23,614 [salt.utils.job   ][INFO    ][15892] Got return from saltmaster.local for job 20160803065922967213\r\n2016-08-03 06:59:23,614 [salt.transport.ipc][DEBUG   ][15892] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc\r\n2016-08-03 06:59:23,615 [salt.utils.event ][DEBUG   ][15892] Sending event - data = {'fun_args': [], 'jid': '20160803065922967213', 'return': ['grains.roledir'], 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2016-08-03T06:59:23.614929', 'fun': 'saltutil.sync_grains', 'id': 'saltmaster.local'}\r\n    ```\r\n\r\n 7. `/var/log/salt/minion`: The minion executes the 119 states from top.sls which are **not** assigned using grains\r\n\r\n    ```\r\n2016-08-03 06:59:23,791 [salt.utils.event ][DEBUG   ][16576] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_56181286e1_pub.ipc\r\n2016-08-03 06:59:23,792 [salt.utils.event ][DEBUG   ][16576] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_56181286e1_pull.ipc\r\n2016-08-03 06:59:23,792 [salt.transport.ipc][DEBUG   ][16576] Initializing new IPCClient for path: /var/run/salt/minion/minion_event_56181286e1_pull.ipc\r\n2016-08-03 06:59:23,806 [salt.utils.event ][DEBUG   ][16576] Sending event - data = {'_stamp': '2016-08-03T06:59:23.805897'}\r\n2016-08-03 06:59:23,836 [salt.fileclient  ][DEBUG   ][16576] In saltenv 'base', looking at rel_path 'basics.sls' to resolve 'salt://basics.sls'\r\n2016-08-03 06:59:23,837 [salt.fileclient  ][DEBUG   ][16576] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/basics.sls' to resolve 'salt://basics.sls'\r\n...\r\n    ```\r\n\r\nWhen I execute `` after the vagrant salt-provisioner has executed the initial highstate, I get:\r\n\r\n```\r\n[vagrant@saltmaster ~]$ sudo salt-call --local grains.item roles\r\nlocal:\r\n    ----------\r\n    roles:\r\n        - master\r\n        - vault\r\n        - consulserver\r\n```\r\n\r\nWhen I manually execute a second highstate using `sudo salt-call state.highstate -l debug` after that initial one, Salt executes all 147 states assigned to the box (including roles grain matches).\r\n\r\nPerhaps this is a race condition? The grains seem to be there and synced, but just not do anything? I'm a bit lost at how to debug this further."}}
{"actor":{"display_login":"jdelic"}}