Bug 45676 - UMC-Server crashes with "KeyError: appcenter"
UMC-Server crashes with "KeyError: appcenter"
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: UMC (Generic)
UCS 4.2
Other Linux
: P5 normal (vote)
: UCS 4.2-2-errata
Assigned To: Florian Best
Richard Ulmer
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2017-11-09 10:35 CET by Florian Best
Modified: 2017-11-15 17:13 CET (History)
0 users

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 7: Crash: Bug causes crash or data loss
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 3: A User would likely not purchase the product
User Pain: 0.240
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional): Error handling
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Florian Best univentionstaff 2017-11-09 10:35:16 CET
The current jenkins selenium tests revealed a UMC-Server crash:

08.11.17 23:51:42.789  MAIN        ( PROCESS ) : Connection timed out.
08.11.17 23:51:42.789  MAIN        ( PROCESS ) : Processor: dying
08.11.17 23:51:42.789  MAIN        ( PROCESS ) : Processor: dying
08.11.17 23:51:43.094  MAIN        ( PROCESS ) : running: ['/usr/sbin/univention-management-console-module', '-m', 'join', '-s', '/var/run/univention-management-console/4059-1510203103094.socket', '-d', '2', '-l', 'en_US.UTF-8']
08.11.17 23:51:43.143  MAIN        ( PROCESS ) : running: ['/usr/sbin/univention-management-console-module', '-m', 'appcenter', '-s', '/var/run/univention-management-console/4059-1510203103143.socket', '-d', '2', '-l', 'en_US.UTF-8']
08.11.17 23:51:43.216  MAIN        ( PROCESS ) : running: ['/usr/sbin/univention-management-console-module', '-m', 'updater', '-s', '/var/run/univention-management-console/4059-1510203103215.socket', '-d', '2', '-l', 'en_US.UTF-8']
08.11.17 23:51:43.830  MAIN        ( PROCESS ) : Connection timed out.
08.11.17 23:51:46.039  MAIN        ( WARN    ) : Socket died (module=join)
08.11.17 23:51:46.039  MAIN        ( WARN    ) : Module process join died (pid: 4218, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.039  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.039  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.051  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.051  MAIN        ( WARN    ) : Module process join died (pid: 4218, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.054  MAIN        ( WARN    ) : Socket died (module=join)
08.11.17 23:51:46.054  MAIN        ( WARN    ) : Module process join died (pid: 4681, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.054  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.054  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.070  MAIN        ( WARN    ) : Socket died (module=updater)
08.11.17 23:51:46.070  MAIN        ( WARN    ) : Module process updater died (pid: 4683, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.070  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.070  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.070  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.070  MAIN        ( WARN    ) : Module process join died (pid: 4681, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.074  MAIN        ( WARN    ) : Socket died (module=ucr)
08.11.17 23:51:46.074  MAIN        ( WARN    ) : Module process ucr died (pid: 4921, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.074  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.074  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.074  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.074  MAIN        ( WARN    ) : Module process updater died (pid: 4683, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.078  MAIN        ( WARN    ) : Socket died (module=join)
08.11.17 23:51:46.078  MAIN        ( WARN    ) : Module process join died (pid: 5128, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.078  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.078  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.078  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.078  MAIN        ( WARN    ) : Module process ucr died (pid: 4921, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.091  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.091  MAIN        ( WARN    ) : Module process join died (pid: 5128, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.095  MAIN        ( WARN    ) : Socket died (module=appcenter)
08.11.17 23:51:46.095  MAIN        ( WARN    ) : Module process appcenter died (pid: 5129, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.095  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.095  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.099  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.099  MAIN        ( WARN    ) : Module process appcenter died (pid: 5129, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.099  MAIN        ( WARN    ) : Socket died (module=updater)
08.11.17 23:51:46.099  MAIN        ( WARN    ) : Module process updater died (pid: 5130, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.099  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.099  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.110  MAIN        ( WARN    ) : Socket died (module=join)
08.11.17 23:51:46.110  MAIN        ( WARN    ) : Module process join died (pid: 5261, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.110  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.110  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.114  MAIN        ( WARN    ) : Socket died (module=updater)
08.11.17 23:51:46.114  MAIN        ( WARN    ) : Module process updater died (pid: 5263, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.114  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.114  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.114  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.114  MAIN        ( WARN    ) : Module process join died (pid: 5261, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.130  MAIN        ( WARN    ) : Socket died (module=updater)
08.11.17 23:51:46.130  MAIN        ( WARN    ) : Module process updater died (pid: 5406, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.130  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.130  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.130  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.130  MAIN        ( WARN    ) : Module process updater died (pid: 5263, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.131  MAIN        ( WARN    ) : Socket died (module=join)
08.11.17 23:51:46.131  MAIN        ( WARN    ) : Module process join died (pid: 5404, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.131  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.131  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.131  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.131  MAIN        ( WARN    ) : Module process updater died (pid: 5406, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.148  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.148  MAIN        ( WARN    ) : Module process join died (pid: 5404, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Socket died (module=appcenter)
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Module process appcenter died (pid: 4682, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Socket died (module=updater)
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Module process updater died (pid: 4219, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.152  MAIN        ( WARN    ) : Remove inactivity timer
08.11.17 23:51:46.188  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.188  MAIN        ( WARN    ) : Module process updater died (pid: 4219, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.188  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.188  MAIN        ( WARN    ) : Module process appcenter died (pid: 4682, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.188  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.189  MAIN        ( WARN    ) : Module process updater died (pid: 5130, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.189  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.189  MAIN        ( WARN    ) : Module process join died (pid: 5533, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.189  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.189  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.189  MAIN        ( WARN    ) : Module process updater died (pid: 5535, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.189  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.205  MAIN        ( PROCESS ) : ModuleProcess: child died
08.11.17 23:51:46.205  MAIN        ( WARN    ) : Module process appcenter died (pid: 5534, exit status: -1, signal: 9, status: 9)
08.11.17 23:51:46.205  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:46.221  MAIN        ( PROCESS ) : Connection timed out.
08.11.17 23:51:46.796  MAIN        ( PROCESS ) : Connection timed out.
08.11.17 23:51:46.796  MAIN        ( PROCESS ) : Processor: dying
08.11.17 23:51:46.796  MAIN        ( PROCESS ) : Connection timed out.
08.11.17 23:51:46.796  MAIN        ( PROCESS ) : Processor: dying
08.11.17 23:51:50.002  MAIN        ( PROCESS ) : running: ['/usr/sbin/univention-management-console-module', '-m', 'join', '-s', '/var/run/univention-management-console/4059-1510203110002.socket', '-d', '2', '-l', 'en_US.UTF-8']
08.11.17 23:51:50.120  MAIN        ( PROCESS ) : running: ['/usr/sbin/univention-management-console-module', '-m', 'appcenter', '-s', '/var/run/univention-management-console/4059-1510203110120.socket', '-d', '2', '-l', 'en_US.UTF-8']
08.11.17 23:51:50.169  MAIN        ( PROCESS ) : running: ['/usr/sbin/univention-management-console-module', '-m', 'updater', '-s', '/var/run/univention-management-console/4059-1510203110169.socket', '-d', '2', '-l', 'en_US.UTF-8']
08.11.17 23:51:53.349  MAIN        ( PROCESS ) : ModuleProcess: dying
08.11.17 23:51:53.349  MAIN        ( WARN    ) : Socket died (module=appcenter)
08.11.17 23:51:53.349  MAIN        ( WARN    ) : Module process appcenter died (pid: 5548, exit status: -1, signal: -1, status: -1)
08.11.17 23:51:53.349  MAIN        ( WARN    ) : Cleaning up requests
08.11.17 23:51:53.349  MAIN        ( PROCESS ) : ModuleProcess: child stopped
08.11.17 23:51:53.377  MAIN        ( ERROR   ) : Traceback (most recent call last):
  File "/usr/sbin/univention-management-console-server", line 243, in <module>
    umc_daemon.do_action()
  File "/usr/lib/pymodules/python2.7/daemon/runner.py", line 186, in do_action
    func(self)
  File "/usr/lib/pymodules/python2.7/daemon/runner.py", line 131, in _start
    self.app.run()
  File "/usr/sbin/univention-management-console-server", line 210, in run
    notifier.loop()
  File "/usr/lib/pymodules/python2.7/notifier/nf_generic.py", line 286, in loop
    step()
  File "/usr/lib/pymodules/python2.7/notifier/nf_generic.py", line 242, in step
    if not timer[ CALLBACK ]():
  File "/usr/lib/pymodules/python2.7/notifier/__init__.py", line 104, in __call__
    return self._function( *tmp, **self._kwargs )
  File "/usr/lib/pymodules/python2.7/univention/management/console/protocol/session.py", line 544, in _mod_connect
    _send_error()
  File "/usr/lib/pymodules/python2.7/univention/management/console/protocol/session.py", line 537, in _send_error
    del self.__processes[mod.name]
KeyError: 'appcenter'

The appcenter log contains only:
08.11.17 23:50:39.944  DEBUG_INIT
08.11.17 23:50:46.773  MODULE      ( PROCESS ) : Loading python module.
08.11.17 23:50:47.788  MODULE      ( PROCESS ) : Imported python module.
08.11.17 23:50:47.788  MODULE      ( PROCESS ) : Module instance created.
08.11.17 23:50:47.789  MODULE      ( PROCESS ) : Module socket initialized.
08.11.17 23:50:47.801  MODULE      ( PROCESS ) : Setting user LDAP DN 'uid=Administrator,cn=users,dc=autotest095,dc=local'
08.11.17 23:50:47.801  MODULE      ( PROCESS ) : Setting auth type to None
08.11.17 23:50:47.801  MODULE      ( PROCESS ) : Initializing module.
08.11.17 23:51:02.192  DEBUG_INIT
08.11.17 23:51:10.230  MODULE      ( PROCESS ) : Loading python module.
08.11.17 23:51:24.992  DEBUG_INIT
08.11.17 23:51:33.155  MODULE      ( PROCESS ) : Loading python module.
08.11.17 23:51:44.743  DEBUG_INIT
08.11.17 23:51:51.752  DEBUG_INIT
08.11.17 23:51:57.543  MODULE      ( PROCESS ) : Loading python module.
08.11.17 23:51:58.361  MODULE      ( PROCESS ) : Imported python module.
08.11.17 23:51:58.371  MODULE      ( PROCESS ) : Module instance created.
08.11.17 23:51:58.372  MODULE      ( PROCESS ) : Module socket initialized.
08.11.17 23:52:26.594  MAIN        ( WARN    ) : Shutting down all open connections
Comment 1 Florian Best univentionstaff 2017-11-09 10:43:43 CET
The code block is the following:
 535 »   »   »   if mod.name in self.__processes:
 536 »   »   »   »   self.__processes[mod.name].__del__()
 537 »   »   »   »   del self.__processes[mod.name]
→ So it must be a concurrency / threading issue.
Comment 2 Florian Best univentionstaff 2017-11-09 10:52:05 CET
The code is during handling an error if the connection to a module process can't be established in 10 seconds. This only happens during high load.

univention-management-console.yaml
51876d73f902 | Bug #45676: Merge branch 'fbest/45676-umc-server-crash-theading' into 4.2-2
2ae5b572ec2b | YAML Bug #45676

univention-management-console (9.0.80-80)
51876d73f902 | Bug #45676: Merge branch 'fbest/45676-umc-server-crash-theading' into 4.2-2
616037600da4 | Bug #45676: fix a UMC-Server crash caused by a threading issue during
Comment 3 Florian Best univentionstaff 2017-11-10 14:26:09 CET
This seems working and caused no other crash in another thread.
Comment 4 Richard Ulmer univentionstaff 2017-11-15 14:44:19 CET
The problem is gone and the code looks reasonable. -> Verified
Comment 5 Arvid Requate univentionstaff 2017-11-15 17:13:09 CET
<http://errata.software-univention.de/ucs/4.2/221.html>