various salt-minions are not replying to test.ping or commands
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	akosiaris
	Jun 17 2015, 2:20 PM

Description

The following hosts are consistently not replying to test.ping or cmd.run commands. We need to investigate and fix the problem, whatever it is

sudo salt -b5% --out raw '*' test.ping |egrep -v 'Executing run on |True' | sort -u

result is:

{'gallium.wikimedia.org': {}}
{'graphite1002.eqiad.wmnet': {}}
{'mc2001.codfw.wmnet': {}}
{'ocg1001.eqiad.wmnet': {}}
{'ocg1002.eqiad.wmnet': {}}
{'ocg1003.eqiad.wmnet': {}}
{'restbase1001.eqiad.wmnet': {}}
{'restbase1002.eqiad.wmnet': {}}
{'restbase1003.eqiad.wmnet': {}}
{'restbase1004.eqiad.wmnet': {}}
{'restbase1005.eqiad.wmnet': {}}
{'restbase1006.eqiad.wmnet': {}}
{'silver.wikimedia.org': {}}
{'wtp1001.eqiad.wmnet': {}}
{'wtp1002.eqiad.wmnet': {}}
{'wtp1003.eqiad.wmnet': {}}
{'wtp1004.eqiad.wmnet': {}}
{'wtp1005.eqiad.wmnet': {}}
{'wtp1006.eqiad.wmnet': {}}
{'wtp1007.eqiad.wmnet': {}}
{'wtp1008.eqiad.wmnet': {}}
{'wtp1009.eqiad.wmnet': {}}
{'wtp1010.eqiad.wmnet': {}}
{'wtp1011.eqiad.wmnet': {}}
{'wtp1012.eqiad.wmnet': {}}
{'wtp1013.eqiad.wmnet': {}}
{'wtp1014.eqiad.wmnet': {}}
{'wtp1015.eqiad.wmnet': {}}
{'wtp1016.eqiad.wmnet': {}}
{'wtp1017.eqiad.wmnet': {}}
{'wtp1018.eqiad.wmnet': {}}
{'wtp1019.eqiad.wmnet': {}}
{'wtp1020.eqiad.wmnet': {}}
{'wtp1021.eqiad.wmnet': {}}
{'wtp1022.eqiad.wmnet': {}}
{'wtp1023.eqiad.wmnet': {}}
{'wtp1024.eqiad.wmnet': {}}
{'wtp2001.codfw.wmnet': {}}
{'wtp2002.codfw.wmnet': {}}
{'wtp2003.codfw.wmnet': {}}
{'wtp2004.codfw.wmnet': {}}
{'wtp2005.codfw.wmnet': {}}
{'wtp2006.codfw.wmnet': {}}
{'wtp2007.codfw.wmnet': {}}
{'wtp2008.codfw.wmnet': {}}
{'wtp2009.codfw.wmnet': {}}
{'wtp2010.codfw.wmnet': {}}
{'wtp2011.codfw.wmnet': {}}
{'wtp2012.codfw.wmnet': {}}
{'wtp2013.codfw.wmnet': {}}
{'wtp2014.codfw.wmnet': {}}
{'wtp2015.codfw.wmnet': {}}
{'wtp2016.codfw.wmnet': {}}
{'wtp2017.codfw.wmnet': {}}
{'wtp2018.codfw.wmnet': {}}
{'wtp2019.codfw.wmnet': {}}
{'wtp2020.codfw.wmnet': {}}
{'zirconium.wikimedia.org': {}}

Event Timeline

akosiaris created this task.Jun 17 2015, 2:20 PM

akosiaris raised the priority of this task from to High.

akosiaris updated the task description. (Show Details)

akosiaris added a project: acl*sre-team.

akosiaris subscribed.

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 17 2015, 2:20 PM

akosiaris set Security to None.Jun 17 2015, 2:21 PM

akosiaris added subscribers: ArielGlenn, fgiunchedi, faidon, Joe.

akosiaris moved this task from Backlog to Doing on the acl*sre-team board.Jun 17 2015, 2:44 PM

Up to now

strace -f -p `pgrep salt-minion`

reveals the minion is in an system call

Process 26406 attached with 5 threads
[pid 26543] epoll_wait(13,  <unfinished ...>
[pid 26490] epoll_wait(8,  <unfinished ...>
[pid 26544] epoll_wait(15,  <unfinished ...>
[pid 26489] epoll_wait(6,  <unfinished ...>
[pid 26406] restart_syscall(<... resuming interrupted call ...>

the 6,8,13,15 FDs are from the child threads are are of the form

anon_inode:[eventpoll]

as lsof -p pgrep salt-minion and ls -l /proc/pgrep salt-minion/fd shows.

The main thread once after a long time resumed into poll(9, ...) but I never managed to reproduce.

Attaching with gdb and calling close on any of those 4 FDs will have the process killed

init: salt-minion main process (26406) killed by ABRT signal

note that akosiaris already encountered this issue on sca1001 and 1002. I note it here in case there's something run in common on these hosts and not the others.

MoritzMuehlenhoff subscribed.Jun 17 2015, 2:58 PM

Got a stacktrace

(gdb) bt
#0  0x00007f5659a51cbd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f565619035d in zmq_poll () from /usr/lib/x86_64-linux-gnu/libzmq.so.3
#2  0x00007f5654da3e91 in ?? () from /usr/lib/python2.7/dist-packages/zmq/backend/cython/_poll.x86_64-linux-gnu.so
#3  0x0000000000530825 in PyEval_EvalFrameEx ()
#4  0x000000000055c594 in PyEval_EvalCodeEx ()
#5  0x000000000052ca8d in PyEval_EvalFrameEx ()
#6  0x000000000055c594 in PyEval_EvalCodeEx ()
#7  0x000000000052ca8d in PyEval_EvalFrameEx ()
#8  0x000000000055c594 in PyEval_EvalCodeEx ()
#9  0x000000000052ca8d in PyEval_EvalFrameEx ()
#10 0x000000000052cf32 in PyEval_EvalFrameEx ()
#11 0x000000000055c594 in PyEval_EvalCodeEx ()
#12 0x000000000052ca8d in PyEval_EvalFrameEx ()
#13 0x000000000055c594 in PyEval_EvalCodeEx ()
#14 0x000000000052ca8d in PyEval_EvalFrameEx ()
#15 0x000000000052cf32 in PyEval_EvalFrameEx ()
#16 0x000000000055c594 in PyEval_EvalCodeEx ()
#17 0x000000000052ca8d in PyEval_EvalFrameEx ()
#18 0x000000000055c594 in PyEval_EvalCodeEx ()
#19 0x00000000005b7392 in PyEval_EvalCode ()
#20 0x0000000000469663 in ?? ()
#21 0x00000000004699e3 in PyRun_FileExFlags ()
#22 0x0000000000469f1c in PyRun_SimpleFileExFlags ()
#23 0x000000000046ab81 in Py_Main ()
#24 0x00007f5659985ec5 in __libc_start_main (main=0x46ac3f <main>, argc=2, argv=0x7fffb1248868, init=<optimized out>, fini=<optimized out>, 
    rtld_fini=<optimized out>, stack_end=0x7fffb1248858) at libc-start.c:287
#25 0x000000000057497e in _start ()

Seems like zeroMQ troubles right now

And finally a python stacktrace

(gdb) py-bt
#5 Frame 0x7f5652ab6d38, for file /usr/lib/python2.7/dist-packages/zmq/sugar/poll.py, line 110, in poll (self=<Poller(sockets=[(<Socket() at remote 0x7f5652aa5460>, 1)], _map={<...>: 0}) at remote 0x7f5652ab50d0>, timeout=7200000)
    return zmq_poll(self.sockets, timeout=timeout)
#9 Frame 0x1faa3b0, for file /usr/lib/python2.7/dist-packages/salt/payload.py, line 239, in send (self=<SREQ(id_='', linger=0, _socket=<Socket() at remote 0x7f5652aa5460>, master='tcp://10.64.16.160:4506', context=<Context(sockopts={}) at remote 0x7f5652aa6c08>, serial=<Serial(serial='msgpack') at remote 0x7f5652a97fd0>, poller=<Poller(sockets=[(<...>, 1)], _map={<...>: 0}) at remote 0x7f5652ab50d0>, opts=None) at remote 0x7f5652a97f90>, enc='aes', load='\x00\xe6\xb0\xd7\xc0?W3\xe1O\x9bw\x13\x99"\x8cah\xa6\xa1u\x1b$\x01(\x82i\xba\xd1\x94?\x7f}\x9b\x1c\xd8\xc0\xa2uI/\xe4Q\x05\x98f\xfcc\xb8a\x1c\xe3\x8a\x9c\x01\'s\x06\x85\xe3\x84+\xe5\xe8\x1emO\x81Q\xcb\xc6>\x00\xcf\xc1J\x0e\x00Hb\r/\xd6\xf0_\x1b\x11\x0cgB\xb6\x0f\x8d/>~\xd4\xc4\x15+-jA\xa9\xcf)\xfe\x90\xae\xe0\xfd/\xe3\xea\\Oz\xb0\xdc\xc4\x0f\xba\x0fG8~s\xe2\xd9\xa2\x99\x84=\xa9\xf3\xfb\xe6\xde\xf2\xee\x7f\xec>\xfbPx\x891d\xf8?\x8d\xe5\xc3(\xab\xbd|D8\x04\xe2Z\xa3\x00\xf5e\x1d\xd9\x1e\xae>,\xddWV\xbf\x16\xa2%\xf8\xa6\x9b\x89\x07\xf9#\xe3\xcf\xff(O!m\xa8}\xf4\xc5\...(truncated)
    polled = self.poller.poll(timeout * 1000)
#13 Frame 0x1faad00, for file /usr/lib/python2.7/dist-packages/salt/transport/__init__.py, line 243, in crypted_transfer_decode_dictentry (self=<ZeroMQChannel(crypt='aes', master_uri='tcp://10.64.16.160:4506', auth=<SAuth(crypticle=<Crypticle(keys=('G\x97\x03Y\xb5\x06\x8b\x06\xbc\x01\xf0\x9d\xc0%\x81\xf3<\xc8M\x1c\xc3+\xa2I', 'C\x8a<\xa8\x07$C\\\xd1Z-\xa6\x81\x80Y!C5\xf0Q\xba%\x0f6@[-\xf0NJ\xa7J'), serial=<Serial(serial='msgpack') at remote 0x7f564ae8bd10>, key_size=192) at remote 0x7f564b1c7710>, pub_path='/etc/salt/pki/minion/minion.pub', rsa_path='/etc/salt/pki/minion/minion.pem', token='v2ADQu0t6YIum0DjLsaSpsIo+DxquzgkM1gVUanvRtsS+6f9Hb9C44Cf7lAx7rSDja+l19gggrE=', mpub='minion_master.pub', serial=<Serial(serial='msgpack') at remote 0x7f564ad224d0>, opts={'ioflo_realtime': True, 'master_alive_interval': 0, 'recon_default': 1000, 'master_port': '4506', 'whitelist_modules': [], 'ioflo_console_logdir': '', 'utils_dirs': ['/var/cache/salt/minion/extmods/utils'], 'states_dirs': [], 'pillar': {'repo_config': {'schol...(truncated)
    ret = self.sreq.send('aes', self.auth.crypticle.dumps(load), tries, timeout)
#17 Frame 0x7f5652aaea28, for file /usr/lib/python2.7/dist-packages/salt/pillar/__init__.py, line 91, in compile_pillar (self=<RemotePillar(id_='wtp1003.eqiad.wmnet', grains={'biosversion': '1.4.6', 'kernel': 'Linux', 'domain': 'eqiad.wmnet', 'zmqversion': '4.0.4', 'kernelrelease': '3.13.0-39-generic', 'pythonpath': ['/usr/bin', '/usr/lib/python2.7', '/usr/lib/python2.7/plat-x86_64-linux-gnu', '/usr/lib/python2.7/lib-tk', '/usr/lib/python2.7/lib-old', '/usr/lib/python2.7/lib-dynload', '/usr/local/lib/python2.7/dist-packages', '/usr/lib/python2.7/dist-packages', '/usr/lib/pymodules/python2.7'], 'serialnumber': '86046X1', 'site': 'eqiad', 'ip_interfaces': {'lo': ['127.0.0.1', '10.2.2.28'], 'eth1': [], 'eth0': ['10.64.32.74']}, 'cluster': 'parsoid', 'fqdn_ip6': [], 'mem_total': 32096, 'saltversioninfo': (2014, 7, 5, 0), 'SSDs': [], 'id': 'wtp1003.eqiad.wmnet', 'osrelease': '14.04', 'ps': 'ps -efHww', 'locale_info': {'defaultlanguage': None, 'defaultencoding': None}, 'realm': 'production', 'lsb_distrib_description': ...(truncated)
    ret_pillar = self.sreq.crypted_transfer_decode_dictentry(load, dictkey='pillar', tries=3, timeout=7200)
#20 Frame 0x2108af0, for file /usr/lib/python2.7/dist-packages/salt/minion.py, line 1418, in pillar_refresh (self=<Minion(_running=True, hexid='c55f1641ac7fab6574b3c80f7f9cf6de319cbace', serial=<Serial(serial='msgpack') at remote 0x7f5652ad77d0>, poller=<Poller(sockets=[(<Socket at remote 0x7f5652a7b808>, 1), (<Socket at remote 0x7f5652a7b7a0>, 1)], _map={<...>: 0, <...>: 1}) at remote 0x7f564acdc710>, win_proc=[], functions=<OrderedDict(_OrderedDict__root=[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[...(truncated)
    self.opts['environment'],
#24 Frame 0x20d9050, for file /usr/lib/python2.7/dist-packages/salt/minion.py, line 1617, in tune_in (self=<Minion(_running=True, hexid='c55f1641ac7fab6574b3c80f7f9cf6de319cbace', serial=<Serial(serial='msgpack') at remote 0x7f5652ad77d0>, poller=<Poller(sockets=[(<Socket at remote 0x7f5652a7b808>, 1), (<Socket at remote 0x7f5652a7b7a0>, 1)], _map={<...>: 0, <...>: 1}) at remote 0x7f564acdc710>, win_proc=[], functions=<OrderedDict(_OrderedDict__root=[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[...(truncated)
    self.pillar_refresh()
#28 Frame 0x7f5652b0e620, for file /usr/lib/python2.7/dist-packages/salt/__init__.py, line 264, in start (self=<Minion(logging_options_group=<OptionGroup(_lon---Type <return> to continue, or q <return> to quit--- 
g_opt={'--versions-report': <Option(_long_opts=['--versions-report'], help="show program's dependencies version number and exit", callback_args=None, callback=None, default=('NO', 'DEFAULT'), nargs=None, choices=None, dest='versions_report', container=<...>, _short_opts=[], action='store_true', const=None, callback_kwargs=None, type=None, metavar=None) at remote 0x7f5652ad9248>, '--pid-file': <Option(_long_opts=['--pid-file'], help='Specify the location of the pidfile. Default: %default', callback_args=None, callback=None, default='/var/run/salt-minion.pid', nargs=1, choices=None, dest='pidfile', container=<...>, _short_opts=[], action='store', const=None, callback_kwargs=None, type='string', metavar=None) at remote 0x7f5652ad9b48>, '--config-dir': <Option(_long_opts=['--config-dir'], help='Pass in an alternative configuration directory. Default: %default', ...(truncated)
    self.minion.tune_in()
#31 Frame 0x7f5652bb5050, for file /usr/lib/python2.7/dist-packages/salt/scripts.py, line 57, in salt_minion (minion=<Minion(logging_options_group=<OptionGroup(_long_opt={'--versions-report': <Option(_long_opts=['--versions-report'], help="show program's dependencies version number and exit", callback_args=None, callback=None, default=('NO', 'DEFAULT'), nargs=None, choices=None, dest='versions_report', container=<...>, _short_opts=[], action='store_true', const=None, callback_kwargs=None, type=None, metavar=None) at remote 0x7f5652ad9248>, '--pid-file': <Option(_long_opts=['--pid-file'], help='Specify the location of the pidfile. Default: %default', callback_args=None, callback=None, default='/var/run/salt-minion.pid', nargs=1, choices=None, dest='pidfile', container=<...>, _short_opts=[], action='store', const=None, callback_kwargs=None, type='string', metavar=None) at remote 0x7f5652ad9b48>, '--config-dir': <Option(_long_opts=['--config-dir'], help='Pass in an alternative configuration directory. Default: %defa...(truncated)
    minion.start()
#35 Frame 0x7f565a145c20, for file /usr/bin/salt-minion, line 14, in <module> ()
    salt_minion()

This indeed points out to zmq_poll having blocked and not returning

interestingly all but one of those in the list (mc1002) were responsive a little after 9 am (utc I guess) today.

Our version of salt has (just barely) tcp keepalive for the sub and pub sockets on the minions. (ZMQ 4.0.4) see http://salt.readthedocs.org/en/latest/ref/configuration/examples.html and check the tcp keepalive stuff. This means in theory that we should see periodic packets going out, and then reconnection attempts on failure. Why don't we, I wonder?

Another few interesting points.

On 9:45 UTC I 've restarted the salt-master. The timing seems to fit.
Also those boxes have firewall via ferm, albeit these are not the only ones. For example etherpad1001.eqiad.wmnet has ferm as well but is not misbehaving. But it could be a contributing factor.
Also most inspected boxes do not have the TCP port 4506 connection to the salt master, while having the TCP port 4505 one

ping_interval set on the minions might be good for this, if it's connected to the salt-master restart, which I really think is the case.

Yes let's try that. I 've also done a last test also conducted by @BBlack. tcpdump on the master. It was never sending anything to a specific minion while doing some sort of keepalives (encrypted traffic) with fine working minions. I observed that finally many salt minions came back online on their own. In the interest of not blocking parsoid deploys, I restarted salt minion on all boxes.

https://gerrit.wikimedia.org/r/#/c/219134/

@ArielGlenn what's left to do here? still prio high?

Restricted Application added a subscriber: Matanya. · View Herald TranscriptJul 21 2015, 1:23 PM

@ArielGlenn what's the status?

ArielGlenn claimed this task.Sep 2 2015, 7:25 PM

ArielGlenn added a project: Salt.

ArielGlenn moved this task from Backlog to Up Next on the Salt board.Sep 14 2015, 1:08 PM

I will be looking into this again this week.

checked with several runs with delay between them, the only two hosts which fail to respond are down or ssh in fails, e.g.:

root@palladium:~# date; salt -b5% --out raw '*' test.ping |egrep -v 'Executing run on |True' | sort -u
Wed Sep 16 11:55:59 UTC 2015

{'etcd1003.eqiad.wmnet': {}}
{'mendelevium.eqiad.wmnet': {}}
root@palladium:~# date; salt -b5% --out raw '*' test.ping |egrep -v 'Executing run on |True' | sort -u
Wed Sep 16 14:32:49 UTC 2015

{'etcd1003.eqiad.wmnet': {}}
{'mendelevium.eqiad.wmnet': {}}

so calling this good. and closing.

ArielGlenn moved this task from Up Next to Done on the Salt board.Sep 28 2015, 8:40 PM

various salt-minions are not replying to test.ping or commandsClosed, ResolvedPublicActions

Description

Event Timeline

various salt-minions are not replying to test.ping or commands
Closed, ResolvedPublic
Actions