{"action":"created","issue":{"url":"https://api.github.com/repos/saltstack/salt/issues/32768","repository_url":"https://api.github.com/repos/saltstack/salt","labels_url":"https://api.github.com/repos/saltstack/salt/issues/32768/labels{/name}","comments_url":"https://api.github.com/repos/saltstack/salt/issues/32768/comments","events_url":"https://api.github.com/repos/saltstack/salt/issues/32768/events","html_url":"https://github.com/saltstack/salt/issues/32768","id":150281322,"number":32768,"title":"Tornado: error deleting fd from IOLoop when master disconnects for a long time in multi-failover","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/Critical","name":"Critical","color":"e95800"},{"url":"https://api.github.com/repos/saltstack/salt/labels/Multi-Master","name":"Multi-Master","color":"006b75"},{"url":"https://api.github.com/repos/saltstack/salt/labels/P3","name":"P3","color":"0a3d77"},{"url":"https://api.github.com/repos/saltstack/salt/labels/Transport","name":"Transport","color":"006b75"}],"state":"closed","locked":false,"assignee":{"login":"DmitryKuzmenko","id":4807387,"avatar_url":"https://avatars.githubusercontent.com/u/4807387?v=3","gravatar_id":"","url":"https://api.github.com/users/DmitryKuzmenko","html_url":"https://github.com/DmitryKuzmenko","followers_url":"https://api.github.com/users/DmitryKuzmenko/followers","following_url":"https://api.github.com/users/DmitryKuzmenko/following{/other_user}","gists_url":"https://api.github.com/users/DmitryKuzmenko/gists{/gist_id}","starred_url":"https://api.github.com/users/DmitryKuzmenko/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/DmitryKuzmenko/subscriptions","organizations_url":"https://api.github.com/users/DmitryKuzmenko/orgs","repos_url":"https://api.github.com/users/DmitryKuzmenko/repos","events_url":"https://api.github.com/users/DmitryKuzmenko/events{/privacy}","received_events_url":"https://api.github.com/users/DmitryKuzmenko/received_events","type":"User","site_admin":false},"milestone":{"url":"https://api.github.com/repos/saltstack/salt/milestones/80","html_url":"https://github.com/saltstack/salt/milestones/B%20-3","labels_url":"https://api.github.com/repos/saltstack/salt/milestones/80/labels","id":1698173,"number":80,"title":"B -3","description":"","creator":{"login":"meggiebot","id":12242451,"avatar_url":"https://avatars.githubusercontent.com/u/12242451?v=3","gravatar_id":"","url":"https://api.github.com/users/meggiebot","html_url":"https://github.com/meggiebot","followers_url":"https://api.github.com/users/meggiebot/followers","following_url":"https://api.github.com/users/meggiebot/following{/other_user}","gists_url":"https://api.github.com/users/meggiebot/gists{/gist_id}","starred_url":"https://api.github.com/users/meggiebot/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/meggiebot/subscriptions","organizations_url":"https://api.github.com/users/meggiebot/orgs","repos_url":"https://api.github.com/users/meggiebot/repos","events_url":"https://api.github.com/users/meggiebot/events{/privacy}","received_events_url":"https://api.github.com/users/meggiebot/received_events","type":"User","site_admin":false},"open_issues":10,"closed_issues":1,"state":"open","created_at":"2016-04-11T15:24:47Z","updated_at":"2016-04-25T18:54:37Z","due_on":"2016-05-09T06:00:00Z","closed_at":null},"comments":3,"created_at":"2016-04-22T06:26:11Z","updated_at":"2016-04-25T18:54:37Z","closed_at":"2016-04-25T18:54:37Z","body":"Using a multi-master failover configuration with a single master, if the master is shut down for a while, I get this in the salt minion logs on the master host:\r\n\r\n```\r\n2016-04-22 08:16:51,740 [salt.minion] [INFO] fire_master failed: master could not be contacted. Request timed out.\r\n2016-04-22 08:16:51,741 [salt.utils.schedule] [INFO] Running scheduled job: __master_alive\r\n2016-04-22 08:16:51,742 [salt.utils.schedule] [DEBUG] schedule: This job was scheduled with jid_include, adding to cache (jid_include defaults to True)\r\n2016-04-22 08:16:51,742 [salt.utils.schedule] [DEBUG] schedule: This job was scheduled with a max number of 2\r\n2016-04-22 08:16:51,746 [salt.utils.schedule] [DEBUG] schedule.handle_func: Checking job against fun status.master: {'fun': 'status.master', 'jid': '20160422080453546650', 'pid': 1936, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,747 [salt.utils.schedule] [DEBUG] schedule.handle_func: Checking job against fun status.master: {'fun': 'status.master', 'jid': '20160422081151722659', 'pid': 2002, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,748 [salt.utils.schedule] [DEBUG] schedule.handle_func: Checking job against fun status.master: {'fun': 'status.master', 'jid': '20160422080452545186', 'pid': 1927, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,752 [salt.utils.schedule] [INFO] Running scheduled job: __update_grains\r\n2016-04-22 08:16:51,752 [salt.utils.schedule] [DEBUG] schedule: This job was scheduled with jid_include, adding to cache (jid_include defaults to True)\r\n2016-04-22 08:16:51,752 [salt.utils.schedule] [DEBUG] schedule: This job was scheduled with a max number of 1\r\n2016-04-22 08:16:51,760 [salt.utils.schedule] [DEBUG] schedule.handle_func: Checking job against fun event.fire: {'fun': 'status.master', 'jid': '20160422080453546650', 'pid': 1936, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,762 [salt.utils.schedule] [DEBUG] schedule.handle_func: adding this job to the jobcache with data {'fun': 'status.master', 'jid': '20160422081651745533', 'pid': 2052, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,763 [salt.utils.schedule] [DEBUG] schedule.handle_func: Checking job against fun event.fire: {'fun': 'status.master', 'jid': '20160422081151722659', 'pid': 2002, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,766 [salt.utils.schedule] [DEBUG] schedule.handle_func: Checking job against fun event.fire: {'fun': 'status.master', 'jid': '20160422080452545186', 'pid': 1927, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__master_alive'}\r\n2016-04-22 08:16:51,770 [salt.transport.zeromq] [DEBUG] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'orch.test.infra.vagrant.local', 'tcp://10.0.1.99:4506', 'aes')\r\n2016-04-22 08:16:51,771 [salt.crypt] [DEBUG] Initializing new SAuth for ('/etc/salt/pki/minion', 'orch.test.infra.vagrant.local', 'tcp://10.0.1.99:4506')\r\n2016-04-22 08:16:51,777 [salt.utils.schedule] [DEBUG] schedule.handle_func: adding this job to the jobcache with data {'fun': 'event.fire', 'jid': '20160422081651759116', 'pid': 2054, 'id': 'orch.test.infra.vagrant.local', 'schedule': '__update_grains'}\r\n2016-04-22 08:16:51,780 [salt.utils.event] [DEBUG] SaltEvent PUB socket URI: ipc:///var/run/salt/minion/minion_event_b1192db92a_pub.ipc\r\n2016-04-22 08:16:51,781 [salt.utils.event] [DEBUG] SaltEvent PULL socket URI: ipc:///var/run/salt/minion/minion_event_b1192db92a_pull.ipc\r\n2016-04-22 08:16:51,782 [salt.utils.event] [DEBUG] Sending event - data = {'_stamp': '2016-04-22T06:16:51.782290'}\r\n2016-04-22 08:16:51,784 [salt.minion] [DEBUG] Handling event 'grains_refresh\\n\\n\\x81\\xa6_stamp\\xba2016-04-22T06:16:51.782290'\r\n2016-04-22 08:16:51,811 [salt.transport.zeromq] [DEBUG] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'orch.test.infra.vagrant.local', 'tcp://10.0.1.99:4506', 'aes')\r\n2016-04-22 08:16:51,811 [salt.crypt] [DEBUG] Initializing new SAuth for ('/etc/salt/pki/minion', 'orch.test.infra.vagrant.local', 'tcp://10.0.1.99:4506')\r\n2016-04-22 08:17:51,543 [salt.transport.zeromq] [DEBUG] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'orch.test.infra.vagrant.local', 'tcp://10.0.1.99:4506', 'aes')\r\n2016-04-22 08:17:51,543 [salt.crypt] [DEBUG] Initializing new SAuth for ('/etc/salt/pki/minion', 'orch.test.infra.vagrant.local', 'tcp://10.0.1.99:4506')\r\n2016-04-22 08:17:51,830 [salt.transport.zeromq] [DEBUG] SaltReqTimeoutError, retrying. (1/3)\r\n2016-04-22 08:17:51,830 [salt.transport.zeromq] [DEBUG] SaltReqTimeoutError, retrying. (1/3)\r\n2016-04-22 08:18:51,599 [salt.transport.zeromq] [DEBUG] SaltReqTimeoutError, retrying. (1/3)\r\n2016-04-22 08:18:51,891 [tornado.general] [DEBUG] Error deleting fd from IOLoop\r\nTraceback (most recent call last):\r\n  File \"/usr/lib/python2.7/dist-packages/tornado/ioloop.py\", line 715, in remove_handler\r\n    self._impl.unregister(fd)\r\n  File \"/usr/lib/python2.7/dist-packages/zmq/eventloop/ioloop.py\", line 115, in unregister\r\n    return self._poller.unregister(fd)\r\n  File \"/usr/lib/python2.7/dist-packages/zmq/sugar/poll.py\", line 71, in unregister\r\n    idx = self._map.pop(socket)\r\nKeyError: None\r\n```\r\n\r\nIt looks like it might be related to trying to reconnect in multiple threads at the same time? `retrying. (1/3)` shows up 3 times within a short period of time.\r\n\r\n```\r\nSalt Version:\r\n           Salt: 2015.8.8.2\r\n \r\nDependency Versions:\r\n         Jinja2: 2.7.3\r\n       M2Crypto: Not Installed\r\n           Mako: Not Installed\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.2.3\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        libgit2: 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: Not Installed\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.3 \r\n        machine: x86_64\r\n        release: 3.16.0-4-amd64\r\n         system: debian 8.3\r\n```\r\n\r\nPossibly related to #32609"},"comment":{"url":"https://api.github.com/repos/saltstack/salt/issues/comments/214478695","html_url":"https://github.com/saltstack/salt/issues/32768#issuecomment-214478695","issue_url":"https://api.github.com/repos/saltstack/salt/issues/32768","id":214478695,"user":{"login":"DmitryKuzmenko","id":4807387,"avatar_url":"https://avatars.githubusercontent.com/u/4807387?v=3","gravatar_id":"","url":"https://api.github.com/users/DmitryKuzmenko","html_url":"https://github.com/DmitryKuzmenko","followers_url":"https://api.github.com/users/DmitryKuzmenko/followers","following_url":"https://api.github.com/users/DmitryKuzmenko/following{/other_user}","gists_url":"https://api.github.com/users/DmitryKuzmenko/gists{/gist_id}","starred_url":"https://api.github.com/users/DmitryKuzmenko/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/DmitryKuzmenko/subscriptions","organizations_url":"https://api.github.com/users/DmitryKuzmenko/orgs","repos_url":"https://api.github.com/users/DmitryKuzmenko/repos","events_url":"https://api.github.com/users/DmitryKuzmenko/events{/privacy}","received_events_url":"https://api.github.com/users/DmitryKuzmenko/received_events","type":"User","site_admin":false},"created_at":"2016-04-25T18:54:37Z","updated_at":"2016-04-25T18:54:37Z","body":"Fixed by #31164 that is already in 2015.8 branch and will be available in the next release."}}