52535 – UMC internal server error (nf_generic.py line 175, in timer_remove, del __timers[id])

Bug 52535 - UMC internal server error (nf_generic.py line 175, in timer_remove, del __timers[id])

Summary: UMC internal server error (nf_generic.py line 175, in timer_remove, del __tim...

Status:	CLOSED FIXED

Alias:	None

Product:	UCS
Classification:	Unclassified
Component:	UMC (Generic)
Version:	UCS 4.4
Hardware:	Other Linux

Importance:	P5 normal
Target Milestone:	UCS 4.4-7-errata
Assignee:	Florian Best
QA Contact:	Dirk Wiesenthal

URL:
Keywords:

Depends on:
Blocks:

Reported:	2020-12-22 17:07 CET by Felix Botner
Modified:	2021-02-10 17:26 CET (History)
CC List:	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
Customer ID:
Max CVSS v3 score:

Attachments
patch? / hotfix (813 bytes, patch) 2021-02-03 19:00 CET, Florian Best	Details \| Diff
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Felix Botner

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

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

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

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

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

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

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

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

2021-02-03 19:00:05 CET

Created attachment 10611 [details]
patch? / hotfix

Comment 11 Florian Best

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

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

2021-02-09 20:54:56 CET

YAML: OK
Mask KeyError: OK

Comment 14 Erik Damrose

2021-02-10 17:26:09 CET

<https://errata.software-univention.de/#/?erratum=4.4x893>