syslog(3) blocks when local socket is full

syslog(3) blocks when local socket is full

[John Sigler]

[ This message has also been posted to comp.unix.programmer ]

Hello everyone,

My platform: Linux 2.6.22.1-rt9 + glibc 2.3.6

I'm writing a "real-time" application that runs with high priority
(40 or 80 in SCHED_FIFO). I use syslog(3) to log.

As far as I can see, syslog(3) blocks when the local socket becomes
full (11 messages on my system).

Consider the following program.

#include <syslog.h>
int main(void)
{
   int i;
   for (i=0; i < 500; ++i) syslog(LOG_INFO, "I=%d", i);
   return 0;
}

I kill syslogd, then start the above program. It blocks.
I kill it, then start syslogd, which grabs the following messages.

Nov 13 11:18:57 venus a.out: I=0
Nov 13 11:18:57 venus a.out: I=1
Nov 13 11:18:57 venus a.out: I=2
Nov 13 11:18:57 venus a.out: I=3
Nov 13 11:18:57 venus a.out: I=4
Nov 13 11:18:57 venus a.out: I=5
Nov 13 11:18:57 venus a.out: I=6
Nov 13 11:18:57 venus a.out: I=7
Nov 13 11:18:57 venus a.out: I=8
Nov 13 11:18:57 venus a.out: I=9
Nov 13 11:18:57 venus a.out: I=10

(The process managed to write 11 messages before being blocked.)

I expected a local socket to buffer way more than 11 messages.
I expected a local socket to discard new messages when it is full.
Apparently, these expectations are incorrect.

I can see how this behavior can become a problem:

Consider process A with prio 80 in SCHED_FIFO and process B with prio 10
in SCHED_FIFO, i.e. process B only runs when A does not want the CPU.
(syslogd is in SCHED_OTHER.)

'A' runs, starts logging, and reaches the 11-message limit. The call to
write() blocks, and 'A' is put to sleep. The scheduler then picks 'B'
because it has higher priority than syslogd. If B runs "forever", 'A'
will never get the CPU back.

Is this scenario possible?

Is this what is called priority inversion?

Regards.

Re: syslog(3) blocks when local socket is full

[Luis Claudio R. Goncalves]

On Tue, Nov 13, 2007 at 03:38:03PM +0100, John Sigler wrote:
| [ This message has also been posted to comp.unix.programmer ]
| 
| Hello everyone,
| 
| My platform: Linux 2.6.22.1-rt9 + glibc 2.3.6
| 
| I'm writing a "real-time" application that runs with high priority
| (40 or 80 in SCHED_FIFO). I use syslog(3) to log.
| 
| As far as I can see, syslog(3) blocks when the local socket becomes
| full (11 messages on my system).
| 
| Consider the following program.
| 
| #include <syslog.h>
| int main(void)
| {
|   int i;
|   for (i=0; i < 500; ++i) syslog(LOG_INFO, "I=%d", i);
|   return 0;
| }

John, I use glibc-2.6-4 and you test program worked fine. Probably your
manpage (3) for syslog may have details on this feature. You probably have
reached one of the old approaches to avoid DoS via syslog. Limited message
rate would be a reasonable assumption.

One way to better understand what's going on is to either setup syslogd or
your client program (via openlog) to enter in debug mode an print to
stderr.

Luis

| 
| I kill syslogd, then start the above program. It blocks.
| I kill it, then start syslogd, which grabs the following messages.
| 
| Nov 13 11:18:57 venus a.out: I=0
| Nov 13 11:18:57 venus a.out: I=1
| Nov 13 11:18:57 venus a.out: I=2
| Nov 13 11:18:57 venus a.out: I=3
| Nov 13 11:18:57 venus a.out: I=4
| Nov 13 11:18:57 venus a.out: I=5
| Nov 13 11:18:57 venus a.out: I=6
| Nov 13 11:18:57 venus a.out: I=7
| Nov 13 11:18:57 venus a.out: I=8
| Nov 13 11:18:57 venus a.out: I=9
| Nov 13 11:18:57 venus a.out: I=10
| 
| (The process managed to write 11 messages before being blocked.)
| 
| I expected a local socket to buffer way more than 11 messages.
| I expected a local socket to discard new messages when it is full.
| Apparently, these expectations are incorrect.
| 
| I can see how this behavior can become a problem:
| 
| Consider process A with prio 80 in SCHED_FIFO and process B with prio 10
| in SCHED_FIFO, i.e. process B only runs when A does not want the CPU.
| (syslogd is in SCHED_OTHER.)
| 
| 'A' runs, starts logging, and reaches the 11-message limit. The call to
| write() blocks, and 'A' is put to sleep. The scheduler then picks 'B'
| because it has higher priority than syslogd. If B runs "forever", 'A'
| will never get the CPU back.
| 
| Is this scenario possible?
| 
| Is this what is called priority inversion?
| 
| Regards.
| 
| -
| To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
| the body of a message to majordomo@vger.kernel.org
| More majordomo info at  http://vger.kernel.org/majordomo-info.html
---end quoted text---

-- 
[ Luis Claudio R. Goncalves                    Bass - Gospel - RT ]
[ Fingerprint: 4FDD B8C4 3C59 34BD 8BE9  2696 7203 D980 A448 C8F8 ]

Re: syslog(3) blocks when local socket is full

[John Sigler]

Luis Claudio R. Goncalves wrote:

> John Sigler wrote:
> 
>> My platform: Linux 2.6.22.1-rt9 + glibc 2.3.6
>> 
>> I'm writing a "real-time" application that runs with high priority
>> (40 or 80 in SCHED_FIFO). I use syslog(3) to log.
>> 
>> As far as I can see, syslog(3) blocks when the local socket becomes
>> full (11 messages on my system).
>> 
>> Consider the following program.
>> 
>> #include <syslog.h>
>> int main(void)
>> {
>>   int i;
>>   for (i=0; i < 500; ++i) syslog(LOG_INFO, "I=%d", i);
>>   return 0;
>> }
> 
> John, I use glibc-2.6-4 and your test program worked fine. Probably

When you write "your test program worked fine" do you mean that
the process ran and exited with 0?

> your man page (3) for syslog may have details on this feature.

What feature are you referring to?

> You probably have reached one of the old approaches to avoid DoS via
> syslog. Limited message rate would be a reasonable assumption.

Did you kill syslogd before running the test program?

> One way to better understand what's going on is to either setup
> syslogd or your client program (via openlog) to enter in debug mode
> an print to stderr.

In my example, syslogd is not running. See below.

>> I kill syslogd, then start the above program. It blocks.
>> I kill it, then start syslogd, which grabs the following messages.
>> 
>> Nov 13 11:18:57 venus a.out: I=0
>> Nov 13 11:18:57 venus a.out: I=1
>> Nov 13 11:18:57 venus a.out: I=2
>> Nov 13 11:18:57 venus a.out: I=3
>> Nov 13 11:18:57 venus a.out: I=4
>> Nov 13 11:18:57 venus a.out: I=5
>> Nov 13 11:18:57 venus a.out: I=6
>> Nov 13 11:18:57 venus a.out: I=7
>> Nov 13 11:18:57 venus a.out: I=8
>> Nov 13 11:18:57 venus a.out: I=9
>> Nov 13 11:18:57 venus a.out: I=10
>> 
>> (The process managed to write 11 messages before being blocked.)
>> 
>> I expected a local socket to buffer way more than 11 messages.
>> I expected a local socket to discard new messages when it is full.
>> Apparently, these expectations are incorrect.
>> 
>> I can see how this behavior can become a problem:
>> 
>> Consider process A with prio 80 in SCHED_FIFO and process B with prio 10
>> in SCHED_FIFO, i.e. process B only runs when A does not want the CPU.
>> (syslogd is in SCHED_OTHER.)
>> 
>> 'A' runs, starts logging, and reaches the 11-message limit. The call to
>> write() blocks, and 'A' is put to sleep. The scheduler then picks 'B'
>> because it has higher priority than syslogd. If B runs "forever", 'A'
>> will never get the CPU back.
>> 
>> Is this scenario possible?
>> 
>> Is this what is called priority inversion?

Re: syslog(3) blocks when local socket is full

[Luis Claudio R. Goncalves]

On Tue, Nov 13, 2007 at 05:15:01PM +0100, John Sigler wrote:
| Luis Claudio R. Goncalves wrote:
| 
| >John Sigler wrote:
| >
| >>My platform: Linux 2.6.22.1-rt9 + glibc 2.3.6
| >>
| >>I'm writing a "real-time" application that runs with high priority
| >>(40 or 80 in SCHED_FIFO). I use syslog(3) to log.
| >>
| >>As far as I can see, syslog(3) blocks when the local socket becomes
| >>full (11 messages on my system).
| >>
| >>Consider the following program.
| >>
| >>#include <syslog.h>
| >>int main(void)
| >>{
| >>  int i;
| >>  for (i=0; i < 500; ++i) syslog(LOG_INFO, "I=%d", i);
| >>  return 0;
| >>}
| >
| >John, I use glibc-2.6-4 and your test program worked fine. Probably
| 
| When you write "your test program worked fine" do you mean that
| the process ran and exited with 0?

Sorry, I wrote that in a hurry and have eatean some words :)

Yes, after running the test program I ended up with 500 messages in syslog
and 0 as the return code. 
 
| >your man page (3) for syslog may have details on this feature.
| 
| What feature are you referring to?

Syslog manpage (3), glibc 2.6-4, talks about the possibility of a DoS in
the system using syslog as the weapon to do that. It also describes some
known ways to protect your system of this possible DoS.

Checking the manpage (man 3 syslog) may give you hints on whether the
behavior you observed is a rate limit imposed by syslog, a "feature" of
your system or nothing related to syslog.

| >You probably have reached one of the old approaches to avoid DoS via
| >syslog. Limited message rate would be a reasonable assumption.
| 
| Did you kill syslogd before running the test program?

Nope. I booted my machine 10 days ago and just compiled and ran the test
code you sent in your email.

| >One way to better understand what's going on is to either setup
| >syslogd or your client program (via openlog) to enter in debug mode
| >an print to stderr.
| 
| In my example, syslogd is not running. See below.

Ugh! I missed that.

I did some more testing, now with syslog turned off. The return code is
always 0, the program runs to completition - without hanging or without
waiting for any event. Turning syslog on, no singe log message from the
test program appears.

strace:

500 repetitions of:

 socket(PF_FILE, SOCK_DGRAM, 0)          = 3
 fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 110) = -1 ENOENT (No such
 file or directory)
 close(3)                                = 0

Anyway, the default for syslog is to be LOG_ODELAY, so it waits until the
conection is made before going on. That can be changed using LOG_NDELAY in
openlog().

 
| >>I kill syslogd, then start the above program. It blocks.
| >>I kill it, then start syslogd, which grabs the following messages.
| >>
| >>Nov 13 11:18:57 venus a.out: I=0
| >>Nov 13 11:18:57 venus a.out: I=1
| >>Nov 13 11:18:57 venus a.out: I=2
| >>Nov 13 11:18:57 venus a.out: I=3
| >>Nov 13 11:18:57 venus a.out: I=4
| >>Nov 13 11:18:57 venus a.out: I=5
| >>Nov 13 11:18:57 venus a.out: I=6
| >>Nov 13 11:18:57 venus a.out: I=7
| >>Nov 13 11:18:57 venus a.out: I=8
| >>Nov 13 11:18:57 venus a.out: I=9
| >>Nov 13 11:18:57 venus a.out: I=10
| >>
| >>(The process managed to write 11 messages before being blocked.)
| >>
| >>I expected a local socket to buffer way more than 11 messages.
| >>I expected a local socket to discard new messages when it is full.
| >>Apparently, these expectations are incorrect.
| >>
| >>I can see how this behavior can become a problem:
| >>
| >>Consider process A with prio 80 in SCHED_FIFO and process B with prio 10
| >>in SCHED_FIFO, i.e. process B only runs when A does not want the CPU.
| >>(syslogd is in SCHED_OTHER.)
| >>
| >>'A' runs, starts logging, and reaches the 11-message limit. The call to
| >>write() blocks, and 'A' is put to sleep. The scheduler then picks 'B'
| >>because it has higher priority than syslogd. If B runs "forever", 'A'
| >>will never get the CPU back.
| >>
| >>Is this scenario possible?
| >>
| >>Is this what is called priority inversion?
---end quoted text---

-- 
[ Luis Claudio R. Goncalves                    Bass - Gospel - RT ]
[ Fingerprint: 4FDD B8C4 3C59 34BD 8BE9  2696 7203 D980 A448 C8F8 ]

Re: syslog(3) blocks when local socket is full

[John Sigler]

(You're using a weird quote character.)

Luis Claudio R. Goncalves wrote:

> I did some more testing, now with syslog turned off. The return code is
> always 0, the program runs to completion - without hanging or without
> waiting for any event. Turning syslog on, no singe log message from the
> test program appears.
> 
> strace:
> 
> 500 repetitions of:
> 
>  socket(PF_FILE, SOCK_DGRAM, 0)          = 3
>  fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
>  connect(3, {sa_family=AF_FILE, path="/dev/log"}, 110) = -1 ENOENT
>    (No such file or directory)
>  close(3)                                = 0

The /dev/log file does not exist because syslogd removed it.
(A process must bind that "address" for the file to exist.)
The program tries to connect, and fails, 500 times.

My description of the setup was incorrect.

#include <syslog.h>
int main(void)
{
   int i;
   for (i=1; i <= 1000; ++i)
   {
     printf("Sending I=%d\n", i);
     syslog(LOG_INFO, "I=%d", i);
   }
   return 0;
}

1. start syslogd (the syslog daemon)
2. send syslogd the STOP signal
3. run the test program (it will block)
4. kill the test program
5. send syslogd the CONT signal

syslogd binds "/dev/log" which "creates" the socket:
$ ls -l /dev/log
srw-rw-rw- 1 root root 0 2007-10-08 09:36 /dev/log=

> Anyway, the default for syslog is to be LOG_ODELAY, so it waits until the
> connection is made before going on. That can be changed using LOG_NDELAY in
> openlog().

LOG_NDELAY and LOG_ODELAY are a different matter.

Regards.