Bug 7966

Summary: syslogd/logger wrong timestamps 1.22.x , 1.23.x
Product: Busybox Reporter: Andreas Friesen <ms.frsn>
Component: NetworkingAssignee: unassigned
Status: RESOLVED WORKSFORME    
Severity: major CC: busybox-cvs
Priority: P5    
Version: 1.22.x   
Target Milestone: ---   
Hardware: Other   
OS: Linux   
Host: Target:
Build:

Description Andreas Friesen 2015-03-19 20:31:22 UTC 
Hardware PowerPC MPC5200B; Toolchain Poky-1.5.1

Timestamps in remains contstant in log. What is wrong ? Hier is small example:

root@hbm-000eef(NFS):/$ ps
...
  64 root      2388 S    /sbin/syslogd -D -S -C64 -l 7 -R172.19.1.6:1514
...

root@hbm-000eef(NFS):/$ date | logger
root@hbm-000eef(NFS):/$ date | logger
root@hbm-000eef(NFS):/$ date | logger


[PC]:$ nc -u -l -p 1514
<13>Dec 31 23:59:59 root: Sat Jan  1 00:24:59 UTC 2000
<13>Dec 31 23:59:59 root: Sat Jan  1 00:31:47 UTC 2000
<13>Dec 31 23:59:59 root: Sat Jan  1 00:31:50 UTC 2000

Other example:

appl.bin 2>&1 | logger -t "$HOSTNAME appl  "&

[PC]:$ nc -u -l -p 1514
#syslog() calls inside the application:
<14>Jan  1 00:00:57 appl.bin: Log: ***************************************
<14>Jan  1 00:00:32 appl.bin: Log: System started
<14>Jan  1 00:00:18 appl.bin: Log: 
<13>Dec 31 23:59:59 hbm-000eef appl  : SYNC status changed to SINGLE on back FW
<13>Dec 31 23:59:59 hbm-000eef appl  : ->Reset PLL
<13>Dec 31 23:59:59 hbm-000eef appl  : Reset PLL
<14>Jan  1 00:01:11 appl.bin: Log: clFileSave::clFlashFileItem::save() /par/SysParam.xml
Comment 1 Denys Vlasenko 2017-05-05 15:09:34 UTC 
Unfortunately, most clients of /dev/log socket generate their own timestamp - they send a message which already has time/date prefix.

Current syslog.c code tries to detect it and not generate its own timestamp prefix:

static void timestamp_and_log(int pri, char *msg, int len)
{
        char *timestamp;
        time_t now;

        /* Jan 18 00:11:22 msg... */
        /* 01234567890123456 */
        if (len < 16 || msg[3] != ' ' || msg[6] != ' '
         || msg[9] != ':' || msg[12] != ':' || msg[15] != ' '
        ) {
                time(&now);
                timestamp = ctime(&now) + 4; /* skip day of week */
        } else {
                now = 0;
                timestamp = msg;
                msg += 16;
        }
        timestamp[15] = '\0';

Thus, the bug is not in syslogd.c.

root@hbm-000eef(NFS):/$ date | logger
root@hbm-000eef(NFS):/$ date | logger
root@hbm-000eef(NFS):/$ date | logger

[PC]:$ nc -u -l -p 1514
<13>Dec 31 23:59:59 root: Sat Jan  1 00:24:59 UTC 2000
<13>Dec 31 23:59:59 root: Sat Jan  1 00:31:47 UTC 2000
<13>Dec 31 23:59:59 root: Sat Jan  1 00:31:50 UTC 2000

I ran a similar setup and can't reproduce it: strace shows that logger does this:

send(3, "<13>May  5 16:59:17 root: Fri May  5 16:59:17 CEST 2017\n\0", 57, MSG_NOSIGNAL) = 57

And this is done by syslog(i, "%s", strbuf) libc call: the date/time prefix is generated in libc, not by logger.c code.

I'd hazard to guess "Poky-1.5.1" (whatever that is) is not doing it right.