UCS Zarafa und Owncloud täglich nicht erreichbar

Guten Morgen,

ich betreibe für 5 User einen UCS Server mit den Paketen Zarafa (+ ZPush) und Owncloud. Alles auf aktuellem Stand. Der Server läuft sein ca. 3 Monaten bei Amazon AWS und eigentlich hatte ich nie wirkliche Probleme:

In den letzten Wochen kommt es täglich bis zu zwei mal vor, dass die Mobilgeräte sich nicht mehr authentifizieren können (Exchangedienste nicht verfügbar). Wenn ich dann auf den UCS sehe, kann ich die Management Oberfläche öffnen. In der Zarafa Webapp steht beim Anmelden “Zarafa Server not aviable” und Owncloud meldet nur eine Seite mit Server Fehler…
Nach einem Neustart das Servers funktionieren wieder alle Dienste.

Ich finde auch in den Log Dateien nichts (bzw. habe keinen Ansatz, woran es liegen kann). Über einen Hinweis wäre ich dankbar.

Seitdem diese “Aussetzer” auftreten, ist die Systemlast deutlich

Mit besten Grüßen

Alex Böhm

Moin,

Was genau meinen Sie mit »öffnen«? Können Sie sich auch in der UMC anmelden, z.B. als »administrator«?

Läuft in dem Moment ein Prozess namens »zarafa-server«? Dieser ist der zentrale Prozess von Zarafa, mit dem alle anderen Prozesse (z.B. »zarafa-gateway« für IMAP und POP3) und Interfaces (z.B. die WebApp) kommunizieren. Schauen Sie auch in die Logdatei /var/log/zarafa/server.log für Hinweise, was das Problem sein kann.

Schauen Sie in dem Moment in die Webserver-Fehler-Logs, also /var/log/apache2/error.log.

Deutlich… frühlinghafter? Flauschiger? Höher?

LG,
mosu

Hi,

also, ich kann mich an der Management Oberfläche ganz normal anmelden (mit dem administrator), auch der ZarafaServer Prozess läuft

4726 root      20   0  357m  79m    0 S   0,3  8,0   0:44.19 zarafa-server 

In der /zarafa/server.log sieht es schon anders aus…

Tue May 3 12:41:48 2016: [fatal ] ECDatabaseMySQL::DoSelect(): query failed Tue May 3 12:41:48 2016: [fatal ] ECCacheManager::GetUserObject(): query failed 80000007 Tue May 3 12:41:48 2016: [fatal ] SQL [00000000] info: Try to reconnect Tue May 3 12:41:48 2016: [fatal ] ECDatabaseMySQL::Connect(): mysql connect fail 80000007 Tue May 3 12:41:48 2016: [fatal ] ECDatabaseMySQL::DoSelect(): query failed

gleiches auch in der /apache2/error.log

[Tue May 03 12:32:45 2016] [error] [client 217.91.90.179] zarafa-webapp user: aboehm: authentication failure at MAPI, referer: https://url.de/webapp/ [Tue May 03 12:32:50 2016] [error] [client 217.91.90.179] zarafa-webapp user: aboehm: authentication failure at MAPI, referer: https://url.de/webapp/index.php?logo

In meinem letzten Satz hab ich irgendwo vergessen, das “höher” einzusetzen - Danke für den Hinweis.

Es scheint so, als ob der SQL Prozess oder vielleicht die Datenbank ein Problem hat…

ich habe ein top | grep mysql abgesetzt, aber da war kein Prozess mehr.

Mit bestem Gruß

Alex Böhm

Moin,

ja dann: die Logdateien von MySQL auswerten. MySQL schreibt oft nach /var/log/syslog, es gibt aber teilweise auch Logs in /var/log/mysql.

Gruß,
mosu

Hi,

die mysql logs sind alle leer… Nur in Syslog stehen die folgenden Zeilen (zu heute Mittag…)

May 3 12:15:56 ucs kernel: [15888.650195] [ 3173] 0 3173 1049 36 8 3 0 0 mysqld_safe May 3 12:15:56 ucs kernel: [15888.650196] [ 3501] 114 3501 109353 27811 102 4 0 0 mysqld May 3 12:15:56 ucs kernel: [15888.650304] Out of memory: Kill process 3501 (mysqld) score 109 or sacrifice child May 3 12:15:56 ucs kernel: [15888.650307] Killed process 3501 (mysqld) total-vm:437412kB, anon-rss:111244kB, file-rss:0kB May 3 12:15:56 ucs mysqld_safe: Number of processes running now: 0 May 3 12:15:56 ucs mysqld_safe: mysqld restarted May 3 12:15:57 ucs mysqld: 160503 12:15:57 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead. May 3 12:15:57 ucs mysqld: 160503 12:15:57 [Note] /usr/sbin/mysqld (mysqld 5.5.46-0.17.201512141630) starting as process 1005 ... May 3 12:15:57 ucs mysqld: 160503 12:15:57 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead. May 3 12:15:57 ucs mysqld: 160503 12:15:57 [Note] Plugin 'FEDERATED' is disabled. May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: The InnoDB memory heap is disabled May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: Mutexes and rw_locks use GCC atomic builtins May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: Compressed tables use zlib 1.2.7 May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: Using Linux native AIO May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: Initializing buffer pool, size = 128.0M May 3 12:15:57 ucs mysqld: InnoDB: mmap(137363456 bytes) failed; errno 12 May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: Completed initialization of buffer pool May 3 12:15:57 ucs mysqld: 160503 12:15:57 InnoDB: Fatal error: cannot allocate memory for the buffer pool May 3 12:15:57 ucs mysqld: 160503 12:15:57 [ERROR] Plugin 'InnoDB' init function returned error. May 3 12:15:57 ucs mysqld: 160503 12:15:57 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. May 3 12:15:57 ucs mysqld: 160503 12:15:57 [ERROR] Unknown/unsupported storage engine: InnoDB May 3 12:15:57 ucs mysqld: 160503 12:15:57 [ERROR] Aborting May 3 12:15:57 ucs mysqld: May 3 12:15:57 ucs mysqld: 160503 12:15:57 [Note] /usr/sbin/mysqld: Shutdown complete May 3 12:15:57 ucs mysqld: May 3 12:15:57 ucs mysqld_safe: mysqld from pid file /var/run/mysqld/mysqld.pid ended May 3 12:55:52 ucs mysqld_safe: Starting mysqld daemon with databases from /var/lib/mysql May 3 12:55:52 ucs mysqld: 160503 12:55:52 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead. May 3 12:55:52 ucs mysqld: 160503 12:55:52 [Note] /usr/sbin/mysqld (mysqld 5.5.46-0.17.201512141630) starting as process 3497 ... May 3 12:55:52 ucs mysqld: 160503 12:55:52 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead. May 3 12:55:52 ucs mysqld: 160503 12:55:52 [Note] Plugin 'FEDERATED' is disabled. May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: The InnoDB memory heap is disabled May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: Mutexes and rw_locks use GCC atomic builtins May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: Compressed tables use zlib 1.2.7 May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: Using Linux native AIO May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: Initializing buffer pool, size = 128.0M May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: Completed initialization of buffer pool May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: highest supported file format is Barracuda. May 3 12:55:52 ucs mysqld: InnoDB: Log scan progressed past the checkpoint lsn 2394973169 May 3 12:55:52 ucs mysqld: 160503 12:55:52 InnoDB: Database was not shut down normally! May 3 12:55:52 ucs mysqld: InnoDB: Starting crash recovery. May 3 12:55:52 ucs mysqld: InnoDB: Reading tablespace information from the .ibd files... May 3 12:55:52 ucs mysqld: InnoDB: Restoring possible half-written data pages from the doublewrite May 3 12:55:52 ucs mysqld: InnoDB: buffer... May 3 12:55:52 ucs mysqld: InnoDB: Doing recovery: scanned up to log sequence number 2394973473 May 3 12:55:53 ucs mysqld: 160503 12:55:53 InnoDB: Starting an apply batch of log records to the database... May 3 12:55:53 ucs mysqld: InnoDB: Progress in percents: 88 89 90 91 92 93 94 95 96 97 98 99 May 3 12:55:53 ucs mysqld: InnoDB: Apply batch completed May 3 12:55:53 ucs mysqld: 160503 12:55:53 InnoDB: Waiting for the background threads to start May 3 12:55:54 ucs mysqld: 160503 12:55:54 InnoDB: 5.5.46 started; log sequence number 2394973473 May 3 12:55:54 ucs mysqld: 160503 12:55:54 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306 May 3 12:55:54 ucs mysqld: 160503 12:55:54 [Note] - '127.0.0.1' resolves to '127.0.0.1'; May 3 12:55:54 ucs mysqld: 160503 12:55:54 [Note] Server socket created on IP: '127.0.0.1'. May 3 12:55:54 ucs mysqld: 160503 12:55:54 [Note] Event Scheduler: Loaded 0 events May 3 12:55:54 ucs mysqld: 160503 12:55:54 [Note] /usr/sbin/mysqld: ready for connections. May 3 12:55:54 ucs mysqld: Version: '5.5.46-0.17.201512141630' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Univention) May 3 12:55:54 ucs /etc/mysql/debian-start[3577]: Upgrading MySQL tables if necessary. May 3 12:55:54 ucs /etc/mysql/debian-start[3581]: /usr/bin/mysql_upgrade: the '--basedir' option is always ignored May 3 12:55:54 ucs /etc/mysql/debian-start[3581]: Looking for 'mysql' as: /usr/bin/mysql May 3 12:55:54 ucs /etc/mysql/debian-start[3581]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck May 3 12:55:54 ucs /etc/mysql/debian-start[3581]: This installation of MySQL is already upgraded to 5.5.46, use --force if you still need to run mysql_upgrade May 3 12:55:54 ucs /etc/mysql/debian-start[3599]: Checking for insecure root accounts. May 3 12:55:54 ucs /etc/mysql/debian-start[3604]: Triggering myisam-recover for all MyISAM tables May 3 12:55:54 ucs mysqld: 160503 12:55:54 [ERROR] /usr/sbin/mysqld: Table './mysql/proc' is marked as crashed and should be repaired May 3 12:55:54 ucs mysqld: 160503 12:55:54 [Warning] Checking table: './mysql/proc' May 3 12:59:38 ucs kernel: [ 280.741368] [ 3169] 0 3169 1049 37 8 3 0 0 mysqld_safe May 3 12:59:38 ucs kernel: [ 280.741370] [ 3497] 114 3497 109126 15979 78 4 0 0 mysqld

Interessanter weise habe ich diverse Kernel Out of Memory Einträge…

root@ucs:~# cat /var/log/syslog | grep "Out of memory" May 2 08:01:07 ucs kernel: [60967.183423] Out of memory: Kill process 5198 (apache2) score 102 or sacrifice child May 2 11:05:25 ucs kernel: [ 504.322966] Out of memory: Kill process 3839 (clamd) score 329 or sacrifice child May 2 12:08:13 ucs kernel: [ 4272.619291] Out of memory: Kill process 14953 (zarafa-dagent) score 171 or sacrifice child May 2 13:18:12 ucs kernel: [ 8472.292940] Out of memory: Kill process 23356 (zarafa-dagent) score 147 or sacrifice child May 2 14:28:14 ucs kernel: [12673.816510] Out of memory: Kill process 32546 (zarafa-dagent) score 129 or sacrifice child May 2 15:38:14 ucs kernel: [16873.816441] Out of memory: Kill process 9770 (zarafa-dagent) score 127 or sacrifice child May 2 15:38:14 ucs kernel: [16873.824688] Out of memory: Kill process 9777 (NotifyThread) score 127 or sacrifice child May 2 15:38:14 ucs kernel: [16873.828621] Out of memory: Kill process 9777 (NotifyThread) score 127 or sacrifice child May 2 16:48:13 ucs kernel: [21072.876887] Out of memory: Kill process 18481 (zarafa-dagent) score 128 or sacrifice child May 2 17:58:21 ucs kernel: [25280.816433] Out of memory: Kill process 27913 (zarafa-dagent) score 120 or sacrifice child May 2 17:58:21 ucs kernel: [25280.820491] Out of memory: Kill process 27917 (NotifyThread) score 121 or sacrifice child May 2 19:08:13 ucs kernel: [29472.966274] Out of memory: Kill process 3501 (mysqld) score 104 or sacrifice child May 2 19:08:13 ucs kernel: [29472.968395] Out of memory: Kill process 14281 (/usr/sbin/amavi) score 90 or sacrifice child May 2 20:15:11 ucs kernel: [33490.401665] Out of memory: Kill process 4730 (zarafa-server) score 134 or sacrifice child May 2 22:02:08 ucs kernel: [39907.728022] Out of memory: Kill process 12241 (/usr/sbin/amavi) score 89 or sacrifice child May 2 22:02:19 ucs kernel: [39918.816791] Out of memory: Kill process 3139 (/usr/sbin/amavi) score 85 or sacrifice child May 2 22:18:11 ucs kernel: [ 694.044335] Out of memory: Kill process 3835 (clamd) score 329 or sacrifice child May 2 22:37:22 ucs kernel: [ 1844.439831] Out of memory: Kill process 4723 (zarafa-server) score 110 or sacrifice child May 2 22:37:22 ucs kernel: [ 1844.445913] Out of memory: Kill process 4761 (NotificationMan) score 111 or sacrifice chil May 3 07:57:19 ucs kernel: [ 371.816451] Out of memory: Kill process 3839 (clamd) score 329 or sacrifice child May 3 12:15:56 ucs kernel: [15888.650304] Out of memory: Kill process 3501 (mysqld) score 109 or sacrifice child May 3 12:59:38 ucs kernel: [ 280.741492] Out of memory: Kill process 3835 (clamd) score 329 or sacrifice child

Das würde ja bedeuten, dass der Speicher volläuft. Oder sehe ich das falsch?

Mit bestem Gruß

Alex Böhm

Moin,

ja, Ihre Programme wollen mehr Speicher benutzen, als Ihre Linux-Instanz zur Verfügung stellt. Entweder, Sie schränken den Speicherbedarf ein (weniger Apache-Prozesse starten, MySQL und Zarafa jeweils weniger Hauptspeicher füh ihre Caches zuordnen…), oder Sie nutzen eine größere Linux-Instanz. Ich rate stark zu »mehr Hauptspeicher«, denn nichts tötet Performance so zuverlässig, wie zu wenig Speicher zur Verfügung zu haben.

Gruß,
mosu

Vielen Dank!

Ich werde mal sehen, wie ich das einstellen kann.

Bester Grüße
Alex Böhm