Seltsames Problem: "syslog-ng" beendet sich oder crasht evtl. nach SIGHUP
Hallo, ich habe seit einigen Wochen einen AMD-Opteron-basierten File-Server im Testeinsatz. Auf dieser Maschine ist SuSE Linux 10.0 installiert, als Kernel läuft ein Vanilla-2.6.14. Am Samstag um 10:30 Uhr hat "cron.daily" das Kommando "logrotate" ge- startet. So weit - so gut. Gegen Mittag wollte ich mich remote via SSH auf der Maschine einloggen. Zwar kam ich noch bis zur Passwortabfrage des SSH-Clients, aber dann hing das Login. Andere Dienste, die auf das ebenfalls auf dieser Ma- schine gehaltene OpenLDAP-Verzeichnis zugreifen wollten, hingen eben- falls. Der auf der selben Maschine laufende Webserver dagegen publizierte zur gleichen Zeit die vorhandenen Test-Webseiten absolut problemlos. Ich fuhr dann am Samstagnachmittag hin zum Standort des Servers und stellte fest: Auch an der Konsole ist kein Login mehr möglich. Eben- falls war nichts Spannendes auf der Konsole, die per "ALT+F10" erreich- bar ist, zu finden. Die Maschine an sich lief aber noch. Der darauf laufende Webserver antwortete einwandfrei und performant. Nach einem Reset lief der Rechner wieder "normal". Interessant war: Seit 10:30:01 Uhr gab es keine Logfile-Einträge in "/var/log/messages" bzw. "/var/log/warn" mehr. Also gut - ich dachte, der OpenLDAP-Server hatte sich aufgehängt und daher Probleme mit dem Login gemacht. Ich hatte anschließend auch in "/etc/ldap.conf" Timeout-Parameter gesetzt, damit im Falle eines nicht erreichabren OpenLDAP-Servers das PAM nicht ewig wartet, sondern lo- kale Benutzer "zur Not" auch bei nicht funktionierendem OpenLDAP-Server reinlässt. Also gut - getestet - Login klappt zur Not auch ohne einen laufenden OpenLDAP-Server nach einem gewissen Timeout von 30 Minuten. Über die Tatsache, weshalb seit 10:30:01 Uhr kein Logfile-Eintrag mehr geschrieben wurde, machte ich mir dort aber noch keine Gedanken. Nächstes Ereignis: Am Sonntag war ich schon am frühen morgen per SSH einloggt (besser ge- sagt - ich hatte die Shell noch vom Samstagabend her offen, und hatte den ganzen Sonntag noch nicht auf der Maschine gearbeitet). Gegen 14 Uhr wollte ich mich mit einer weiteren Shell einloggen, da ich zwei Kommandozeilenfenster zum Server haben wollte für diverse Arbeiten. Aber: Das selbe Problem wie am Tag zuvor: Auf der zweiten Shell war kein Login möglich. SSH-Daemon fordert (ziemlich träge) das Passwort an und macht nach Eingabe desselben gar nichts mehr. Ich beendete und restartete in der ersten Shell diverse Dienste, da ich dachte, sie seien evtl. für das Verhalten verantwortlich. Nichts zu sehen. Auch nichts, was massenhaft CPU oder Speicher in Anspruch nahm. Dann blickte ich nach "/var/log/messages" und sah mir gegen 14 Uhr die letzten Ausgaben an: | Oct 30 09:30:02 fsa01-neu slapd[5549]: conn=0 op=583 SRCH base="dc=egu,dc=schule,dc=ulm,dc=de" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=squid))" | Oct 30 09:30:02 fsa01-neu slapd[5549]: conn=0 op=583 SRCH attr=uid userPassword uidNumber gidNumber cn homeDirectory loginShell gecos description objectClass | Oct 30 09:30:02 fsa01-neu slapd[5549]: <= bdb_equality_candidates: (uid) index_param failed (18) | Oct 30 09:30:02 fsa01-neu slapd[5549]: conn=0 op=583 SEARCH RESULT tag=101 err=0 nentries=0 text= | Oct 30 09:30:02 fsa01-neu syslog-ng[4813]: SIGHUP received, restarting syslog-ng | Oct 30 09:30:03 fsa01-neu slapd[5549]: conn=0 op=584 SRCH base="dc=egu,dc=schule,dc=ulm,dc=de" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=man))" Ah ja. Die Maschine hatte die ganze Nacht durch diverse Meldungen der OpenLDAP-DB nach "/var/log/messages" geschrieben. Ist ja auch okay. Aber um 09:30 Uhr, genau 24 Stunden nach dem Log-Stopp am Samstag (-> Zeitumstellung) hört das Logging erneut auf. Nach einem Restart des "syslog-ng"... | Oct 30 14:39:09 fsa01-neu syslog-ng[5985]: syslog-ng version 1.6.8 starting ...konnte ich mich dann problemlos wieder einloggen: | Oct 30 14:39:14 fsa01-neu sshd[5889]: Accepted keyboard-interactive/pam for root from 10.0.0.1 port 35203 ssh2 Nun habe ich nicht darauf geachtet, ob der "syslog-ng" tot war oder gar nicht mehr lief. Mein Verdacht war dann: "logrotate" schickt (wenn es was zu rotieren gibt) - laut der Da- tei "/etc/logrotate.d/syslog" ein "/etc/init.d/syslog reload". Das wiederum dürfte ein "SIGHUP" senden. Heute (Montag) ist nichts passiert. "syslog-ng" loggt einwandfrei und neue SSH-Connections sind auch kein Problem. Aber heute hat "logrotate" auch nichts zum Rotieren gehabt. Also auch keine "post- rotate"-Kommandos, und damit kein "/etc/init.d/syslog reload". Seltsamerweise kann ich das Aufhängen (oder Beenden) des "syslog-ng" nicht provozieren, indem ich den "/etc/init.d/syslog reload" manuell ausführe. Ich warte jetzt also ab bis "logrotate" wieder rotiert. Die Fragen, die sich mir stellen, sind jetzt: - Warum "spinnt" der "syslog-ng" herum, wenn er ein HUP-Signal ge- sendet bekommt? Warum hört er dann mit dem Logging auf? - Hat dieses Verhalten denn sonst schon jemand beobachtet, ins- besondere unter SuSE Linux 10.0 x86_64? Die neusten SuSE-Updates dürften alle eingespielt sein. Bis auf den Vanilla-2.6.14-Kernel sind eigentlich keine großartigen Ver- änderungen an der Standardinstallation vorgenommen worden. - Wie verhält sich denn ein Rechner, bei dem der Syslog-Daemon gar nicht mehr läuft? Kann es tatsächlich zu dem von mir beobachteten Fall kommen, dass nach einer gewissen Zeit die Dienste, die loggen wollen, hängen? Wenn ich das richtig sehe, schreiben die Dienste, die loggen wollen, in das "named socket" unter "/dev/log" rein. Was aber passiert, wenn dort niemand mehr rausliest? Puffert der Kernel eine Weile? Und erst nach einer gewissen Anzahl an Meldungen passiert's? Denn, wenn ich den "syslog-ng" manuell beende, kann ich mich (zumin- dest unmittelbar danach) noch problemlos via SSH einloggen oder an- dere Dienste benutzen, die loggen (z.B. OpenLDAP-Anfragen stellen). Längere Zeit hatte ich den Syslog-Daemon bisher nicht absichtlich beendet lassen. Oder treten die Hänger der Applikationen nur dann auf, wenn Syslog- Daemon-Prozess zwar noch läuft, sich aber aufgehängt hat? Fragen über Fragen. Vielleicht weiß ja hier jemand weiter oder kann zumindest Details zur Arbeit des Syslog-Daemons sagen. Ich wollte auf jeden Fall mal auf Nummer sicher gehen, bevor ich an SuSE einen Bug melde bzgl. "syslog-ng". Danke und Grüße, Steffen
Hallo Steffen,
Am Samstag um 10:30 Uhr hat "cron.daily" das Kommando "logrotate" ge- startet. So weit - so gut.
Na ja, vielleicht war das die Wurzel allen Übels. Ist dein /tmp vielleicht "noexec" gemountet? Dann hast du das selbe Problem wie ich vor einiger Zeit: http://lists.suse.com/archive/suse-linux/2005-Oct/1745.html Die Lösung ist hier http://lists.suse.com/archive/suse-linux/2005-Oct/2327.html http://www.rootforum.de/forum/viewtopic.php?p=236919 Zur Erklärung: logrotate legt in /tmp ein Skript mit dem postrotate-Befehl an. Ist /tmp auf noexec, schlägt die Ausführung diese Skriptes fehl. Der zweite "Lösungs"-Link oben enthält eine mögliche Abhilfe durch setzen eines anderen Verzeichnisses für temporäre Dateien. Viele Grüße, Bernhard
Hallo Bernhard, * On Mon, Oct 31, 2005 at 04:04 PM (+0100), Bernhard Schalk wrote:
Nein, das ist hier nicht der Fall. Habe gerade zur Sicherheit nochmals nachgesehen: | fsa01-neu:~ # mount | | /dev/md1 on / type ext3 (rw,acl,user_xattr) | proc on /proc type proc (rw) | sysfs on /sys type sysfs (rw) | tmpfs on /dev/shm type tmpfs (rw) | devpts on /dev/pts type devpts (rw,mode=0620,gid=5) | /dev/md0 on /boot type ext3 (rw,acl,user_xattr) | /dev/md3 on /tmp type ext3 (rw,acl,user_xattr) | /dev/md2 on /usr type ext3 (rw,acl,user_xattr) | /dev/md4 on /var type ext3 (rw,acl,user_xattr) | /dev/mapper/system-home on /home type xfs (rw,usrquota) | /dev/mapper/system-export on /srv/export type xfs (rw) | usbfs on /proc/bus/usb type usbfs (rw) Da die Maschine auch "nur" als Fileserver läuft und wir unseren Usern keine lokale Shell geben, habe ich bislang auch noch keinen Grund ge- sehen, "/tmp" mit "noexec" zu mounten. Aber trotzdem - vielen Dank für den Tipp. Wenn es daran gelegen hätte, wäre ich -wenn überhaupt- erst nach sehr, sehr langem Suchen drauf ge- stoßen. Gruß, Steffen
Hallo Andreas, * On Mon, Oct 31, 2005 at 05:30 PM (+0100), Andreas Winkelmann wrote:
Ja, den Speicher habe ich geprüft, diverse CPU-Test-Geschichten ließ ich auch relativ lange drüberlaufen. Der Grund dafür: Nach dem Zusammenbau dieser Dual-Opteron-Maschine (zwei Opteron Single-Core-CPUs 246 und 2 GB RAM auf einem Tyan Thunder S2892) hatte ich das Problem, dass "grep" ständig crashte: | Oct 20 14:30:44 fsa01-neu kernel: grep[15069]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf30 error 4 | Oct 20 14:30:44 fsa01-neu kernel: grep[15079]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf30 error 4 | Oct 20 14:30:59 fsa01-neu kernel: grep[15489]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf50 error 4 | Oct 20 14:31:00 fsa01-neu kernel: grep[15543]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf50 error 4 | Oct 20 14:31:00 fsa01-neu kernel: grep[15573]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf50 error 4 | Oct 20 14:31:08 fsa01-neu kernel: grep[16055]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf60 error 4 Ich gehe davon aus, dass ich auf diesen Hardware-Bug gestoßen bin, der leider erst von aktuellen Kernels "aufgedeckt" wurde: http://bugzilla.kernel.org/show_bug.cgi?id=4851 Das ist auch der Grund, weshalb ich nicht den mit der SuSE 10.0 mitge- lieferten SuSE-Kernel einsetze, sondern einen Vanilla-2.6.14. Dieser erkennt, dass die Hardware diesen Bug hat und berücksichtigt dies, indem er das entsprechende Feature deaktiviert. So erklärte es mir jedenfalls Andi Kleen von SuSE. Jedenfalls hatte ich seit dem Einsatz von 2.6.14 auch keinerlei "grep"- Crashes mehr - und der Rest läuft stabil. Naja, von "traceroute" einmal abgesehen, das hängt sich manchmal auf. Aber das dürfte 'ne andere Bau- stelle sein. Gruß, Steffen
Hallo Andreas, * On Mon, Oct 31, 2005 at 08:25 PM (+0100), Andreas Winkelmann wrote:
Die Filesysteme habe ich inzwischen gecheckt (es sind "ext3"- und "xfs"-Systeme im Einsatz, wobei die systemrelevanten Dinge alle auf "ext3" liegen und die "xfs"-Dateisysteme für die eigentlichen Nutz- daten der Fileserver-Dienstes da sind, wie z.B. "/home" oder "/export"). Keine Fehler gefunden. Natürlich habe ich bei den "ext3"- Filesystemen einen Check erzwungen. Die Platten an sich hatte ich vor zwei Wochen unmittelbar nach dem Zusammenbau des Rechners mit "badblocks" getestet. Keine Fehler. Auch die SMART-Werte sehen gut aus, Meldungen über Lese-/Schreib- probleme seitens des Kernels gab es bislang auch keine. Auch RAM und CPU zeigten, wie gesagt, bei keinem Test Probleme.
Nun, die Frage ist sicher berechtigt. Allerdings scheint das ein klar umgrenzter Bug der Hardware (Mainboard oder CPUs) zu sein, der einfach dadurch "umschifft" wird, indem das entsprechende Feature vom Kernel nicht genutzt wird, so wie es schon frühere Kernel-Versionen nicht genutzt haben (und damit wohl unentdeckt blieb). Anscheinend soll aber der Hersteller des Mainboards (Tyan) an einem BIOS-Update arbeiten (und es für verwandte Boards schon draußen haben), das dieses Problem lösen soll. Wobei ich fairerweise dazusagen muss, dass ich noch nicht weiß, ob damit wirklich das Problem an sich gelöst wird oder ob da ebenfalls nur ein "buggy Feature" der Opteron-CPUs "unterdrückt" wird. Ich werde mir die Details zu diesem Bug ansehen. Ich weiß z.B. momentan nicht, ob es sich um einen Bug in den Opteron-CPUs oder um einen Bug im Mainboard handelt. Auf jeden Fall plant wohl auch SuSE, zukünftige SuSE-Kernels abchecken zu lassen, ob auf der Hardware dieser Bug vorliegt oder nicht. Je nach dem wird dann von dem Feature Gebrauch gemacht oder eben nicht. Momentan kann der SuSE-Kernel der 10.0 das wohl noch nicht, aber der 2.6.14 ist dazu in der Lage. Danke und Grüße, Steffen
Hallo, * On Mon, Oct 31, 2005 at 08:56 PM (+0100), Steffen Moser wrote:
So, wie ich das verstehe, ist es ein Bug in einigen AMD-Opteron-CPUs: http://bugzilla.kernel.org/show_bug.cgi?id=4851 Von AMD gibt es dazu auch ein Paper, das den Fehler zumindest er- wähnt: http://www.amd.com/us-en/assets/content_type/white_papers_and_tech_docs/3334... Durch ein BIOS-Update sollte sich das Problem auch bei meinem Board (Tyan Thunder K8SE S2892) umgehen lassen, in dem wohl das BIOS dem OS das entsprechende buggy Feature der CPU nicht mehr mitteilt. Danach macht das OS davon keinen Gebrauch mehr. Das BIOS habe ich inzwischen upgegraded. Da ich aber eh schon einen Kernel eingesetzt habe (2.6.14), der das Feature nicht benutzt, wenn der Bug vorliegt, merke ich vermutlich diesbezüglich nichts davon. Ich bin bislang noch nicht dazu gekommen, zu testen, wie sich das System nun verhält, wenn ich den mitgelieferten SuSE-Kernel starte. Aber, mit anderen Worten: Ich denke, dass diese Sache zumindest damit keine Relevanz für mein Syslog-Problem mehr hat. Die in http://lists.suse.com/archive/suse-linux/2005-Oct/2586.html von mir am Rande erwähnten Probleme mit "traceroute" dürften ein Problem mit dem Kernel 2.6.14 sein. Zumindest gibt es dort bereits Beobachtungen von anderen Usern: http://lkml.org/lkml/2005/10/31/216 Ob mein Syslog-Problem damit zusammenhängt, muss ich noch klären. Gruß, Steffen
Hallo, * On Tue, Nov 01, 2005 at 08:41 AM (+0100), Steffen Moser wrote:
Für's Archiv und der Vollständigkeit halber: Das "traceroute"-Problem war ein Kernel-Problem in 2.6.14, gefixt durch den Patch: --- a/net/core/datagram.c 2005-11-01 11:38:31.000000000 +0100 +++ b/net/core/datagram.c 2005-11-01 11:38:45.000000000 +0100 @@ -213,6 +213,10 @@ { int i, err, fraglen, end = 0; struct sk_buff *next = skb_shinfo(skb)->frag_list; + + if (!len) + return 0; + next_skb: fraglen = skb_headlen(skb); i = -1; Gruß, Steffen
Moin, On Mon, 31 Oct 2005 15:37:34 +0100 Steffen Moser <lists@steffen-moser.de> wrote:
Jepp.
- Warum "spinnt" der "syslog-ng" herum, wenn er ein HUP-Signal ge- sendet bekommt? Warum hört er dann mit dem Logging auf?
Du kannst definitiv ausschließen, dass du auch noch andere Logfiles rotierst, deren Dienste nicht neugestartet werden? Insbesondere hier wohl LDAP (scheint aber ja ins Syslog zu gehen), named, nscd.
Die Aufrufe an die jeweiligen Logging-Routinen blocken dann für gewöhnlich. /dev/log ist ja ein FIFO, der hat glaube ich immer einen gewissen Puffer (8k?).
Ich glaube eher nicht an den syslog-Dienst als Schuldigen. Ich vermute, du ziehst einem anderen Dienst sein Logfile mit logrotate weg und startest ihn nicht neu (oder bringst ihn anders dazu, das Logfilehandle zu schließen und neu zu öffnen). Irgendwas kritisches... Dafür spricht ja auch, dass erstmal alles weiterläuft, wenn du syslog-ng beendest. Gruß, -hwh
Hallo Hans-Werner, * On Mon, Oct 31, 2005 at 04:15 PM (+0100), Hans-Werner Hilse wrote:
Ich kann sonst nichts erkennen. Außerdem war ja wirklich in "messages" nichts mehr los nach dem "rotate". Und dass keiner der Dienste (auch der zunächst mehrfach neu gestartete LDAP-Daemon) gar nichts vom Syslog protokollieren ließ, wäre ja eher seltsam. Den "nscd" hatte ich am Sonn- tag übrigens auch mehrfach neu gestartet. Also gehe ich schon davon aus, dass "syslog-ng" Probleme hatte. Aller- dings wurde nur am Samstag "messages" rotiert. Am Sonntag war dafür die "localmessages" dran - aber auch die wird ja vom Syslog beschrieben, al- so hat er den SIGHUP gekriegt (und der steht ja noch im Logfile drin). Ich habe eben noch weiter gestetet, d.h. die Logfiles künstlich gefüllt und mehrfach dafür gesorgt, dass die Skripte in "/etc/cron.daily" abge- arbeitet wurden. Ich konnte den Fehler nicht provozieren. Das "logrotate" rotierte einwandfrei - auch Dateien des Syslogs und reloadete ihn neu.
Okay... Ich schalte jetzt mal den "syslog-ng" ab und warte ein paar Stunden, ob sich das System dann genauso verhält wie am Samstag und am Sonntag. Um einen Vor-Ort-Einsatz zu umgehen, lasse ich eine SSH- Connection offen.
Oder aber der Puffer des FIFO hat bei meinen kurzen Abschaltungen soweit erstmal alles aufgenommen. Daher lasse ich ihn jetzt mal längere Zeit aus und sorge dafür, dass z.B. der LDAP etwas loggt. Da die Maschine noch nicht wirklich im Einsatz ist (sondern erst in etwa einer Woche richtig genutzt werden soll), spielt es keine Rolle, wenn heute Abend für einige Stunden nicht mitgeloggt wird. Aber auf jeden Fall einmal Danke für Deine Hinweise - ich werde auch insbesondere noch auf andere Dienste und deren Logfiles achten. Viele Grüße, Steffen
Hallo nochmal, On Mon, 31 Oct 2005 18:07:31 +0100 Steffen Moser <lists@steffen-moser.de> wrote:
Einen hab' ich jetzt doch noch, und das wird abenteuerlich: hast du die Unix-Authentifizierung über das LDAP laufen, das der Rechner selbst über den besagten LDAP-Dienst anbietet? Dann könnten wir u.U. eine Art Race Condition haben. Wenn dann nämlich der Neustart von syslog-ng eine Anfrage an das LDAP-Verzeichnis provoziert (z.B. Rechte des ausführenden Nutzers etc.pp.) _und_ dabei der FIFO voll läuft _und_ dadurch dann OpenLDAP blockt, ja dann beißt sich die Katze in den Schwanz und nichts geht mehr (sprich, es hängt der Neustart des syslog-ng fest). Gruß, -hwh
Hallo Hans-Werner, * On Mon, Oct 31, 2005 at 09:09 PM (+0100), Hans-Werner Hilse wrote:
Ja, das habe ich...
Dann könnten wir u.U. eine Art Race Condition haben.
Das könnte in der Tat sein. Du wirst lachen, ich hatte schon an eine Art "Race Condition" gedacht, was das Neustarten des Syslog betrifft, ich dachte aber gar nicht an den OpenLDAP, sondern eher daran, dass es vielleicht mit anderen Cron-Daily-Jobs Probleme gibt und hatte da- her gestern bei meinen Erzwungenen Cron-Daily-Läufen auch versucht, eben nicht nur "logrotate" auszuführen, sondern alle Cron-Daily-Ge- schichten. Aber das, was Du hier schreibst, ist ein hochinteressanter Aspekt, dem ich nachgehen werde.
Wieso "syslog-ng" das tun sollte, ist mir zwar noch nicht ganz klar, aber ausschließen kann ich's nicht. "syslog-ng" läuft natürlich als "root" und "root" wird lokal verwaltet. Aber vielleicht ist es ja auch nur eine Anfrage im Rahmen von "nss_ldap", also z.B. die Auf- lösung irgend eines Namens (nein, die Hostnamen verwalte ich schon per DNS, aber vielleicht irgendwie "Benutzername <---> UID").
Auf jeden Fall schonmal vielen Dank für den Tipp, das muss ich un- bedingt näher untersuchen... Bei meinen Tests mit abgeschaltetem Syslog gestern Abend blieb das System übrigens über Stunden stabil. Ein "strace" von "/bin/logger" zeigte auch, dass es beim Versuch, "/dev/log" zu öffnen, während der Syslog abgeschaltet ist, einfach ein "Connection refused" gibt und "/bin/logger" dann halt nichts schreibt - und fertig. Es kam auf jeden Fall (selbst nach dem ich bei abgeschaltetem Sys- log in einer Endlosschleife den "/bin/logger" massiv loggen ließ) nicht zu einer Situation, wo "/bin/logger" in irgend einer Art und Weise auf das "/dev/log"-Socket gewartet hatte und sich dabei ver- klemmte. Das würde auf jeden Fall dagegen sprechen, dass der Syslog beim Auf- treten des Problems am Samstag und Sonntag "abgestellt" war. Er müsste zumindest noch soweit aktiv gewesen sein, dass Anwendungen versucht haben, nach "/dev/log" zu schreiben, also nicht schon gleich mit einem "Connection refused" abgewiesen wurden. Ich weiß leider zu wenig, wie "named sockets" funktionieren. Es gibt auch Unterschiede zwischen "named sockets" und FIFOs. Die "named sockets" haben ja ein "s" im "Spezialflag" des Dateisystems, während die FIFOs (oder auch "named pipes") ein "p" haben: | steffen@pc01:~> ll /dev/log | srw-rw-rw- 1 root root 0 2005-10-15 20:08 /dev/log Ich versuche jetzt einmal abzuklären, ob es tatsächlich zu einer "Race Condition" kommen kann. So nach dem Motto: Der Syslog will reloaden. Er läuft dabei. Er muss aber zum Reload -aus welchem Grund auch immer- den OpenLDAP fragen. Dieser will daraufhin auch antworten, aber loggt natürlich erstmal. Da der Syslog noch läuft, kriegt der OpenLDAP auch kein "Connection refused" beim Öffnen des Log-Sockets. Also schreibt der OpenLDAP ins Log-Socket, aber auf der anderen Seite liest niemand raus, und OpenLDAP hängt fest. Der Syslog kommt dann nie zu seiner angeforder- ten Antwort. Dem gehe ich nachher einmal nach... Es muss ja auch gar nicht unbe- dingt "OpenLDAP" sein, sondern evtl. ein ganz anderer Prozess, der dann den Syslog blockiert. Viele Grüße, Steffen
Hallo Hans-Werner, * On Tue, Nov 01, 2005 at 09:01 AM (+0100), Steffen Moser wrote:
Und genau in die Richtung scheint es zu gehen! Gerade ist es bei einem manuell initiierten "SuSEconfig"-Lauf wieder dazu gekommen: - OpenLDAP lief zunächst nicht (wegen Offlinearbeiten an der OpenLDAP- DB) - "syslog-ng" hat sich reloadet (vermutlich irgendwo von SuSEconfig dazu initiiert) - Mehr oder weniger parallel dazu habe ich "rcldap start" ausgeführt, also den OpenLDAP-Dämon gestartet. - Ausgabe in "/var/log/messages": | Nov 2 16:25:41 fsa01-neu syslog-ng[7574]: SIGHUP received, restarting syslog-ng - "strace -s 255 -p 7574" ergibt: | fsa01-neu:/var/lib/ldap # strace -s 355 -p 7574 | Process 7574 attached - interrupt to quit | sendto(4, "<14>Nov 2 16:25:54 syslog-ng: nss_ldap: reconnecting to LDAP server (sleeping 16 seconds)...", 93, MSG_NOSIGNAL, NULL, 0 (Ich habe gestern bereits herausgefunden, dass ein "rcsyslog reload" auf jeden Fall die "nss_ldap" aufruft). - Jetzt hängt der "syslog-ng" fest, obgleich "nss_ldap" eigentlich in der "/etc/ldap.conf" einen Bind-Timeout von 30 Sekunden konfi- guriert bekommen hat. - Wenn ich "strace logger Hallo!" eintippe, sehe ich, wie "logger" das "/dev/log" öffnen möchte und dann ebenso hängen bleibt... Er kriegt (wie gestern schon vermutet) eben gerad kein "Connection re- fused", da eben der Syslog doch noch läuft (aber festhängt). - Und wenn ich mich per "strace" in "slapd" einklinke, dann sehe ich, (welch Überraschung): | fsa01-neu:~ # strace -s 255 -p 21055 | Process 21055 attached - interrupt to quit | sendto(3, "<167>Nov 2 16:25:50 slapd[21055]: bdb_db_destroy: txn_checkpoint failed: Invalid argument (22)\n", 96, MSG_NOSIGNAL, NULL, 0 Und das ist genau eine Syslog-Ausgabe. Ich wette, dass die "3" das Handle für "/dev/log" ist. - Mit anderen Worten: "syslog-ng" will etwas vom OpenLDAP. Dieser will aber erst diesen DB-Fehler loggen. Das führt zur Blockade. - Alle anderen Dienste, die loggen wollen, hängen auch fest. Denn das "/dev/log" lässt sich ja öffnen. So ist aktuell (wie am Wochenende) kein SSH-Login möglich. Der SSHD hängt fest, weil er loggen will: | fsa01-neu:~ # strace -s 255 -p 21155 | Process 21155 attached - interrupt to quit | sendto(4, "<35>Nov 2 16:43:49 sshd[21155]: pam_ldap: ldap_simple_bind Can\'t contact LDAP server", 85, MSG_NOSIGNAL, NULL, 0 Jetzt muss ich noch schauen, wie ich das sicher reproduzieren kann, dann geht's an SuSE als Bugreport raus. Gestern hatte ich einige Zeit herumgespielt, es aber nicht "auf Befehl" hingekriegt. Die Frage dürfte vor allem sein: Wieso braucht "syslog-ng" die "nss_ldap" und wieso hilft hier der Timeout nicht aus der Ver- klemmung? Nochmals - ganz herzlichen Dank für Deinen Tipp. Der ging genau in die richtige Richtung! Ich hätte vermutlich noch ewig gesucht. Mich wundert bloß: Bin ich wirklich der Erste, dem dies auffällt, schließlich verwende ich ja weitgehend eine SuSE-Standardkonfigu- ration? Viele Grüße, Steffen
Moin, On Wed, 2 Nov 2005 16:47:14 +0100 Steffen Moser <lists@steffen-moser.de> wrote:
syslog-ng parst die Konfiguration neu. Dabei dürften die Anfragen rausgehen. Vielleicht der Nutzer/die Gruppe, auf die syslog-ng seine Rechte abwirft, vielleicht Einstellungen zu den Rechten der Logfiles oder des Unix-Sockets (/dev/log). Das Problem scheint nss_ldap zu sein. Es blockt nämlich scheinbar, wenn der Unix-Socket zwar bereits offen ist - es gibt schließlich auch schon ein Handle - aber die hineingeschriebenen Daten nicht liest. Das MSG_DONTWAIT-Flag bei sendto ist ja auch nicht gesetzt. Der kürzeste Weg aus der Misere scheint mir zu sein, mal /etc/nsswitch.conf zu checken. Sollte so aussehen: passwd: files ldap (und nicht "passwd: ldap files") gilt auch für die anderen. Die Bedeutung ist dann anders: Es wird erst versucht, auf Dateibasis alles zu machen, und wenn's da Probleme gibt, wird auf LDAP zurückgegriffen. Dann müssen natürlich die User rund um syslog-ng auch über das "files"-Modul verfügbar sein. Grundsätzlich wäre es bei so etwas grundlegendem wie dem nss_ldap/pam_ldap-Modul vielleicht auch besser, mit einem Timeout zu arbeiten... (achso ja, in /etc/pam.d natürlich auch nach der Präferenz der Authentifizierungsverfahren gucken, sollte hier aber mangels Authentifikation nicht relevant sein, wenn ich nicht irre). Vielleicht magst du ja auch deine augenblickliche Fassung von /etc/nsswitch.conf mal posten. Gruß, -hwh
Hallo Hans-Werner, * On Wed, Nov 02, 2005 at 07:55 PM (+0100), Hans-Werner Hilse wrote:
Ich gehe davon aus, dass das die Ursache war. Ich musste wohl in einem Zustand geistiger Umnachtung dort "ldap compat" reinge- schrieben haben. Ich habe nach Deiner Mail das auf "compat ldap" geändert ("files ldap" ginge natürlich auch). Komischerweise konnte ich unmittelbar nach der Korrektur nochmals einen Hänger provozieren, als ich den "SuSEconfig" ausführte und dieses den "syslog-ng" wohl ebenfalls neu startete. Möglicherweise hatte dabei der "nscd" seine Finger im Spiel und noch die Informa- tion gecacht, dass zuerst das LDAP-Verzeichnis zu befragen ist. Ich habe es dann aber vorerst nicht näher untersucht, allerdings jetzt einige Wochen beobachtet: "logrotate" hat in der Zeit jetzt einige Male die Logfiles rotiert und das Problem ist seither nicht mehr aufgetreten.
Danke für die Erklärung. War mir eigentlich schon klar, ich weiß selbst nicht mehr, warum ich da "ldap compat" reingeschrieben hatte. ;-) Nochmals Danke für Deine zahlreichen Tipps! Ich gehe davon aus, dass das Problem dadurch erledigt ist. Viele Grüße, Steffen
Hallo Steffen,
Am Samstag um 10:30 Uhr hat "cron.daily" das Kommando "logrotate" ge- startet. So weit - so gut.
Na ja, vielleicht war das die Wurzel allen Übels. Ist dein /tmp vielleicht "noexec" gemountet? Dann hast du das selbe Problem wie ich vor einiger Zeit: http://lists.suse.com/archive/suse-linux/2005-Oct/1745.html Die Lösung ist hier http://lists.suse.com/archive/suse-linux/2005-Oct/2327.html http://www.rootforum.de/forum/viewtopic.php?p=236919 Zur Erklärung: logrotate legt in /tmp ein Skript mit dem postrotate-Befehl an. Ist /tmp auf noexec, schlägt die Ausführung diese Skriptes fehl. Der zweite "Lösungs"-Link oben enthält eine mögliche Abhilfe durch setzen eines anderen Verzeichnisses für temporäre Dateien. Viele Grüße, Bernhard
Hallo Bernhard, * On Mon, Oct 31, 2005 at 04:04 PM (+0100), Bernhard Schalk wrote:
Nein, das ist hier nicht der Fall. Habe gerade zur Sicherheit nochmals nachgesehen: | fsa01-neu:~ # mount | | /dev/md1 on / type ext3 (rw,acl,user_xattr) | proc on /proc type proc (rw) | sysfs on /sys type sysfs (rw) | tmpfs on /dev/shm type tmpfs (rw) | devpts on /dev/pts type devpts (rw,mode=0620,gid=5) | /dev/md0 on /boot type ext3 (rw,acl,user_xattr) | /dev/md3 on /tmp type ext3 (rw,acl,user_xattr) | /dev/md2 on /usr type ext3 (rw,acl,user_xattr) | /dev/md4 on /var type ext3 (rw,acl,user_xattr) | /dev/mapper/system-home on /home type xfs (rw,usrquota) | /dev/mapper/system-export on /srv/export type xfs (rw) | usbfs on /proc/bus/usb type usbfs (rw) Da die Maschine auch "nur" als Fileserver läuft und wir unseren Usern keine lokale Shell geben, habe ich bislang auch noch keinen Grund ge- sehen, "/tmp" mit "noexec" zu mounten. Aber trotzdem - vielen Dank für den Tipp. Wenn es daran gelegen hätte, wäre ich -wenn überhaupt- erst nach sehr, sehr langem Suchen drauf ge- stoßen. Gruß, Steffen
Hallo Andreas, * On Mon, Oct 31, 2005 at 05:30 PM (+0100), Andreas Winkelmann wrote:
Ja, den Speicher habe ich geprüft, diverse CPU-Test-Geschichten ließ ich auch relativ lange drüberlaufen. Der Grund dafür: Nach dem Zusammenbau dieser Dual-Opteron-Maschine (zwei Opteron Single-Core-CPUs 246 und 2 GB RAM auf einem Tyan Thunder S2892) hatte ich das Problem, dass "grep" ständig crashte: | Oct 20 14:30:44 fsa01-neu kernel: grep[15069]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf30 error 4 | Oct 20 14:30:44 fsa01-neu kernel: grep[15079]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf30 error 4 | Oct 20 14:30:59 fsa01-neu kernel: grep[15489]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf50 error 4 | Oct 20 14:31:00 fsa01-neu kernel: grep[15543]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf50 error 4 | Oct 20 14:31:00 fsa01-neu kernel: grep[15573]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf50 error 4 | Oct 20 14:31:08 fsa01-neu kernel: grep[16055]: segfault at 0000000000000000 rip 00002aaaaaaae05c rsp 00007fffffffcf60 error 4 Ich gehe davon aus, dass ich auf diesen Hardware-Bug gestoßen bin, der leider erst von aktuellen Kernels "aufgedeckt" wurde: http://bugzilla.kernel.org/show_bug.cgi?id=4851 Das ist auch der Grund, weshalb ich nicht den mit der SuSE 10.0 mitge- lieferten SuSE-Kernel einsetze, sondern einen Vanilla-2.6.14. Dieser erkennt, dass die Hardware diesen Bug hat und berücksichtigt dies, indem er das entsprechende Feature deaktiviert. So erklärte es mir jedenfalls Andi Kleen von SuSE. Jedenfalls hatte ich seit dem Einsatz von 2.6.14 auch keinerlei "grep"- Crashes mehr - und der Rest läuft stabil. Naja, von "traceroute" einmal abgesehen, das hängt sich manchmal auf. Aber das dürfte 'ne andere Bau- stelle sein. Gruß, Steffen
Hallo Andreas, * On Mon, Oct 31, 2005 at 08:25 PM (+0100), Andreas Winkelmann wrote:
Die Filesysteme habe ich inzwischen gecheckt (es sind "ext3"- und "xfs"-Systeme im Einsatz, wobei die systemrelevanten Dinge alle auf "ext3" liegen und die "xfs"-Dateisysteme für die eigentlichen Nutz- daten der Fileserver-Dienstes da sind, wie z.B. "/home" oder "/export"). Keine Fehler gefunden. Natürlich habe ich bei den "ext3"- Filesystemen einen Check erzwungen. Die Platten an sich hatte ich vor zwei Wochen unmittelbar nach dem Zusammenbau des Rechners mit "badblocks" getestet. Keine Fehler. Auch die SMART-Werte sehen gut aus, Meldungen über Lese-/Schreib- probleme seitens des Kernels gab es bislang auch keine. Auch RAM und CPU zeigten, wie gesagt, bei keinem Test Probleme.
Nun, die Frage ist sicher berechtigt. Allerdings scheint das ein klar umgrenzter Bug der Hardware (Mainboard oder CPUs) zu sein, der einfach dadurch "umschifft" wird, indem das entsprechende Feature vom Kernel nicht genutzt wird, so wie es schon frühere Kernel-Versionen nicht genutzt haben (und damit wohl unentdeckt blieb). Anscheinend soll aber der Hersteller des Mainboards (Tyan) an einem BIOS-Update arbeiten (und es für verwandte Boards schon draußen haben), das dieses Problem lösen soll. Wobei ich fairerweise dazusagen muss, dass ich noch nicht weiß, ob damit wirklich das Problem an sich gelöst wird oder ob da ebenfalls nur ein "buggy Feature" der Opteron-CPUs "unterdrückt" wird. Ich werde mir die Details zu diesem Bug ansehen. Ich weiß z.B. momentan nicht, ob es sich um einen Bug in den Opteron-CPUs oder um einen Bug im Mainboard handelt. Auf jeden Fall plant wohl auch SuSE, zukünftige SuSE-Kernels abchecken zu lassen, ob auf der Hardware dieser Bug vorliegt oder nicht. Je nach dem wird dann von dem Feature Gebrauch gemacht oder eben nicht. Momentan kann der SuSE-Kernel der 10.0 das wohl noch nicht, aber der 2.6.14 ist dazu in der Lage. Danke und Grüße, Steffen
participants (4)
-
Andreas Winkelmann -
Bernhard Schalk -
Hans-Werner Hilse -
Steffen Moser