Re: [bug-inetutils] syslog - blocks all procceses by a infinite read after poll

[Daniel Lehne]

On 01.3.2012 г. 13:35, D. Lehne wrote:
> Hello,
>
> in relation to a feature of circular log (clog) for syslog, i've seen 
> a strange behavior on the system resulting by syslog.
>
> The system is a:
> Linux 4S 2.6.33.7.2-rt30-A4-2011.02.0 #1 PREEMPT RT Tue Feb 7 17:39:13 
> CET 2012 armv6l GNU/Linux
>
> Syslog is from inetutil-1.6:
> address@hidden:~#ldd /sbin/syslogd
>         libresolv.so.2 => /lib/libresolv.so.2 (0x40026000)
>         libnsl.so.1 => /lib/libnsl.so.1 (0x4003a000)
>         libc.so.6 => /lib/libc.so.6 (0x40056000)
>         /lib/ld-linux.so.3 (0x40000000)
>
> After syslog started the following situation happens. Syslog returns 
> from poll(), by an unknown sender, for a /proc/kmsg event of the fd 
> but there is no data to read and syslog reads infinite. All other 
> processes sending to syslog (like /dev/log) are blocked until a 
> message is sended to /proc/kmsg. This lock happens once after 20 or 
> more restarts, that means it is really rarly.
>
> This is the strace of syslog:
>
> address@hidden:~#cat /tmp/sys1trace
> read(3,<unfinished ...>
> address@hidden:~#ls -l /proc/498/fd
> lr-x------    1 root     root            64 Feb 28 15:54 3 ->  /proc/kmsg
>
> This is a strace of a application:
>
> address@hidden:/proc/496#cat /tmp/armtrace
> send(6, "<134>Feb 28 13:47:19 : 28/02/12 "..., 99, 
> MSG_NOSIGNAL<unfinished ...>
>
> The file discriptor handling is done in main():
>
> for (;;)
>
>     {
>
>       int nready;
>
>       nready = poll (fdarray, nfds, -1);
>
>       if (nready == 0)          /* ??  noop */
>
>         continue;
> ...
>       for (i = 0; i<  nfds; i++)
>         if (fdarray[i].revents&  (POLLIN | POLLPRI))
>           {
>             int result;
>             size_t len;
>             if (fdarray[i].fd == -1)
>               continue;
>             else if (fdarray[i].fd == fklog)
>               {
>                 result = read (fdarray[i].fd,&kline[kline_len],
>                                sizeof (kline) - kline_len - 1);
> ...
>
> The file discriptor fklog represent /proc/kmsg. The fdarray consist 
> actually only of 2 active file descriptors, one is proc/kmsg and the 
> other dev/log. The read function blocks further processing.
>
> The kernel man says for /proc/kmsg:
>
> /proc/kmsg
>               ..., and only one process should read this file.  This 
> file should not be read if a syslog process is running which uses the 
> syslog(2) sys‐
>               tem call facility to log kernel messages.
>
>
> My questions are the following:
>
> 1. Which other processes are working with /proc/kmsg?
> 2. Why poll() is used and not ppoll() ?
> 3. My patch is working with pwritev(), does it have influences on 
> poll() ?
> 4. Any suggest for a further/better debugging?
>
> Best regards!
Hello,

once again after further investigation the following results. The read() 
of /proc/kmsg seem to wait infinite on the wait_event_interruptible() 
function, because the expression (log_start - log_end) wouldn't  become 
true. My opinion is, that O_NONBLOCK would fix this, once kernel code 
could not interrupted. With the disadvantage of losing a /proc/kmsg line.

/linux-2.6.33/fs/proc/kmsg.c:

static ssize_t kmsg_read(struct file *file, char __user *buf,
                         size_t count, loff_t *ppos)
{
        if ((file->f_flags & O_NONBLOCK) && !do_syslog(9, NULL, 0))
                return -EAGAIN;
        return do_syslog(2, buf, count);
}

and  linux-2.6.33/kernel/printk.c:

int do_syslog(int type, char __user *buf, int len)
{
...
        error = security_syslog(type);
        if (error)
                return error;
...
        switch (type) {
...
        case 2:         /* Read from log */
...
                error = wait_event_interruptible(log_wait,
                                                        (log_start - 
log_end));
               if (error)
                        goto out;
                i = 0;
                raw_spin_lock_irq(&logbuf_lock);
                while (!error && (log_start != log_end) && i < len) {
                        c = LOG_BUF(log_start);
                        log_start++;
                        raw_spin_unlock_irq(&logbuf_lock);
                        error = __put_user(c,buf);
                        buf++;
                        i++;
                        cond_resched();
                        raw_spin_lock_irq(&logbuf_lock);
                }
                raw_spin_unlock_irq(&logbuf_lock);
                if (!error)
                        error = i;
                break;
...
        case 9:         /* Number of chars in the log buffer */
                error = log_end - log_start;
...
        return error;
}


     Wait Queues <include/linux/wait.h> <SLEEPS>


...., it's used to guarantee that if you are checking for a condition, 
and going to sleep if it's not true, that there is no gap between the 
check and the sleeping.

*Queuing*

   ... There is a macro to do this: `wait_event_interruptible()'
   <include/linux/sched.h>. The first argument is the wait queue head,
   and the second is an expression which is evaluated; the macro
   returns 0 when this expression is true, or -ERESTARTSYS if a signal
   is received.

Best regards!