SSH schreibt in falsches Logfile (nach Log-Rotation)

W

wakko

Member
[GELÖST] SSH schreibt in falsches Logfile (nach Log-Rotation)

Hallo,
bin mir nicht sicher, ob das nicht besser in "Sonstige Serverdienste" gepasst hätte da das auch mit logrotate oder dem rsyslogd zu tun haben kann, aber das Symptom tritt nur bei SSH auf, bzw. dessen Logfile:

Der sshd auf meinem Debian 7.6 loggt nach dem Logrotate nicht nach auth.log
sondern in die soeben "wegortierte" auth.log.1
Die Rotation passiert per cronjob ein mal pro Woche. Ein weiteres Logrotate fasst die auth.log.1 nicht mehr an so dass die irgendwann riesig wird. Die auth.log bleibt nach der Rotation leer.
Abgesehen vom anwachsenden Riesen-logfile versagt dann auch fail2ban da es nur in der auth.log sucht.
Ich habe jetzt um das vorläufig zu beheben die auth.log.1 nach auth.log umbenannt. Dann wird auch wieder in die richtige Datei geschrieben.

Hat da jemand eine Idee wo ich noch suchen kann?
 
Last edited by a moderator:
Der Dienst, der in die Log-Datei schreibt, muß nach der Rotation einmal neu gestartet werden, damit er erkennt, daß die Datei unbenannt wurde und in die neu erstellte schreibst. Sonst zeigt der Pointer weiterhin auf die ursprüngliche Datei. GGfl. mußt du dazu die logrotate Konfig anpassen.
 
Danke für die Antwort.
Die logrotate config für den sshd bzw. das auth.log ist identisch mit diversen anderen logfiles. Auch in der config des rsyslogd kann ich keine Ungereimtheiten finden.
Dass die anderen Dienste bei der Log-Rotation neugestartet werden ist nicht zu erkennen. Wieso sollte das nur beim sshd bzw. der auth.log anders sein?

Wenn das Schreiben ins auth.log mit dem File-Handle des schreibenden Programms zusammenhängt, und das File-Handle nach der Log-Rotation noch auf die bereits umbenannte Datei zeigt, scheint das ein Fall für einen Bug-Report zu sein. Ich weiss nur noch nicht für welchen Dienst...
 
das ist kein Bug sondern das "völlig normale" Verhalten. Nach dem das File geöffnet wurde wird nur noch über den Filehandle draufzugegriffen, der Name der Datei ist danach nicht mehr relevant. Du kannst sie sogar löschen (sprich aus dem Fileverzeichnis entfernen) und weiter drauf schreiben lassen...

Poste doch mal Deine Logrotate-Konfig. Dann raten wir nicht im Nebel herum.
 
Dienste, die das File-Handle nicht dauerhaft geöffnet halten, müssen nicht neu gestartet werden. Ansonsten ist das Verhalten normal. Bei Rotieren wird nur der Namenseintrag in der Verzeichnisliste geändert, die Datei selber bleibt aber gleich und somit auch das File-Handle weiter gültig. Das ist kein Fehler sondern per Design so.
 
Hmmm.
Dann scheint das Zusammenspiel vom sshd mit dem rsyslogd nicht zu passen, denn der rsyslogd scheint für das Logging der auth.log zuständig zu sein. Und da findet (ziemlich weit unten) ein "invoke-rc.d rsyslog rotate > /dev/null" statt. Manuell neugestartet hatte ich den natürlich auch schon.
Code: 
*********@***********:~$ cat /etc/logrotate.conf 
# see "man logrotate" for details
# rotate log files weekly
weekly

# keep 4 weeks worth of backlogs
rotate 4

# create new (empty) log files after rotating old ones
create

# uncomment this if you want your log files compressed
#compress

# packages drop log rotation information into this directory
include /etc/logrotate.d

# no packages own wtmp, or btmp -- we'll rotate them here
/var/log/wtmp {
    missingok
    monthly
    create 0664 root utmp
    rotate 1
}

/var/log/btmp {
    missingok
    monthly
    create 0660 root utmp
    rotate 1
}

# system-specific logs may be configured here
*****@**************:~$ cat /etc/logrotate.d/rsyslog 
/var/log/syslog
{
	rotate 7
	daily
	missingok
	notifempty
	delaycompress
	compress
	postrotate
		invoke-rc.d rsyslog rotate > /dev/null
	endscript
}

/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
	rotate 4
	weekly
	missingok
	notifempty
	compress
	delaycompress
	sharedscripts
	postrotate
		invoke-rc.d rsyslog rotate > /dev/null
	endscript
}
 
Last edited by a moderator:
Hab grad mal nachgeschaut, aber in der SSHD Config ist nichts von einem Logfile zu sehen. Die einzigen relevanten Einträge für die auth.log wohnen in der/etc/rsyslog.conf und in der logrotate config.
Irgendwie ist der Fehler auch schwer zu reproduzieren, da die Rotation des auth.log nur einmal pro Woche passiert. Vielleicht schaut logrotate da auf die Timestamps des logfiles.
 
Logrotate ist recht simple ausgebaut. Die älteste wird gelöscht, anschließend rücken alle Log-Dateien durch Umbenennen eins nach hinten (wobei die mit der 1 am Ende i.d.R. noch per gzip gepackt wird). Anschließend wird die eigentliche Log-Datei umbenannt (bekommt das .1 ans Ende - das passiert auch, wenn die Datei leer ist.
Den Timestamp der Log-Datei nutzt logrotate gar nicht. Allerdings schreibt logrotate in die /var/lib/logrotate/status, an welchem Datum es welche Datei rotiert hat.
Vielleicht postest du einfach mal ein paar Logzeilen, die nach dem Rotieren noch in der auth.log.1 gelandet sind.
Im übrigens habe ich ebenfalls Debian Whezzy mit rsyslogd als Syslog-Daemon im Einsatz und konnte das von dir beschriebene Phänomen bei mir nicht beobachten.
 
So. Der Fehler tritt immer noch auf. Die Logrotation findet wie geplant Sonntags um kurz nach 0 Uhr statt. So steht das auch in der /var/lib/logrotate/status. Nach der Rotation existieren folgende auth.logs:
Code: 
*****@*********:/var/log# ls -l auth.log*
-rw-r----- 1 root adm    0 Okt 19 00:14 /var/log/auth.log
-rw-r----- 1 root adm 580K Okt 19 12:52 /var/log/auth.log.1
-rw-r----- 1 root adm 149K Okt 14 22:32 /var/log/auth.log.2.gz
-rw-r----- 1 root adm 172K Okt  9 20:56 /var/log/auth.log.3.gz
-rw-r----- 1 root adm  16K Sep 28 00:13 /var/log/auth.log.4.gz
Direkt nach der Rotation bleibt die auth.log leer.

Snippet aus der auth.log.1 zum Rotationszeitpunkt:
Code: 
Oct 18 23:57:37 lvps176-28-19-69 sshd[31277]: Failed password for invalid user test from 213.25.50.248 port 37903 ssh2
Oct 18 23:57:37 lvps176-28-19-69 sshd[31277]: Connection closed by 213.25.50.248 [preauth]
Oct 19 00:03:01 lvps176-28-19-69 CRON[31285]: pam_unix(cron:session): session opened for user root by (uid=0)
Oct 19 00:03:01 lvps176-28-19-69 CRON[31285]: pam_unix(cron:session): session closed for user root
Oct 19 00:09:01 lvps176-28-19-69 CRON[31296]: pam_unix(cron:session): session opened for user root by (uid=0)
Oct 19 00:09:01 lvps176-28-19-69 CRON[31296]: pam_unix(cron:session): session closed for user root
Oct 19 00:13:01 lvps176-28-19-69 CRON[31309]: pam_unix(cron:session): session opened for user root by (uid=0)
Oct 19 00:17:01 lvps176-28-19-69 CRON[482]: pam_unix(cron:session): session opened for user root by (uid=0)
Oct 19 00:17:01 lvps176-28-19-69 CRON[482]: pam_unix(cron:session): session closed for user root
Oct 19 00:20:24 lvps176-28-19-69 sshd[488]: Did not receive identification string from 193.104.41.10
Oct 19 00:20:25 lvps176-28-19-69 sshd[489]: Invalid user admin from 193.104.41.10
Oct 19 00:20:25 lvps176-28-19-69 sshd[489]: input_userauth_request: invalid user admin [preauth]
Oct 19 00:20:25 lvps176-28-19-69 sshd[489]: pam_unix(sshd:auth): check pass; user unknown
Oct 19 00:20:25 lvps176-28-19-69 sshd[489]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10 
Oct 19 00:20:27 lvps176-28-19-69 sshd[489]: Failed password for invalid user admin from 193.104.41.10 port 64635 ssh2
Oct 19 00:20:28 lvps176-28-19-69 sshd[489]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:28 lvps176-28-19-69 sshd[491]: Invalid user admin from 193.104.41.10
Oct 19 00:20:28 lvps176-28-19-69 sshd[491]: input_userauth_request: invalid user admin [preauth]
Oct 19 00:20:28 lvps176-28-19-69 sshd[491]: pam_unix(sshd:auth): check pass; user unknown
Oct 19 00:20:28 lvps176-28-19-69 sshd[491]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10 
Oct 19 00:20:30 lvps176-28-19-69 sshd[491]: Failed password for invalid user admin from 193.104.41.10 port 52759 ssh2
Oct 19 00:20:30 lvps176-28-19-69 sshd[491]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:32 lvps176-28-19-69 sshd[493]: Invalid user admin from 193.104.41.10
Oct 19 00:20:32 lvps176-28-19-69 sshd[493]: input_userauth_request: invalid user admin [preauth]
Oct 19 00:20:32 lvps176-28-19-69 sshd[493]: pam_unix(sshd:auth): check pass; user unknown
Oct 19 00:20:32 lvps176-28-19-69 sshd[493]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10 
Oct 19 00:20:34 lvps176-28-19-69 sshd[493]: Failed password for invalid user admin from 193.104.41.10 port 55588 ssh2
Oct 19 00:20:34 lvps176-28-19-69 sshd[493]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:35 lvps176-28-19-69 sshd[495]: Invalid user admin from 193.104.41.10
Oct 19 00:20:35 lvps176-28-19-69 sshd[495]: input_userauth_request: invalid user admin [preauth]
Oct 19 00:20:35 lvps176-28-19-69 sshd[495]: pam_unix(sshd:auth): check pass; user unknown
Oct 19 00:20:35 lvps176-28-19-69 sshd[495]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10 
Oct 19 00:20:38 lvps176-28-19-69 sshd[495]: Failed password for invalid user admin from 193.104.41.10 port 61153 ssh2
Oct 19 00:20:38 lvps176-28-19-69 sshd[495]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:40 lvps176-28-19-69 sshd[497]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10  user=root
Oct 19 00:20:41 lvps176-28-19-69 sshd[497]: Failed password for root from 193.104.41.10 port 49805 ssh2
Oct 19 00:20:41 lvps176-28-19-69 sshd[497]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:43 lvps176-28-19-69 sshd[499]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10  user=root
Oct 19 00:20:45 lvps176-28-19-69 sshd[499]: Failed password for root from 193.104.41.10 port 53624 ssh2
Oct 19 00:20:45 lvps176-28-19-69 sshd[499]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:46 lvps176-28-19-69 sshd[501]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10  user=root
Oct 19 00:20:48 lvps176-28-19-69 sshd[501]: Failed password for root from 193.104.41.10 port 58052 ssh2
Oct 19 00:20:48 lvps176-28-19-69 sshd[501]: fatal: Read from socket failed: Connection reset by peer [preauth]
Oct 19 00:20:50 lvps176-28-19-69 sshd[503]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=193.104.41.10  user=root
Auffällig sind hauptsächlich die Einträge "fatal: Read from socket failed: Connection reset by peer [preauth]", da bin ich grad auf der Suche, woran das liegen könnte. Immerhin werden die Enträge geloggt, aber halt in die falsche Datei...

EDIT: Oha! Bei genauerem Hinsehen passiert das auch bei allen anderen Logs die von Logrotate rotiert werden...
Da scheint was größeres im kaputt zu sein....

EDIT #2:
Da das Problem auch beim /var/log/syslog auftritt habe ich da mal versucht zu analysieren:
Code: 
****@************:/var/log# lsof syslog
****@************:/var/log# lsof syslog.1
COMMAND   PID USER   FD   TYPE      DEVICE SIZE/OFF   NODE NAME
rsyslogd 1766 root    1w   REG 182,1033697  3777784 393248 syslog.1
Wenn ich den rsyslog neu starten will kommt folgende Ausgabe:
Code: 
****@************:/var/log# service rsyslog restart
[ ok ] Stopping enhanced syslogd: rsyslogd already stopped.
[....] Starting enhanced syslogd: rsyslogd Already running. If you want to run multiple instances, you need to specify different pid files (use -i option)
[ ok ady started.
Dasselbe passiert bei /etc/init.d/rsyslog force-reload.

EDIT #3:
OK. Neustarten des rsyslogd klappt jetzt, nachdem ich aus /var/run ein rsyslogd.pid vom 05.09.2014 gelöscht habe.
DAS war das Problem. Seit dem wird wieder in die richtigen logfiles geschrieben...

Woher können denn solche PID-Leichen kommen?
 
Last edited by a moderator:
You must log in or register to reply here.
Back
Top