badges-web01/02 is constantly timing out and crashing. While restarting seemed to help get things working, the time between needing to restarts have come down to about 3-5 minutes.
At this point we do not have any resources to fix this for the forseeable future. We can
A little bit of data from nagios from 02-18-2020 15:13:27 to 02-25-2020 15:13:27 (7days):
http-badges.fedoraproject.org-tahrir on badges-web01.phx2.fedoraproject.org : 29 CRITICAL Alerts http-badges.fedoraproject.org-tahrir on badges-web02.phx2.fedoraproject.org : 55 CRITICAL Alerts
Metadata Update from @smooge: - Issue priority set to: Waiting on External (was: Needs Review)
@smooge @cverna Is it possible to get some of the alert / log data into this ticket? A link to this ticket was passed to #fedora-badges and we're evaluating options from a community point-of-view. But not all of us have access to view the logs / errors.
#fedora-badges
We're looking for a stop-gap solution while we are getting together a long-term plan beginning with an Outreachy intern this summer (see mentored-projects#74).
@jflory7 you can see the nagios alerts here --> https://nagios.fedoraproject.org/nagios/
If you look under "Current Status" --> "Problems" --> "Services" you will see the alerts for badges.
To look at historical data you have the "Reports" --> "Alerts" --> "Summary" menu.
To access the logs on the server you need a member of the sysadmin-badges group, I think we can sponsor you if you need.
I am taking a look at the logs
So, if the issue is 100% CPU usage, the culprit is _make_leaderboard. It is called twice on index, the comments say the function is expensive.
I would suggest to use a cache on the result of _make_leaderboard (like make it 2 functions, add the decorator), we are already using dogpile, and I do not think we need to update the leaderboard more often than every 5 minutes.
The service was blocked this morning. I did a quick debugging and then restarted it, and it seems to be caused by a memcached lock (given the gdb backtrace).
I pushed a change adding a dogpile memcached backend timeout on https://infrastructure.fedoraproject.org/cgit/ansible.git/commit/?id=f560e5b74ff103dd3672176d03e9bbb9a3ae1e6f
Given the cache is used only for make_avatar_method (and to be fair, I do not even see why), I think it is safe to have it set at 5 seconds. let's wait a bit to see if this did fix and/or reduce the problems.
So this didn't reduce the problem, but since the cache is almost unused and after discussing on Telegram, I pushed a commit that set it to null. It is easier than chang the code and deploy it, it didn't had any adverse effect when I tried.
Still unclear why the previous fix didn't work.
Also, for reference:
(gdb) py-bt #4 Frame 0x7fb49d510238, for file /usr/lib/python2.7/site-packages/dogpile/cache/backends/memcached.py, line 42, in acquire (self=<MemcachedLock(timeout=0, client_fn=<function at remote 0x7fb49d6c0d70>, key='_lo ck9a487532bfdbcc5a2ed458948be9da8999215668') at remote 0x7fb4964f9650>, wait=True, client=<Client at remote 0x7fb49d8ef7a0>, i=15, sleep_time=<float at remote 0x7fb4a80233f0>) time.sleep(sleep_time) #8 Frame 0x7fb49d78aa00, for file /usr/lib/python2.7/site-packages/dogpile/core/dogpile.py, line 128, in _enter_create (self=<Lock(expiretime=100, async_creator=None, value_and_created_fn=<function at remote 0x7fb49d6c0cf8>, mutex=<MemcachedLock(timeout=0, client_fn=<function at remote 0x7fb49d6c0d70>, key='_lock9a487532bfdbcc5a2ed458948be9da8999215668') at remote 0x7fb4964f9650>, creator=<function at remote 0x7fb49d6c0410>) at remote 0x7fb4964f9710>, createdtime=-1, async=False) self.mutex.acquire() #11 Frame 0x7fb49d517430, for file /usr/lib/python2.7/site-packages/dogpile/core/dogpile.py, line 98, in _enter (self=<Lock(expiretime=100, async_creator=None, value_and_created_fn=<function at remote 0x7fb49d6c0cf8>, mutex=<MemcachedLock(timeout=0, client_fn=<function at remote 0x7fb49d6c0d70>, key='_lock9a487532bfdbcc5a2ed458948be9da8999215668') at remote 0x7fb4964f9650>, creator=<function at remote 0x7fb49d6c0410>) at remote 0x7fb4964f9710>, value_fn=<function at remote 0x7fb49d6c0cf8>, value=<object at remote 0x7fb4cc0e7280>, createdtime=-1) generated = self._enter_create(createdtime) #14 Frame 0x7fb49da7d3b0, for file /usr/lib/python2.7/site-packages/dogpile/core/dogpile.py, line 158, in __enter__ (self=<Lock(expiretime=100, async_creator=None, value_and_created_fn=<function at remote 0x7fb49d6c0cf8>, mutex=<MemcachedLock(timeout=0, client_fn=<function at remote 0x7fb49d6c0d70>, key='_lock9a487532bfdbcc5a2ed458948be9da8999215668') at remote 0x7fb4964f9650>, creator=<function at remote 0x7fb49d6c0410>) at remote 0x7fb4964f9710>) return self._enter() #21 Frame 0x7fb4a818e2e0, for file /usr/lib/python2.7/site-packages/dogpile/cache/region.py, line 657, in get_or_create (self=<CacheRegion(async_creation_runner=None, name=None, _hard_invalidated=None, _lock_registry=<NameRegistry(_mutex=<_RLock(_Verbose__verbose=False, _RLock__owner=None, _RLock__block=<thread.lock at remote 0x7fb4a2ddafd0>, _RLock__count=0) at remote 0x7fb4ac2e19d0>, _values=<WeakValueDictionary(_remove=<function at remote 0x7fb4ac3505f0>, data={'9a487532bfdbcc5a2ed458948be9da8999215668': <KeyedRef at remote 0x7fb49c7277d0>}) at remote 0x7fb4a7cd66c8>, creator=<instancemethod at remote 0x7fb4a113a690>) at remote 0x7fb4ac2e1950>, _soft_invalidated=None, function_multi_key_generator=<function at remote 0x7fb4a7a418c0>, function_key_generator=<function at remote 0x7fb4a7a416e0>, key_mangler=<function at remote 0x7fb4a7a41938>, expiration_time=100, _user_defined_key_mangler=<function at remote 0x7fb4a7a41938>, backend=<MemcachedBackend(distributed_lock=True, lock_timeout=0, memcached_expire_time=0,...(truncated) async_creator) as value: #25 Frame 0x7fb4a8181d50, for file /usr/lib/python2.7/site-packages/dogpile/cache/region.py, line 1053, in decorate (arg=('http://okozina.id.fedoraproject.org/', 64), kw={}, key='tahrir.utils:_avatar_function|http://okozina.id.fedoraproject.org/ 64', creator=<function at remote 0x7fb49d6c0758>, timeout=None) should_cache_fn) #29 Frame 0x7fb49d78ed38, for file /usr/lib/python2.7/site-packages/tahrir/utils.py, line 135, in avatar_method (self=<Person(website=None, bio=None, _sa_instance_state=<InstanceState(obj=<weakref at remote 0x7fb496b33260>, _strong_obj=None, callables={}, session_id=1, committed_state={}, class_=<DeclarativeMeta(website=<InstrumentedAttribute(comparator=<Comparator(_adapt_to_entity=None, property=<ColumnProperty(key='website', _configure_started=True, expire_on_flush=True, group=None, _is_polymorphic_discriminator=False, extension=None, instrument=True, _orig_columns=[<Column(_label=<_truncated_label(quote=None, lower=<function at remote 0x7fb49d795de8>) at remote 0x7fb49d7500b0>, key='website', dispatch=<DDLEventsDispatch(_parent_cls=<VisitableType(__module__='sqlalchemy.sql.schema', _make_proxy=<function at remote 0x7fb4a4ece938>, __visit_name__='column', _compiler_dispatch=<function at remote 0x7fb4a4ece500>, __str__=<function at remote 0x7fb4a4ece5f0>, _on_table_attach=<function at remote 0x7fb4a4ece848>, get...(truncated) return _avatar_function(ident, size) #33 Frame 0x7fb4a8012f10, for file functions_mak, line 177, in render_avatar_thumbnail (context=<Context(_outputting_as_unicode=True, _buffer_stack=[<FastEncodingBuffer(as_unicode=True, errors='strict', encoding=None, delim=u'', write=<built-in method append of collections.deque object at remote 0x7fb49d908fa0>, data=<collections.deque at remote 0x7fb49d908fa0>) at remote 0x7fb48df08ad0>], namespaces={('master_mak', u'functions'): <TemplateNamespace(inherits=None, _templateuri=u'functions.mak', avatar_thumbnail=<functools.partial at remote 0x7fb496ace368>, context=<...>, template=<Template(imports=None, module=<module at remote 0x7fb49d793788>, error_handler=None, module_id=u'functions_mak', enable_loop=True, cache_args={}, _source=None, strict_undefined=False, filename=u'/usr/lib/python2.7/site-packages/tahrir/templates/functions.mak', _code=u"from mako import runtime, filters, cache\nUNDEFINED = runtime.UNDEFINED\n__M_dict_builtin = dict\n__M_locals_builtin = locals\n_magic_number = 8\n_modified_time = 15827956...(truncated)
That's the backtrace I got with gdb ( https://wiki.python.org/moin/DebuggingWithGdb ) on badges01.
So, this seems to have fixed it up. Thanks a bunch @misc !
Metadata Update from @kevin: - Issue close_status updated to: Fixed - Issue status updated to: Closed (was: Open)