Bug 52535 - UMC internal server error (nf_generic.py line 175, in timer_remove, del __timers[id])
UMC internal server error (nf_generic.py line 175, in timer_remove, del __tim...
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: UMC (Generic)
UCS 4.4
Other Linux
: P5 normal (vote)
: UCS 4.4-7-errata
Assigned To: Florian Best
Dirk Wiesenthal
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2020-12-22 17:07 CET by Felix Botner
Modified: 2021-02-10 17:26 CET (History)
6 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 5: Major Usability: Impairs usability in key scenarios
Who will be affected by this bug?: 3: Will affect average number of installed domains
How will those affected feel about the bug?: 3: A User would likely not purchase the product
User Pain: 0.257
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number: 2020122121000549, 2021011121000676, 2021010321000575, 2020123021000835, 2020122921000301, 2020122421000061, 2020122121000674, 2021010621000168, 2020121721000361, 2020121921000277, 2021010721000184, 2021012321000573, 2021012121000442, 2021012121000399
Bug group (optional): External feedback, Regression
Max CVSS v3 score:


Attachments
patch? / hotfix (813 bytes, patch)
2021-02-03 19:00 CET, Florian Best
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Felix Botner univentionstaff 2020-12-22 17:07:59 CET
univention-management-console:
  Installiert:           11.0.6-3A~4.4.0.202012161931
  Installationskandidat: 11.0.6-3A~4.4.0.202012161931
  Versionstabelle:
 *** 11.0.6-3A~4.4.0.202012161931 500
        500 .../4.4/maintained/component 4.4-7-errata/all/ Packages


Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/cherrypy/_cprequest.py", line 670, in respond
    response.body = self.handler()
  File "/usr/lib/python2.7/dist-packages/cherrypy/lib/encoding.py", line 217, in __call__
    self.body = self.oldhandler(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/cherrypy/_cpdispatch.py", line 61, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/usr/sbin/univention-management-console-web-server", line 777, in default
    return self.get_response(self.create_sessionid(), path, self.get_arguments(kwargs))
  File "/usr/sbin/univention-management-console-web-server", line 934, in get_response
    response = super(CPCommand, self).get_response(sessionid, path, args)
  File "/usr/sbin/univention-management-console-web-server", line 817, in get_response
    response = self.make_queue_request(sessionid, req)
  File "/usr/sbin/univention-management-console-web-server", line 836, in make_queue_request
    user.reset_timeout()
  File "/usr/sbin/univention-management-console-web-server", line 390, in reset_timeout
    self.disconnect_timer()
  File "/usr/sbin/univention-management-console-web-server", line 395, in disconnect_timer
    notifier.timer_remove(self._timeout_id)
  File "/usr/lib/python2.7/dist-packages/notifier/nf_generic.py", line 175, in timer_remove
    del __timers[id]
KeyError: 85906

I get this fairly often lately on our internal uvmm server. The UMC/SAML session seems to survive this, after a browser reload everything looks fine (i'm still logged in).
Comment 2 Florian Best univentionstaff 2021-01-05 14:02:09 CET
Maybe occurs when multiple similar requests in different threads try to remove the same timer?
Caused by Bug #52273.
Comment 3 Christian Castens univentionstaff 2021-01-05 15:19:17 CET
reported again:

Version: 4.4-7 errata850 (Blumenthal)

Remark: Fehler trat beim Versuch auf, die Systemdiagnose zu öffnen

Error:
Traceback (most recent call last):
  File "%PY2.7%/cherrypy/_cprequest.py", line 670, in respond
    response.body = self.handler()
  File "%PY2.7%/cherrypy/lib/encoding.py", line 217, in __call__
    self.body = self.oldhandler(*args, **kwargs)
  File "%PY2.7%/cherrypy/_cpdispatch.py", line 61, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/usr/sbin/univention-management-console-web-server", line 777, in default
    return self.get_response(self.create_sessionid(), path, self.get_arguments(kwargs))
  File "/usr/sbin/univention-management-console-web-server", line 934, in get_response
    response = super(CPCommand, self).get_response(sessionid, path, args)
  File "/usr/sbin/univention-management-console-web-server", line 817, in get_response
    response = self.make_queue_request(sessionid, req)
  File "/usr/sbin/univention-management-console-web-server", line 836, in make_queue_request
    user.reset_timeout()
  File "/usr/sbin/univention-management-console-web-server", line 390, in reset_timeout
    self.disconnect_timer()
  File "/usr/sbin/univention-management-console-web-server", line 395, in disconnect_timer
    notifier.timer_remove(self._timeout_id)
  File "%PY2.7%/notifier/nf_generic.py", line 175, in timer_remove
    del __timers[id]
KeyError: 74


Role: domaincontroller_master
Comment 4 Christian Castens univentionstaff 2021-01-06 15:07:31 CET
Version: 4.4-7 errata849 (Blumenthal) - UCS@school 4.4 v8
Remark: nach Aufruf der Richtlinien DNS Management-Console
Role: domaincontroller_master
Comment 6 Riya Bhattacharjee univentionstaff 2021-01-12 11:06:37 CET
Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/cherrypy/_cprequest.py", line 670, in respond
response.body = self.handler()
File "/usr/lib/python2.7/dist-packages/cherrypy/lib/encoding.py", line 217, in __call__
self.body = self.oldhandler(*args, **kwargs)
File "/usr/lib/python2.7/dist-packages/cherrypy/_cpdispatch.py", line 61, in __call__
return self.callable(*self.args, **self.kwargs)
File "/usr/sbin/univention-management-console-web-server", line 777, in default
return self.get_response(self.create_sessionid(), path, self.get_arguments(kwargs))
File "/usr/sbin/univention-management-console-web-server", line 934, in get_response
response = super(CPCommand, self).get_response(sessionid, path, args)
File "/usr/sbin/univention-management-console-web-server", line 817, in get_response
response = self.make_queue_request(sessionid, req)
File "/usr/sbin/univention-management-console-web-server", line 836, in make_queue_request
user.reset_timeout()
File "/usr/sbin/univention-management-console-web-server", line 390, in reset_timeout
self.disconnect_timer()
File "/usr/sbin/univention-management-console-web-server", line 395, in disconnect_timer
notifier.timer_remove(self._timeout_id)
File "/usr/lib/python2.7/dist-packages/notifier/nf_generic.py", line 175, in timer_remove
del __timers[id]
KeyError: 218

Traceback (most recent call last):
Comment 7 Riya Bhattacharjee univentionstaff 2021-01-12 15:05:04 CET
UCS Version: 4.4-7 errata850 (Blumenthal)

Traceback (most recent call last):670, in respond
  File "/usr/lib/python2.7/dist-packages/cherrypy/_cprequest.py", line
    response.body = self.handler()
217, in __call__
  File "/usr/lib/python2.7/dist-packages/cherrypy/lib/encoding.py", line
    self.body = self.oldhandler(*args, **kwargs)
61, in __call__
  File "/usr/lib/python2.7/dist-packages/cherrypy/_cpdispatch.py", line
    return self.callable(*self.args, **self.kwargs)
in default
  File "/usr/sbin/univention-management-console-web-server", line 777,
self.get_arguments(kwargs))
    return self.get_response(self.create_sessionid(), path,
in get_response
  File "/usr/sbin/univention-management-console-web-server", line 934,
    response = super(CPCommand, self).get_response(sessionid, path, args)
in get_response
  File "/usr/sbin/univention-management-console-web-server", line 817,
    response = self.make_queue_request(sessionid, req)
in make_queue_request
  File "/usr/sbin/univention-management-console-web-server", line 836,
    user.reset_timeout()
in reset_timeout
  File "/usr/sbin/univention-management-console-web-server", line 390,
    self.disconnect_timer()
in disconnect_timer
  File "/usr/sbin/univention-management-console-web-server", line 395,
    notifier.timer_remove(self._timeout_id)
175, in timer_remove
  File "/usr/lib/python2.7/dist-packages/notifier/nf_generic.py", line
    del __timers[id]
KeyError: 9813

Traceback (most recent call last):
Comment 8 Ingo Steuwer univentionstaff 2021-01-25 09:10:31 CET
If I understand correctly this is a timing issue that occures if many people using the same UMC, am I right?

I don't think the high values for "who is affected" and "type of bug" are correct, I reduce them slightly.
Comment 9 Florian Best univentionstaff 2021-01-25 13:43:01 CET
(In reply to Ingo Steuwer from comment #8)
> If I understand correctly this is a timing issue that occures if many people
> using the same UMC, am I right?
I don't think it's triggered by multiple persons. It looks for me, it occurs when one session is doing parallel requests very fast (e.g. progress bars) so that 2 threads are conflicting.

> I don't think the high values for "who is affected" and "type of bug" are
> correct, I reduce them slightly.
This is a very very often reported error. I think the user pain very high (>=0.3).
Comment 10 Florian Best univentionstaff 2021-02-03 19:00:05 CET
Created attachment 10611 [details]
patch? / hotfix
Comment 11 Florian Best univentionstaff 2021-02-03 19:01:18 CET
The logfile contains many of the lines:

MAIN        ( WARN    ) : Could not remove SAML session: (-30988, 'BDB0073 DB_NOTFOUND: No matching key/data pair found')
Comment 12 Florian Best univentionstaff 2021-02-09 12:36:43 CET
Fixed in:

univention-management-console.yaml
7b685e2c5966 | Bug #52535: prevent KeyError when session timer has already been removed

univention-management-console (11.0.6-8)
7b685e2c5966 | Bug #52535: prevent KeyError when session timer has already been removed
Comment 13 Dirk Wiesenthal univentionstaff 2021-02-09 20:54:56 CET
YAML: OK
Mask KeyError: OK