{"action":"created","issue":{"url":"https://api.github.com/repos/saltstack/salt/issues/34872","repository_url":"https://api.github.com/repos/saltstack/salt","labels_url":"https://api.github.com/repos/saltstack/salt/issues/34872/labels{/name}","comments_url":"https://api.github.com/repos/saltstack/salt/issues/34872/comments","events_url":"https://api.github.com/repos/saltstack/salt/issues/34872/events","html_url":"https://github.com/saltstack/salt/issues/34872","id":166968518,"number":34872,"title":"\"Minion did not return\" executing state with long running command, 2016.3 regression","user":{"login":"cbuechler","id":95730,"avatar_url":"https://avatars.githubusercontent.com/u/95730?v=3","gravatar_id":"","url":"https://api.github.com/users/cbuechler","html_url":"https://github.com/cbuechler","followers_url":"https://api.github.com/users/cbuechler/followers","following_url":"https://api.github.com/users/cbuechler/following{/other_user}","gists_url":"https://api.github.com/users/cbuechler/gists{/gist_id}","starred_url":"https://api.github.com/users/cbuechler/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cbuechler/subscriptions","organizations_url":"https://api.github.com/users/cbuechler/orgs","repos_url":"https://api.github.com/users/cbuechler/repos","events_url":"https://api.github.com/users/cbuechler/events{/privacy}","received_events_url":"https://api.github.com/users/cbuechler/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/saltstack/salt/labels/Cannot%20Reproduce","name":"Cannot Reproduce","color":"c7def8"},{"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":517,"closed_issues":969,"state":"open","created_at":"2013-05-28T22:24:12Z","updated_at":"2016-08-04T21:49:06Z","due_on":null,"closed_at":null},"comments":10,"created_at":"2016-07-22T04:33:57Z","updated_at":"2016-08-05T19:31:47Z","closed_at":null,"body":"This is a setup I've been using for about a year, on a variety of 2015 versions, with no issue. Upgrading the minion to 2016.3.1 makes it stop working. I believe it's long-running commands, but maybe something else specific to what I'm doing. \r\n\r\nTake the following state: \r\n```\r\ngzcat /root/image-latest.img.gz | dd of=/dev/null bs=1M:\r\n  cmd.run\r\n```\r\n\r\nWhere image-latest.img.gz is a gzipped disk image file, which in normal operation is sent to dd with output to a hard drive, but for sake of example, /dev/null behaves in the same way. Any sufficiently large gz file (100 MB would suffice) will show the end result problem. \r\n\r\nWhen executing that state from the master via `salt my-deploy state.sls write-disk`, the master claims the minion didn't return. \r\n```\r\n[DEBUG   ] Reading configuration from /usr/local/etc/salt/master\r\n[DEBUG   ] Using cached minion ID from /usr/local/etc/salt/minion_id: dev-salt-master.example.com\r\n[DEBUG   ] Missing configuration file: /root/.saltrc\r\n[DEBUG   ] Configuration file path: /usr/local/etc/salt/master\r\n[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.\r\n[DEBUG   ] Reading configuration from /usr/local/etc/salt/master\r\n[DEBUG   ] Using cached minion ID from /usr/local/etc/salt/minion_id: dev-salt-master.example.com\r\n[DEBUG   ] Missing configuration file: /root/.saltrc\r\n[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc\r\n[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc\r\n[DEBUG   ] LazyLoaded local_cache.get_load\r\n[DEBUG   ] Reading minion list from /var/cache/salt/master/jobs/66/c9f0cb3dfb31a4e0eae44ad32a108d/.minions.p\r\n[DEBUG   ] get_iter_returns for jid 20160722001528110729 sent to set(['my-deploy']) will timeout at 00:15:33.119337\r\n[DEBUG   ] Checking whether jid 20160722001528110729 is still running\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] LazyLoaded no_return.output\r\nmy-deploy:\r\n    Minion did not return. [Not connected]\r\n```\r\n\r\nBut if you watch the minion's log, it's running the command, and it finishes successfully. So the minion works, it just apparently doesn't reply back to the master, leaving it thinking it disconnected. \r\n\r\nMinion log when master reports \"Minion did not return\". \r\n\r\n```\r\n[INFO    ] Running state [gzcat /root/image-latest.img.gz | dd of=/dev/null bs=1M] at time 00:15:37.880888\r\n[INFO    ] Executing state cmd.run for gzcat /root/image-latest.img.gz | dd of=/dev/null bs=1M\r\n[INFO    ] Executing command 'gzcat /root/image-latest.img.gz | dd of=/dev/null bs=1M' in directory '/root'\r\n[INFO    ] {'pid': 2344, 'retcode': 0, 'stderr': '0+131072 records in\\n8191+1 records out\\n8589888000 bytes transferred in 33.619007 secs (255506891 bytes/sec)', 'stdout': ''}\r\n[INFO    ] Completed state [gzcat /root/image-latest.img.gz | dd of=/dev/null bs=1M] at time 00:16:11.539727 duration_in_ms=33658.839\r\n[INFO    ] Returning information for job: 20160722001528110729\r\n```\r\n\r\nMaster log from 2015.8.1 which works correctly. \r\n\r\n```\r\n[DEBUG   ] Reading configuration from /usr/local/etc/salt/master\r\n[DEBUG   ] Using cached minion ID from /usr/local/etc/salt/minion_id: dev-salt-master.example.com\r\n[DEBUG   ] Missing configuration file: /root/.saltrc\r\n[DEBUG   ] Configuration file path: /usr/local/etc/salt/master\r\n[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.\r\n[DEBUG   ] Reading configuration from /usr/local/etc/salt/master\r\n[DEBUG   ] Using cached minion ID from /usr/local/etc/salt/minion_id: dev-salt-master.example.com\r\n[DEBUG   ] Missing configuration file: /root/.saltrc\r\n[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc\r\n[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc\r\n[DEBUG   ] LazyLoaded local_cache.get_load\r\n[DEBUG   ] Reading minion list from /var/cache/salt/master/jobs/ac/a63465b4ec61ac13c59cb3545fa507/.minions.p\r\n[DEBUG   ] get_iter_returns for jid 20160722042210217054 sent to set(['my-deploy']) will timeout at 04:22:15.225950\r\n[DEBUG   ] Checking whether jid 20160722042210217054 is still running\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] Checking whether jid 20160722042210217054 is still running\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] Checking whether jid 20160722042210217054 is still running\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] Checking whether jid 20160722042210217054 is still running\r\n[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/usr/local/etc/salt/pki/master', 'dev-salt-master.example.com_master', 'tcp://[::]:4506', 'clear')\r\n[DEBUG   ] jid 20160722042210217054 return from my-deploy\r\n[DEBUG   ] LazyLoaded highstate.output\r\n[DEBUG   ] LazyLoaded nested.output\r\n```\r\n\r\n\r\n### Versions Report\r\nNot working:\r\n```\r\nSalt Version:\r\n           Salt: 2016.3.1\r\n\r\nDependency Versions:\r\n           cffi: Not Installed\r\n       cherrypy: Not Installed\r\n       dateutil: 2.3\r\n          gitdb: Not Installed\r\n      gitpython: Not Installed\r\n          ioflo: Not Installed\r\n         Jinja2: 2.8\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.7\r\n   mysql-python: Not Installed\r\n      pycparser: Not Installed\r\n       pycrypto: 2.6.1\r\n         pygit2: Not Installed\r\n         Python: 2.7.11 (default, Mar 17 2016, 01:24:00)\r\n   python-gnupg: Not Installed\r\n         PyYAML: 3.11\r\n          PyZMQ: 15.2.0\r\n           RAET: Not Installed\r\n          smmap: Not Installed\r\n        timelib: Not Installed\r\n        Tornado: 4.3\r\n            ZMQ: 4.1.4\r\n\r\nSystem Versions:\r\n           dist:\r\n        machine: amd64\r\n        release: 10.2-RELEASE-p14\r\n         system: FreeBSD\r\n        version: Not Installed\r\n```\r\n\r\nWorking: \r\n```\r\n    Salt Version:\r\n               Salt: 2015.8.1\r\n\r\n    Dependency Versions:\r\n             Jinja2: 2.8\r\n           M2Crypto: Not Installed\r\n               Mako: Not Installed\r\n             PyYAML: 3.11\r\n              PyZMQ: 14.7.0\r\n             Python: 2.7.10 (default, Nov  5 2015, 01:15:39)\r\n               RAET: Not Installed\r\n            Tornado: 4.3\r\n                ZMQ: 4.1.3\r\n               cffi: Not Installed\r\n           cherrypy: Not Installed\r\n           dateutil: 2.3\r\n              gitdb: Not Installed\r\n          gitpython: Not Installed\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: Not Installed\r\n          pycparser: Not Installed\r\n           pycrypto: 2.6.1\r\n             pygit2: Not Installed\r\n       python-gnupg: Not Installed\r\n              smmap: Not Installed\r\n            timelib: Not Installed\r\n\r\n    System Versions:\r\n               dist:\r\n            machine: amd64\r\n            release: 10.1-RELEASE-p24\r\n```\r\n\r\nThe OS used doesn't matter either way, FreeBSD 10.2 with any 2015 salt version works fine. "},"comment":{"url":"https://api.github.com/repos/saltstack/salt/issues/comments/237942152","html_url":"https://github.com/saltstack/salt/issues/34872#issuecomment-237942152","issue_url":"https://api.github.com/repos/saltstack/salt/issues/34872","id":237942152,"user":{"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},"created_at":"2016-08-05T19:31:47Z","updated_at":"2016-08-05T19:31:47Z","body":"Ok, please let us know if it resurfaces.\r\n\r\nHave the minion systems been under extra load when this happens?"}}
{"actor":{"display_login":"thatch45"}}