#8689 Badges (tahrir) is currently broken
Closed: Fixed by kevin. Opened by smooge.

Describe what you would like us to do:

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

  1. Turn off badges until someone can fix it and patch out all the areas where badges is called.
  2. while 1 restart badges until that no longer works (probably next month).
  3. find a group of people who can move badges to a different toolkit or place.

When do you need this to be done by? (YYYY/MM/DD)



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.

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)

Metadata