ALT Linux Bugzilla – #17250

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