Hello everyone,

(My platform is Linux 2.6.22 + glibc 2.3.6)

I'm trying to figure out who adds timestamps to syslog messages between
the "client" i.e. syslog(3) and the "server" i.e. the syslog daemon.

I ran strace on a trivial program. The following system calls are made
the first time syslog(3) is called:

time([1191574011]) = 1191574011
open("/etc/localtime", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7f24000
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\f\0\0\0\ f\0\0"...,
4096) = 2945
close(3) = 0
munmap(0xb7f24000, 4096) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 3
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
connect(3, {sa_family=AF_FILE, path="/dev/log"}, 16) = 0
send(3, "<14>Oct 5 10:46:51 a.out: HELLO", 32, MSG_NOSIGNAL) = 32

Obviously, syslog(3) adds a timestamp (expressed in localtime).

I suppose the fstat64 and stat64 calls are made from strftime()?

The following system calls are made the second time syslog(3) is called:

time([1191574011]) = 1191574011
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
send(3, "<14>Oct 5 10:46:51 a.out: BYE", 30, MSG_NOSIGNAL) = 30

Why does syslog(3) need to call stat64 three times?

I set up syslogd to send the messages to another host, and sniffed
syslog traffic with tcpdump:

11:02:15.289113 IP (tos 0x0, ttl 1, id 0, offset 0, flags [DF], proto:
UDP (17), length: 45) 10.10.10.208.syslog > 239.10.12.14.syslog: SYSLOG,
length: 17
Facility user (1), Severity info (6)
Msg: a.out: HELLO\012
0x0000: 4500 002d 0000 4000 0111 69ce 0a0a 0ad0 E..-..@...i.....
0x0010: ef0a 0c0e 0202 0202 0019 7a94 3c31 343e ..........z.<14>
0x0020: 612e 6f75 743a 2048 454c 4c4f 0a a.out:.HELLO.

11:02:15.289627 IP (tos 0x0, ttl 1, id 0, offset 0, flags [DF], proto:
UDP (17), length: 43) 10.10.10.208.syslog > 239.10.12.14.syslog: SYSLOG,
length: 15
Facility user (1), Severity info (6)
Msg: a.out: BYE\012
0x0000: 4500 002b 0000 4000 0111 69d0 0a0a 0ad0 E..+..@...i.....
0x0010: ef0a 0c0e 0202 0202 0017 b2f4 3c31 343e ............<14>
0x0020: 612e 6f75 743a 2042 5945 0a a.out:.BYE.

syslogd seems to have stripped the timestamp from the messages. This
means that it will be the responsibility of the remote syslogd to
provide a timestamp for the message.

Does the local syslogd use the timestamp provided by syslog(3) or does
it provide a new one?

Why does syslog(3) provide a timestamp if that timestamp is subsequently
ignored by the consumer of the data, syslogd?

Regards.