Created attachment 4580 [details]
Apache error.log

Die Fehler fingen schon vor der Anmeldung an, in einer laufenden Session reagierte die UMC nicht mehr (z. B. ein Click auf das DNS-Modul zeigte kein Ergebnis).  Anbei das (anonymisierte) Apache error.log.

Comment 2 Alexander Kläser 2012-08-07 16:35:53 CEST

Danke für die Bug-Meldung. Um welche UCS-Version (ucr search --brief '^version/') handelt es sich? 

Es scheint sich um zwei Probleme zu handeln:

* Zum einen das Auslaufen der Session. Dabei könnte es sich um das Verhalten wie es in Bug 28108 beschrieben ist handeln (in meinen Logs bekomme ich diesbzgl. ähnliche Fehler). Passt das dort beschriebene Fehlverhalten auf diesen Fall? Kann man andere Module öffnen (bspw. Config Registry) und nur Domain-Management-Module nicht?

* Zum anderen scheint der UDM-Web-Server bei der Anmeldung nicht mehr erreichbar zu sein. Läuft der UMC-Web-Server in diesem Fall noch (ps afx | grep management-console-web-server)?

Derzeit:

root@vp-s01:/var/log# ucr search --brief '^version/'
version/erratalevel: 106
version/patchlevel: 2
version/releasename: Horn-Lehe
version/security-patchlevel: <empty>
version/version: 3.0

Das war als der Bug auftrat aber noch ein anderes Errata da ich danach sicherheitshalber noch mal Updates eingespielt hatte.  Ich werde aus dem updater.log aber nicht ganz schlau da da scheinbar ein Update von heute morgen (auf 105) fehlt:

----8<----

Starting univention-upgrade. Current UCS version is 3.0-2 errata93

Checking for local repository:                          none
Checking for release updates:                           none
Checking for package updates:                           none
Checking for errata updates:                            found

Starting errata update at Thu Aug  2 10:17:17 2012...
Starting errata update
Update to 3.0 errata94
Update to 3.0 errata95
Update to 3.0 errata96
Update to 3.0 errata97
Update to 3.0 errata98
Update to 3.0 errata99
Update to 3.0 errata100
Update to 3.0 errata101
Errata update finished errata94 at Thu Aug  2 10:18:10 2012...
Checking for release updates:                           none
Checking for package updates:                           none
Checking for errata updates:                            none

...

Starting univention-upgrade. Current UCS version is 3.0-2 errata105

Checking for local repository:                          none
Checking for release updates:                           none
Checking for package updates:                           none
Checking for errata updates:                            found

Starting errata update at Tue Aug  7 16:00:03 2012...
Starting errata update
Update to 3.0 errata106
Errata update finished errata106 at Tue Aug  7 16:00:20 2012...
Checking for release updates:                           none
Checking for package updates:                           none
Checking for errata updates:                            none
----8<----


Ich muss das mal beobachten.   Waren die Patches aus Bug 28108 im errata106?  (Passt von der Zeit ungefähr.)


Ob der Dienst noch lief weiß ich gerade nicht, werde ich beim nächsten Auftreten überprüfen.

Mögliche Fehlerquellen sind evtl. der UVMM da ich dafür merkwürdige Meldungen im Log habe und meiner Meinung nach kurz zuvor immer damit gearbeitet habe (aber ich mache da gerade viel mit, das kann also auch Zufall sein):

----8<----
management-console-server.log:07.08.12 12:02:07.864  MAIN        ( WARN    ) : Socket died (module=uvmm)
management-console-server.log:07.08.12 12:02:07.864  MAIN        ( WARN    ) : Module process uvmm died (pid: 28865, exit status: -1, signal: -1)
----8<----

Oder der connector-s4 da ich ebenfalls gerade Probleme habe mit der Anbindung eines Samba3 Member Servers an die Samba 4 Domäne:

----8<----
07.08.2012 13:04:52,993 LDAP        (Ps4-connector.log: 07.08.2012 13:04:52,993 LDAP        (PROCESS): sync from ucs:   Resync rejected file: /var/lib/univention-connector/s4/1343907078.446278
s4-connector.log: 07.08.2012 13:04:52,994 LDAP        (PROCESS): sync from ucs: [  container_dc] [    modify] dc=exampleexample,dc=net
s4-connector.log: 07.08.2012 13:04:53,61 LDAP        (WARNING): sync failed, saved as rejected
s4-connector.log: 07.08.2012 13:04:53,61 LDAP        (WARNING): Traceback (most recent call last):
s4-connector.log:   File "/usr/lib/pymodules/python2.6/univention/s4connector/__init__.py", line 751, in __sync_file_from_ucs
s4-connector.log:     or (not old_dn and not self.sync_from_ucs(key, object, premapped_ucs_dn, old_dn, old))):
s4-connector.log:   File "/usr/lib/pymodules/python2.6/univention/s4connector/s4/__init__.py", line 2181, in sync_from_ucs
s4-connector.log:     self.lo_s4.lo.add_ext_s(compatible_modstring(object['dn']), compatible_addlist(addlist), serverctrls=ctrls) #FIXME encoding
s4-connector.log:   File "/usr/lib/python2.6/dist-packages/ldap/ldapobject.py", line 180, in add_ext_s
s4-connector.log:     return self.result(msgid,all=1,timeout=self.timeout)
s4-connector.log:   File "/usr/lib/python2.6/dist-packages/ldap/ldapobject.py", line 422, in result
s4-connector.log:     res_type,res_data,res_msgid = self.result2(msgid,all,timeout)
s4-connector.log:   File "/usr/lib/python2.6/dist-packages/ldap/ldapobject.py", line 426, in result2
s4-connector.log:     res_type, res_data, res_msgid, srv_ctrls = self.result3(msgid,all,timeout)
s4-connector.log:   File "/usr/lib/python2.6/dist-packages/ldap/ldapobject.py", line 432, in result3
s4-connector.log:     ldap_result = self._ldap_call(self._l.result3,msgid,all,timeout)
s4-connector.log:   File "/usr/lib/python2.6/dist-packages/ldap/ldapobject.py", line 96, in _ldap_call
s4-connector.log:     result = func(*args,**kwargs)
s4-connector.log: NO_SUCH_OBJECT: {'info': '00002030: No such object - objectclass: Cannot add dc=exampleexample,dc=net, parent does not exist!', 'desc': 'No such object'}
s4-connector.log: 
s4-connector.log: 07.08.2012 13:04:53,62 LDAP        (PROCESS): sync to ucs: Resync rejected dn: DC=doa,DC=example,DC=net
s4-connector.log: 07.08.2012 13:04:53,65 LDAP        (WARNING): encode_s4_object: encode attrib repsTo failed, ignored!
s4-connector.log: 07.08.2012 13:04:53,68 LDAP        (PROCESS): sync to ucs:   [  container_dc] [       add] DC=doalane,dc=net
s4-connector.log: 07.08.2012 13:04:53,68 LDAP        (ERROR  ): sync of rejected object failed 
s4-connector.log:         DC=doa,DC=example,DC=net
s4-connector.log: 07.08.2012 13:04:53,69 LDAP        (ERROR  ): Traceback (most recent call last):
s4-connector.log:   File "/usr/lib/pymodules/python2.6/univention/s4connector/s4/__init__.py", line 1906, in resync_rejected
s4-connector.log:     sync_successfull = self.sync_to_ucs(property_key, mapped_object, premapped_s4_dn)
s4-connector.log:   File "/usr/lib/pymodules/python2.6/univention/s4connector/__init__.py", line 1275, in sync_to_ucs
s4-connector.log:     position.setDn( string.join( ldap.explode_dn( object['dn'] )[1:], "," ) )
s4-connector.log:   File "/usr/lib/pymodules/python2.6/univention/admin/uldap.py", line 144, in setDn
s4-connector.log:     raise univention.admin.uexceptions.noObject, _("DN not found: %s.") % dn
s4-connector.log: noObject: DN not found: dc=net.
----8<----

Comment 4 Alexander Kläser 2012-08-08 13:26:02 CEST

(In reply to comment #3)
> Derzeit:
> 
> root@vp-s01:/var/log# ucr search --brief '^version/'
> version/erratalevel: 106
> version/patchlevel: 2
> version/releasename: Horn-Lehe
> version/security-patchlevel: <empty>
> version/version: 3.0

Ok, gut das ist die aktuelle 3.0-2-Version, danke.
 
> Das war als der Bug auftrat aber noch ein anderes Errata da ich danach
> sicherheitshalber noch mal Updates eingespielt hatte.  Ich werde aus dem
> updater.log aber nicht ganz schlau da da scheinbar ein Update von heute morgen
> (auf 105) fehlt:
> ... 

Nein, soweit ich das gibt es keinen Probleme, es sollten alle Erratas soweit eingespielt werden.

> Ich muss das mal beobachten.   Waren die Patches aus Bug 28108 im errata106? 
> (Passt von der Zeit ungefähr.)

Das beschriebene Problem aus Bug 28108 ist seit heute Vormittag mit den Errata 107 und 108 behoben.

> Ob der Dienst noch lief weiß ich gerade nicht, werde ich beim nächsten
> Auftreten überprüfen.

Ja, danke, bitte noch einmal Rückmeldung geben, ob es noch Probleme gibt (gerade bei der Anmeldung).

> Mögliche Fehlerquellen sind evtl. der UVMM da ich dafür merkwürdige Meldungen
> im Log habe und meiner Meinung nach kurz zuvor immer damit gearbeitet habe
> (aber ich mache da gerade viel mit, das kann also auch Zufall sein):
> ...

Mein Einschätzung wäre, dass das damit nicht in Zusammenhang steht.

Git es noch irgendwelche Protokolldateien die möglicherweise hilfreich sein könnten bzw. soll ich für einen Dienst den loglevel hochdrehen?

Comment 6 Alexander Kläser 2012-08-09 14:18:18 CEST

(In reply to comment #5)
> Git es noch irgendwelche Protokolldateien die möglicherweise hilfreich sein
> könnten bzw. soll ich für einen Dienst den loglevel hochdrehen?

Optimal in diesem Zusammenhang wäre es, die Log-Leven der UMC-Server-Komponenten hoch zu setzen:

  ucr set umc/{module,server}/debug/level=4
  invoke-rc.d univention-management-console-server restart
  invoke-rc.d univention-management-console-web-server restart

Durch folgenden Befehl erhält man eine Datei, die alle relevanten Daten in der korrekten zeitlichen Abfolge enthält:

  UMC=/var/log/univention/management-console
  tail -f ${UMC}-web-server.log ${UMC}-server.log ${UMC}-module-udm.log \
      /var/log/apache2/access.log /var/log/apache2/error.log | tee /tmp/umc.log

Wenn das Problem auftritt, bitte die Einträge seit dem letzten Login (oder der letzten Stunden) aus dieser Datei /tmp/umc.log hier anhängen.

Comment 7 Tim Petersen 2013-01-04 11:35:54 CET

Ebenfalls an Ticket #2012121721001562 berichtet.
UMC Server und Web-Server laufen noch - Debug mit Level 4 sind aus dem USI am Ticket einsehbar.

Comment 8 Alexander Kläser 2013-01-04 12:31:58 CET

(In reply to comment #7)
> Ebenfalls an Ticket #2012121721001562 berichtet.
> UMC Server und Web-Server laufen noch - Debug mit Level 4 sind aus dem USI am
> Ticket einsehbar.

Super, danke!

Folgendes lassen die Log-Dateien erkennen:

========== UMC-Server-Log ==========
> 12.12.12 22:18:39.967  MAIN        ( INFO    ) : The module schoolgroups is inactive for to long. Sending EXIT request to module
> 12.12.12 22:18:39.967  PROTOCOL    ( INFO    ) : Sending UMCP EXIT REQUEST 135535071996732-16
> 12.12.12 22:18:39.967  MAIN        ( INFO    ) : Ask module schoolgroups to shutdown gracefully
> 12.12.12 22:18:39.977  PARSER      ( INFO    ) : UMCP RESPONSE 135535071996732-16 parsed successfully
> 12.12.12 22:18:39.977  PROTOCOL    ( INFO    ) : Received UMCP RESPONSE 135535071996732-16
> 12.12.12 22:18:39.978  MAIN        ( INFO    ) : The given response is invalid or not known (135535071996732-16)
> 12.12.12 22:18:40.192  MAIN        ( WARN    ) : Socket died (module=schoolgroups)
> 12.12.12 22:18:40.192  MAIN        ( WARN    ) : Module process schoolgroups died (pid: 16285, exit status: -1, signal: -1)
> 12.12.12 22:18:40.192  MAIN        ( INFO    ) : Checking for kill timer (schoolgroups)
> 12.12.12 22:18:40.192  MAIN        ( INFO    ) : Stopping kill timer)
> 12.12.12 22:18:40.192  MAIN        ( WARN    ) : Cleaning up requests
> 12.12.12 22:18:40.192  MAIN        ( INFO    ) : No pending requests found
> 12.12.12 22:18:40.202  MAIN        ( PROCESS ) : ModuleProcess: child died
> 12.12.12 22:18:40.203  MAIN        ( INFO    ) : Module process schoolgroups died on purpose
> 12.12.12 22:18:40.203  MAIN        ( INFO    ) : Checking for kill timer ()
> 12.12.12 22:18:50.459  MAIN        ( INFO    ) : The module computerroom is inactive for to long. Sending EXIT request to module
> 12.12.12 22:18:50.459  PROTOCOL    ( INFO    ) : Sending UMCP EXIT REQUEST 135535073045981-17
> 12.12.12 22:18:50.459  MAIN        ( INFO    ) : Ask module computerroom to shutdown gracefully
> 12.12.12 22:18:50.470  PARSER      ( INFO    ) : UMCP RESPONSE 135535073045981-17 parsed successfully
> 12.12.12 22:18:50.470  PROTOCOL    ( INFO    ) : Received UMCP RESPONSE 135535073045981-17
> 12.12.12 22:18:50.470  MAIN        ( INFO    ) : The given response is invalid or not known (135535073045981-17)
> 12.12.12 22:18:50.701  MAIN        ( PROCESS ) : ModuleProcess: child died
> 12.12.12 22:18:50.701  MAIN        ( INFO    ) : Module process computerroom died on purpose
> 12.12.12 22:18:50.701  MAIN        ( INFO    ) : Checking for kill timer (computerroom)
> 12.12.12 22:18:50.701  MAIN        ( INFO    ) : Stopping kill timer)
> 12.12.12 22:18:50.701  MAIN        ( WARN    ) : Cleaning up requests
> 12.12.12 22:18:50.701  MAIN        ( INFO    ) : No pending requests found
> 12.12.12 22:18:50.701  MAIN        ( WARN    ) : Socket died (module=computerroom)
> 12.12.12 22:18:54.030  SSL         ( WARN    ) : SSL error: (-1, 'Unexpected EOF'). Probably the socket was closed by the client.
> 12.12.12 22:18:54.030  MAIN        ( INFO    ) : The session is shutting down. Sending UMC modules an EXIT request (0 processes)
====================
Hier sieht man, dass nach Beenden des Computerraum-Moduls ein SSL-Fehler auftritt und die Verbindung zum UMC-Web-Server abbricht. Interessanterweise finden sich die letzten Requests nicht im LOG-File des Computerraummoduls

Dies hört auf bei:
========== Computerraum-Modul-Log ==========
> 20.12.12 13:43:42.278  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.278  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.278  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.278  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.278  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.786  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.786  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.786  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.786  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.786  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:42.796  MODULE      ( INFO    ) : currently not connected
> 20.12.12 13:43:43.286  PARSER      ( INFO    ) : UMCP REQUEST 135601102328011-10 parsed successfully
> 20.12.12 13:43:43.355  MODULE      ( INFO    ) : Received request 135601102328011-10
> 20.12.12 13:43:43.355  PROTOCOL    ( INFO    ) : Received UMCP EXIT REQUEST 135601102328011-10
> 20.12.12 13:43:43.355  MODULE      ( INFO    ) : EXIT: module shutdown in 100ms
> 20.12.12 13:43:43.355  PROTOCOL    ( INFO    ) : Sending UMCP RESPONSE 135601102328011-10
> 20.12.12 13:43:43.460  MODULE      ( INFO    ) : Commiting suicide
> 20.12.12 13:43:43.460  MODULE      ( INFO    ) : Cleaning up
> 20.12.12 13:43:43.460  MODULE      ( INFO    ) : Removing lock file for room info2 (...)
> 20.12.12 13:43:43.461  MODULE      ( WARN    ) : lockDN: ... userDN: ...
> 20.12.12 13:43:43.461  MAIN        ( WARN    ) : Shutting down all open connections
====================
Wobei die Zeilen "currentlz not connected" sich sehr oft wiederholen.

Die letzten Zeilen des Web-Servers sehen wie folgt aus:
========== UMC-Web-Server-Log ==========
> 12.12.12 22:08:49.611  PROTOCOL    ( INFO    ) : Sending UMCP COMMAND REQUEST 135535012960074-510
> 12.12.12 22:08:49.624  PARSER      ( INFO    ) : UMCP RESPONSE 135535012960074-510 parsed successfully
> 12.12.12 22:08:49.624  PROTOCOL    ( INFO    ) : Received UMCP RESPONSE 135535012960074-510
> 12.12.12 22:08:49.624  MAIN        ( INFO    ) : SessionClient(0x2089210): got response(135535012960074-510): status=200 queue=0x2088830
> 12.12.12 22:08:49.624  MAIN        ( INFO    ) : CPCommand (...) got response(0x2089450) from queue(0x2088830): status=200 (sessionid="58708d00-85cf-4ed3-8fab-03625050f271")
> 12.12.12 22:18:54.030  MAIN        ( INFO    ) : SessionClient(0x2089210): timed out!
> 12.12.12 22:18:54.030  MAIN        ( INFO    ) : SessionClient(0x2089210): Closing connection to UMC server
> 12.12.12 22:18:54.030  MAIN        ( INFO    ) : Open sessions: 82fea849-fbc1-406e-8176-479cfe8e24b1,58708d00-85cf-4ed3-8fab-03625050f271
> 12.12.12 22:18:54.030  MAIN        ( INFO    ) : Cleaning up session 58708d00-85cf-4ed3-8fab-03625050f271
====================
Es fand also keine Kommunikation zwischen UMC-Server und UMC-Web-Server mehr statt, doch die Verbindung brach ab, vielleicht durch einen provozierten Fehler durch das Computerraum-Modul?

Comment 9 Alexander Kläser 2013-01-10 11:14:15 CET

Created attachment 4968 [details]
Test alive script

Anbei ein Test-Skript, um einen nicht mehr erreichbaren UMC-Server zu erkennen. Das Skript versucht sich als Benutzer "testalive" zu authentifizieren. Ist der Server erreichbar, wird ein HTTP-Code von 411 zurückgegeben. Ansonsten wird nichts zurückgegeben und der Verbindungsaufbau bricht nach 15sec (-q Parameter von nc) ab.

Ich kann das leider nicht mehr prüfen da das System so nicht mehr läuft.  Auf dem System war aber auf jeden Fall kein Computerraum-Modul installiert.  Es trat auch schon länger nicht mehr auf.

Comment 11 Alexander Kläser 2013-01-15 15:45:50 CET

(In reply to comment #10)
> Ich kann das leider nicht mehr prüfen da das System so nicht mehr läuft.  Auf
> dem System war aber auf jeden Fall kein Computerraum-Modul installiert.  Es
> trat auch schon länger nicht mehr auf.

Ok, vielen Dank für die Information!

Comment 12 Tim Petersen 2013-01-24 10:06:51 CET

Folgenden interessanten Hinweis habe ich vom Kunden erhalten:

root@ucs-srv:~# ./check_umc.sh
Restarting Univention Management Console Server.
done.
Restarting Univention Management Console Web Server.
Traceback (most recent call last):
  File "/usr/sbin/univention-management-console-web-server", line 770, in <module>
    http_daemon.do_action()
  File "/usr/lib/pymodules/python2.6/daemon/runner.py", line 186, in do_action
    func(self)
  File "/usr/sbin/univention-management-console-web-server", line 705, in _restart
    self._stop()
  File "/usr/lib/pymodules/python2.6/daemon/runner.py", line 154, in _stop
    self._terminate_daemon_process()
  File "/usr/sbin/univention-management-console-web-server", line 743, in _terminate_daemon_process
    os.kill( pid, signal.SIGKILL )
OSError: [Errno 3] No such process
done.

Der Web-Server scheint also doch "weg" zu sein, wenn das auftritt.

Comment 13 Tim Petersen 2013-05-29 11:09:20 CEST

Vermutlich erneut an 2013051721001369 aufgetreten.

Comment 14 Stefan Gohmann 2013-05-29 11:56:27 CEST

(In reply to comment #13)
> Vermutlich erneut an 2013051721001369 aufgetreten.

Kannst du die Versionsnummern der installierten Pakete noch anhängen?

Gibt es aktuellen Debug am Ticket? Vielleicht Debug Level 4.

Comment 15 Tim Petersen 2013-05-29 12:04:10 CEST

(In reply to comment #14)
> (In reply to comment #13)
> > Vermutlich erneut an 2013051721001369 aufgetreten.
> 
> Kannst du die Versionsnummern der installierten Pakete noch anhängen?
> 
> Gibt es aktuellen Debug am Ticket? Vielleicht Debug Level 4.

Versionsstände der UMC-Pakete hängen am Ticket, dpkg-l wurde bereits angefragt, reiche ich nach.
Logfiles gibt es ebenfalls - das Debug-Level kann ich nicht mit Sicherheit sagen - das könnte ich nochmal anfragen bzw auf 4 setzen lassen.

Comment 16 Tim Petersen 2013-05-29 12:06:22 CEST

Created attachment 5252 [details]
UMC-Version

Comment 17 Tim Petersen 2013-05-30 07:54:34 CEST

Created attachment 5254 [details]
full package list

Im Anhang die volle Paketliste. UCS 3.1-1 errata91 mit UCS@school 3.1r1 ist im Einsatz.
Der Kunde hat erwähnt, dass sehr wahrscheinlich ausschließlich das Computerraummodul beim letzten eingegrenzten Vorfall verwendet wurde. Das deckt sich auch mit den am Ticket verfügbaren Logdateien des letzten Aufrufs.

Comment 18 Alexander Kläser 2013-06-12 18:08:45 CEST

(In reply to Tim Petersen from comment #12)
> Folgenden interessanten Hinweis habe ich vom Kunden erhalten:
> 
> root@ucs-srv:~# ./check_umc.sh
> Restarting Univention Management Console Server.
> done.
> Restarting Univention Management Console Web Server.
> Traceback (most recent call last):
>   File "/usr/sbin/univention-management-console-web-server", line 770, in
> <module>
>     http_daemon.do_action()
>   File "/usr/lib/pymodules/python2.6/daemon/runner.py", line 186, in
> do_action
>     func(self)
>   File "/usr/sbin/univention-management-console-web-server", line 705, in
> _restart
>     self._stop()
>   File "/usr/lib/pymodules/python2.6/daemon/runner.py", line 154, in _stop
>     self._terminate_daemon_process()
>   File "/usr/sbin/univention-management-console-web-server", line 743, in
> _terminate_daemon_process
>     os.kill( pid, signal.SIGKILL )
> OSError: [Errno 3] No such process
> done.
> 
> Der Web-Server scheint also doch "weg" zu sein, wenn das auftritt.

Durch das Erratum mit Bug 31130 sollten jetzt genauere Informationen zum Absturz in den Logdatein enthalten sein.

Comment 19 Stefan Gohmann 2013-08-22 19:27:24 CEST

(In reply to Alexander Kläser from comment #18)
> Durch das Erratum mit Bug 31130 sollten jetzt genauere Informationen zum
> Absturz in den Logdatein enthalten sein.

OK, solange warten wir.

Comment 20 Florian Best 2016-10-07 18:30:04 CEST

This issue has been filed against UCS 3.0.

UCS 3.0 is out of maintenance and many UCS components have vastly changed in
later releases. Thus, this issue is now being closed.

If this issue still occurs in newer UCS versions, please use "Clone this bug".
In this case please provide detailed information on how this issue is affecting
you.