[Gelöst] RSyslog - Schreibt komplette HD voll

[matth]

Guten Tag!

Ich bin neu hier auf dem Board, und auch recht neu, was die Thematik Linux und Serveradministration angeht. Aber jeder fängt mal an und lernt, nicht wahr?

Zu meinem Problem:
Ich habe mehrere Maschinen in zwei Standorten stehen.
Standort A hat ein eigenes Netz, Standort B ebenso. Beide sind über die Firewalls miteinander verbunden.
Die Maschinen sind in beiden Standortden identtisch.
Admin-Server - Webserver - Proxy-Server - Radius - Database-Server

Auf allen Geräten (Ausnahme Database) ist Debian Squeeze installiert. NTP zur Zeitsynchronisation läuft einwandfrei.
Nun mein Problem:
Ich habe RSyslog installiert, auf allen Maschinen. Die Admin-Server sollen als Server fungieren und die Logfiles schreiben, die anderen als reportende Clients, alle Clients reporten an beide Admin-Server, die Admins selbst nur „an sich“. Die Logs sollen dann in eine MySQL-DB geschrieben werden und werden mittels „LogAnalyzer“ ausgewertet.
Grundsätzlich funktioniert diese Konfiguration auch, nur dass die Logfiles innerhalb weniger Stunden die komplette Platte vollschreiben (750GB und mehr).
Und das hauptsächlich mit Nonsens, wie

Code: Alles auswählen

Nov  5 08:14:44 admin1 rsyslogd: [origin software="rsyslogd" swVersion="4.6.4" x-pid="21015" x-info="http://www.rsyslog.com"] (re)start
Nov  5 08:14:44 admin1 rsyslogd: [origin software="rsyslogd" swVersion="4.6.4" x-pid="21015" x-info="http://www.rsyslog.com"] (re)start
Nov  5 08:14:44 admin1 kernel: imklog 4.6.4, log source = /proc/kmsg started.
Nov  5 08:14:44 admin1 kernel: imklog 4.6.4, log source = /proc/kmsg started.

Im Loganalyzer sieht das dann so aus:



Und dann kommen, wie ihr seht, die Messages noch nicht mal chronologisch korrekt rein, sie haben teilweise 3h Zeitversatz. Das kann ich so nicht hinnehmen. Und meine Chefs schon gar nicht. Wenn ich die beiden Admin-Server so konfiguriere, dass sie sich gegenseitig reporten, wird es noch schlimmer.
Ich bin kein Linux-Pro, ich habe innerhalb eines Projektes eben die Aufgabe übernommen NTP und RSyylog zum laufen zu kriegen. Mit der Aufgabe bin ich auch recht glücklich, nur komme ich hier nicht weiter.

Die rsyslog.conf: (auf beiden Maschinen identisch, nur die Adressen geändert)

Code: Alles auswählen

#  /etc/rsyslog.conf    Configuration file for rsyslog.
#
#                       For more Information see
#                       /usr/share/doc/rsyslog-doc/html/rsyslog_conf.html

#################
#### MODULES ####
#################

$ModLoad ommysql
$ModLoad imuxsock # provides support for local system logging
$ModLoad imklog   # provides kernel logging support (previously done by rklogd)
#$ModLoad immark  # provides --MARK-- message capability
$IncludeConfig /etc/rsyslog.d/*.conf

# provides UDP syslog reception
$ModLoad imudp
$UDPServerRun 514
$UDPServerTimeRequery 2


# provides TCP syslog reception
$ModLoad imtcp
$InputTCPServerRun 514

###########################
#### GLOBAL DIRECTIVES ####
###########################

#
# Use traditional timestamp format.
# To enable high precision timestamps, comment out the following line.
#
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$RepeatedMsgReduction on

#
# Set the default permissions for all log files.
#
$FileOwner root
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022

#

###############
#### RULES ####
###############

#
# First some standard log files.  Log by facility.
#

*.info                          @192.168.150.162 
#*.*                            ~      # Derzeit auskommentiert,  zur Fehlersuche
*.info                          @192.168.250.162  # Normalerweise auskommentiert, führt zu einer Art Loggingschleife


auth,authpriv.*                 /var/log/auth.log
*.*;auth,authpriv.none          -/var/log/syslog
#cron.*                         /var/log/cron.log
*.info                          /var/log/syslog
daemon.*                        -/var/log/daemon.log
kern.*                          -/var/log/kern.log
lpr.*                           -/var/log/lpr.log
mail.*                          -/var/log/mail.log
user.*                          -/var/log/user.log

#

#
# Some "catch-all" log files.
#
*.=debug;\
        auth,authpriv.none;\
        news.none;mail.none     -/var/log/debug
*.=info;*.=notice;*.=warn;\
        auth,authpriv.none;\
        cron,daemon.none;\
        mail,news.none          -/var/log/messages

#


#
# NOTE: adjust the list below, or you'll go crazy if you have a reasonably
#      busy site..
#
daemon.*;mail.*;\
        news.err;\
        #*.=debug;\
        *.=info;\
        *.=notice;*.=warn       |/dev/xconsole

Ich habe den Post innerhalb von ca. 1h neben meiner restlichen Arbeit erstellt. nur eine Maschine ist derzeit am loggen, der genannte Adminserver aus Standort B, und er hat 14GB logfiles geschrieben. Unfassbar. Ihr könnt euch ausmalen, was das für mein Netz und die Festplatten heisst, wenn ich an allen Maschinen das loggen aktiviere?

Ich bitte um eure Hilfe!
Danke
Matthias

[syssi]

Ich vermute mal, dass du mehrere Probleme zu loesen hast. Erstmal ist es nicht normal, dass in so kurzer Zeit solche rauen Mengen an Logdaten anfallen. Du solltest einmal feststellen, welche der Meldungen so derart haeufig geloggt werden. Dein Logauszug (hier einmal in lesbar)



sieht ausserdem nicht normal aus. Zum einen solltest du das Problem "Db error: Unkown database 'Syslog'" loesen. Die "[origin..." und "imklog"-Meldungen sehe ich auf meinen Systemen nur nach deinem Restart von rsyslog. Wieso restartet dein rsyslog dermaßen haeufig? Dann solltest du kontrollieren, ob sich wiederholende Logeintraege vom rsyslog vernichtet werden. Die Stichworte dazu lauten "RepeatedMsgContainsOriginalMsg" und "RepeatedMsgReduction". Hast du eine Vorstellung, was dein LogAnalyzer mit den Logs auf Dauer tut? Gibt es einen Mechanismus, der aehnlich arbeitet, wie "logrotate"?

Dann solltest du testweise auch mal eine Datei schreiben lassen und die Abweichungen in den Zeitstempeln pruefen. Ein Drift von ein paar Sekunden kann ich mir vorstellen, da rsyslog die Daten seriell loggt (so wie sie herein kommen). Mehrere Stunden kann ich mir nicht erklaeren. Ist neben der Zeit auch die gleiche Zeitzone eingestellt?

Gruss syssi

[ralfi]

Also ich weiss nicht ob es sinnvoll ist mit dem Info Loglevel zu arbeiten. Probier doch erstmal aus, wie alles mit der Standardkonfiguration (oder mit error / warn Fac.) funktioniert.

[matth]

Hallo,
Vielen Dank, für eure Antworten.

@ralfi: Den Info-Loglevel habe ich gewählt, da ich dachte, damit der Sache Herr zu werden.

@syssi: Das Problem "Db error: Unkown database 'Syslog'" habe ich gelöst - rsyslog-mysql hatte einen Fehler (DB existierte nicht).
Die logs sollen in der SQL DB verbleiben und mittels einem Script nach 30Tagen verworfen werden.
"RepeatedMsgReduction" habe ich in meiner config schon eingebaut, leider anscheinend ohne Funktion.
"RepeatedMsgContainsOriginalMsg" verhält sich genauso. Leider.
Syntax "$RepeatedMsgContainsOriginalMsg on" sollte stimmen (?)

Wenn ich wüsste, was das andauernde neustarten des Rsyslog bewirkt, wäre ich einen riesen Schritt weiter. Im Grunde ist das ja der Fehler, der meine Platten voll schreibt.

Ich habe mit
"tail -f /var/log/syslog"
mail geschaut, wie die logs der anderen Maschinen ankommen. Es sind derzeit "nur" 12-20s delay. Habe das logging vorerst wieder deaktiviert.

Kennt jemand eine Schwachstelle, die ein solches Verhalten verursachen könnte?
Ich stehe noch am Anfang meiner Administratorenaufgabe und habe noch recht wenig Erfahrung mit Linux, daher erhoffe ich mir hier Hilfe.
Danke
Matthias

[syssi]

Verstehe ich es nicht, dass ausschliesslich "[origin ..." und "imklog" die Eintraege sind, welche das Log uebermaessig fuellen?

[matth]

Im Moment, füllen fast ausschließlich diese beiden Einträge (4 Zeilen) das Log. Es kommen noch ein paar Einträge von sshd und snmpd und anderen Diensten aber nur sehr wenige, so wie man sich das wünscht.
Wenn ich die anderen Maschinen wieder aktiviere (also rsyslog starte) dann sieht es noch viel heftiger aus.

[syssi]

Kannst du diese Mal in den Thread pasten? Von der " [origin "-Zeile ist das Ende entscheidend.

[matth]

Meinst Du die Zeilen, die den Log überfluten?
Die standen schon im Anfangspost:

Nov 5 08:14:44 admin1 rsyslogd: [origin software="rsyslogd" swVersion="4.6.4" x-pid="21015" x-info="http://www.rsyslog.com"] (re)start
Nov 5 08:14:44 admin1 rsyslogd: [origin software="rsyslogd" swVersion="4.6.4" x-pid="21015" x-info="http://www.rsyslog.com"] (re)start
Nov 5 08:14:44 admin1 kernel: imklog 4.6.4, log source = /proc/kmsg started.
Nov 5 08:14:44 admin1 kernel: imklog 4.6.4, log source = /proc/kmsg started.

An den Zeilen ändert sich nur die Uhrzeit.

[syssi]

Was liefert "ps aux | grep rsyslogd" ? Kannst du den Befehl mehrere Male ausfuehren? Aendert sich die Prozess-ID permanent?

[matth]

Hier ist das Ergebnis.

Code: Alles auswählen

root@admin1:~# ps aux | grep rsyslogd
root     28172 59.2  0.0 221740  2520 ?        Sl   10:08  48:09 /usr/sbin/rsyslogd -c4 -4
root@admin1:~# ps aux | grep rsyslogd
root     28172 59.2  0.0 221740  2496 ?        Sl   10:08  48:15 /usr/sbin/rsyslogd -c4 -4
root     32501  0.0  0.0   6028   688 pts/1    S+   11:30   0:00 grep rsyslogd
root@admin1:~# ps aux | grep rsyslogd
root     28172 59.2  0.0 221740  2484 ?        Sl   10:08  48:23 /usr/sbin/rsyslogd -c4 -4
root     32503  0.0  0.0   6028   688 pts/1    S+   11:30   0:00 grep rsyslogd
root@admin1:~#
root@admin1:~#
root@admin1:~# ps aux | grep rsyslogd
root     28172 59.2  0.0 221740  2520 ?        Sl   10:08  48:29 /usr/sbin/rsyslogd -c4 -4
root     32505  0.0  0.0   6028   684 pts/1    S+   11:30   0:00 grep rsyslogd

[matth]

OK, jetzt hat sich was getan.
Auf anraten eines Kollegen, habe ich die Zeile

Code: Alles auswählen

$ModLoad imklog

am Anfang der config auskommentiert, da somit gewährleistet sei, dass die Maschine nicht in Richtung Kernel loggt, und der Kernel wieder zurück.

Die zwei Zeilen

Code: Alles auswählen

Nov 5 08:14:44 admin1 kernel: imklog 4.6.4, log source = /proc/kmsg started.
Nov 5 08:14:44 admin1 kernel: imklog 4.6.4, log source = /proc/kmsg started.

kommen auch nicht mehr vor, dafür schreibt, nach aktivierung, jede Maschine ihre logs doppelt.
Also eine Signifikante Verbesserung der Situation, denn ich muss davon ausgehen, dass die anderen das vorher auch schon machten, ich es nur nicht sehen konnte, da das System ausgelastet war.
RSyslog startet noch immer andauernd neu, dafür habe ich noch nichts gefunden.

[syssi]

Hi,

ich bin gerade etwas ratlos, da irgendwie die Anhaltspunkte fehlen, um das Problem zu lokalisieren. Ich bin mir noch nichtmal sicher, ob es ueberhaupt ein Problem gibt. Deine Prozessliste sagt eigentlich aus, dass dein rsyslogd immer mit der gleichen Prozess-ID laeuft (sich also nicht neu startet). Die Logmeldung sagt aber aus, dass rsyslog neu gestartet wurde. Waere es nur ein "kill -HUP" gewesen, dann wuerde die Logmeldung dies entsprechend melden. An deiner Stelle wuerde ich einfach nochmal von vorn anfangen. Deine Konfigurationen verwerfen und ausgehend vom Original die gewuenschte Funktionalitaet abbilden. Notfalls innerhalb einer, zwei oder sogar drei virtuellen Maschinen (virtualbox).

Wieso hast du eigentlich diese Zeile 2x in der Konfiguration stehen?

Code: Alles auswählen

*.info                          @192.168.150.162 
#*.*                            ~      # Derzeit auskommentiert,  zur Fehlersuche
*.info                          @192.168.250.162  # Normalerweise auskommentiert, führt zu einer Art Loggingschleife

Das koennte die Ursache sein, wieso Logeintraege doppelt ankommen.

[matth]

Hallo Syssi,

Ich habe das Problem gestern gelöst.

die Zeile mit der IP der Maschine mussten raus... Daher kam die "Schleife".
Ziemlich nervig, zumal ich die Config mit einem TUT des Herstellers erstellt habe...

Jetzt funktioniert alles wunderbar.
Vielen Dank, dass Du/Ihr dich/euch in mein Problem reingedacht habt!

VG
Matthias