{"action":"created","issue":{"url":"https://api.github.com/repos/saltstack/salt/issues/30500","labels_url":"https://api.github.com/repos/saltstack/salt/issues/30500/labels{/name}","comments_url":"https://api.github.com/repos/saltstack/salt/issues/30500/comments","events_url":"https://api.github.com/repos/saltstack/salt/issues/30500/events","html_url":"https://github.com/saltstack/salt/issues/30500","id":127907857,"number":30500,"title":"Salt master+minion: Received bad data when setting the match from the top file when gitfs fails to check out?","user":{"login":"anlutro","id":163093,"avatar_url":"https://avatars.githubusercontent.com/u/163093?v=3","gravatar_id":"","url":"https://api.github.com/users/anlutro","html_url":"https://github.com/anlutro","followers_url":"https://api.github.com/users/anlutro/followers","following_url":"https://api.github.com/users/anlutro/following{/other_user}","gists_url":"https://api.github.com/users/anlutro/gists{/gist_id}","starred_url":"https://api.github.com/users/anlutro/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/anlutro/subscriptions","organizations_url":"https://api.github.com/users/anlutro/orgs","repos_url":"https://api.github.com/users/anlutro/repos","events_url":"https://api.github.com/users/anlutro/events{/privacy}","received_events_url":"https://api.github.com/users/anlutro/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/saltstack/salt/labels/Bug","name":"Bug","color":"e11d21"},{"url":"https://api.github.com/repos/saltstack/salt/labels/Core","name":"Core","color":"fef2c0"},{"url":"https://api.github.com/repos/saltstack/salt/labels/High%20Severity","name":"High Severity","color":"ff9143"},{"url":"https://api.github.com/repos/saltstack/salt/labels/P4","name":"P4","color":"031a39"}],"state":"open","locked":false,"assignee":null,"milestone":{"url":"https://api.github.com/repos/saltstack/salt/milestones/13","html_url":"https://github.com/saltstack/salt/milestones/Approved","labels_url":"https://api.github.com/repos/saltstack/salt/milestones/13/labels","id":9265,"number":13,"title":"Approved","description":"All issues that are ready to be worked on, both bugs and features.","creator":{"login":"thatch45","id":507599,"avatar_url":"https://avatars.githubusercontent.com/u/507599?v=3","gravatar_id":"","url":"https://api.github.com/users/thatch45","html_url":"https://github.com/thatch45","followers_url":"https://api.github.com/users/thatch45/followers","following_url":"https://api.github.com/users/thatch45/following{/other_user}","gists_url":"https://api.github.com/users/thatch45/gists{/gist_id}","starred_url":"https://api.github.com/users/thatch45/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/thatch45/subscriptions","organizations_url":"https://api.github.com/users/thatch45/orgs","repos_url":"https://api.github.com/users/thatch45/repos","events_url":"https://api.github.com/users/thatch45/events{/privacy}","received_events_url":"https://api.github.com/users/thatch45/received_events","type":"User","site_admin":false},"open_issues":2843,"closed_issues":3276,"state":"open","created_at":"2011-05-14T04:00:56Z","updated_at":"2016-02-02T02:50:51Z","due_on":null,"closed_at":null},"comments":6,"created_at":"2016-01-21T11:52:59Z","updated_at":"2016-02-02T12:42:23Z","closed_at":null,"body":"On our salt masters, it looks like if a gitfs checkout fails, a `salt '*' state.apply` fails ONLY for the minion running on the same salt master. Every other minion works fine. If I wait a bit and run the same command, it'll work just fine.\r\n\r\nI suspect this has something to do with us using the same git repository for pillars as for states. Maybe Salt is trying to check out both the states and the pillars at the same time?\r\n\r\n/var/log/salt/master has this line:\r\n```\r\n2016-01-21 12:42:50,353 [salt.utils.gitfs ][ERROR   ][18179] Failed to checkout master from git_pillar remote 'master git@REDACTED': REDACTED: The index is locked. This might be due to a concurrent or crashed process\r\n```\r\n\r\n/var/log/salt/minion has this:\r\n```\r\n2016-01-21 12:42:50,365 [salt.state       ][INFO    ][2270] Loading fresh modules for state activity\r\n2016-01-21 12:42:50,394 [salt.fileclient  ][INFO    ][2270] Fetching file from saltenv 'base', ** skipped ** latest already in cache u'salt://top.sls'\r\n2016-01-21 12:42:50,412 [salt.minion      ][ERROR   ][2270] Received bad data when setting the match from the top file\r\n```\r\n\r\nI'm not 100% sure if these are correlated, but the timestamps seem to match somewhat, and the minion error only seems to happen when the master error is also present in the logs.\r\n\r\nVersions report:\r\n\r\n```\r\nSalt Version:\r\n           Salt: 2015.8.3\r\n \r\nDependency Versions:\r\n         Jinja2: 2.7.3\r\n       M2Crypto: Not Installed\r\n           Mako: 1.0.0\r\n         PyYAML: 3.11\r\n          PyZMQ: 14.4.0\r\n         Python: 2.7.9 (default, Mar  1 2015, 12:57:24)\r\n           RAET: Not Installed\r\n        Tornado: 4.2.1\r\n            ZMQ: 4.0.5\r\n           cffi: 0.8.6\r\n       cherrypy: 3.5.0\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        libnacl: 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: 0.23.1\r\n   python-gnupg: Not Installed\r\n          smmap: 0.8.2\r\n        timelib: Not Installed\r\n \r\nSystem Versions:\r\n           dist: debian 8.2 \r\n        machine: x86_64\r\n        release: 3.16.0-4-amd64\r\n         system: debian 8.2\r\n```"},"comment":{"url":"https://api.github.com/repos/saltstack/salt/issues/comments/178552744","html_url":"https://github.com/saltstack/salt/issues/30500#issuecomment-178552744","issue_url":"https://api.github.com/repos/saltstack/salt/issues/30500","id":178552744,"user":{"login":"anlutro","id":163093,"avatar_url":"https://avatars.githubusercontent.com/u/163093?v=3","gravatar_id":"","url":"https://api.github.com/users/anlutro","html_url":"https://github.com/anlutro","followers_url":"https://api.github.com/users/anlutro/followers","following_url":"https://api.github.com/users/anlutro/following{/other_user}","gists_url":"https://api.github.com/users/anlutro/gists{/gist_id}","starred_url":"https://api.github.com/users/anlutro/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/anlutro/subscriptions","organizations_url":"https://api.github.com/users/anlutro/orgs","repos_url":"https://api.github.com/users/anlutro/repos","events_url":"https://api.github.com/users/anlutro/events{/privacy}","received_events_url":"https://api.github.com/users/anlutro/received_events","type":"User","site_admin":false},"created_at":"2016-02-02T12:42:23Z","updated_at":"2016-02-02T12:42:23Z","body":"I increased the log level and think I tracked down the exact cause. This is being logged by one of the salt-master daemon processes:\r\n\r\n```\r\n2016-02-02 13:32:47,174 [salt.fileserver  ][DEBUG   ][5656] Updating git fileserver cache\r\n2016-02-02 13:32:47,175 [salt.utils.gitfs ][DEBUG   ][5656] Set lock for REDACTED\r\n2016-02-02 13:32:47,175 [salt.utils.gitfs ][DEBUG   ][5656] gitfs is fetching from 'REDACTED'\r\n```\r\n\r\n... right before the process of `salt 'name-of-minion' state.apply` starts:\r\n\r\n```\r\n2016-02-02 13:32:47,412 [salt.config      ][DEBUG   ][7387] Reading configuration from /etc/salt/master\r\n```\r\n\r\nLater on in the log:\r\n\r\n```\r\n2016-02-02 13:32:47,820 [salt.loaded.int.pillar.git_pillar][DEBUG   ][5761] git_pillar is processing pillar SLS from /var/cache/salt/master/git_pillar/REDACTED/pillars for pillar env 'base'\r\n2016-02-02 13:32:47,817 [salt.utils.gitfs ][ERROR   ][5766] Failed to checkout master from git_pillar remote 'master REDACTED': The index is locked. This might be due to a concurrent or crashed process\r\nTraceback (most recent call last):\r\n  File \"/usr/lib/python2.7/dist-packages/salt/utils/gitfs.py\", line 749, in checkout\r\n    self.repo.checkout(local_ref)\r\n  File \"/usr/local/lib/python2.7/dist-packages/pygit2/repository.py\", line 277, in checkout\r\n    self.checkout_tree(treeish, **kwargs)\r\n  File \"/usr/local/lib/python2.7/dist-packages/pygit2/repository.py\", line 231, in checkout_tree\r\n    check_error(C.git_checkout_tree(self._repo, cptr[0], copts))\r\n  File \"/usr/local/lib/python2.7/dist-packages/pygit2/errors.py\", line 64, in check_error\r\n    raise GitError(message)\r\nGitError: The index is locked. This might be due to a concurrent or crashed process\r\n```\r\n\r\nNote the timestamps in the log above, as the log entries did not get written in chronological order.\r\n\r\nLater on in the log, after the state run has finished, the gitfs lock is removed:\r\n\r\n```\r\n2016-02-02 13:32:51,507 [salt.utils.gitfs ][DEBUG   ][5656] gitfs remote 'REDACTED' is up-to-date\r\n2016-02-02 13:32:51,508 [salt.utils.gitfs ][DEBUG   ][5656] pygit2 does not support detecting stale refs for authenticated remotes, saltenvs will not reflect branches/tags removed from remote 'REDACTED'\r\n2016-02-02 13:32:51,508 [salt.utils.gitfs ][DEBUG   ][5656] Removed lock for REDACTED\r\n```"}}