Bug 17250

Summary: doesn't log after syslogd restart
Product: Branch 4.1 Reporter: Ivan Zakharyaschev <imz>
Component: klogdAssignee: Dmitry V. Levin <ldv>
Status: CLOSED NOTABUG QA Contact: qa-4.1 <qa-4.1>
Severity: critical    
Priority: P2 CC: stanv
Version: unspecified   
Hardware: all   
OS: Linux   
Bug Depends on: 17720, 17716, 17717, 17718    
Bug Blocks:    

Description Ivan Zakharyaschev 2008-09-21 17:37:18 MSD
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 ~]#
Comment 1 Ivan Zakharyaschev 2008-09-21 17:58:11 MSD
This was also true on syslogd-1.4.1-alt19, klogd-1.4.1-alt19.
Comment 2 Andriy Stepanov (stanv) 2008-10-28 11:22:18 MSK
У меня что-то не получается воспроизвести

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
->при этом вроде и соединение не рвётся
->странно
Comment 3 Dmitry V. Levin 2008-10-28 12:54:37 MSK
Функция 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. 
Comment 4 Ivan Zakharyaschev 2008-10-28 17:43:54 MSK
(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, 

Comment 5 Ivan Zakharyaschev 2008-10-28 17:46:30 MSK
(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
# 
Comment 6 Dmitry V. Levin 2008-10-28 17:51:27 MSK
(In reply to comment #4)
> connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = -1 EACCES (Permission denied)

Это совсем другое дело: испортились права на /dev/log, /dev или /.
Comment 7 Dmitry V. Levin 2008-10-28 17:52:37 MSK
(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'ы.
Comment 8 Ivan Zakharyaschev 2008-10-28 18:11:25 MSK
(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. Если бы он сразу отваливался, было бы удобно.
Comment 9 Ivan Zakharyaschev 2008-10-28 18:17:37 MSK
(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, я тоже пока не понял.
Comment 10 Ivan Zakharyaschev 2008-10-28 18:25:11 MSK
(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. Если бы он сразу отваливался, было бы удобно.
> 

Comment 11 Ivan Zakharyaschev 2008-10-28 18:34:01 MSK
(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:
# 

Наверное, по моей вине когда-то.
Comment 12 Ivan Zakharyaschev 2008-10-29 01:39:50 MSK
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