Täglicher Ausfall von Zarafa Mail

german

#1

Hallo zusammen!

Seit dem letzten Update auf Zarafa ZCP 7.2.4.29 habe ich ein seltsamen Problem:

Nahezu jede Nacht (manchmal auch nur jede zweite) zwischen 4 und 5 Uhr Früh schießt sich irgendwas am Server. Danach sind keine Verbindungen (Outlook, Webapp) mehr zum Mailserver möglich.
Ein Neustart des Servers behebt das Problem.

Beim durchforsten der Logs habe ich folgendes gefunden:

Tue Aug 2 05:00:01 2016: [error ] Unable to get database connection: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2) Tue Aug 2 05:00:02 2016: [error ] ECDatabaseMySQL::Connect(): mysql connect fail 80000007 Tue Aug 2 05:00:02 2016: [error ] ECDatabaseMySQL::DoSelect(): query failed

Hat da jemand eine Lösung für mich?

LG
mandelbrot


#2

Moin,

ziemlich neu bei Zarafa4UCS ist, dass die Dienste als nicht privilegierter User »zarafa« laufen und nicht mehr als »root«. Ich vermute als Erstes daher auf Berechtigungsprobleme, wobei ich nicht von Vorneherein weiß, warum die immer nur sporadisch auftreten sollten.

Zeigen Sie doch bitte mal die Ausgabe der folgenden Befehle, wenn das Problem wieder auftritt (also vor dem Neustart des Servers):

ls -ld /var /var/run /var/run/mysqld /var/run/mysqld/mysqld.sock ps uaxw|grep zarafa

Gruß,
mosu


#3

Hallo,

Danke für die rasche Antwort.

Hier die Ergebnisse:

root@mail:~# ls -ld /var /var/run /var/run/mysqld /var/run/mysqld/mysqld.sock drwxr-xr-x 14 root root 4096 Jul 5 2015 /var lrwxrwxrwx 1 root root 4 Jul 5 2015 /var/run -> /run drwxr-xr-x 2 mysql root 80 Aug 2 06:58 /var/run/mysqld srwxrwxrwx 1 mysql mysql 0 Aug 2 06:58 /var/run/mysqld/mysqld.sock root@mail:~# ps uaxw|grep zarafa zarafa 4121 0.0 0.4 138776 9328 ? S 07:00 0:00 /usr/sbin/zarafa-dagent -d -c /etc/zarafa/dagent.cfg zarafa 4123 0.0 0.2 131480 5120 ? Sl 07:00 0:00 /usr/sbin/zarafa-dagent -d -c /etc/zarafa/dagent.cfg zarafa 4154 0.0 0.3 119780 7940 ? S 07:00 0:00 /usr/sbin/zarafa-gateway -c /etc/zarafa/gateway.cfg zarafa 4155 0.0 0.1 112368 4236 ? Sl 07:00 0:00 /usr/sbin/zarafa-gateway -c /etc/zarafa/gateway.cfg zarafa 4183 0.0 0.3 112712 7508 ? S 07:00 0:00 /usr/sbin/zarafa-ical -c /etc/zarafa/ical.cfg zarafa 4185 0.0 0.1 105416 3544 ? Sl 07:00 0:00 /usr/sbin/zarafa-ical -c /etc/zarafa/ical.cfg zarafa 4214 0.0 0.4 200092 9408 ? Sl 07:00 0:01 /usr/sbin/zarafa-licensed -c /etc/zarafa/licensed.cfg zarafa 4244 0.0 0.4 183552 11196 ? Sl 07:00 0:00 /usr/sbin/zarafa-monitor -c /etc/zarafa/monitor.cfg zarafa 4273 0.0 0.9 193356 20840 ? Sl 07:00 0:06 /usr/bin/python /usr/sbin/zarafa-presence zarafa 4305 0.5 1.4 268144 33408 ? Sl 07:00 1:12 /usr/bin/python /usr/sbin/zarafa-search -c /etc/zarafa/search.cfg zarafa 4337 2.1 4.4 537532 103012 ? Sl 07:00 4:56 /usr/sbin/zarafa-server -c /etc/zarafa/server.cfg zarafa 4368 0.0 0.5 214232 12676 ? Sl 07:00 0:01 /usr/sbin/zarafa-spooler -c /etc/zarafa/spooler.cfg zarafa 4370 0.0 0.2 131408 4952 ? Sl 07:00 0:00 /usr/sbin/zarafa-spooler -c /etc/zarafa/spooler.cfg zarafa 4919 0.6 1.2 266628 29892 ? Sl 07:01 1:28 /usr/bin/python /usr/sbin/zarafa-search -c /etc/zarafa/search.cfg zarafa 4945 0.0 0.8 257356 19980 ? Sl 07:01 0:01 /usr/bin/python /usr/sbin/zarafa-search -c /etc/zarafa/search.cfg root 14654 0.0 0.0 11320 2000 pts/0 S+ 10:54 0:00 grep zarafa root@mail:~#


#4

Moin,

die Berechtigungen sehen OK aus. Haben sie jetzt gerade das akute Problem? Wie gesagt, mich interessieren die Berechtigungen und Prozesse von dem Zeitpunkt, an dem der Zarafa-Server gerade keine Verbindung bekommt.

Gruß,
mosu


#5

hallo,

Die obeigen Ergebnisse sind natürlich bei ordentlichen Betrieb entstanden.
Ich werde die Befehle bei nächsten Ausfall nochmals ausführen und posten

LG
mandelbrot


#6

Guten Morgen!

Heute hatten wir wieder diesen Ausfall.
Hier die Ergebnisse:

root@mail:~# ls -ld /var /var/run /var/run/mysqld /var/run/mysqld/mysqld.socks -ld /var /var/run /var/run/mysqld /var/run/mysqld/mysqld.sock
ls: Zugriff auf /var/run/mysqld/mysqld.socks nicht möglich: Datei oder Verzeichnis nicht gefunden
ls: Zugriff auf /var/run/mysqld/mysqld.sock nicht möglich: Datei oder Verzeichnis nicht gefunden
drwxr-xr-x 14 root  root 4096 Jul  5  2015 /var
drwxr-xr-x 14 root  root 4096 Jul  5  2015 /var
lrwxrwxrwx  1 root  root    4 Jul  5  2015 /var/run -> /run
lrwxrwxrwx  1 root  root    4 Jul  5  2015 /var/run -> /run
drwxr-xr-x  2 mysql root   40 Aug  9 04:56 /var/run/mysqld
drwxr-xr-x  2 mysql root   40 Aug  9 04:56 /var/run/mysqld
root@mail:~# ps uaxw|grep zarafa
zarafa    4121  0.0  0.2 138776  5556 ?        S    Aug02   0:04 /usr/sbin/zarafa-dagent -d -c /etc/zarafa/dagent.cfg
zarafa    4123  0.0  0.1 131480  3128 ?        Sl   Aug02   0:01 /usr/sbin/zarafa-dagent -d -c /etc/zarafa/dagent.cfg
zarafa    4154  0.0  0.2 119780  4908 ?        S    Aug02   0:03 /usr/sbin/zarafa-gateway -c /etc/zarafa/gateway.cfg
zarafa    4155  0.0  0.1 112368  3148 ?        Sl   Aug02   0:00 /usr/sbin/zarafa-gateway -c /etc/zarafa/gateway.cfg
zarafa    4183  0.0  0.2 112712  4948 ?        S    Aug02   0:03 /usr/sbin/zarafa-ical -c /etc/zarafa/ical.cfg
zarafa    4185  0.0  0.1 105416  2472 ?        Sl   Aug02   0:00 /usr/sbin/zarafa-ical -c /etc/zarafa/ical.cfg
zarafa    4214  0.0  0.4 200824  9956 ?        Sl   Aug02   0:28 /usr/sbin/zarafa-licensed -c /etc/zarafa/licensed.cfg
zarafa    4244  0.0  0.4 184448 10140 ?        Sl   Aug02   0:23 /usr/sbin/zarafa-monitor -c /etc/zarafa/monitor.cfg
zarafa    4273  0.0  0.1 193356  3292 ?        Sl   Aug02   2:52 /usr/bin/python /usr/sbin/zarafa-presence
zarafa    4305  0.1  1.6 299988 37416 ?        Sl   Aug02  13:41 /usr/bin/python /usr/sbin/zarafa-search -c /etc/zarafa/search.cfg
zarafa    4337  1.9 13.7 899104 318392 ?       Sl   Aug02 191:53 /usr/sbin/zarafa-server -c /etc/zarafa/server.cfg
zarafa    4368  0.2  0.4 214104 10800 ?        Sl   Aug02  21:22 /usr/sbin/zarafa-spooler -c /etc/zarafa/spooler.cfg
zarafa    4370  0.0  0.1 131408  3236 ?        Sl   Aug02   0:00 /usr/sbin/zarafa-spooler -c /etc/zarafa/spooler.cfg
zarafa    4919  0.0  0.5 268468 11792 ?        Sl   Aug02   5:07 /usr/bin/python /usr/sbin/zarafa-search -c /etc/zarafa/search.cfg
zarafa    4945  0.0  0.3 257208  8292 ?        Sl   Aug02   0:12 /usr/bin/python /usr/sbin/zarafa-search -c /etc/zarafa/search.cfg
root     24160  0.0  0.0   9256  2020 pts/0    D+   06:32   0:00 grep zarafa
root@mail:~#

#7

Moin,

die Socket-Datei ist nicht vorhanden? Das ist nicht gut :slight_smile: Das sollte eigentlich nur dann sein, wenn MySQL selber nicht läuft. Falls der Zustand akut noch anhält: prüfen Sie bitte, ob MySQL selber noch läuft (»ps uaxw|grep mysql«).

Bis auf MySQL selber ist mir kein Programm bekannt, kein Cleanup-Job oder so etwas, das die Socket-Datei entfernen würde. Falls MySQL in diesem Moment nicht laufen sollte, so hat MySQL selber die Datei entfernt; dann sollten Sie mal in den üblichen Logdateien (»/var/log/syslog« sowie denen in »/var/log/mysql«) nach möglichen Ursachen dafür suchen, dass die Datenbank heruntergefahren wurde.

Falls MySQL in so einer Situation allerdings noch laufen sollte, so ist das Ganze noch mysteriöser. Nun müssten Sie versuchen herauszufinden, welches Programm dafür sorgt, dass die Datei entfernt wird. Das ist nicht ganz einfach.

Gruß,
mosu


#8

moin!

Hab den Server nach meinem letzten Post gleich neugestartet da wir sonst nicht arbeiten können.
Ob mysql in dieser Situation gelaufen ist kann ich nicht sagen. werds aber beim nöchsten Ausfall prüfen.

Im syslog habe ich folgendes bemerkt:

Aug 9 04:38:33 mail mysqld: 160809 4:38:33 [Note] /usr/sbin/mysqld: Normal shutdown Aug 9 04:38:33 mail mysqld: Aug 9 04:38:33 mail mysqld: 160809 4:38:33 [Note] Event Scheduler: Purging the queue. 0 events Aug 9 04:38:36 mail mysqld: 160809 4:38:36 [Warning] /usr/sbin/mysqld: Forcing close of thread 2304 user: 'zarafaDbUser' Aug 9 04:38:36 mail mysqld: Aug 9 04:38:36 mail mysqld: 160809 4:38:36 [Warning] /usr/sbin/mysqld: Forcing close of thread 44 user: 'zarafaDbUser' Aug 9 04:38:36 mail mysqld: Aug 9 04:38:38 mail mysqld: 160809 4:38:38 InnoDB: Starting shutdown...

Irgendwas stopp hier den mysql-dienst. das ist genau die Uhrzeit wo das auch sonst immer passiert ist.


#9

Moin,

prüfen Sie die Logs (allen voran das syslog), ob in dem Zeitfenster andere Sachen laufen, die dafür verantwortlich sein können: Cron-Jobs, Backupprogramme, ein falsch konfiguriertes Logrotate…

Gruß,
mosu


#10

Hallo,

hier ein Auszug aus der syslog:

Aug 9 04:00:01 mail /USR/SBIN/CRON[20921]: (root) CMD ( if [ -x /usr/sbin/univention-umount-homedirs ]; then /usr/sbin/univention-umount-homedirs; fi) Aug 9 04:00:01 mail /USR/SBIN/CRON[20923]: (root) CMD (/usr/sbin/univention-mrtg) Aug 9 04:00:02 mail /USR/SBIN/CRON[20954]: (root) CMD ( [ -x /usr/lib/univention-pam/ldap-group-to-file.py ] && /usr/lib/univention-pam/ldap-group-to-file.py --check_member) Aug 9 04:00:02 mail /USR/SBIN/CRON[20955]: (root) CMD (/usr/share/univention-ssl/ssl-sync >>/var/log/univention/ssl-sync.log 2>&1) Aug 9 04:00:02 mail /USR/SBIN/CRON[20959]: (root) CMD ([ -x /usr/sbin/univention-system-stats ] && /usr/sbin/univention-system-stats >/dev/null) Aug 9 04:00:02 mail /USR/SBIN/CRON[20961]: (root) CMD (if [ -x /usr/bin/mrtg ] && [ -r /etc/mrtg.cfg ] && [ -d "$(grep '^[[:space:]]*[^#]*[[:space:]]*WorkDir' /etc/mrtg.cfg | awk '{ print $NF }')" ]; then mkdir -p /var/log/mrtg ; env LANG=C /usr/bin/mrtg /etc/mrtg.cfg 2>&1 | tee -a /var/log/mrtg/mrtg.log ; fi) Oct 1 01:26:40 mail kernel: [591328.528081] INFO: rcu_sched detected stalls on CPUs/tasks: { 0} (detected by 1, t=5252 jiffies, g=6468970, c=6468969, q=20) Oct 1 01:26:55 mail kernel: [591328.528125] Task dump for CPU 0: Oct 1 01:27:11 mail kernel: [591328.528130] swapper/0 R running task 0 0 0 0x00000008 Oct 1 01:27:27 mail kernel: [591328.528136] 0000000000000000 ffffffff8184f800 0000000000000000 0000000000000000 Oct 1 01:27:42 mail kernel: [591328.528140] ffffffffffffffc1 ffffffff8105e192 0000000000000010 0000000000000296 Oct 1 01:27:58 mail kernel: [591328.528144] ffffffff81803eb0 0000000000000018 ffffffff81020a8c ffffffff81800000 Oct 1 01:28:13 mail kernel: [591328.528149] Call Trace: Oct 1 01:28:29 mail kernel: [591328.528209] [<ffffffff8105e192>] ? native_safe_halt+0x2/0x10 Oct 1 01:28:44 mail kernel: [591328.528231] [<ffffffff81020a8c>] ? default_idle+0x1c/0xb0 Oct 1 01:28:59 mail kernel: [591328.528252] [<ffffffff810b67f4>] ? cpu_startup_entry+0x314/0x3e0 Oct 1 01:29:15 mail kernel: [591328.528279] [<ffffffff8191b093>] ? start_kernel+0x48d/0x498 Oct 1 01:29:30 mail kernel: [591328.528284] [<ffffffff8191a95d>] ? set_init_arg+0x50/0x50 Oct 1 01:29:46 mail kernel: [591328.528288] [<ffffffff8191a117>] ? early_idt_handler_array+0x117/0x120 Oct 1 01:30:01 mail kernel: [591328.528291] [<ffffffff8191a117>] ? early_idt_handler_array+0x117/0x120 Oct 1 01:30:17 mail kernel: [591328.528294] [<ffffffff8191a720>] ? x86_64_start_kernel+0x14a/0x159 Aug 9 04:38:31 mail kernel: [593531.831323] INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by 0, t=556077 jiffies, g=6468970, c=6468969, q=277) Aug 9 04:38:31 mail kernel: [593531.831336] All QSes seen, last rcu_sched kthread activity 549756 (4443275253-4442725497), jiffies_till_next_fqs=1, root ->qsmask 0x0 Aug 9 04:38:31 mail kernel: [593531.831340] /usr/sbin/amavi R running task 0 2698 1 0x00000008 Aug 9 04:38:31 mail kernel: [593531.831346] ffff88008fc17100 ffffffff81851300 ffffffff810d7948 0000000000000000 Aug 9 04:38:31 mail kernel: [593531.831351] 0000000000000096 0000000000000000 000000000062b56a ffffffff81851300 Aug 9 04:38:31 mail kernel: [593531.831355] 0000000000000115 000000006e6a8dad 0000000000000083 ffff88008fc03e50 Aug 9 04:38:31 mail kernel: [593531.831359] Call Trace: Aug 9 04:38:31 mail kernel: [593531.831377] <IRQ> [<ffffffff810d7948>] ? rcu_check_callbacks+0x738/0x740 Aug 9 04:38:31 mail kernel: [593531.831422] [<ffffffff810ec7c0>] ? tick_sched_do_timer+0x40/0x40 Aug 9 04:38:31 mail kernel: [593531.831428] [<ffffffff810dcc54>] ? update_process_times+0x34/0x70 Aug 9 04:38:31 mail kernel: [593531.831432] [<ffffffff810ec45c>] ? tick_sched_handle.isra.12+0x2c/0x70 Aug 9 04:38:31 mail kernel: [593531.831436] [<ffffffff810ec809>] ? tick_sched_timer+0x49/0x80 Aug 9 04:38:31 mail kernel: [593531.831439] [<ffffffff810dd57d>] ? __run_hrtimer+0x6d/0x1b0 Aug 9 04:38:31 mail kernel: [593531.831443] [<ffffffff810ddd4d>] ? hrtimer_interrupt+0xed/0x210 Aug 9 04:38:31 mail kernel: [593531.831448] [<ffffffff815a0c59>] ? smp_apic_timer_interrupt+0x39/0x50 Aug 9 04:38:31 mail kernel: [593531.831458] [<ffffffff8159ecfe>] ? apic_timer_interrupt+0x6e/0x80 Aug 9 04:38:31 mail kernel: [593531.831461] <EOI> [<ffffffff810e3340>] ? ktime_get_ts64+0xa0/0xf0 Aug 9 04:38:31 mail kernel: [593531.831468] [<ffffffff810e32e6>] ? ktime_get_ts64+0x46/0xf0 Aug 9 04:38:31 mail kernel: [593531.831489] [<ffffffff811e8945>] ? poll_select_set_timeout+0x55/0x80 Aug 9 04:38:31 mail kernel: [593531.831495] [<ffffffff8101c43a>] ? emulate_vsyscall+0x34a/0x3c0 Aug 9 04:38:31 mail kernel: [593531.831498] [<ffffffff811e94c3>] ? SyS_select+0xa3/0x110 Aug 9 04:38:31 mail kernel: [593531.831502] [<ffffffff8159de72>] ? system_call_fast_compare_end+0xc/0x6b Aug 9 04:38:31 mail kernel: [593531.831506] rcu_sched kthread starved for 549756 jiffies! Aug 9 04:38:31 mail kernel: [593531.835292] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 1025s! [z-s: 127.0.0.1:4113] Aug 9 04:38:31 mail kernel: [593531.835317] Modules linked in: xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 bridge stp llc overlay ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_tcpudp nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_mangle ip6table_filter ip6_tables xt_state iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_filter ip_tables x_tables rpcsec_gss_krb5 nfsd auth_rpcgss nfs_acl nfs lockd grace fscache sunrpc quota_v2 quota_tree iosf_mbi crct10dif_pclmul crc32_pclmul acpi_cpufreq parport_pc psmouse parport 8250_fintek i2c_piix4 pcspkr evdev processor thermal_sys joydev virtio_balloon serio_raw pvpanic cryptd ext4 crc16 mbcache jbd2 dm_snapshot dm_bufio dm_mirror dm_region_hash dm_log dm_mod hid_generic usbhid hid sg sr_mod cdrom sd_mod ata_generic bochs_drm ata_piix crc32c_intel uhci_hcd ttm libata floppy ehci_hcd drm_kms_helper usbcore virtio_pci drm scsi_mod e1000 virtio_ring usb_common virtio button Aug 9 04:38:31 mail kernel: [593531.835713] CPU: 2 PID: 4113 Comm: z-s: 127.0.0.1 Tainted: G L 4.1.0-ucs190-amd64 #1 Debian 4.1.6-1.190.201604142226 Aug 9 04:38:31 mail kernel: [593531.835716] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 Aug 9 04:38:31 mail kernel: [593531.835720] task: ffff8800894214f0 ti: ffff880089a40000 task.ti: ffff880089a40000 Aug 9 04:38:31 mail kernel: [593531.835722] RIP: 0010:[<ffffffff810e3349>] [<ffffffff810e3349>] ktime_get_ts64+0xa9/0xf0 Aug 9 04:38:31 mail kernel: [593531.835731] RSP: 0018:ffff880089a43a98 EFLAGS: 00000202 Aug 9 04:38:31 mail kernel: [593531.835733] RAX: 85452eb8dcee4485 RBX: ffffffff8105ddee RCX: 00000000000905e4 Aug 9 04:38:31 mail kernel: [593531.835736] RDX: 000000000f1ecb23 RSI: 00000000075e3287 RDI: ffff88008fff2080 Aug 9 04:38:31 mail kernel: [593531.835738] RBP: 00000000058cec20 R08: 0000000000000010 R09: 0000000000000000 Aug 9 04:38:31 mail kernel: [593531.835740] R10: 000000000000000f R11: 0000000000000293 R12: 0000000000000282 Aug 9 04:38:31 mail kernel: [593531.835742] R13: ffff88008a9ff2e8 R14: ffff88008fd17380 R15: ffff88008fd17380 Aug 9 04:38:31 mail kernel: [593531.835745] FS: 00007f36cd485700(0000) GS:ffff88008fd00000(0000) knlGS:0000000000000000 Aug 9 04:38:31 mail kernel: [593531.835748] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Aug 9 04:38:31 mail kernel: [593531.835750] CR2: ffffffffff600400 CR3: 000000008b391000 CR4: 00000000001006e0 Aug 9 04:38:31 mail kernel: [593531.835767] Stack: Aug 9 04:38:31 mail kernel: [593531.835770] ffff880089a43f18 ffff8800894214f0 0000000000000001 ffffffff811e8829 Aug 9 04:38:31 mail kernel: [593531.835774] 0000000057a93988 ffffffff811e8795 0000000000000000 0000000000000000 Aug 9 04:38:31 mail kernel: [593531.835778] 0000000000000000 0000000000000000 0000000000000000 ffffffff811e9c29 Aug 9 04:38:31 mail kernel: [593531.835782] Call Trace: Aug 9 04:38:31 mail kernel: [593531.835789] [<ffffffff811e8829>] ? select_estimate_accuracy+0x29/0xf0 Aug 9 04:38:31 mail kernel: [593531.835793] [<ffffffff811e8795>] ? poll_freewait+0x45/0xb0 Aug 9 04:38:31 mail kernel: [593531.835796] [<ffffffff811e9c29>] ? do_sys_poll+0x4b9/0x510 Aug 9 04:38:31 mail kernel: [593531.835816] [<ffffffff814d9eb8>] ? ip_finish_output+0x1e8/0x830 Aug 9 04:38:31 mail kernel: [593531.835822] [<ffffffff810da808>] ? lock_timer_base.isra.36+0x38/0x70 Aug 9 04:38:31 mail kernel: [593531.835825] [<ffffffff810dbffb>] ? del_timer+0x5b/0x80 Aug 9 04:38:31 mail kernel: [593531.835834] [<ffffffff814ee84c>] ? tcp_validate_incoming+0x12c/0x310 Aug 9 04:38:31 mail kernel: [593531.835839] [<ffffffff811e85c0>] ? poll_schedule_timeout+0x70/0x70 Aug 9 04:38:31 mail kernel: [593531.835863] [<ffffffff81301ee8>] ? copy_to_iter+0x88/0x340 Aug 9 04:38:31 mail kernel: [593531.835881] [<ffffffff8148d26e>] ? skb_copy_datagram_iter+0x5e/0x250 Aug 9 04:38:31 mail kernel: [593531.835886] [<ffffffff81482526>] ? release_sock+0xe6/0x170 Aug 9 04:38:31 mail kernel: [593531.835889] [<ffffffff814e40fd>] ? tcp_recvmsg+0x69d/0xc20 Aug 9 04:38:31 mail kernel: [593531.835894] [<ffffffff810a2b6d>] ? try_to_wake_up+0x1dd/0x330 Aug 9 04:38:31 mail kernel: [593531.835902] [<ffffffff81510fd2>] ? inet_recvmsg+0x72/0x90 Aug 9 04:38:31 mail kernel: [593531.835915] [<ffffffff8147dea4>] ? SYSC_recvfrom+0x114/0x170 Aug 9 04:38:31 mail kernel: [593531.835919] [<ffffffff810e334f>] ? ktime_get_ts64+0xaf/0xf0 Aug 9 04:38:31 mail kernel: [593531.835923] [<ffffffff810e32e6>] ? ktime_get_ts64+0x46/0xf0 Aug 9 04:38:31 mail kernel: [593531.835926] [<ffffffff811e895c>] ? poll_select_set_timeout+0x6c/0x80 Aug 9 04:38:31 mail kernel: [593531.835930] [<ffffffff811e9d50>] ? SyS_poll+0x70/0x100 Aug 9 04:38:31 mail kernel: [593531.835934] [<ffffffff8159de72>] ? system_call_fast_compare_end+0xc/0x6b Aug 9 04:38:31 mail kernel: [593531.835936] Code: 9d 00 3b 2d da 2f 9d 00 75 97 48 01 f0 48 03 0b 48 3d ff c9 9a 3b 76 2a 31 d2 0f 1f 84 00 00 00 00 00 48 2d 00 ca 9a 3b 83 c2 01 <48> 3d ff c9 9a 3b 77 ef 48 01 ca 48 89 43 08 48 89 13 5b 5d 41 Aug 9 04:38:31 mail rsyslogd-2177: imuxsock lost 115410 messages from pid 21674 due to rate-limiting Aug 9 04:38:32 mail /USR/SBIN/CRON[21060]: (root) CMD (/usr/share/univention-ldap/create-dh-parameter-files) Aug 9 04:38:33 mail mysqld: 160809 4:38:33 [Note] /usr/sbin/mysqld: Normal shutdown Aug 9 04:38:33 mail mysqld: Aug 9 04:38:33 mail mysqld: 160809 4:38:33 [Note] Event Scheduler: Purging the queue. 0 events Aug 9 04:38:36 mail mysqld: 160809 4:38:36 [Warning] /usr/sbin/mysqld: Forcing close of thread 2304 user: 'zarafaDbUser' Aug 9 04:38:36 mail mysqld: Aug 9 04:38:36 mail mysqld: 160809 4:38:36 [Warning] /usr/sbin/mysqld: Forcing close of thread 44 user: 'zarafaDbUser' Aug 9 04:38:36 mail mysqld: Aug 9 04:38:38 mail mysqld: 160809 4:38:38 InnoDB: Starting shutdown...

Das einzig ungewöhnliche ist hier dass plötzlich Zeilen mit Datum 1.Oktober auftauchen.

Kann das das Problem sein? Ist es möglich dass irgendein Dienst eine andere Zeit und Darum verwendet?

LG mandelbrot


#11

Das einzig Komische? Das, was mir sofort ins Auge springt, sind die Meldungen über hängende Prozesse vom Kernel, die auf einem normal funktionierenden System normalerweise nie auftauchen sollten. Das sieht mir aufgrund von »Bochs« nach einem virtualisierten System aus, oder? Ich rate, dass Sie das System (also das komplette Betriebssystem inklusive Zarafa und seiner Daten, nicht aber den Virtualisierer selbst) einmal auf eine andere Hardware umziehen; direkt auf Hardware ist eine Option, eine andere ist z.B. die Verwendung des kostenlosen VMware ESXi als Virtualisierer dazwischen. Wir sind nun im Bereich potenzieller Fehler der Hardware oder der Virtualisierungsschicht, und da heißt es: Ausschließen möglicher Fehlerquellen.


#12

Hallo,

Sorry, ich bin da nicht so fit was die Fehlermeldungen betrifft.

Also wir haben eine Qnap auf welcher virtuell der Univention-Server inkl. Zarafa läuft.
Dies mittlerweile schon über 1 Jahr.
Es gab damit auch nie Probleme bis das Update auf ZCP 7.2.1 kam.
Seit dem haben wir 2-3 Mal pro Woche die oben beschriebenen Ausfälle.

Leider hab ich nicht die Möglichkeit die VM auf andere Hardware zu schieben da wir nur diese eine Qnap haben. Welche Möglichkeiten gäbe es noch um die Probleme in den Griff zu bekommen?

LG


#13

Hallo nochmal,

Anhand welcher Fehlermeldungen erkennen sie die hängenden Prozesse?

LG


#14

Moin,

Sie verwechseln hier Korrelation und Kausalität. Nur, weil Sie meinen, dass zwei Ereignisse (Upgrade ZCP sowie die beobachteten Fehler) im zeitlichen Zusammenhang (Korrelation) stehen, bedeutet das noch lange nicht, dass sie auch in irgend einer Form voneinander abhängen oder das eine Ursache des anderen ist (Kausalität). Wir Menschen sind extrem schlecht darin, intuitiv zu entscheiden, ob solche Ereignisse zusammenhängen. Wir merken uns sehr leicht gewisse Dinge (»ich habe ZCP manuell aktualisiert«), aber viele andere Dinge, die ebenfalls geschehen können sein (z.B. dabei ein Kernelupgrade, oder ein Upgrade der QNAP-Firmware, oder die Tatsache, dass das Problem bereits vor dem Upgrade mal aufgetaucht ist aber dann als einmaliges Ereignis abgetan wurde), entgehen völlig unserer Wahrnehmung.

Konkret: die Meldungen, die ich meine, sind der komplette Block, bei dem die Zeilen mit »kernel:« bezeichnet sind. Bereits die erste Zeile »rcu_sched detected stalls on CPU/tasks…« ist das, was mich aufmerksam gemacht hat. Weiter unten finden Sie »NMI watchdog: BUG: soft lockup - CPU#2 stuck for 1025s!« (wobei das meiner Erfahrung nach nur eine Folgeerscheinung der ersten Meldung ist, sie ist also nicht Ursache sondern ein Symptom). Direkt im Anschluss beendet sich MySQL. Auch hier kann man argumentieren, dass zeitliche Korrelation zwischen den Kernel-Meldungen und dem MySQL-Shutdown nicht zwangsläufig Kausalität bedeutet, also dass die Kernelmeldungen und der Shutdown begründet zusammenhängen, aber ich vermute, dass Sie ähnliche Abfolgen finden würden, wenn Sie ältere syslog-Dateien durchsuchen würden.

Was so eine Meldung bedeutet? Es gibt da leider viele mögliche Ursachen. Eine ist ein Bug im Kernel (eher selten, passiert aber mal), eine andere sind unerwartete Hänger in Codepfaden, in denen es keine Hänger geben sollte, z.B. aufgrund von defekter Hardware — oder aber aufgrund von Inkompatibilitäten mit der Virtualisierung oben drüber. Dort können genau so Bugs enthalten sein.

Was meiner Erfahrung nach aber nie eine Ursache für solche Meldungen ist, sind User-Space-Programme wie Amavis, MySQL oder Zarafa. Die können höchstens das eigentliche Problem triggern.

Daher kann ich wirklich nur mit Nachdruck raten, die Maschine auf eine andere Hardware umzuziehen, um zu testen, ob sich am Verhalten etwas ändert. Wenn das partout nicht möglich ist, dann können Sie noch versuchen, UCS mit einer anderen Kernel-Version laufen zu lassen. Weiterhin sollten Sie prüfen, ob es für die QNAP neuere Firmware gibt und falls ja auch diese testweise ausprobieren.

Gruß,
mosu