{"action":"created","issue":{"url":"https://api.github.com/repos/saltstack/salt/issues/26115","labels_url":"https://api.github.com/repos/saltstack/salt/issues/26115/labels{/name}","comments_url":"https://api.github.com/repos/saltstack/salt/issues/26115/comments","events_url":"https://api.github.com/repos/saltstack/salt/issues/26115/events","html_url":"https://github.com/saltstack/salt/issues/26115","id":99732616,"number":26115,"title":"Lazyloading of state modules happening in wrong order","user":{"login":"wt","id":416255,"avatar_url":"https://avatars.githubusercontent.com/u/416255?v=3","gravatar_id":"","url":"https://api.github.com/users/wt","html_url":"https://github.com/wt","followers_url":"https://api.github.com/users/wt/followers","following_url":"https://api.github.com/users/wt/following{/other_user}","gists_url":"https://api.github.com/users/wt/gists{/gist_id}","starred_url":"https://api.github.com/users/wt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wt/subscriptions","organizations_url":"https://api.github.com/users/wt/orgs","repos_url":"https://api.github.com/users/wt/repos","events_url":"https://api.github.com/users/wt/events{/privacy}","received_events_url":"https://api.github.com/users/wt/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2015-08-07T21:24:41Z","updated_at":"2015-08-07T21:27:03Z","closed_at":null,"body":"salt-call --versions:\r\n\r\n               Salt: 2015.5.3\r\n             Python: 2.6.9 (unknown, Apr  1 2015, 18:16:00)\r\n             Jinja2: 2.7.2\r\n           M2Crypto: 0.21.1\r\n     msgpack-python: 0.4.6\r\n       msgpack-pure: Not Installed\r\n           pycrypto: 2.6.1\r\n            libnacl: Not Installed\r\n             PyYAML: 3.10\r\n              ioflo: Not Installed\r\n              PyZMQ: 14.3.1\r\n               RAET: Not Installed\r\n                ZMQ: 3.2.5\r\n               Mako: Not Installed\r\n            Tornado: Not Installed\r\n\r\nI believe that I have a case where the ordering of states is not working properly.\r\n\r\nI have a file root with the following files in it:\r\n\r\npostfix.sls:\r\n\r\n    postfix:\r\n      service.running\r\n\r\npython-pip.sls:\r\n\r\n    python_pip_pkg:\r\n      pkg.latest:\r\n        - pkgs:\r\n          - python26-pip\r\n          - python27-pip\r\n\r\ndocker-py.sls:\r\n\r\n    include:\r\n      - base: python-pip\r\n    \r\n    docker-py:\r\n      pip.installed:\r\n        - name: docker-py>=1.2.2\r\n        - bin_env: /usr/bin/pip-2.7\r\n        - watch_in:\r\n          - service: postfix\r\n\r\nThe \r\nHere a result of trying to use them before installing pip:\r\n\r\n    # salt-call --local --file-root /root/blah state.apply postfix,docker-py\r\n    local:\r\n        - The function \"state.highstate\" is running as PID 13502 and was started at 2015, Aug 07 20:49:59.225647 with jid 20150807204959225647\r\n    # salt-call --local --file-root /root/blah state.apply postfix,docker-py 2>&1 | sed 's/^/    /'\r\n    [INFO    ] Loading fresh modules for state activity\r\n    [INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://postfix.sls'\r\n    [INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://docker-py.sls'\r\n    [INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://python-pip.sls'\r\n    /usr/lib64/python2.6/dist-packages/Crypto/Util/number.py:57: PowmInsecureWarning: Not using mpz_powm_sec.  You should rebuild using libgmp >= 5 to avoid timing attack vulnerability.\r\n      _warn(\"Not using mpz_powm_sec.  You should rebuild using libgmp >= 5 to avoid timing attack vulnerability.\", PowmInsecureWarning)\r\n    [ERROR   ] An un-handled exception was caught by salt's global exception handler:\r\n    KeyError: 'pip.installed'\r\n    Traceback (most recent call last):\r\n      File \"/usr/bin/salt-call\", line 11, in <module>\r\n        salt_call()\r\n      File \"/usr/lib/python2.6/site-packages/salt/scripts.py\", line 227, in salt_call\r\n        client.run()\r\n      File \"/usr/lib/python2.6/site-packages/salt/cli/call.py\", line 69, in run\r\n        caller.run()\r\n      File \"/usr/lib/python2.6/site-packages/salt/cli/caller.py\", line 236, in run\r\n        ret = self.call()\r\n      File \"/usr/lib/python2.6/site-packages/salt/cli/caller.py\", line 138, in call\r\n        ret['return'] = func(*args, **kwargs)\r\n      File \"/usr/lib/python2.6/site-packages/salt/modules/state.py\", line 296, in apply_\r\n        return sls(mods, **kwargs)\r\n      File \"/usr/lib/python2.6/site-packages/salt/modules/state.py\", line 681, in sls\r\n        ret = st_.state.call_high(high_)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 2067, in call_high\r\n        ret = dict(list(disabled.items()) + list(self.call_chunks(chunks).items()))\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 1623, in call_chunks\r\n        running = self.call_chunk(low, running, chunks)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 1858, in call_chunk\r\n        running = self.call_chunk(chunk, running, chunks)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 1769, in call_chunk\r\n        self._mod_init(low)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 612, in _mod_init\r\n        self.states['{0}.{1}'.format(low['state'], low['fun'])]  # pylint: disable=W0106\r\n      File \"/usr/lib/python2.6/site-packages/salt/utils/lazy.py\", line 90, in __getitem__\r\n        raise KeyError(key)\r\n    KeyError: 'pip.installed'\r\n    Traceback (most recent call last):\r\n      File \"/usr/bin/salt-call\", line 11, in <module>\r\n        salt_call()\r\n      File \"/usr/lib/python2.6/site-packages/salt/scripts.py\", line 227, in salt_call\r\n        client.run()\r\n      File \"/usr/lib/python2.6/site-packages/salt/cli/call.py\", line 69, in run\r\n        caller.run()\r\n      File \"/usr/lib/python2.6/site-packages/salt/cli/caller.py\", line 236, in run\r\n        ret = self.call()\r\n      File \"/usr/lib/python2.6/site-packages/salt/cli/caller.py\", line 138, in call\r\n        ret['return'] = func(*args, **kwargs)\r\n      File \"/usr/lib/python2.6/site-packages/salt/modules/state.py\", line 296, in apply_\r\n        return sls(mods, **kwargs)\r\n      File \"/usr/lib/python2.6/site-packages/salt/modules/state.py\", line 681, in sls\r\n        ret = st_.state.call_high(high_)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 2067, in call_high\r\n        ret = dict(list(disabled.items()) + list(self.call_chunks(chunks).items()))\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 1623, in call_chunks\r\n        running = self.call_chunk(low, running, chunks)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 1858, in call_chunk\r\n        running = self.call_chunk(chunk, running, chunks)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 1769, in call_chunk\r\n        self._mod_init(low)\r\n      File \"/usr/lib/python2.6/site-packages/salt/state.py\", line 612, in _mod_init\r\n        self.states['{0}.{1}'.format(low['state'], low['fun'])]  # pylint: disable=W0106\r\n      File \"/usr/lib/python2.6/site-packages/salt/utils/lazy.py\", line 90, in __getitem__\r\n        raise KeyError(key)\r\n    KeyError: 'pip.installed'\r\n\r\nRunning the previous command with debug logging appears to indicate that the pip module is LazyLoaded just before the crash and before it ever tries applying any of the states. I expected the python-pip state file to be applied first since it is included from the docker-py which actually happens if I remove the watch_in requisite from the docker-py. I actually think this is an important piece of info for this bug.\r\n\r\nI also tried other cases.\r\n\r\nIf I install pip before running the command, it will work.\r\n\r\nIf I swap the postfix and docker-py states on the commandline before I install pip, it also works:\r\n\r\n    # salt-call --local --file-root /root/blah state.apply docker-py,postfix\r\n    [INFO    ] Loading fresh modules for state activity\r\n    [INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://docker-py.sls'\r\n    [INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://python-pip.sls'\r\n    [INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://postfix.sls'\r\n    [INFO    ] Running state [python_pip_pkg] at time 20:52:17.637019\r\n    [INFO    ] Executing state pkg.latest for python_pip_pkg\r\n    [INFO    ] Executing command \"repoquery --plugins --queryformat '%{NAME}_|-%{VERSION}_|-%{RELEASE}_|-%{ARCH}_|-%{REPOID}' --all --pkgnarrow=installed\" in directory '/root'\r\n    [INFO    ] Executing command ['yum', '-q', 'clean', 'expire-cache'] in directory '/root'\r\n    [INFO    ] Executing command ['yum', '-q', 'check-update'] in directory '/root'\r\n    [INFO    ] Executing command \"repoquery --plugins --queryformat '%{NAME}_|-%{VERSION}_|-%{RELEASE}_|-%{ARCH}_|-%{REPOID}'   --pkgnarrow=available python26-pip python27-pip\" in directory '/root'\r\n    [INFO    ] Executing command 'yum -y     install python26-pip python27-pip' in directory '/root'\r\n    [INFO    ] Executing command \"repoquery --plugins --queryformat '%{NAME}_|-%{VERSION}_|-%{RELEASE}_|-%{ARCH}_|-%{REPOID}' --all --pkgnarrow=installed\" in directory '/root'\r\n    [INFO    ] Installed Packages:\r\n    python26-pip changed from absent to 6.1.1-1.20.amzn1\r\n    python27-pip changed from absent to 6.1.1-1.20.amzn1\r\n    \r\n    [INFO    ] Loading fresh modules for state activity\r\n    [INFO    ] Completed state [python_pip_pkg] at time 20:52:31.346377\r\n    [INFO    ] Running state [docker-py>=1.2.2] at time 20:52:31.483259\r\n    [INFO    ] Executing state pip.installed for docker-py>=1.2.2\r\n    [INFO    ] Executing command '/usr/bin/pip-2.7 freeze' in directory '/root'\r\n    [INFO    ] Executing command '/usr/bin/pip-2.7 install' in directory '/root'\r\n    [INFO    ] Python package docker-py>=1.2.2 was already installed\r\n    All packages were successfully installed\r\n    [INFO    ] Completed state [docker-py>=1.2.2] at time 20:52:31.967712\r\n    [INFO    ] Running state [postfix] at time 20:52:31.969605\r\n    [INFO    ] Executing state service.running for postfix\r\n    [INFO    ] Executing command '/sbin/service postfix status' in directory '/root'\r\n    [INFO    ] The service postfix is already running\r\n    [INFO    ] Completed state [postfix] at time 20:52:31.988342\r\n    local:\r\n        ----------\r\n        pip_|-docker-py_|-docker-py>=1.2.2_|-installed:\r\n            ----------\r\n            __run_num__:\r\n                1\r\n            changes:\r\n                ----------\r\n            comment:\r\n                Python package docker-py>=1.2.2 was already installed\r\n                All packages were successfully installed\r\n            duration:\r\n                484.453\r\n            name:\r\n                docker-py>=1.2.2\r\n            result:\r\n                True\r\n            start_time:\r\n                20:52:31.483259\r\n        pkg_|-python_pip_pkg_|-python_pip_pkg_|-latest:\r\n            ----------\r\n            __run_num__:\r\n                0\r\n            changes:\r\n                ----------\r\n                python26-pip:\r\n                    ----------\r\n                    new:\r\n                        6.1.1-1.20.amzn1\r\n                    old:\r\n                python27-pip:\r\n                    ----------\r\n                    new:\r\n                        6.1.1-1.20.amzn1\r\n                    old:\r\n            comment:\r\n                The following packages were successfully installed/upgraded: python26-pip, python27-pip\r\n            duration:\r\n                13709.358\r\n            name:\r\n                python_pip_pkg\r\n            result:\r\n                True\r\n            start_time:\r\n                20:52:17.637019\r\n        service_|-postfix_|-postfix_|-running:\r\n            ----------\r\n            __run_num__:\r\n                2\r\n            changes:\r\n                ----------\r\n            comment:\r\n                The service postfix is already running\r\n            duration:\r\n                18.737\r\n            name:\r\n                postfix\r\n            result:\r\n                True\r\n            start_time:\r\n                20:52:31.969605\r\n\r\nIf I explicitly prepend the applied states with the \"python-pip\" state file, it works:\r\n\r\n    # salt-call --local --file-root /root/blah state.apply python-pip,postfix,docker-py\r\n    ...\r\n\r\nIf I remove the \"watch_in\" requisite from the docker-py state in the docker-py.sls file, it will also work. However, I want to restart the postfix service whenever docker-py is changed, so I actually do want that requisite.\r\n\r\nJust so you know, the actual daemon that I am dealing with is one in use at my company. I am just using postfix so that the examples can work more easily for others."},"comment":{"url":"https://api.github.com/repos/saltstack/salt/issues/comments/128837363","html_url":"https://github.com/saltstack/salt/issues/26115#issuecomment-128837363","issue_url":"https://api.github.com/repos/saltstack/salt/issues/26115","id":128837363,"user":{"login":"wt","id":416255,"avatar_url":"https://avatars.githubusercontent.com/u/416255?v=3","gravatar_id":"","url":"https://api.github.com/users/wt","html_url":"https://github.com/wt","followers_url":"https://api.github.com/users/wt/followers","following_url":"https://api.github.com/users/wt/following{/other_user}","gists_url":"https://api.github.com/users/wt/gists{/gist_id}","starred_url":"https://api.github.com/users/wt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wt/subscriptions","organizations_url":"https://api.github.com/users/wt/orgs","repos_url":"https://api.github.com/users/wt/repos","events_url":"https://api.github.com/users/wt/events{/privacy}","received_events_url":"https://api.github.com/users/wt/received_events","type":"User","site_admin":false},"created_at":"2015-08-07T21:27:03Z","updated_at":"2015-08-07T21:27:03Z","body":"I am pretty sure this behavior is different between 2015.5.3 and 2015.5.2."}}