syslogd-1.4.1-alt28 klogd-1.4.1-alt28 After syslogd is restarted, klogd doesn't write anymore messages to the logfiles. (This means that klogd becomes useless after the first logrotate.) The example is below. iptables omn 10.1.1.2 were told to log (and redirect) the kind of connections I will make (ftp from another computer). I start with an empty /var/log/kernel/warnings (0). In take 1 (1), I show how it should be. In take (2), I do the same things after I restart syslogd; and the logging deosn't happen! In take (3), I ultimately restart klogd and demonstrate that it's again logging well. In practice, this situation occurs after logrotate. [root@arrakis ~]# tail /var/log/kernel/warnings # (0) The pre-condition. [root@arrakis ~]# su - ivan # (1) Take 1. Everything will be OK. [ivan@arrakis data]$ ssh 10.1.1.4 -l imz Enter passphrase for key '/home/ivan/.ssh/id_dsa': Last login: Sun Sep 21 17:16:21 2008 from arrakis.zephyrous [imz@etik ~]$ lftp 10.1.1.2 # iptables on 10.1.1.2 was told to log such connections lftp 10.1.1.2:~> ls drwxrwxr-x 6 ftp ftp 32768 Aug 09 2005 Exped -rw-r--r-- 1 ftp ftp 336 Sep 19 12:27 README drwxrwxr-x 14 ftp ftp 32768 Sep 19 00:01 п═п╟п╠п╬я┤п╦п╧ я│я┌п╬п╩ п╦п╥ Windows lftp 10.1.1.2:/> exit [imz@etik ~]$ Connection to 10.1.1.4 closed. [ivan@arrakis data]$ exit [root@arrakis ~]# # tail /var/log/kernel/warnings # And here it is! Sep 21 17:23:49 arrakis kernel: Redirecting (pre)IN=homenet OUT= MAC=00:11:95:f5:8a:4f:00:0d:87:7f:85:f6:08:00 SRC=10.1.1.4 DST=10.1.1.2 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=33376 DF PROTO=TCP SPT=4910 DPT=21 WINDOW=5840 RES=0x00 SYN URGP=0 [root@arrakis ~]# service syslogd restart # (2) Take 2. The error will be here. Stopping system logger service: [ DONE ] Starting system logger service: [ DONE ] [root@arrakis ~]# su - ivan [ivan@arrakis data]$ ssh 10.1.1.4 -l imz Enter passphrase for key '/home/ivan/.ssh/id_dsa': Last login: Sun Sep 21 17:20:49 2008 from arrakis.zephyrous [imz@etik ~]$ lftp 10.1.1.2 lftp 10.1.1.2:~> ls drwxrwxr-x 6 ftp ftp 32768 Aug 09 2005 Exped -rw-r--r-- 1 ftp ftp 336 Sep 19 12:27 README drwxrwxr-x 14 ftp ftp 32768 Sep 19 00:01 п═п╟п╠п╬я┤п╦п╧ я│я┌п╬п╩ п╦п╥ Windows lftp 10.1.1.2:/> exit [imz@etik ~]$ Connection to 10.1.1.4 closed. [ivan@arrakis data]$ exit # tail /var/log/kernel/warnings # It's not there! Sep 21 17:23:49 arrakis kernel: Redirecting (pre)IN=homenet OUT= MAC=00:11:95:f5:8a:4f:00:0d:87:7f:85:f6:08:00 SRC=10.1.1.4 DST=10.1.1.2 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=33376 DF PROTO=TCP SPT=4910 DPT=21 WINDOW=5840 RES=0x00 SYN URGP=0 [root@arrakis ~]# date # (3) Take 3. Again OK after ther restart Sun Sep 21 17:29:09 MSD 2008 [root@arrakis ~]# service klogd restart Stopping kernel logger service: [ DONE ] Starting kernel logger service: [ DONE ] [root@arrakis ~]# tail /var/log/kernel/warnings Sep 21 17:23:49 arrakis kernel: Redirecting (pre)IN=homenet OUT= MAC=00:11:95:f5:8a:4f:00:0d:87:7f:85:f6:08:00 SRC=10.1.1.4 DST=10.1.1.2 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=33376 DF PROTO=TCP SPT=4910 DPT=21 WINDOW=5840 RES=0x00 SYN URGP=0 [root@arrakis ~]# su - ivan [ivan@arrakis data]$ ssh 10.1.1.4 -l imz Enter passphrase for key '/home/ivan/.ssh/id_dsa': Last login: Sun Sep 21 17:24:59 2008 from arrakis.zephyrous [imz@etik ~]$ lftp 10.1.1.2 lftp 10.1.1.2:~> ls drwxrwxr-x 6 ftp ftp 32768 Aug 09 2005 Exped -rw-r--r-- 1 ftp ftp 336 Sep 19 12:27 README drwxrwxr-x 14 ftp ftp 32768 Sep 19 00:01 п═п╟п╠п╬я┤п╦п╧ я│я┌п╬п╩ п╦п╥ Windows lftp 10.1.1.2:/> exit [imz@etik ~]$ Connection to 10.1.1.4 closed. [ivan@arrakis data]$ logout [root@arrakis ~]# tail /var/log/kernel/warnings # It's there. Sep 21 17:23:49 arrakis kernel: Redirecting (pre)IN=homenet OUT= MAC=00:11:95:f5:8a:4f:00:0d:87:7f:85:f6:08:00 SRC=10.1.1.4 DST=10.1.1.2 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=33376 DF PROTO=TCP SPT=4910 DPT=21 WINDOW=5840 RES=0x00 SYN URGP=0 Sep 21 17:32:43 arrakis kernel: Redirecting (pre)IN=homenet OUT= MAC=00:11:95:f5:8a:4f:00:0d:87:7f:85:f6:08:00 SRC=10.1.1.4 DST=10.1.1.2 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=15609 DF PROTO=TCP SPT=1402 DPT=21 WINDOW=5840 RES=0x00 SYN URGP=0 [root@arrakis ~]#
This was also true on syslogd-1.4.1-alt19, klogd-1.4.1-alt19.
У меня что-то не получается воспроизвести rpm -q syslogd klogd syslogd-1.4.1-alt28 klogd-1.4.1-alt28 # service klogd status klogd is running # service syslogd status syslogd is running # tail -f /var/log/kernel/warnings (*1) # echo '<4>Before syslogd reload' >/dev/kmsg в (*1) появилось: Oct 27 11:10:37 stanv kernel: Before syslogd reload В /etc/logrotate.d/syslog идет вызов: /sbin/reload-syslog >/dev/null вызовим его: # /sbin/reload-syslog Stopping system logger service: [ DONE ] Starting system logger service: [ DONE ] # echo '<4>After syslogd reload' >/dev/kmsg в (*1) появилось: Oct 27 11:16:42 stanv kernel: After syslogd reload аналогично и для #service syslogd restart в разговоре с vsu@ ->вообще патч на восстановление соединения у нас вроде бы давно приложен ->и /dev/log в чруте klogd наблюдается ->у меня, кстати, это работает правильно ->ну сделай strace -p $klogd_pid и посмотри, что с ним происходит Process 6018 attached - interrupt to quit read(4, "<4>Test\n", 4095) = 8 time(NULL) = 1225117143 write(3, "<4>Oct 27 17:19:03 kernel: Test\0", 32) = -1 ECONNREFUSED (Connection refused) close(3) = 0 socket(PF_FILE, SOCK_DGRAM, 0) = 3 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = 0 write(3, "<4>Oct 27 17:19:03 kernel: Test\0", 32) = 32 read(4, ->вообще reload, т.е. посылает SIGHUP ->при этом вроде и соединение не рвётся ->странно
Функция vsyslog(), определённая в syslog.c и используемая klogd, содержит следующий код: /* output the message to the local logger */ result = write(LogFile, tbuf, cnt + 1); if (result == -1 && (errno == ECONNRESET || errno == ENOTCONN || errno == ECONNREFUSED)) { closelog(); openlog(LogTag, LogStat | LOG_NDELAY, LogFacility); result = write(LogFile, tbuf, cnt + 1); } Начиная с 1.4.1-alt17, файл CHANGES содержит следующую строку: - klogd will reconnect to the logger (mostly syslogd) after it went away. Остаётся предположить, что сокет /var/lib/klogd/dev/log не проинициализирован правильно из-за того, что со ссылкой /etc/syslog.d/klogd что-то случилось. P.S. Я точно знаю, что этой проблемы нет, и если бы Reporter не имел хорошую репутацию, то я бы закрыл этот баг сразу как NOTABUG.
(In reply to comment #2) > ->ну сделай strace -p $klogd_pid и посмотри, что с ним происходит # strace -p 2819 Process 2819 attached - interrupt to quit read(4, "<4>After syslogd reload\n", 4095) = 24 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = -1 EACCES (Permission denied) time(NULL) = 1225197029 write(3, "<4>Oct 28 15:30:29 kernel: After"..., 48) = -1 ENOTCONN (Transport endpoint is not connected) close(3) = 0 socket(PF_FILE, SOCK_DGRAM, 0) = 3 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = -1 EACCES (Permission denied) write(3, "<4>Oct 28 15:30:29 kernel: After"..., 48) = -1 ENOTCONN (Transport endpoint is not connected) read(4,
(In reply to comment #3) > Остаётся предположить, что сокет /var/lib/klogd/dev/log не проинициализирован > правильно из-за того, что со ссылкой /etc/syslog.d/klogd что-то случилось. # l /var/lib/klogd/dev/log /etc/syslog.d/klogd srw-rw-rw- 1 root root 0 Oct 26 12:02 /var/lib/klogd/dev/log= lrwxrwxrwx 1 root root 22 Sep 19 14:48 /etc/syslog.d/klogd -> /var/lib/klogd/dev/log= # lsof /var/lib/klogd/dev/log /dev/log COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME syslogd 28270 syslogd 3u unix 0xb5a93c80 22814548 /dev/log syslogd 28270 syslogd 40u unix 0xb8480ac0 22814550 /var/lib/klogd/dev/log #
(In reply to comment #4) > connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = -1 EACCES (Permission denied) Это совсем другое дело: испортились права на /dev/log, /dev или /.
(In reply to comment #6) > (In reply to comment #4) > > connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = -1 EACCES (Permission denied) > > Это совсем другое дело: испортились права на /dev/log, /dev или /. Например, у группы klogd и каталога /var/lib/klogd/dev отличаются gid'ы.
(In reply to comment #7) > Например, у группы klogd и каталога /var/lib/klogd/dev отличаются gid'ы. > Да, так и есть. Спасибо! я бы не скоро это понял: # pidof klogd 2819 # fgrep -i gid /proc/2819/status Tgid: 2819 Gid: 26 26 26 26 # fgrep klogd /etc/group klogd:x:261: # fgrep :26: /etc/group shadow:x:26: # l -d /var/lib/klogd/dev/log /var/lib/klogd/dev /var/lib/klogd /var/lib /var / /dev/log /dev drwxr-xr-x 10 root root 4260 Oct 26 12:02 /dev/ srw-rw-rw- 1 root root 0 Oct 26 12:02 /dev/log= drwx--x--- 2 root klogd 72 Oct 26 12:02 /var/lib/klogd/dev/ srw-rw-rw- 1 root root 0 Oct 26 12:02 /var/lib/klogd/dev/log= drwxr-xr-x 41 root root 1120 Oct 11 15:18 /var/lib/ drwxr-xr-x 32 root root 840 Sep 20 03:19 /var/ drwxr-xr-x 25 root root 592 Sep 19 20:02 // drwx--x--- 3 root klogd 72 Oct 4 2007 /var/lib/klogd/ # Теперь мне нужно понять, почему klogd не с тем gid. А ещё трудность этой ситуации в том, что сначала klogd работает, но перестаёт после перезапуска syslogd. Если бы он сразу отваливался, было бы удобно.
(In reply to comment #8) > Теперь мне нужно понять, почему klogd не с тем gid. > > А ещё трудность этой ситуации в том, что сначала klogd работает, но перестаёт > после перезапуска syslogd. Если бы он сразу отваливался, было бы удобно. Вот я сделал # service klogd restart Stopping kernel logger service: [ DONE ] Starting kernel logger service: [ DONE ] с gid ситуация такая же: # pidof klogd 18943 # fgrep -i gid /proc/18943/status Tgid: 18943 Gid: 26 26 26 26 но он почему-то работает: во время "echo '<4>After klogd restart' >/dev/kmsg" видим: # strace -p 18943 Process 18943 attached - interrupt to quit read(4, "<4>After klogd restart\n", 4095) = 23 time(NULL) = 1225199147 write(3, "<4>Oct 28 16:05:47 kernel: After"..., 47) = 47 read(4, При start не происходит всех тех проверок прав, что происходит при переподсоединении. Кажется, для предсказуемости лучше, чтобы при start происходили настолько же жёсткие проверки, как и при переподсоединении. Ну а откуда береётся gid 26 вместо 261, я тоже пока не понял.
(In reply to comment #8) > (In reply to comment #7) > > > Например, у группы klogd и каталога /var/lib/klogd/dev отличаются gid'ы. > > > > Да, так и есть. Т.е. всё-таки не совсем так: у процесса почему-то gid не совпадает с gid под именем klogd. А с каталогами всё хорошо. > # pidof klogd > 2819 > # fgrep -i gid /proc/2819/status > Tgid: 2819 > Gid: 26 26 26 26 > # fgrep klogd /etc/group > klogd:x:261: > # fgrep :26: /etc/group > shadow:x:26: > # l -d /var/lib/klogd/dev/log /var/lib/klogd/dev /var/lib/klogd /var/lib /var / /dev/log /dev > drwxr-xr-x 10 root root 4260 Oct 26 12:02 /dev/ > srw-rw-rw- 1 root root 0 Oct 26 12:02 /dev/log= > drwx--x--- 2 root klogd 72 Oct 26 12:02 /var/lib/klogd/dev/ > srw-rw-rw- 1 root root 0 Oct 26 12:02 /var/lib/klogd/dev/log= > drwxr-xr-x 41 root root 1120 Oct 11 15:18 /var/lib/ > drwxr-xr-x 32 root root 840 Sep 20 03:19 /var/ > drwxr-xr-x 25 root root 592 Sep 19 20:02 // > drwx--x--- 3 root klogd 72 Oct 4 2007 /var/lib/klogd/ > # > > Теперь мне нужно понять, почему klogd не с тем gid. > > А ещё трудность этой ситуации в том, что сначала klogd работает, но перестаёт > после перезапуска syslogd. Если бы он сразу отваливался, было бы удобно. >
(In reply to comment #9) > Ну а откуда береётся gid 26 вместо 261, я тоже пока не понял. А, это просто -- рассогласовались /etc/passwd и группа klogd: # fgrep klogd /etc/passwd klogd:*:108:26::/dev/null:/dev/null # fgrep klogd /etc/group klogd:x:261: # Наверное, по моей вине когда-то.
Not a bug, но можно придумать улучшения (текущая ситуация, что по сути из-за опечатки эта проблема была, но не была замечена кучу времени, не очень хороша): в klogd: https://bugzilla.altlinux.org/show_bug.cgi?id=17716 https://bugzilla.altlinux.org/show_bug.cgi?id=17717 более системные проверки: https://bugzilla.altlinux.org/show_bug.cgi?id=17718 https://bugzilla.altlinux.org/show_bug.cgi?id=17719 https://bugzilla.altlinux.org/show_bug.cgi?id=17720
